Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Maloja randomly goes idle and cannot be used #130

Closed
duckfromdiscord opened this issue Jan 27, 2024 · 13 comments
Closed

Maloja randomly goes idle and cannot be used #130

duckfromdiscord opened this issue Jan 27, 2024 · 13 comments

Comments

@duckfromdiscord
Copy link

Describe the bug
Maloja randomly stops scrobbling.

To Reproduce
Steps to reproduce the behavior:

  1. Run for an unknown amount of time

Expected behavior
Maloja target should start when hitting the "Start" button under "Idle."

Logs
It's just this but repeated:

2024-01-26T23:02:36+00:00 info    : [Heartbeat] [Clients] Attempted to restart 1 clients that were not processing scrobbles.
2024-01-26T23:02:36+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing retries (0) less than max processing retries (5), restarting processing after 3 second delay...
2024-01-26T23:02:36+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')
TypeError: 
    at t.buildTrackString (CWD/build/server.js:12:93846)
    at m.existingScrobble (CWD/build/server.js:1:40936)
    at m.alreadyScrobbled (CWD/build/server.js:1:63181)
    at m.doProcessing (CWD/build/server.js:1:45857)
    at m.startScrobbling (CWD/build/server.js:1:42873)
    at m.initScrobbleMonitoring (CWD/build/server.js:1:42386)
2024-01-26T23:02:36+00:00 error   : [Scrobblers] [Maloja - myMaloja] Scrobble processing interrupted
2024-01-26T23:02:36+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing started
2024-01-26T23:02:36+00:00 info    : [Scrobblers] [Maloja - myMaloja] [Heartbeat] Should be processing scrobbles! Attempting to restart scrobbling...
2024-01-26T22:44:38+00:00 warn    : [Scrobblers] [Maloja - myMaloja] Scrobble processing retries (5) equal to max processing retries (5), stopping processing!
2024-01-26T22:44:38+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')

Versions (please complete the following information):
Provide version information for any related sources/clients.

  • multi-scrobbler: v0.6.3
  • maloja: 3.2.2

Additional context
Other times, maloja scrobbling doesn't happen at all but there is no error spam.
@duckfromdiscord duckfromdiscord mentioned this issue Jan 27, 2024
Closed
@duckfromdiscord
Copy link
Author

It seems after a couple backlog scrobbles this also happens.

2024-01-27T00:51:50+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Waiting 363ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-27T00:51:51+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobbled (Backlog)     => (Spotify) [redacted] @ 2024-01-26T03:25:12+00:00 (C)
2024-01-27T00:51:51+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Raw Payload: [redacted]
2024-01-27T00:51:51+00:00 error   : [Scrobblers] [Maloja - myMaloja] Scrobble processing interrupted
2024-01-27T00:51:51+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')
TypeError:
    at t.buildTrackString (CWD/build/server.js:12:93846)
    at m.existingScrobble (CWD/build/server.js:1:40936)
    at m.alreadyScrobbled (CWD/build/server.js:1:63181)
    at m.doProcessing (CWD/build/server.js:1:45857)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async m.startScrobbling (CWD/build/server.js:1:42862)
2024-01-27T00:51:51+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing retries (0) less than max processing retries (5), restarting processing after 4 second delay...
2024-01-27T00:51:55+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing started
2024-01-27T00:51:56+00:00 error   : [Scrobblers] [Maloja - myMaloja] Scrobble processing interrupted
2024-01-27T00:51:56+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')

@duckfromdiscord
Copy link
Author

@FoxxMD I need some kind of workaround for this in the meantime. Around a quarter of my scrobbles are lost because of this and I have to manually scrobble. Could this be fixed by a downgrade?

@duckfromdiscord
Copy link
Author

I also suggest that this error should not cause all scrobbling to stop, because other scrobbles may get through if the error is dropped after a couple retires.

FoxxMD added a commit that referenced this issue Jan 30, 2024
@FoxxMD
refactor(scrobbler): Use simpler method for handling queued scrobbles #…
41e607c 
…130
@FoxxMD
Copy link
Owner

FoxxMD commented Jan 30, 2024

Maloja randomly stops scrobbling.

Unless the whole app is silently crashing there is absolutely a reason why it stops scrobbling and it is logged as the entire scrobble loop is in a try-catch block. Please post the logs before it stops scrobbling so I can better help you.

this error should not cause all scrobbling to stop

The error is showstopping. It is occurs in a function that should not have any exceptions thrown and is occurring because the play information is entirely missing. Continuing execution would be useless because data is likely no longer structured as intended and would only serve to cause more log noise as every queued bad-data-scrobble would throw the same exception. There is a reason it is the way it is.

