Calendar stops updating after FetchError, UnhandledPromiseRejectionWarning

[srabraham]

Hi there, thanks for your great work on this module!

I run a view that combines two Google calendars. Sometimes I'll see a transient error like the one below relating to one of the calendars, and that'll stop that calendar from getting updated entirely until MagicMirror is restarted. Notice how in the log, calendar:1 is not seen again after the error.

I can include my config too if you'd like. I make use of deduplicateEventsOn and a view transform function, but otherwise I think the config is fairly standard.

[06.10.2022 12:41.10.835] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000
[06.10.2022 12:41.16.179] [LOG]   [CALEXT2] calendar:0 >> Scanned: 62, Selected: 62
[06.10.2022 12:48.27.944] [LOG]   [CALEXT2] calendar:1 >> Scanning start with interval:600000
[06.10.2022 12:48.33.573] [LOG]   [CALEXT2] calendar:1 >> Scanned: 28, Selected: 28
[06.10.2022 12:51.16.197] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000
[06.10.2022 12:51.21.668] [LOG]   [CALEXT2] calendar:0 >> Scanned: 62, Selected: 62
[06.10.2022 12:58.33.598] [LOG]   [CALEXT2] calendar:1 >> Scanning start with interval:600000
[06.10.2022 12:58.33.818] [ERROR] (node:687) UnhandledPromiseRejectionWarning: FetchError: request to https://calendar.google.com/calendar/ical/[REDACTED]/basic.ics failed, reason: connect ENETUNREACH [REDACTED, probably a Google ipv6 address]:443 - Local (:::0)
    at ClientRequest.<anonymous> (file:///home/pi/dev/MagicMirror/modules/MMM-CalendarExt2/node_modules/node-fetch/src/index.js:108:11)
    at ClientRequest.emit (node:events:527:28)
    at TLSSocket.socketErrorListener (node:_http_client:454:9)
    at TLSSocket.emit (node:events:527:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:83:21)
(Use `electron --trace-warnings ...` to show where the warning was created)
[06.10.2022 12:58.33.821] [ERROR] (node:687) 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: 1)
[06.10.2022 13:01.21.686] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000
[06.10.2022 13:01.27.845] [LOG]   [CALEXT2] calendar:0 >> Scanned: 62, Selected: 62
[06.10.2022 13:11.27.869] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000
[06.10.2022 13:11.34.987] [LOG]   [CALEXT2] calendar:0 >> Scanned: 62, Selected: 62
[06.10.2022 13:21.35.000] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000
[06.10.2022 13:21.40.230] [LOG]   [CALEXT2] calendar:0 >> Scanned: 62, Selected: 62
[06.10.2022 13:31.40.239] [LOG]   [CALEXT2] calendar:0 >> Scanning start with interval:600000

[klaernie]

That definitely is an error that should be fixed. I'll just need to acquire the skills to figure out how to handle this properly. So if anybody else knows how to fix this, I'm all ears.

[srabraham]

I dug in a bit more tonight. I found a way to reliably reproduce the problem and I came up with a fix: https://github.com/MMM-CalendarExt2/MMM-CalendarExt2/pull/238

The problem can be reliably reproduced on a Linux/OSX machine by adding a line like this to your /etc/hosts file. This makes all requests to fetch a calendar fail. The fix makes it so that the fetch will be attempted again after scanInterval, rather than failing permanently.

127.0.0.1       calendar.google.com  # or whatever your ical host is, if not Google

[klaernie]

Thanks! I guess with that PR we are closer to fixing it. The only gotcha is, that we need to differentiate between temporary and permanent errors. We cannot make continuous requests with a wrong password for example, since that could easily lock somebody's account.

[srabraham]

Thanks! I can imagine a few ways forward. Maybe the best would be to try to have the fetch call distinguish the type of HTTP error. You could reasonably fail permanently on any 4xx error (a client error), but continue with subsequent fetches on 5xx errors (a server error). What do you think?

An easier alternative would be to try only once the first time you fetch a calendar, failing permanently if that doesn't work for any reason. There's your lockout mitigation. After that, you'd always do subsequent fetches, regardless of whether they're successful, presuming the errors are transient at that point.

[klaernie]

You're definitely onto something there. Generally differentiating on 4xx vs 5xx is a good first, but I'd say 401s should be handled specially always, since it's in each credential's nature to expire at some point (password changed, token expired etc).

[srabraham]

Oh yeah, true, I should've called out 401. I'm a total novice with Node and JavaScript generally, but if it's easy enough to get a status code from the failed call, what we're chatting about here sounds ideal.

I fixed my PR, by the way. Apparently the linter didn't like it before, but I think it should be good now.

[srabraham]

@klaernie here's an enhanced version. Let me know what you think. I don't love how complicated the error checking becomes, but oh well :S. Also I'm not sure what would happen the user doesn't have the fetch module installed (I see you tried to make it an optional import). This code at least would need FetchError as an import from that module, though perhaps that could be worked around.

const data = await fetch(url, opts).then(
  // got a 3xx-5xx response code
  (response) => {
    if (response.ok) {
      return response.text();
    }
    // This should actually be a much longer list, e.g. we'd definitely want 403 and especially 429.
    // I'd really be tempted to just permanently fail on any 4xx error.
    // https://developer.mozilla.org/en-US/docs/Web/HTTP/Status#client_error_responses
    if (response.status == 401 || response.status == 404) {
      throw new Error(`[CALEXT2] calendar:${calendar.name} >> permanent fetch error ${response.status}. Will not try again.`);
    }
    Log.error(`[CALEXT2] calendar:${calendar.name} >> got retriable fetch error ${response.status}.`);
    return null;
  },
  // got no response code, e.g. because we failed to connect to the server
  (err) => {
    if (err instanceof FetchError) {
      Log.error(`[CALEXT2] calendar:${calendar.name} >> got retriable fetch error ${err}`);
      return null;
    }
    // Fail permanently, since this was a very unexpected error.
    throw err
  }
);

[klaernie]

That looks really good to me. Throw that into a pull request, and given the tooling likes it I'll merge it. I wouldn't care too much about the optional import, since what it this module good for unless one can fetch calendars? But to be honest: I'm not a javascript dev, but a tinkerer at best. So I don't have a real grasp of the import mechanism at all - so since you definitely understand more of it, feel free to adjust as you see fit.

[klaernie]

oh, and thank you very much for pouring time into this issue, @srabraham ! It is very much appreciated!

[srabraham]

Thanks! I've been using this module for a while now and I really like it, so I'm happy to help give back :D. I'll enhance that code snippet a bit in the next few days, then send a PR over to you. I'm very much not a frontend developer, but this is proving to be a great way for me to learn some JavaScript!