MMM-GooglePhotos

[gonzonia]

@Sean I’ve been looking into this, because I’m really don’t think it’s my network (no other module has this issue and there’s no similar problems anywhere else on the network). The first error doesn’t seem to be fatal, but the second is.

These are the errors I’m seeing in my Out.log

[2020-04-27 17:33:15.365] [LOG]    2020-04-27T17:33:15 <log> [GPHOTOS:CORE] Error: socket hang up (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)

and

[2020-04-27 18:51:15.155] [LOG]    2020-04-27T18:51:15 <log> [GPHOTOS:CORE] Error: Client network socket disconnected before secure TLS connectionwas established (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)

I came across this issue on gitub related to Google APIs. https://github.com/googleapis/nodejs-bigquery/issues/624
Not sure it’s related.

In Error.log I see

2020-04-27 17:33:15.356] [ERROR]  2020-04-27T17:33:15 <error> Error: socket hang up
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.socketOnEnd (_http_client.js:436:23)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) {
  code: 'ECONNRESET'
} (/home/pi/MagicMirror/js/app.js:40 process.<anonymous>)
[2020-04-27 17:33:15.361] [ERROR]  2020-04-27T17:33:15 <error> Error: socket hang up
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.socketOnEnd (_http_client.js:436:23)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) {
  code: 'ECONNRESET'
} (/home/pi/MagicMirror/js/app.js:40 process.<anonymous>)
[2020-04-27 17:33:15.367] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Error: socket hang up
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.socketOnEnd (_http_client.js:436:23)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 17:33:15.368] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Error: socket hang up
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.socketOnEnd (_http_client.js:436:23)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 17:33:15.369] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 17:33:15.369] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 17:33:15.370] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 17:33:15.371] [ERROR]  2020-04-27T17:33:15 <error> (node:17589) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)

and

[2020-04-27 18:51:15.161] [ERROR]  2020-04-27T18:51:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Error: Client network socket disconnected before secure TLS connection was established
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.onConnectEnd (_tls_wrap.js:1355:19)
    at Object.onceWrapper (events.js:288:20)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 18:51:15.164] [ERROR]  2020-04-27T18:51:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Error: Client network socket disconnected before secure TLS connection was established
    at connResetException (internal/errors.js:559:14)
    at TLSSocket.onConnectEnd (_tls_wrap.js:1355:19)
    at Object.onceWrapper (events.js:288:20)
    at TLSSocket.emit (events.js:205:15)
    at endReadableNT (_stream_readable.js:1154:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:9) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 18:51:15.166] [ERROR]  2020-04-27T18:51:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 4) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)
[2020-04-27 18:51:15.168] [ERROR]  2020-04-27T18:51:15 <error> (node:17589) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 4) (/home/pi/MagicMirror/internal/process/warning.js:27 writeOut)

[bhepler]

@zolabus - That is merely a warning, not an error. That won’t be the source of the problem.

[sdetweil]

@bhepler Unhandled promise rejection.

I disagree… that means the code didn’t anticipate the error, and was waiting for the good completion which will never come…

gotta have a .catch() on every .then()

[A Former User]

Unhandled promise rejection is not the reason of this symptom, rather result.
Anyway,
I think Client network socket disconnected before secure TLS connection was established is not coming from program logic. It probably might be caused from unstable network status. (Especially handling TLS connection).
There is no one reason of that issue, so it has no simple solution to diagnose or solve.
I can’t represent this symptom, so hard to find the solution at this moment.

@gonzonia
For me;

reconnect once the connection works again, the image being stuck won’t be an issue. Right now once the connection breaks the module can’t recover.

When I force to break the connection then reconnect again, the module works again without issue. This module just loads an image from external google URL on each update schedule. So, if network is ok, image should be loaded and displayed. I suspect your router or proxy setting is interfering TLS connection between Google Server. but not sure.

Anyway, at this moment hard to find reason why yours are not working.

[gonzonia]

@Sean I appreciate you trying. I’ll see if I can figure out more detail. It’s weird because it’ll work fine sometimes for days and then all of a sudden I can’t get it to do more than 1 or 2 photos before it stops. Nothing else on the pi has that issue, newsfeeds still update, weather updates, CalendarExt2 updates.

I’m going to circumvent the pihole I have set up and point to GoogleDNS and see if that helps.

I wasn’t seeing anything from the MagicMirror in the query logs for the pihole which was in itself odd.

[bhepler]

@sdetweil - I was replying to the warning about the buffer package being deprecated.

[sdetweil]

@bhepler ah. never mind!

[gonzonia]

@Sean I’ve got a theory. I don’t know enough about how it’s all working to be sure, but I’m testing it a little. I noticed in the logs that the error seemed to coincide with something the CalendarExt2 module was doing. Since they’re both connecting to Google, I thought, perhaps there’s something happening there. I’ve disabled the CalendarExt2 module and haven’t had a problem. I’m going to see how it all runs for today and then turn the module back on to see if the problem returns.

[A Former User]

@gonzonia
It makes some sense. By racing to use the same connection, there could be some conflicts. Hmmmm…

[gonzonia]

