hermanho / MMM-GooglePhotos

Display your photos on MagicMirror from Google Photos.
MIT License
170 stars 65 forks source link

Photos are only shown in the evening #127

Closed bhaules closed 2 years ago

bhaules commented 2 years ago

I had this configuration for more than a year and recently re-installed Magic Mirror and all the modules. This is my GooglePhotos config:

 {
 226           module: "MMM-GooglePhotos",
 227           position: "fullscreen_below",
 228           config: {
 229                 albums: ["FamilyPhotos"], // Set your album name. like ["My wedding", "family share", "Travle to Paris"]
 230                 updateInterval: 1000 * 60 *2, // minimum 10 seconds.
 231                 scanInterval:1000*60*10
 232                 sort: "random", // "old", "random"
 233                 uploadAlbum: null, // Only album created by `create_uploadable_album.js`.
 234                 condition: {
 235                     fromDate: null, // Or "2018-03", RFC ... format available
 236                     toDate: null, // Or "2019-12-25",
 237                     minWidth: null, // Or 400
 238                     maxWidth: null, // Or 8000
 239                     minHeight: null, // Or 400
 240                     maxHeight: null, // Or 8000
 241                     minWHRatio: null,
 242                     maxWHRatio: null,
 243                     // WHRatio = Width/Height ratio ( ==1 : Squared Photo,   < 1 : Portraited Photo, > 1 : Landscaped Photo)
 244                 },
 245                 showWidth: 1080, // These values will be used for quality of downloaded photos to show. real size to show in your MagicMirror region is recommended.
 246                 showHeight: 1920,
 247                 timeFormat: "DD MMM YYYY HH:mm", // Or `relative` can be used.
 248               debug: true,
 249               }
 250         },

When I go to the MagicMirror-out.log I get:

 267546 [19.12.2021 10:58.04.127] [LOG]   [GPHOTOS] Getting album list
 267547 [19.12.2021 10:58.04.137] [LOG]   [GPHOTOS:AUTH] Token is alive.
 267548 [19.12.2021 10:58.04.143] [LOG]   [GPHOTOS:CORE] Getting Album info chunks.
 267549 [19.12.2021 10:58.04.807] [LOG]   [GPHOTOS:CORE] Error: Request failed with status code 429
 267550 [19.12.2021 10:59.04.127] [LOG]   [GPHOTOS] Starting Initialization
 267551 [19.12.2021 10:59.04.134] [LOG]   [GPHOTOS] Getting album list
 267552 [19.12.2021 10:59.04.143] [LOG]   [GPHOTOS:AUTH] Token is alive.
 267553 [19.12.2021 10:59.04.146] [LOG]   [GPHOTOS:CORE] Getting Album info chunks.
 267554 [19.12.2021 10:59.05.781] [LOG]   [GPHOTOS:CORE] Error: Request failed with status code 429

When I go to MagicMirror-error.log I get:

 212039 [19.12.2021 10:59.05.786] [ERROR] (node:25894) 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(). To         terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 6)
 212040 [19.12.2021 11:00.05.787] [ERROR] (node:25894) UnhandledPromiseRejectionWarning: Error: Request failed with status code 429
 212041     at createError (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_modules/axios/lib/core/createError.js:16:15)
 212042     at settle (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_modules/axios/lib/core/settle.js:17:12)
 212043     at IncomingMessage.handleStreamEnd (/home/pi/MagicMirror/modules/MMM-GooglePhotos/node_modules/axios/lib/adapters/http.js:236:11)
 212044     at IncomingMessage.emit (events.js:327:22)
 212045     at endReadableNT (internal/streams/readable.js:1327:12)
 212046     at processTicksAndRejections (internal/process/task_queues.js:80:21)

What I found about this error was this page from the forum: https://forum.magicmirror.builders/topic/14871/mmm-googlephotos-unhandled-promise-rejection/8 but I can't seem to figure out how am I getting too may requests as I should be below that number with a request every 5 minutes.