some kind of workaround

I would recommend at the very least updating to the latest version, 0.6.4. If you are still using flatpak I would also recommend switching to docker installation because:

  • I run spotify -> maloja on my own server and have never experienced any of the long-running issues you are creating
    • There may be problems with flatpak and long-running processes I am not aware of.
  • I publish fixes ahead of official releases using docker images because its tremendously easier for me to control for the user's environment and deploy (flatpak is a huge PITA which is why it only gets offical releases)
    • A potential fix for this is published to foxxmd/multi-scrobbler:develop right now

@duckfromdiscord
Copy link
Author

duckfromdiscord commented Jan 30, 2024 •
edited

Please post the logs before it stops scrobbling so I can better help you.

The main reason I haven't been able to do this is because my setup is currently kind of a mess and I don't know how to save logs to a file while they're being printed. Is there an option or some way to automatically log both to the console and also a file? I think if we could do that, I could send more useful logs.

EDIT: Just read the other issue, I'll try that.

If you are still using flatpak I would also recommend switching to docker installation

Yeah, I'm using flatpak. I would imagine Docker takes more memory (I don't have much available besides what I've already allocated) but perhaps I should try it. I have also noticed I've been having some strange issues that generally haven't happened to you or anyone else. I wonder what causes these. I was originally thinking it could be a discrepancy in the system clock, but that would only explain backlog issues, not issues like this one.

I'll have to try Docker then. Is it possible to move my cache and configuration (in ~/.var/app/io.github.foxxmd.multiscrobbler/[cache,config,etc]) to Docker?

@FoxxMD
Copy link
Owner

FoxxMD commented Jan 30, 2024 •
edited

This is the memory footprint for MS with an empty config running on my machine in both flatpak and docker:

image

The top two processes are flatpak -- 86 + 31 = 117mb
The bottom two processes are docker -- 53 + 17 = 70mb

That doesn't include the memory footprint of docker itself but at least on the application level there is little difference and docker is even lighter than flatpak.

To move your configuration copy the entire folder found at ~/.var/app/io.github.foxxmd.multiscrobbler/config somewhere else and use that as the volume mount for /config in the docker container

P.S. I run docker on multiple raspberry pi4's with 2GB ram. This one has 7 containers running and system, in total, is only using 630MB ram

image

@duckfromdiscord
Copy link
Author

duckfromdiscord commented Jan 30, 2024 •
edited

Impressive. I don't know why I thought docker used more memory than that. I'm not worried anymore. I'll swap to Docker, How does this command sound: docker run -e "PUID=1000" -e "PGID=1000" -p 9078:9078 -v [configpath]:/config foxxmd/multi-scrobbler:develop?

EDIT: I did have to add --add-host=host.docker.internal:host-gateway and change maloja's IP to host.docker.internal, then it connected.

@duckfromdiscord
Copy link
Author

I think this issue is solved. I'll run multi-scrobbler for a bit longer, and also try backlog scrobbling, and close the issue if it's solved. I'm using the develop branch on Docker.

@duckfromdiscord
Copy link
Author

I haven't had to try backlog scrobbling yet because multi-scrobbler hasn't crashed since I started using docker 😂

@FoxxMD
Copy link
Owner

FoxxMD commented Feb 8, 2024

I added a disclaimer about instability with flatpak installs to the docs..

It's honestly disappointing and a little confusing. Flatpak is supposed to be a "batteries included" environment somewhat (but not the same) as docker where your app should "just work" and be sandboxed with its own dependencies etc...there should not be this much variance in behavior between flatpak and docker. MS is only one process, run by node, with very few system calls or dependencies (just writing log files, if enabled). I don't know what could cause it to crash or have such weird behavior that wouldn't also show up in the docker version. The environment should have very little influence on how it behaves.

On top of that Flatpak is infamously hard to debug. It does not easily output a stacktrace or decent debug options for the tools it does provide.

@duckfromdiscord
Copy link
Author

This morning there were a couple instances of the Cannot read properties of undefined (reading 'data') issue, but now that I'm running Docker, logs are so much easier to deal with and I can post helpful logs.


