@cowboysdude said in MMM-GooglePhotos:

He added logging and in there it should tell you why it’s failing…

Yes. This is the error and I appreciate all @Sean has done. However, whatever is causing the error below isn’t something I can identify/control/fix. There are no network issues anywhere else on my network except this single module. At least once a day I need to manually intervene to get it started again.

 Error: Client network socket disconnected before secure TLS connection was established (/home/pi/MagicMirror/modules/MMM-GooglePhotos/GPhotos.js:124 GPhotos.log)

@cowboysdude The URLs only last for an hour. That’s why it re-indexes and updates after 50 min. The issue @kykzzang and I are having is that sometimes during indexing there’s a network issue and the indexing doesn’t complete. When that happens the URLs don’t get updated and the module tries using the old URLs resulting in the the failed image loading.

@Sean Okay. I think I’m understanding the behavior a little more. It ran yesterday for over 12 hours. When it failed, it happened on indexing, then a single image was loaded successfully. After that all images failed and the module never tried refreshing the token or indexing again.

I don’t know what the cause of the network socket disconnected error is, but is there any way for the module to recover?

If it recovered even in another 50 min when it should do another scan, I think that’s reasonable. The problem is that the error is fatal to the scanning process and all the URLs are bad after the 60 min lifespan. The module never restarts the scanning after the initial failure.

@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)

@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.

@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?

@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.

@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.

@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.

@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)