In the evenings though the Google Photos module seems to start working. Last night it worked from about 8PM to about 2AM:

263628 [19.12.2021 02:01.29.956] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4230
 263629 [19.12.2021 02:01.31.057] [LOG]   en
 263630 [19.12.2021 02:01.31.937] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263631 [19.12.2021 02:01.33.091] [LOG]   en
 263632 [19.12.2021 02:01.33.590] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4270
 263633 [19.12.2021 02:01.34.612] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263634 [19.12.2021 02:01.35.775] [LOG]   en
 263635 [19.12.2021 02:01.36.816] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4319
 263636 [19.12.2021 02:01.37.552] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263637 [19.12.2021 02:01.38.690] [LOG]   en
 263638 [19.12.2021 02:01.40.010] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4369
 263639 [19.12.2021 02:01.40.261] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263640 [19.12.2021 02:01.41.418] [LOG]   en
 263641 [19.12.2021 02:01.42.818] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263642 [19.12.2021 02:01.43.235] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4419
 263643 [19.12.2021 02:01.44.146] [LOG]   en
 263644 [19.12.2021 02:01.45.877] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4468
 263645 [19.12.2021 02:01.45.912] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263646 [19.12.2021 02:01.47.045] [LOG]   en
 263647 [19.12.2021 02:01.48.018] [LOG]   Notification: GET_SOLAR Payload: [object Object]
 263648 [19.12.2021 02:01.48.421] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4518
 263649 [19.12.2021 02:01.48.595] [LOG]   NOAA3 weather updated.. next update in 1 hour
 263650 [19.12.2021 02:01.50.022] [LOG]   en
 263651 [19.12.2021 02:01.50.694] [LOG]   starting network connection testing
 263652 [19.12.2021 02:01.51.086] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4568
 263653 [19.12.2021 02:01.52.585] [LOG]   [GPHOTOS] Start Album scanning
 263654 [19.12.2021 02:01.52.596] [LOG]   [GPHOTOS] Prepping to get photo list from 'FamilyPhotos'
 263655 [19.12.2021 02:01.52.602] [LOG]   [GPHOTOS:AUTH] Token is alive.
 263656 [19.12.2021 02:01.52.605] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  0
 263657 [19.12.2021 02:01.54.347] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4615
 263658 [19.12.2021 02:01.54.845] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  45
 263659 [19.12.2021 02:01.56.918] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4659
 263660 [19.12.2021 02:01.58.438] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  91
 263661 [19.12.2021 02:01.59.317] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4702
 263662 [19.12.2021 02:02.01.182] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  140
 263663 [19.12.2021 02:02.01.943] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4749
 263664 [19.12.2021 02:02.03.825] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  187
 263665 [19.12.2021 02:02.05.659] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4798
 263666 [19.12.2021 02:02.06.479] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  234
 263667 [19.12.2021 02:02.09.398] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4847
 263668 [19.12.2021 02:02.09.927] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  276
 263669 [19.12.2021 02:02.11.982] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4897
 263670 [19.12.2021 02:02.13.361] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  325
 263671 [19.12.2021 02:02.15.614] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4946
 263672 [19.12.2021 02:02.17.021] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  375
 263673 [19.12.2021 02:02.19.028] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  4995
 263674 [19.12.2021 02:02.20.643] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  420
 263675 [19.12.2021 02:02.21.314] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5044
 263676 [19.12.2021 02:02.22.998] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  468
 263677 [19.12.2021 02:02.23.433] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5094
 263678 [19.12.2021 02:02.26.387] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  515
 263679 [19.12.2021 02:02.26.760] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5143
 263680 [19.12.2021 02:02.32.390] [INFO]  Calendar-Fetcher: Broadcasting 15 events.
 263681 [19.12.2021 02:02.32.949] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5191
 263682 [19.12.2021 02:02.32.978] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  559
 263683 [19.12.2021 02:02.36.310] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  607
 263684 [19.12.2021 02:02.36.335] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5240
 263685 [19.12.2021 02:02.39.673] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5289
 263686 [19.12.2021 02:02.39.770] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  651
 263687 [19.12.2021 02:02.41.940] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5338
 263688 [19.12.2021 02:02.42.876] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  696
 263689 [19.12.2021 02:02.45.429] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5388
 263690 [19.12.2021 02:02.46.248] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  734
 263691 [19.12.2021 02:02.48.599] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  778
 263692 [19.12.2021 02:02.49.679] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5438
 263693 [19.12.2021 02:02.50.705] [LOG]   [GPHOTOS:CORE] Error: Request failed with status code 429
 263694 [19.12.2021 02:02.52.221] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5488
 263695 [19.12.2021 02:02.53.756] [LOG]   [GPHOTOS:CORE] Error: Request failed with status code 429
 263696 [19.12.2021 02:04.05.930] [LOG]   [GPHOTOS] Image loading fails. Check your network.: https://lh3.googleusercontent.com/lr/AFBm1_b84YissZJVOjwjMwQ-ztj7i-L_kjglXaMKSLMzhSWx5pqfSI_BDFFNToYwrOzJAQqcUPworEBaXfJVagYWNppK9g-0giQ_3iHKwGWnaT9CDBLUfAQP9gBRnTYouHAP-                    gI053J7hFAuWRv1y072K_dEL9K7Kipr5Inm5OoTnR4gPG6_Nq1y6hBoCFrAjJTOnsrdYlLJixbIm4bKgzdrGzQSxzt3zUolBG-1VBbhzurYmrY9AIt7o_NqPn8bdQZTpXVF7-D9MWT91yq7sH0yzkFmxqOz3qeaMr_VYnfs4eSaQOuDQQw80ZggI4KZlkxeCr8fTSVoCQ5oZaZwsirn6cFsAlFNkX1B8-mCm7TYnWYlJbEzeKkfMxqKVlBdERpmc-                   jXAl3Ip8FgrNGrgebzUnfzglYUkyWvWjZAnwVqCDzKCEVVHjAy1zxd94TiqV37uXmP8C3Sp-f4_lvCVkDSuk-X8NzosEKcStZRMJl0mxP75UnVfHHhlCql8AXncwmVstX5y2ftlqRuj499_LFKx6b_2Kkz-xC4OOJoUvy-                                                                                                              jSPVp1UiH0hMMLhhTwwi1X89jwCInvK9HwHHF3jE7lUs9NgmTcC0ffheLS0fYNcZ7OxLlV15SIPH60XdNYNM2OfWBajJtbFeDuMQmTx6WUx1QADfpa81DoAffv8jj7PRJ6U2Fv_scoNcN08IgbKt_DJjgVk67b69BtHJciymhmkSx8EWzeUFBMFwe3D0k6vcbnOssDMw96XTVZU5SGQKewYNIh7zOm_TD8EvI-PuWKwVDgOiESMuVynxNIRvlgggwSdu5HlSnq9-        HTQgwQOHx_v-N0ca99ULapd6=w1080-h1920
 263697 [19.12.2021 02:04.05.931] [LOG]   [GPHOTOS] num to ref:  8 , DesChunk:  8 , totalLength:  6228 , Pntr:  343
 263698 [19.12.2021 02:04.05.933] [LOG]   [GPHOTOS:AUTH] Token is alive.