2024-02-08T13:01:18+00:00 debug   : [Sources] [Spotify - MySpotify] [Player x-iPhone-SingleUser] (1bivf8GaSEUDXHVUZzwPqn) ２８１４ - 新宿ゴールデン街 added after met thresholds with tracked time of 513.18s (wanted 240s) and tracked percent of 97.00% (wanted 50%) and not matching any prior plays
2024-02-08T13:01:18+00:00 info    : [Sources] [Spotify - MySpotify] Discovered => ２８１４ - 新宿ゴールデン街 @ 2024-02-08T13:01:18+00:00 (C)
2024-02-08T13:01:18+00:00 debug   : [Sources] [Spotify - MySpotify] Last activity was at 2024-02-08T13:01:18+00:00. Will check again in interval 10.00 seconds.
2024-02-08T13:01:18+00:00 verbose : [Sources] [Spotify - MySpotify] Sleeping for 10.00s
2024-02-08T13:01:18+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Refreshing recent scrobbles
2024-02-08T13:01:18+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Found 40 recent scrobbles
2024-02-08T13:01:18+00:00 error   : [Scrobblers] [Maloja - myMaloja] Scrobble processing interrupted
2024-02-08T13:01:18+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')
TypeError: 
    at buildTrackString (CWD/src/core/StringUtils.ts:61:9)
    at MalojaScrobbler.existingScrobble (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:422:58)
    at MalojaScrobbler.alreadyScrobbled (CWD/src/backend/scrobblers/MalojaScrobbler.ts:379:28)
    at MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:586:56)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:515:27)
2024-02-08T13:01:18+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing retries (2) less than max processing retries (5), restarting processing after 15 second delay...
2024-02-08T13:01:28+00:00 debug   : [Sources] [Spotify - MySpotify] Refreshing recently played
2024-02-08T13:01:28+00:00 debug   : [Sources] [Spotify - MySpotify] [Player x-iPhone-SingleUser] Incoming play state ((3tRNZWwNVqJc4Swf48Qu9Z) ２８１４ - 遠くの愛好家)
...

2024-02-08T13:35:44+00:00 debug   : [Sources] [Spotify - MySpotify] [Player x-iPhone-SingleUser] (14oP6leIOPTvqP6zEcpW4Y) HKE - 独自一人,一起 added after met thresholds with tracked time of 543.00s (wanted 240s) and tracked percent of 100.00% (wanted 50%) and not matching any prior plays
2024-02-08T13:35:44+00:00 info    : [Sources] [Spotify - MySpotify] Discovered => HKE - 独自一人,一起 @ 2024-02-08T13:35:44+00:00 (C)
2024-02-08T13:35:44+00:00 debug   : [Sources] [Spotify - MySpotify] Last activity was at 2024-02-08T13:35:44+00:00. Will check again in interval 10.00 seconds.
2024-02-08T13:35:44+00:00 verbose : [Sources] [Spotify - MySpotify] Sleeping for 10.00s
2024-02-08T13:35:44+00:00 error   : [Scrobblers] [Maloja - myMaloja] Scrobble processing interrupted
2024-02-08T13:35:45+00:00 error   : [Scrobblers] [Maloja - myMaloja] Cannot read properties of undefined (reading 'data')
TypeError: 
    at buildTrackString (CWD/src/core/StringUtils.ts:61:9)
    at MalojaScrobbler.existingScrobble (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:422:58)
    at MalojaScrobbler.alreadyScrobbled (CWD/src/backend/scrobblers/MalojaScrobbler.ts:379:28)
    at MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:586:56)
    at MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:515:27)
2024-02-08T13:35:45+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing retries (0) less than max processing retries (5), restarting processing after 3 second delay...
2024-02-08T13:35:48+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobble processing started
2024-02-08T13:35:54+00:00 debug   : [Sources] [Spotify - MySpotify] Refreshing recently played

The strange part is that these scrobbles did not show up under Queued or Failed Scrobbles. These errors seem to be fewer and further between. Something tells me it has something to do with Unicode artist names and track titles, as I can't find an instance of this happening since I've started Docker with any tracks with exclusively Latin characters.

This is foxxmd/multi-scrobbler:develop by the way.

FoxxMD added a commit that referenced this issue Feb 8, 2024
@FoxxMD
test: Add test that handles no existing scrobble match with score gre…
4e45d35 
…ater than 0 #130

Detects track string error thrown reported via #130 (comment)
FoxxMD added a commit that referenced this issue Feb 8, 2024
@FoxxMD
fix: Handle when no existing scrobble match with score greater than 0 #…
be9675b 
…130

#130 (comment)
@FoxxMD
Copy link
Owner

FoxxMD commented Feb 8, 2024

@duckfromdiscord i may have a fix for that issue. please pull the latest foxxmd/multi-scrobbler:develop image and restart your MS container

@duckfromdiscord
Copy link
Author

Pulled new image, stopped container, removed it, ran again. Will let you know of results.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@FoxxMD @duckfromdiscord