@Sean Sadly, it doesn’t look like that’s it. Everything ran great for 12 hours, than quit again. Restarted this morning and it lasted an hour or two. The problem always appears arround indexing.

[2020-04-30 08:56:17.785] [LOG]    2020-04-30T08:56:17 <log> [GPHOTOS] Start Album scanning (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_helper.js:44 Class.log)
[2020-04-30 08:56:17.789] [LOG]    2020-04-30T08:56:17 <log> [GPHOTOS:AUTH] Token is alive. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:20 Auth.log)
[2020-04-30 08:56:17.791] [LOG]    2020-04-30T08:56:17 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
REPEATS....
[2020-04-30 08:56:55.332] [LOG]    2020-04-30T08:56:55 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-04-30 08:57:17.685] [LOG]    2020-04-30T08:57:17 <log> [GPHOTOS:CORE] Error: Client network socket disconnected before secure TLS connection was established (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-04-30 08:57:18.712] [LOG]    2020-04-30T08:57:18 <log> [GPHOTOS] Image loaded: https://lh3.googleusercontent.com/XXXXXX (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_helper.js:44 Class.log)
[2020-04-30 08:59:18.130] [LOG]    2020-04-30T08:59:18 <log> [GPHOTOS] Image loading fails. Check your network.: https://lh3.googleusercontent.com/XXXXXXXX(/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_helper.js:44 Class.log)

I’m determined to figure this out though.

[sdetweil]

@gonzonia

correct, the code then fails, the module sends the helper a message

      case 'IMAGE_LOAD_FAIL':
        this.log("Image loading fails. Check your network.:", payload)
        break

and the helper logs it, but never does anything after that
so, now the module is waiting for another image,

      case 'UPLOAD':
        this.upload(payload)
        break

but the helper doesn’t know

[A Former User]

@sdetweil
Nothing can be dine after image loading fails. Even connected again, couldn’t be recognized. It is just kind logging.
I’m not sure what could be possible to do for this kind of network issue by module itself.

[RoggerFabri]

Hi @Sean , thanks a lot for your time and effort on creating this module, I was searching for something similar for a long time already. From time to time, I’m getting several Forbidden 403 responses from the requests to load new pictures, this gives the impression that the pictures are stuck. Do you have an idea of what might be causing that?

[A Former User]

@RoggerFabri
All those kinds of errors (403, 500, …) means network/server errors. Nothing could do in client(module) itself. Only thing would be just waiting(stuck) problem solved by network/server.

[bhepler]

@RoggerFabri - I don’t know if this is relevant, but I know Amazon AWS bulk storage returns 403 errors if you get the URL wrong. I’m not sure if their security model is so granular that files have to be authorized independently or if the wrong URL attempts to serve up the directory index and that file is locked out. And I have no idea if Google uses the same technique.

Either way, I would check the request to make sure it is pointing to a valid asset.

[gonzonia]

@Sean 403 is a “forbidden” status. Is it possible to catch that status being returned and then go back to refreshing the token and starting the process over from there?

[A Former User]

@gonzonia
There could be possibility “dead url after it’s lifetime”(60 minutes) but to avoid it, photos working urls would be rescanned and refreshed per 50mins.
Of course, if there be network error to prevent resurrection, it will not work. That is not the token issue.

[orayoflighto]

This post is deleted!

[gonzonia]

@Sean Okay. Thanks. As a stab in the dark I changed the pageSize in the getAlbum call to 25. It’s been running now for 14 hours without an error. If it’s still good in the morning I’ll restore the old version and see if the error comes back. I don’t remember what led me down that path but something this morning made me think to give it a try.

[gonzonia]

@Sean So I had over 24 hours with it working. Swapped back to the original file and it errored out within 2 hours. Swapped back to new file and again errored in 2 hours. I don’t get it. I was mistaken with what I changed, I changed the getImage call to a pageSize of 25. This made indexing take longer. It always returns the TLS error when indexing. I have it looking at two albums. One is big with 937 images. The other is only 129. When the error happens it is always while indexing the first one. Is the large album the problem?

[2020-05-02 21:35:51.841] [LOG]    2020-05-02T21:35:51 <log> [GPHOTOS] Start Album scanning (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_helper.js:44 Class.log)
[2020-05-02 21:35:51.845] [LOG]    2020-05-02T21:35:51 <log> [GPHOTOS:AUTH] Token is alive. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:20 Auth.log)
[2020-05-02 21:35:51.848] [LOG]    2020-05-02T21:35:51 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:35:53.427] [LOG]    2020-05-02T21:35:53 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:35:55.358] [LOG]    2020-05-02T21:35:55 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:35:56.996] [LOG]    2020-05-02T21:35:56 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:35:58.431] [LOG]    2020-05-02T21:35:58 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:35:59.769] [LOG]    2020-05-02T21:35:59 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:36:01.544] [LOG]    2020-05-02T21:36:01 <log> [GPHOTOS:CORE] Indexing photos now. (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)
[2020-05-02 21:36:16.288] [LOG]    2020-05-02T21:36:16 <log> [GPHOTOS:CORE] Error: Client network socket disconnected before secure TLS connection was established (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)