search

ashthespy / Vollibrespot

Spotify Connect daemon for Volumio
MIT License
20 stars 9 forks source link

Panic after playing a few tracks in a playlists #17

Open EpicLPer opened 3 months ago

EpicLPer commented 3 months ago

Heya,

it seems there is an issue for some people trying to play Spotify playlists, including me, where vollibrespot first hangs not playing the next track in a playlist, when trying to skip the stuck track it then panics.

The issue was brought up over at the HiFiBerry Github, I also replied there with my log output: https://github.com/hifiberry/hifiberry-os/issues/519

My journalctl output is as follows:

Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', /home/matuschd/buildroot-3/host/share/cargo/git/checkouts/librespot-e4d7c35a023053af/1a224a3/playback/src/player.rs:232:61
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]: stack backtrace:
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    0:   0x9d7b20 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    1:   0x9fefd8 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    2:   0x9d04c0 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    3:   0x9da120 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    4:   0x9d9b08 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    5:   0x9da80c - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    6:   0x9da2e4 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    7:   0x9d80d8 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    8:   0x9da22c - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:    9:   0x4c28bc - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   10:   0x4c2990 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   11:   0x5da23c - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   12:   0x5a8d60 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   13:   0x5a6ab4 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   14:   0x4e5db0 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   15:   0x508250 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   16:   0x50aaf8 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   17:   0x4f76bc - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   18:   0x50a818 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   19:   0x532014 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   20:   0x4fcce8 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   21:   0x4e85e8 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   22:   0x520b18 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   23:   0x520ce4 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   24:   0x9dacfc - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   25:   0x4e9d28 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   26: 0x76ca46e0 - <unknown>
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]:   27: 0x76ca47e4 - __libc_start_main
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]: [Vollibrespot] : Player thread panicked!
Apr 03 15:10:36 hifiberry-stefan-zimmer vollibrespot[1707]: [Vollibrespot] : EventSender disconnected
Apr 03 15:10:36 hifiberry-stefan-zimmer systemd[1]: spotify.service: Main process exited, code=exited, status=101/n/a
Apr 03 15:10:36 hifiberry-stefan-zimmer systemd[1]: spotify.service: Failed with result 'exit-code'.
Apr 03 15:10:36 hifiberry-stefan-zimmer python3[369]: INFO: powercontroller - Update LED state for state=paused
Apr 03 15:10:36 hifiberry-stefan-zimmer python3[369]: ERROR: powercontroller - Could not write to power controller: 121
Apr 03 15:10:36 hifiberry-stefan-zimmer node[747]: Source 'spotify' has deactivated.
Apr 03 15:10:36 hifiberry-stefan-zimmer python3[369]: INFO: http_post - posted metadata update to http://127.0.0.1:80/sources/metadata ({'artist': 'Da Tweekaz', 'title': 'Sunrise', 'albumArtist': None, 'albumTitle': 'Sunrise', 'artUrl': 'https://i.scdn.co/image/ab67616d0000b273cdab17d23a96e5a0d08d2f37', 'externalArtUrl': None, 'discNumber': None, 'tracknumber': None, 'playerName': 'spotify', 'playerState': 'paused', 'streamUrl': None, 'playCount': None, 'mbid': None, 'artistmbid': None, 'albummbid': None, 'loved': None, 'wiki': None, 'loveSupported': False, 'tags': [], 'skipped': False, 'host_uuid': None, 'releaseDate': None, 'trackid': None, 'hifiberry_cover_found': False, 'duration': 0, 'time': 0, 'position': 0, 'positionupdate': 1712148474.585062})
Apr 03 15:10:37 hifiberry-stefan-zimmer sshd[2160]: kex_exchange_identification: Connection closed by remote host
Apr 03 15:10:37 hifiberry-stefan-zimmer sshd[2160]: Connection closed by XXXXXX port 55987
Apr 03 15:10:41 hifiberry-stefan-zimmer node[747]: Checking MPD database update status...
Apr 03 15:10:41 hifiberry-stefan-zimmer systemd[1]: spotify.service: Scheduled restart job, restart counter is at 3.
Apr 03 15:10:41 hifiberry-stefan-zimmer systemd[1]: Stopped Vollibrespot.
Thom61 commented 3 months ago

