Authentication test failed due to a network issue - requires Docker container restart to resolve, losing queued scrobbles

infinitejones commented 6 days ago

Describe the bug

Original Issues: https://github.com/FoxxMD/multi-scrobbler/issues/159

At times, Multi-scrobbler loses the ability to connect to clients, and clicking the Start button on their tiles does not re-start them. Restarting the connection seems to require a restart of the Docker container, which has a side effect of losing queued scrobbles.

Screenshot

Clicking Start does not re-start the connection. Clicking re-authenticate for Last.fm does start the re-authentication workflow.

Expected behavior I'd like to be able to re-connect to the clients without needing to restart the Docker container.

Logs If possible reproduce the issue with debug logging ON

[2024-06-25 17:29:25.338 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:29:25+10:00 | Next check interval: 10.00s
[2024-06-25 17:29:25.336 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:29:25.317 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:29:16.051 +1000] WARN   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Cannot start scrobble processing because auth test failed
[2024-06-25 17:29:16.041 +1000] ERROR  : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
Error: Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
    at ListenbrainzScrobbler.testAuth (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:188:31)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at ListenbrainzScrobbler.initScrobbleMonitoring (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:458:17)
    at <anonymous> (CWD/src/backend/server/api.ts:420:9)
    at async wrappedMiddleware (CWD/node_modules/@awaitjs/express/index.js:116:7)
caused by: Error: getaddrinfo EAI_AGAIN api.listenbrainz.org
    at __node_internal_captureLargerStackTrace (node:internal/errors:496:5)
    at __node_internal_ (node:internal/errors:715:10)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
[2024-06-25 17:29:16.039 +1000] ERROR  : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Could not communicate with Listenbrainz API
[2024-06-25 17:29:15.299 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:29:15+10:00 | Next check interval: 10.00s
[2024-06-25 17:29:15.297 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:29:15.278 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:29:11.030 +1000] INFO   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Trying to start scrobbler...
[2024-06-25 17:29:11.028 +1000] WARN   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Polling is already stopped!
[2024-06-25 17:29:11.026 +1000] INFO   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Checking (and trying) to stop scrobbler if already running...
[2024-06-25 17:29:11.024 +1000] VERBOSE: [App] [Scrobblers] [Listenbrainz - Listenbrainz] User requested (re)start via API call
[2024-06-25 17:29:05.260 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:29:05+10:00 | Next check interval: 10.00s
[2024-06-25 17:29:05.258 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:29:05.238 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:55.223 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:55+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:55.221 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:55.202 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:45.185 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:45+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:45.183 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:45.163 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:35.146 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:35+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:35.144 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:35.124 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:27.509 +1000] WARN   : [App] [Scrobblers] [Lastfm - last.fm] Cannot start scrobble processing because auth test failed
[2024-06-25 17:28:27.493 +1000] ERROR  : [App] [Scrobblers] [Lastfm - last.fm] Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
Error: Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
    at LastfmScrobbler.testAuth (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:188:31)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at LastfmScrobbler.initScrobbleMonitoring (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:458:17)
    at <anonymous> (CWD/src/backend/server/api.ts:420:9)
    at async wrappedMiddleware (CWD/node_modules/@awaitjs/express/index.js:116:7)
caused by: Error: API call failed due -> API call timed out <- after max retries hit 2
    at LastfmApiClient.callApi (CWD/src/backend/common/vendor/LastfmApiClient.ts:133:27)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at LastfmApiClient.testAuth (CWD/src/backend/common/vendor/LastfmApiClient.ts:181:30)
    at LastfmScrobbler.doAuthentication (CWD/src/backend/scrobblers/LastfmScrobbler.ts:48:20)
    at LastfmScrobbler.testAuth (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:182:27)
    at LastfmScrobbler.initScrobbleMonitoring (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:458:17)
    at <anonymous> (CWD/src/backend/server/api.ts:420:9)
    at async wrappedMiddleware (CWD/node_modules/@awaitjs/express/index.js:116:7)
caused by: Error: getaddrinfo EAI_AGAIN ws.audioscrobbler.com
    at __node_internal_captureLargerStackTrace (node:internal/errors:496:5)
    at __node_internal_ (node:internal/errors:715:10)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
[2024-06-25 17:28:27.490 +1000] ERROR  : [App] [Scrobblers] [API - Lastfm - last.fm] Testing auth failed
[2024-06-25 17:28:25.105 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:25+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:25.103 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:25.083 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:19.479 +1000] WARN   : [App] [Scrobblers] [API - Lastfm - last.fm] API call failed due to network issue (getaddrinfo EAI_AGAIN ws.audioscrobbler.com), retrying in 3 seconds...
[2024-06-25 17:28:15.065 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:15+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:15.063 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:15.041 +1000] WARN   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Cannot start scrobble processing because auth test failed
[2024-06-25 17:28:15.032 +1000] ERROR  : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
Error: Authentication test failed! Due to a network issue. Will retry authentication on next heartbeat.
    at ListenbrainzScrobbler.testAuth (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:188:31)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at ListenbrainzScrobbler.initScrobbleMonitoring (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:458:17)
    at <anonymous> (CWD/src/backend/server/api.ts:420:9)
    at async wrappedMiddleware (CWD/node_modules/@awaitjs/express/index.js:116:7)
caused by: Error: getaddrinfo EAI_AGAIN api.listenbrainz.org
    at __node_internal_captureLargerStackTrace (node:internal/errors:496:5)
    at __node_internal_ (node:internal/errors:715:10)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)
[2024-06-25 17:28:15.029 +1000] ERROR  : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Could not communicate with Listenbrainz API
[2024-06-25 17:28:14.898 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:28:12.969 +1000] WARN   : [App] [Scrobblers] [API - Lastfm - last.fm] API call failed due to network issue (getaddrinfo EAI_AGAIN ws.audioscrobbler.com), retrying in 1.5 seconds...
[2024-06-25 17:28:10.021 +1000] INFO   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Trying to start scrobbler...
[2024-06-25 17:28:10.019 +1000] WARN   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Polling is already stopped!
[2024-06-25 17:28:10.017 +1000] INFO   : [App] [Scrobblers] [Listenbrainz - Listenbrainz] Checking (and trying) to stop scrobbler if already running...
[2024-06-25 17:28:10.015 +1000] VERBOSE: [App] [Scrobblers] [Listenbrainz - Listenbrainz] User requested (re)start via API call
[2024-06-25 17:28:07.961 +1000] INFO   : [App] [Scrobblers] [Lastfm - last.fm] Trying to start scrobbler...
[2024-06-25 17:28:07.958 +1000] WARN   : [App] [Scrobblers] [Lastfm - last.fm] Polling is already stopped!
[2024-06-25 17:28:07.957 +1000] INFO   : [App] [Scrobblers] [Lastfm - last.fm] Checking (and trying) to stop scrobbler if already running...
[2024-06-25 17:28:07.955 +1000] VERBOSE: [App] [Scrobblers] [Lastfm - last.fm] User requested (re)start via API call
[2024-06-25 17:28:04.882 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:28:04+10:00 | Next check interval: 10.00s
[2024-06-25 17:28:04.880 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:28:04.856 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:27:54.840 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:27:54+10:00 | Next check interval: 10.00s
[2024-06-25 17:27:54.838 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:27:54.822 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:27:44.804 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:27:44+10:00 | Next check interval: 10.00s
[2024-06-25 17:27:44.802 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:27:44.786 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:27:34.771 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity was at 2024-06-25T17:27:34+10:00 | Next check interval: 10.00s
[2024-06-25 17:27:34.769 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered
[2024-06-25 17:27:34.759 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] [Player 1-matt] Started new Player listen range.
[2024-06-25 17:27:34.758 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] [Player 1-matt] New Play: (ec95a4ce8b8e8a0888eeaccb73529acd) The Wolfgang Press - The Wedding
[2024-06-25 17:27:34.749 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Refreshing recently played
[2024-06-25 17:27:04.705 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] Last activity 2024-06-25T16:38:24+10:00 is 44 minutes outside of polling period (last activity + 300s) | Next check interval: (10 + 20)s
[2024-06-25 17:27:04.703 +1000] DEBUG  : [App] [Sources] [Subsonic - Navidrome] No new tracks discovered

Versions (please complete the following information):

multi-scrobbler: 0.7.1 on Docker
navidrome: 0.52.5 on Docker

Additional context

I've confirmed the server on which the Docker container is running still has connectivity to the internet when this is happening.
The docker container itself still has inbound connectivity because it is successfully polling Navidrome for the playing track.
From inside the docker container (docker compose exec -it multi-scrobbler /bin/bash) I can ping the Navidrome container and I can ping IP addresses, eg. 8.8.8.8 - but I cannot ping domain names, eg. www.google.com
Earlier today I was able to scrobble to both last.fm and listenbrainz, and the Multi-scrobbler container has not been changed, stopped or re-started since then.
However after docker compose down && docker compose up -d, connectivity to both clients is resolved - with no additional changes to the server's internet connection or the docker network for my stack.
At this point, I can ping www.google.com from within the container.
So the issue seems to be losing the ability to resolve DNS, and therefore possibly not a problem with the application itself...?

FoxxMD commented 6 days ago

Thanks for the detailed writeup! These logs are exactly what I need.

Can you try using the foxxmd/multi-scrobbler:0.7.1-debian docker image?

infinitejones commented 5 days ago

No worries - thanks for Multi-scrobbler!

I've pulled the Debian image and re-started the container. If/when it fails again I'll post the same detail again here.

infinitejones commented 17 hours ago

Following up on this - the container's been running with the Debian image since my last comment, with no problems at all.

I occasionally see timeout errors for Listenbrainz in the log but I think that's the Listenbrainz API rather than the Multi Scrobbler. They don't prevent tracks being scrobbled correctly.

(None visible in the log currently - I can post some in another issue if I see any again, if you want...?)

FoxxMD commented 3 hours ago

That's likely the the LZ API. Glad the debian image has resolved the issue for you. I may be switching to use that image as the default in the near future since alpine seems to still have unresolved dns issues.

FoxxMD / multi-scrobbler

Authentication test failed due to a network issue - requires Docker container restart to resolve, losing queued scrobbles #160