Looking at the logs what I found curious was that it seems that there are multiple streams of indexing happeing in paralel:

 263684 [19.12.2021 02:02.36.335] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5240
 263685 [19.12.2021 02:02.39.673] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5289
 263686 [19.12.2021 02:02.39.770] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  651
 263687 [19.12.2021 02:02.41.940] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5338
 263688 [19.12.2021 02:02.42.876] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  696
 263689 [19.12.2021 02:02.45.429] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5388
 263690 [19.12.2021 02:02.46.248] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  734
 263691 [19.12.2021 02:02.48.599] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  778
 263692 [19.12.2021 02:02.49.679] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5438

Does anybody have an idea on what I should try to fix this? Thank you

bhaules commented 2 years ago

image

I just went in my google api account and clicked around and found that I was going over my quota every day and probably my quota was reset at in the evening and fill it up by morning. Still don't know why I'm going over my quota in just a few hours.

bhaules commented 2 years ago

Anyone having any ideas?

eouia commented 2 years ago

You might have too many folders and photos in your "FamilyPhotos" and too often scanning. Your config shows, it tries to scan your album every 10 minutes. At each scan, it will consume quite a lot of quota due to your amount of photos.

My suggestions;

eouia commented 2 years ago

PS; Over 1-hour scanInterval might not be a good idea. As far as I remember, Google Photos' temporal instant URL of photos would be expired after 1 hour from request. Anyway, your photos are too many to handle with a limited quota.