After not using Spotify with HifiBerry OS from the Spotify Windows App for two weeks I had the same issue. I reinstalled the Windows App and now it's not connecting at all with Vollibrespot. It tries and then falls back again. Using the iOS Spotify App the situation is still the same as EpicLPer discribed.

JCBird1012 commented 1 month ago

I have a slightly different stack trace (if that helps) - also using HiFiBerryOS. librespot and vollibrespot haven't had releases in a while, and HiFiBerryOS hasn't changed versions for either of them lately either (as far as I can tell) + this was working just fine prior to a few months ago - I wonder if this is a change on Spotify's side that has caused a sudden breakage.

Jun 22 21:21:02 patio vollibrespot[2363]: thread '<unnamed>' panicked at /home/matuschd/buildroot-4/host/share/cargo/git/checkouts/librespot-e4d7c35a023053af/1a224a3/playback/src/player.rs:771:56:
Jun 22 21:21:02 patio vollibrespot[2363]: Vorbis error: OggError(HashMismatch(3493727944, 3229890524))
Jun 22 21:21:02 patio vollibrespot[2363]: stack backtrace:
Jun 22 21:21:02 patio vollibrespot[2363]:    0:       0x558bda5674 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    1:       0x558bdce0fc - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    2:       0x558bda1cd8 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    3:       0x558bda54a8 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    4:       0x558bda6aac - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    5:       0x558bda67c0 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    6:       0x558bda7068 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    7:       0x558bda6f30 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    8:       0x558bda5b58 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:    9:       0x558bda6c88 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:   10:       0x558b93e2f8 - <unknown>
Jun 22 21:21:02 patio vollibrespot[2363]:   11:       0x558b93e650 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   12:       0x558ba1ee08 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   13:       0x558b9698d0 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   14:       0x558b9684f8 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   15:       0x558b98b30c - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   16:       0x558b973034 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   17:       0x558bdab46c - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   18:       0x7fb5827e00 - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   19:       0x7fb588d80c - <unknown>
Jun 22 21:21:03 patio vollibrespot[2363]:   20:                0x0 - <unknown>
JCBird1012 commented 1 month ago

So, I'm seeing the same behavior using MoOde Audio - which uses librespot so I definitely suspect this issue affects upstream as well. Something common I've seen while hunting for others that have seen this issue is - Connection reset by peer (os error 104)

Here's the librespot logs with -v right after the audio drop out happens -

[2024-06-23T18:16:55Z DEBUG librespot_audio::fetch] File f60ac5f55772e997bc11e0ef834995dbe3abbf7a complete, saving to cache

--- AUDIO DROP OUT ---

[2024-06-23T18:18:41Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 272280023922639872859213807815316687315, audio_type: Track })
[2024-06-23T18:18:41Z DEBUG librespot_playback::player] Preloading track
[2024-06-23T18:18:41Z DEBUG librespot_core::session] Invalidating session[0]
[2024-06-23T18:18:41Z ERROR librespot_playback::player] Unable to load audio item: MercuryError
[2024-06-23T18:18:41Z DEBUG librespot_core::session] drop Dispatch
[2024-06-23T18:18:41Z ERROR librespot_core::session] Connection reset by peer (os error 104)
[2024-06-23T18:18:41Z ERROR librespot_connect::spirc] subscription terminated
[2024-06-23T18:18:41Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2024-06-23T18:18:41Z DEBUG librespot_playback::player] Shutting down player thread ...
[2024-06-23T18:18:41Z DEBUG librespot_playback::player] drop PlayerInternal[0]
[2024-06-23T18:18:41Z DEBUG librespot_playback::player] PlayerInternal thread finished.
[2024-06-23T18:18:41Z DEBUG librespot_core::session] drop Session[0]
[2024-06-23T18:18:41Z DEBUG librespot::component] drop AudioKeyManager
[2024-06-23T18:18:41Z DEBUG librespot::component] drop ChannelManager
[2024-06-23T18:18:41Z DEBUG librespot::component] drop MercuryManager
[2024-06-23T18:18:41Z WARN  librespot] Spirc shut down unexpectedly
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:80
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Failed to resolve Access Point: Unable to resolve any viable access points.
[2024-06-23T18:18:41Z WARN  librespot_core::apresolve] Using fallback "ap.spotify.com:443"
[2024-06-23T18:18:41Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"
JCBird1012 commented 1 month ago

https://github.com/librespot-org/librespot/issues/1292 and https://github.com/librespot-org/librespot/issues/1151 are related to this.