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.