bhaules commented 2 years ago

thanks mate for your help. I'll try scanning less often, didn't realise that this was killing my quota (to be honest I didn't really understand what it did until now). My config has been the same all this time and the photos in the album grew by a few a day. 2021-12-22 07_43_11-Photos

This bit here makes me think I have 2 instances running in the same time, or maybe the scanning hasn't finished in the 10 minutes and it started a new instance of scanning the photos?

 263684 [19.12.2021 02:02.36.335] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5240
 263685 [19.12.2021 02:02.39.673] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5289
 263686 [19.12.2021 02:02.39.770] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  651
 263687 [19.12.2021 02:02.41.940] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5338
 263688 [19.12.2021 02:02.42.876] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  696
 263689 [19.12.2021 02:02.45.429] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5388
 263690 [19.12.2021 02:02.46.248] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  734
 263691 [19.12.2021 02:02.48.599] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  778
 263692 [19.12.2021 02:02.49.679] [LOG]   [GPHOTOS:CORE] Indexing photos now. total:  5438
eouia commented 2 years ago

Your opinion is Interesting, it could be possible.

Hmmm.. Is MM or module executed twice? Probably you might check that thing already...

I believe the module owner @aneaville could help you. This module have been modified since the ownership was transferred from me to @aneaville, So my knowledge about this module is somehow out-of-date. I hope he can diagnose deeper and help you.

bhaules commented 2 years ago
pi@MagicMirror2:~/MagicMirror/modules $ pm2 restart all
Use --update-env to update environment variables
[PM2] Applying action restartProcessId on app [all](ids: [ 0 ])
[PM2] [MagicMirror](0) ✓
┌─────┬────────────────┬─────────────┬─────────┬─────────┬──────────┬────────┬──────┬───────────┬──────────┬──────────┬──────────┬──────────┐
│ id  │ name           │ namespace   │ version │ mode    │ pid      │ uptime │ ↺    │ status    │ cpu      │ mem      │ user     │ watching │
├─────┼────────────────┼─────────────┼─────────┼─────────┼──────────┼────────┼──────┼───────────┼──────────┼──────────┼──────────┼──────────┤
│ 0   │ MagicMirror    │ default     │ 2.17.1  │ fork    │ 1324     │ 0s     │ 8    │ online    │ 0%       │ 2.7mb    │ pi       │ disabled │
└─────┴────────────────┴─────────────┴─────────┴─────────┴──────────┴────────┴──────┴───────────┴──────────┴──────────┴──────────┴──────────┘

I don't think I'm running the module twice, but I don't know how to find that out other than the above

eouia commented 2 years ago

If you run MM twice by mistake, it will spit out error earlier because the same port is used. So this is not the case. I suspect the algorithm of module, using setInterval instead of my old setTimeout method, @aneaville did. Usually that approach will work well, it will prevent the stop of module while not severe error happens. My old code was stopping module on meeting even tiny problem. So probably his modification is advanced. But in this case, I suspect module is trying to scan forcely despite of some issue, so the connections might be established twice.

I’m not sure really what happened. I hope @aneaville come back and solve our issues.

aneaville commented 2 years ago

From the times in your log, it took about 1.5 min to scan from 4230 to 5488. 63628 [19.12.2021 02:01.29.956] [LOG] [GPHOTOS:CORE] Indexing photos now. total: 4230 263694 [19.12.2021 02:02.52.221] [LOG] [GPHOTOS:CORE] Indexing photos now. total: 5488

You have 6288 photos in the album to scan, so I expect a full scan to take about 7.5 min. This can get slowed down by many things though, and it will start a new scan in parallel if the scan interval is too fast. I'm not sure if things work nicely in this case or if counters will get shared and mess things up.

But I do expect slowing the scan interval down will solve the issue. Scanning every 10 min ate up your quota and you are correct that your quota gets reset every 24 hours. I recommend increasing the scan interval to 60 min or longer.

The scan just gets a list of all the photos the module needs to show. This list rarely changes unless you add a new photo to the album. Detecting within an hour is usually fine. Also since the scan takes so long, the module saves that photo list as a file(just the IDs, not the actual photos), so it can start showing pictures faster. So once a scan is completed successfully, the module could work even if the scan fails continuously.

Eouia is right though, the link for a photo is only good for about an hour. Another change I made was to 'refresh' the link to the photos that are getting showed. So scanning at slower than 60 min is ok. The refreshing uses the same quota though, and if it can't refresh the links, it will stop working.

Hope this helps, sorry for being slow to respond. Please let us know if changing the scan interval to 60 min solves your issues.

bhaules commented 2 years ago

But I do expect slowing the scan interval down will solve the issue. Scanning every 10 min ate up your quota and you are correct that your quota gets reset every 24 hours. I recommend increasing the scan interval to 60 min or longer. I guess where this seems a bit odd is the fact that I had this configuration for a full year and it only started doing this after I re-installed Magic Mirror and all the modules. So in theory can I set the scan to happen once a day? In this way it will scan my 6000 photos only once. How many requests will it eat when scanning 6000 photos? Before the reinstallation this is how my quota looked: image

Steps I will take: Set the scan interval to 24 hours assuming that the links are being refreshed. If it doesn't work to 60 mins Would a full re-install of the module do anything? How many requests do I make to the Google API for each scan?

Thank you for taking your time to respond to this. You don't

aneaville commented 2 years ago

I love the annotated graph.

The most likely cause is the change that made the code more robust by using an interval timer rather than waiting for the scan to complete before starting a timer. Old way: start scan - finish scan - wait time - start scan New way: Every 'wait time' kick off new scan regardless if previous one is done. This would make the scan happen more frequently with the same settings.

A contributing factor is that the list is 'refreshed' before using, which uses additional API calls.

With these 2 factors, and the settings you had, I suspect your API calls would increase by 3x, which explains the graphs you show.

Google limits API requests to only get 50 photos at a time, so 6000 photos will take 6000/50 = 120 API calls. With a 10 minute scan interval, 24 hours 60 min / 10 min = 144 scans per day. Thats 144 scans120 API calls = 17,280 API calls just for scans. Every 20 min the links are 'refreshed' with a single API call, using an extra 24 hours * 60 min / 20min per refresh = 72 calls.

With the new changes, fast scanning no longer helps anything other than detecting newly added photos faster. With 6000 photos and randomly showing, its doubtful that new photos would be noticed that soon.

Hope this helps explain things a bit.

I don't expect a full reinstall would change anything. Scan interval of 24 hours should work, but 1 or 2 hours should be fine.

bhaules commented 2 years ago

Thank you very much for your detailed response. Changed the scan time to 30 minutes and it solved my issue. My API calls are down to 3500. Thanks for making me understand how things work under the hood. image Thanks again. You can clos this ticket