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

Panic after playing a few tracks in a playlists #17

Open
EpicLPer opened this issue Apr 3, 2024 · 4 comments
Open

Panic after playing a few tracks in a playlists #17

EpicLPer opened this issue Apr 3, 2024 · 4 comments

Comments

@EpicLPer
Copy link

EpicLPer commented Apr 3, 2024 •
edited
Loading

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: hifiberry/hifiberry-os#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.
@EpicLPer EpicLPer changed the title Panick after a playing a few tracks in playlists Panic after a playing a few tracks in playlists Apr 3, 2024
@EpicLPer EpicLPer changed the title Panic after a playing a few tracks in playlists Panic after playing a few tracks in a playlists Apr 3, 2024
@Thom61
Copy link

Thom61 commented Apr 26, 2024

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
Copy link

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
Copy link

JCBird1012 commented Jun 23, 2024 •
edited
Loading

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
Copy link

JCBird1012 commented Jun 23, 2024 •
edited
Loading

librespot-org/librespot#1292 and librespot-org/librespot#1151 are related to this.

@JCBird1012 JCBird1012 mentioned this issue Jun 24, 2024
Closed
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
3 participants
@JCBird1012 @EpicLPer @Thom61