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.

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

Application sometimes freezes #44

Open
tmh-alex opened this issue Feb 4, 2025 · 7 comments
Open

Application sometimes freezes #44

tmh-alex opened this issue Feb 4, 2025 · 7 comments
Labels
bug Something isn't working

Comments

@tmh-alex
Copy link
Collaborator

tmh-alex commented Feb 4, 2025

The application sometimes freezes. May happen before the first song even played or after many hours. Won't read new tags or see an existing one disappear, volume buttons don't have an effect and produce no log output, already running songs would keep playing until the end (don't know about the behaviour of playlists). The raspi itself remains responsive and can be reached via ssh.

In the following are the last 5 lines of the drempelbox unit logs for three different crashes.

Jan 26 09:20:46 toniblaster drempelbox[607]: 2025-01-26T08:20:46.993013Z  INFO drempelbox::ntag215: MFRC522 version version=146
Jan 26 09:20:46 toniblaster drempelbox[607]: 2025-01-26T08:20:46.993293Z DEBUG drempelbox::amp: submitted amp power on request
Jan 26 09:20:46 toniblaster drempelbox[607]: 2025-01-26T08:20:46.993737Z  INFO drempelbox::server: Starting http server...
Jan 26 09:20:47 toniblaster drempelbox[607]: 2025-01-26T08:20:47.245429Z DEBUG drempelbox::led: submitted amp LED on request
Jan 26 09:21:00 toniblaster drempelbox[607]: 2025-01-26T08:21:00.338818Z ERROR drempelbox::ntag215: error in SPI comms: IncompleteFrame
Jan 26 10:52:29 toniblaster drempelbox[744]: 2025-01-26T09:52:29.277768Z  INFO drempelbox::player: playing spotify from url log_url="https://open.spotify.com/track/4S1vA0mTayFbnHrwdkzPWT?si=x0xQratgREGxo19ivfn6DA"
Jan 26 10:52:29 toniblaster drempelbox[744]: 2025-01-26T09:52:29.277800Z DEBUG drempelbox::amp: submitted amp on request
Jan 26 10:52:29 toniblaster drempelbox[744]: Playing...
Jan 26 10:52:29 toniblaster drempelbox[744]: 2025-01-26T09:52:29.312126Z  WARN librespot_core::apresolve: Failed to resolve all access points, using fallbacks
Jan 26 10:52:29 toniblaster drempelbox[744]: 2025-01-26T09:52:29.312206Z  WARN librespot_core::apresolve: Resolve access points error: Service unavailable { client error (Connect) }
Feb 01 07:13:58 toniblaster drempelbox[607]: 2025-02-01T06:13:58.286483Z DEBUG drempelbox::ndef: got bytes [55]
Feb 01 07:13:58 toniblaster drempelbox[607]: 2025-02-01T06:13:58.286499Z DEBUG drempelbox::ndef: got bytes [04, 6f, 70, 65, 6e, 2e, 73, 70, 6f, 74, 69, 66, 79, 2e, 63, 6f, 6d, 2f, 74, 72, 61, 63, 6b, 2f, 33, 63, 4a, 53, 4a, 54, 72, 45, 4b, 4e, 66, 6d, 31, 54, 6d, 6f, 73, 77, 45, 72, 6b, 57, 3f, 73, 69, 3d, 61, 33, 75, 74, 48, 71, 71, 79, 52, 67, 57, 45, 47, 43, 73, 64, 42, 44, 47, 7a, 50, 67]
Feb 01 07:13:58 toniblaster drempelbox[607]: 2025-02-01T06:13:58.286713Z  INFO drempelbox::player: received URL player request log_url="https://open.spotify.com/track/3cJSJTrEKNfm1TmoswErkW?si=a3utHqqyRgWEGCsdBDGzPg"
Feb 01 07:13:58 toniblaster drempelbox[607]: 2025-02-01T06:13:58.286747Z  INFO drempelbox::player: playing spotify from url log_url="https://open.spotify.com/track/3cJSJTrEKNfm1TmoswErkW?si=a3utHqqyRgWEGCsdBDGzPg"
Feb 01 07:13:58 toniblaster drempelbox[607]: 2025-02-01T06:13:58.286771Z DEBUG drempelbox::amp: submitted amp on request
Feb 01 07:13:58 toniblaster drempelbox[607]: Playing...

I trapped the IncompleteFrame error just like the TimeoutError (see #40) but cannot tell if that changed anything about the frequency of the freezes. That is, I don't know if it's one possible cause.

@tmh-alex tmh-alex added the bug Something isn't working label Feb 4, 2025
@tmh-alex
Copy link
Collaborator Author

tmh-alex commented Feb 4, 2025

@washed Is there a way to get a full trace for the librespot crate?

@washed
Copy link
Owner

washed commented Feb 4, 2025

@tmh-alex yep, you can adjust individual crate/module log levels with the RUST_LOG env var in the service file.

@tmh-alex
Copy link
Collaborator Author

tmh-alex commented Feb 5, 2025

Turned the box on in the morning with trace log level for the librespot crate enabled, placed tags on the read on occasion, and that's what I eventually got:

Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:24.984800Z  INFO librespot_playback::player: Loading <Fünf kleine Fische> with Spotify URI <spotify:track:3LUEc1W82JkHDFudlPyaWW>
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:24.984934Z DEBUG librespot_audio::fetch: File c3f17d31c6835950bf62d9c3e844c6aa2c261dfe already in cache
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:24.985000Z  WARN librespot_playback::player: Unable to load key, continuing without decryption: Internal error { channel closed }
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.075861Z  WARN librespot_playback::player: Unable to read cached audio file: Symphonia Decoder Error: end of stream. Trying to download it.
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.077985Z DEBUG librespot_audio::fetch: Downloading file c3f17d31c6835950bf62d9c3e844c6aa2c261dfe
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.078175Z DEBUG librespot_core::http_client: Requesting https://spclient.wg.spotify.com:443/storage-resolve/files/audio/interactive/c3f17d31c6835950bf62d9c3e844c6aa2c261dfe?product=0&country=DE&salt=2095654795
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.110702Z TRACE librespot_core::cdn_url: Resolved CDN storage: CdnUrl {
Feb 05 12:25:25 toniblaster drempelbox[760]:     file_id: FileId(
Feb 05 12:25:25 toniblaster drempelbox[760]:         Ok(
Feb 05 12:25:25 toniblaster drempelbox[760]:             "c3f17d31c6835950bf62d9c3e844c6aa2c261dfe",
Feb 05 12:25:25 toniblaster drempelbox[760]:         ),
Feb 05 12:25:25 toniblaster drempelbox[760]:     ),
Feb 05 12:25:25 toniblaster drempelbox[760]:     urls: MaybeExpiringUrls(
Feb 05 12:25:25 toniblaster drempelbox[760]:         [
Feb 05 12:25:25 toniblaster drempelbox[760]:             MaybeExpiringUrl(
Feb 05 12:25:25 toniblaster drempelbox[760]:                 "https://audio-akp.spotifycdn.com/audio/c3f17d31c6835950bf62d9c3e844c6aa2c261dfe?__token__=exp=1738841125~hmac=b239a43bd688335ad5c3c4c7403d95adc32c0234472159bb1b17a2fbe3a83446",
Feb 05 12:25:25 toniblaster drempelbox[760]:                 Some(
Feb 05 12:25:25 toniblaster drempelbox[760]:                     Date(
Feb 05 12:25:25 toniblaster drempelbox[760]:                         2025-02-06 11:20:25.0 +00:00:00,
Feb 05 12:25:25 toniblaster drempelbox[760]:                     ),
Feb 05 12:25:25 toniblaster drempelbox[760]:                 ),
Feb 05 12:25:25 toniblaster drempelbox[760]:             ),
Feb 05 12:25:25 toniblaster drempelbox[760]:             MaybeExpiringUrl(
Feb 05 12:25:25 toniblaster drempelbox[760]:                 "https://audio4-fa.scdn.co/audio/c3f17d31c6835950bf62d9c3e844c6aa2c261dfe?1738841125_vuZRwfK3Ir5nKHx04DFvVJca0ulQVAGqLkT2VmsFFSQ=",
Feb 05 12:25:25 toniblaster drempelbox[760]:                 Some(
Feb 05 12:25:25 toniblaster drempelbox[760]:                     Date(
Feb 05 12:25:25 toniblaster drempelbox[760]:                         2025-02-06 11:20:25.0 +00:00:00,
Feb 05 12:25:25 toniblaster drempelbox[760]:                     ),
Feb 05 12:25:25 toniblaster drempelbox[760]:                 ),
Feb 05 12:25:25 toniblaster drempelbox[760]:             ),
Feb 05 12:25:25 toniblaster drempelbox[760]:         ],
Feb 05 12:25:25 toniblaster drempelbox[760]:     ),
Feb 05 12:25:25 toniblaster drempelbox[760]: }
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.110860Z TRACE librespot_audio::fetch: Streaming from https://audio-akp.spotifycdn.com/audio/c3f17d31c6835950bf62d9c3e844c6aa2c261dfe?__token__=exp=1738841125~hmac=b239a43bd688335ad5c3c4c7403d95adc32c0234472159bb1b17a2fbe3a83446
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.157328Z  WARN librespot_playback::player: Unable to load key, continuing without decryption: Internal error { channel closed }
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.279691Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 121 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.279962Z  WARN librespot_audio::fetch::receive: Throughput 1 kbps lower than minimum 8, setting to minimum
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.280001Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 8 kbps
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.333800Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 85 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.375480Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 372 kbps
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.407149Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 48 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.470073Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 546 kbps
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.499127Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 29 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.549714Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 698 kbps
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.609127Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 924 kbps
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.631070Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 24 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.767691Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 21 ms
Feb 05 12:25:25 toniblaster drempelbox[760]: 2025-02-05T11:25:25.801718Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 1084 kbps
Feb 05 12:25:26 toniblaster drempelbox[760]: 2025-02-05T11:25:26.773525Z TRACE librespot_audio::fetch::receive: Time to first byte now estimated as: 22 ms
Feb 05 12:25:26 toniblaster drempelbox[760]: 2025-02-05T11:25:26.830115Z TRACE librespot_audio::fetch::receive: Throughput now estimated as: 960 kbps
Feb 05 12:25:27 toniblaster drempelbox[760]: 2025-02-05T11:25:27.578631Z DEBUG librespot_audio::fetch: Downloading file c3f17d31c6835950bf62d9c3e844c6aa2c261dfe complete
Feb 05 12:25:27 toniblaster drempelbox[760]: 2025-02-05T11:25:27.579328Z ERROR librespot_playback::player: Unable to read audio file: Symphonia Decoder Error: end of stream
Feb 05 12:25:27 toniblaster drempelbox[760]: 2025-02-05T11:25:27.579612Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:3LUEc1W82JkHDFudlPyaWW")>: ()
Feb 05 12:25:27 toniblaster drempelbox[760]: 2025-02-05T11:25:27.593370Z DEBUG librespot_audio::fetch: File c3f17d31c6835950bf62d9c3e844c6aa2c261dfe cached to "/var/cache/drempelbox/audio/c3/f17d31c6835950bf62d9c3e844c6aa2c261dfe"
Feb 05 12:25:31 toniblaster drempelbox[760]: 2025-02-05T11:25:31.270691Z  INFO drempelbox::ntag: token removed: [04, 03, 27, 69, ff, 61, 80]
Feb 05 12:25:31 toniblaster drempelbox[760]: 2025-02-05T11:25:31.270819Z  INFO drempelbox::player: received stop request
Feb 05 12:25:31 toniblaster drempelbox[760]: 2025-02-05T11:25:31.270896Z DEBUG drempelbox::amp: submitted amp off request
Feb 05 12:25:31 toniblaster drempelbox[760]: 2025-02-05T11:25:31.270951Z  INFO drempelbox::spotify_player: stopping spotify
Feb 05 12:25:31 toniblaster drempelbox[760]: 2025-02-05T11:25:31.271058Z DEBUG librespot_playback::player: command=Stop

Couldn't analyze it yet, but two things stand out:

  • Unable to read cached audio file: Symphonia Decoder Error: end of stream. Trying to download it.
  • The application itself is responsive this time. So this is a new issue as the app only refuses to play but remains responsive.

@tmh-alex
Copy link
Collaborator Author

May be related to this librespot issue when playing 96 kbps files. Apparently some regression on the type definitions. Investigation and fix here, however, hasn't made it into the main branch yet. Will wait if the next release will fix my issue.

@tmh-alex
Copy link
Collaborator Author

Here's the logs from a failed session with the trace logging option on.

journald_drempelbox_20250205_symphoniadecodererror.txt

@photovoltex
Copy link

May be related to librespot-org/librespot#1433 when playing 96 kbps files.

Just checked the log file, and this doesn't seem to be related to the 96 kbps issue.

if it was the 96 kbps issue, one of the format types would like this

...
format: Some(
    11
),
...

But all your format entries have a specific enum variation similar to this

...
format: Some(
    OGG_VORBIS_96
),
...

But I saw the error recently on a different issue. Tho I think it's a separate issue from the issue commented on from what I see here, but that's just a guess so far.

@tmh-alex
Copy link
Collaborator Author

@photovoltex Thank you for checking on our issue, very much appreciated! Unfortunately I'm now completely at a loss here, as the upstream issue you linked doesn't seem to be at work here either. I experienced a couple of freezes in the past 24 h, yet my router says it's been continuously connected to the internet for the past three days.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants