Spotifyd stops after a few minutes: "Unable to load audio item: MercuryError"

[aykevl]

Description

Since a few weeks, Spotifyd has become unusable for me. It does still work, but when playing a few songs it will inevitably stop playing after a few minutes (about 5 or 10 minutes or so). Actually, the UI in Android thinks it has disconnected even before that, so clearly the connection to the Spotify servers appears to be broken and Spotifyd only realizes it a little bit later.

To Reproduce
Not anything in particular, just play some songs and it'll eventually stop working. I don't do anything different from what I did in the past.

Expected behavior
Not drop the connection, or if it does it should reestablish the connection without interrupting the music.

Logs

Full log where it happens. The ^C at the end is where I stopped Spotifyd when the music stopped.

Click to show logs

CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: Some("taken out for privacy"), username_cmd: None, password: Some("taken out for privacy"), password_cmd: None, use_keyring: false, use_mpris: None, dbus_type: None, on_song_change_hook: None, cache_path: Some("/home/ayke/.cache/spotifyd"), no-audio-cache: false, backend: Some(Alsa), volume_controller: None, device: None, control: None, mixer: None, device_name: Some("Frambozentaart"), bitrate: None, audio_format: None, initial_volume: Some("70"), volume_normalisation: false, normalisation_pregain: None, zeroconf_port: None, proxy: None, device_type: None, autoplay: false, max_cache_size: Some(1000000000) } }
Found user shell: Some("/bin/bash")
No proxy specified
registering event source with poller: token=Token(2147483649), interests=READABLE
Using software volume controller.
registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
signal: Want
signal found waiting giver, notifying
poll_want: taker wants!
signal: Want
signal: Want
deregistering event source from poller
signal: Closed
Ignoring blacklisted access point ap-gew4.spotify.com:4070
Ignoring blacklisted access point ap-gew4.spotify.com:443
Ignoring blacklisted access point ap-gew4.spotify.com:80
Ignoring blacklisted access point ap-gue1.spotify.com:80
Connecting to AP "ap-guc3.spotify.com:443"
registering event source with poller: token=Token(16777216), interests=READABLE | WRITABLE
Authenticated as "0bzabjufeuoh2wmg0n912ftgw" !
new Session[0]
Mixing with softvol and volume control: Log(60.0)
new Spirc[0]
canonical_username: 0bzabjufeuoh2wmg0n912ftgw
new MercuryManager
Session[0] strong=2 weak=1
Country: "NL"
new Player[0]
Input volume 45874 mapped to: 12.59%
Converting with ditherer: tpdf
Using AlsaSink with format: S16
command=AddEventSender
command=VolumeSet(45874)
subscribed uri=hm://remote/user/0bzabjufeuoh2wmg0n912ftgw/ count=0
kMessageTypeNotify "Web Player (Firefox)" 28ce822ac5abd43b382d08900cbd3fe07c00fd52 1011876153 1688934022695 kPlayStatusStop
kMessageTypeNotify "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011933281 1688934079823 kPlayStatusPlay
kMessageTypeLoad "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011935370 1688934079823 kPlayStatusPlay
State: context_uri: "spotify:playlist:6gqEdHsiou4E6r6s9nxXy6" index: 0 position_ms: 41200 status: kPlayStatusPlay position_measured_at: 1688934081977 context_description: "Chillstep [Instrumental]" shuffle: true repeat: false playing_from_fallback: true row: 0 playing_track_index: 0 track {gid: "ub\321WJ\354O\213\234ln\261\367 >$"} track {gid: "}\340\374\037%4B\244\225#I$=\357\262_"} track {gid: "M}\311t\246XB\217\234\377<\314\014\206\255\375"} track {gid: "\007\357\035Ai\342O\023\227;\32295\025\261\327"} track {gid: "\352\300~\0258\022H\355\211\342\266/@p\376\t"} track {gid: "\'\306<\334t\371M\000\225\276,\013\302h\330\230"} track {gid: "\310@;\026\270-Co\215\311\225f\361\303Da"} track {gid: "&V\321\277\215\260M\212\242\032\334%\205\252\365n"} track {gid: "\227*\310\342\032gG\245\271[9O\351\200\026\357"} track {gid: ">:\206\260\317\267G\025\232\225\262\216S\236f?"} track {gid: "d\rM:\204A@\275\210?A.\311\315\3232"} track {gid: "\242\265P2\342\222@g\236mg\332\206\277\026\376"} track {gid: "R\r\000\240\247\206@|\210\366\304\277\3046(Y"} track {gid: "!\3224<|ID\264\263y\010@\307\305\267}"} track {gid: "u\250;h\t\220HS\247\255a\202\361\272\013\233"} track {gid: "\271\342o5\344\177@,\273\276S\221_<\257\246"} track {gid: "M\250\2178\215\003L?\270}\334\322\362\265\224-"} track {gid: "\324\200J%\377/H\312\225\036+\217i\273\033y"} track {gid: "\347\363_\352\210\300F\\\264\036T\344\n+\244l"} track {gid: "\265>\312\246\3006K^\276\277\227\027\323\317\214\235"} track {gid: "\340\274}\006|\324I\363\234\323\210\227\357\261[w"} track {gid: "TY\213\271\311&M\026\272\r\253\\\376\225\222^"} track {gid: "p \302C\005\326F\030\211\026\240\377+\346\017^"} track {gid: "\376a\330u\223\352F\224\215\302\2568\203\374\210\016"} track {gid: "\242`4\"\247}N\370\202.\314\361.\314y\327"} track {gid: "\034ou\373c1G\006\216f\203\330<\362\345`"} track {gid: "&\374\341!~\325M\006\234\315\037L\274\307\321\277"} track {gid: "\243\326bI\227\271DC\245aY\010\204a\333\\"} track {gid: "\247\305\341\n\271\227Oq\276\3118\022\273\032\237t"} track {gid: "\272\263\231\034n\301O\304\246\036\240\243z\"y\213"} track {gid: "\277\344:\304t\323J\361\205\005\346\030PyH\227"} track {gid: "\r8\361\033\342\227B>\254z\240\265\231\247\234\255"} track {gid: "\002\320\340\002\313\311J\203\203J\335\345kE(:"} track {gid: "\"kT\006#/K_\212\325j\266\014L\354\236"} track {gid: "\351\024\013\301,\345Ng\240\020\032\330\346F \347"} track {gid: ")O\242\365|\324O\315\266h\232\265\244\\\372J"} track {gid: "-x\276tbFHE\212\307\273\263\232?DI"} track {gid: "^\277\313R\010\305L<\250\255R\"\3470\316\032"} track {gid: "\335\307X*ciG\350\216\351T5\353`\350`"} track {gid: "\315\005F\2771\363O\332\243\253#\235\343?J\322"} track {gid: "O}\027\265I\223G\271\223\253\232 \242\333\335!"} track {gid: " \206\355\352\"\023C%\240S\255m(9\303\210"} track {gid: "\031\303g\375\375\243@\344\255\233\357Z\350\323YY"} track {gid: "\354\313\201\177CaJ\027\224\224d\tL\331A\010"} track {gid: "h\360\007\371\262%C\242\253\31430!?s\007"} track {gid: "$\0215\235\031\032O\005\247\004g\240\210\211\361-"} track {gid: "\0047r\313WdJ\266\250\014\336\370q\244\211X"} track {gid: "J# \017\340%N|\227\236UN\031\207\261\203"} track {gid: "\331\211\202n\303\215H#\270\337\000\364\311\223L\332"} track {gid: "\225\000\342\2236\257I\220\205\321\277\213\t\2270X"} track {gid: "\324\203\363VAeM\367\223\344r\321@\220\244V"} track {gid: "X\364gP\005\016I7\2431.\270\313\003\023\247"} track {gid: ",aT_}wM\364\273Bj\361\ri\263\036"} track {gid: "\020\372\333\'\303\326D\212\2319)\245\244\305e;"} track {gid: "@\346V\270<~ID\267n\230x\026\016\026`"} track {gid: ",PK7L@E\207\206\362\2441\264\331\240M"} track {gid: "t\271cX\363,E\231\275\360\021\317\t\352^\230"} track {gid: "9\320\234\005\360\245F\235\242\3000(\210~\277\360"} track {gid: "\207\267\026\000B\253L\275\245\304g\241\302w%\031"} track {gid: "\220\232Rd\363\246HF\277\375N\212\230\004\3104"} track {gid: "}L\2244a\002@\272\212\243H\216\265\253\372T"} track {gid: "#\306\004\356\257\241G\326\260\212\204w\330vZ\000"} track {gid: "\0249\207\222\327\313J\357\223\225Y\307\302p\210O"} track {gid: "\304\202a\264\270wEq\225%\326\324\367\301\333\335"} track {gid: "\205\367v745F\341\203][\003\"\246\361\217"} track {gid: "+UUt wM\320\277i+\312\000\276\207\""} track {gid: "C\265|z\352\210M\020\234\321\200ZE>\025\213"} track {gid: "\021\273\202\262q\201E(\270\341H\350[\207\022t"} track {gid: "\363\033\323\014\315\204O\212\230\005\353C\357\330\263/"} track {gid: "d\244\304H\027kM\007\222\323\223\215j\3567\030"} track {gid: "X\332\010G\222\226M\016\213\324\2733\"\007#s"} track {gid: "\270\225\033_\253\031L\257\247\207\325\3315Y7\366"} track {gid: "\227\2060\010L\016K5\200c\240\365\201\326\221\036"} track {gid: "\361\266\n\252\321|Is\244`\346\261\310\252\374n"} track {gid: "\035\237l\353>nH\255\234G\234\275\237\340-\327"} track {gid: "\215\340\241f\213\232NE\252\240[\313\'\023\362\307"} track {gid: "\026\013\246`$$C\341\231\254V\302y\337[\223"} track {gid: "-\005\376#\326\272G\351\204\266\rSG\300\003\312"} track {gid: ",\206\242\300,/Ny\223\234h\371\344\270W\217"} track {gid: "\002\315k\005J\243L\361\255%\274\026\3653=\270"} track {gid: "g\230)u\300\337Cf\242\342\343\241:\025\340\""}
Frame has 81 tracks
Sending status to server: [kPlayStatusPlay]
command=SetAutoNormaliseAsAlbum(false)
command=Load(SpotifyId { id: 156032766538616445039987056503406214692, audio_type: Track }, true, 41200)
Sending status to server: [kPlayStatusPlay]
Loading <View from Above> with Spotify URI <spotify:track:3zvgftom9uehc26wxgK4ni>
Downloading file 5f0aaa581562e3f262946eb0a0f3bea28926f4ea
new ChannelManager
unknown subscription uri=social-connect/v2/session_update
new AudioKeyManager
kMessageTypeNotify "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011937272 1688934083814 kPlayStatusStop
<View from Above> (277394 ms) loaded
== Starting sink ==
Desired Frames per Buffer: 22050
Desired Frames per Period: 5512
Actual Frames per Buffer: 22050
Actual Frames per Period: 5512
Period Buffer size in bytes: 22048
Period Buffer capacity: 22048
Sending status to server: [kPlayStatusPlay]
==> kPlayStatusPlay
Stream waiting for download of file position 729196. Downloaded ranges: ([0, 16383][651728, 668115][692448, 708835][712812, 729195][733172, 749559][814616, 831003][977508, 993895][1303288, 1319675][2606412, 2622799][5212664, 5229047]). Pending ranges: ([729196, 733171][749560, 814615][831004, 847387])
Read at postion 729196 completed. 2299 bytes returned, 2299 bytes were requested.
kMessageTypeNotify "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011938173 1688934084715 kPlayStatusStop
kMessageTypeNotify "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011938788 1688934085330 kPlayStatusStop
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011940604 1688934085330 kPlayStatusStop
Input volume 46898 mapped to: 14.02%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(46898)
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011941177 1688934085330 kPlayStatusStop
Input volume 47922 mapped to: 15.62%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(47922)
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011942384 1688934088172 kPlayStatusStop
Input volume 48946 mapped to: 17.40%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(48946)
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011942958 1688934088172 kPlayStatusStop
Input volume 49970 mapped to: 19.39%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(49970)
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011943475 1688934088172 kPlayStatusStop
Input volume 50994 mapped to: 21.60%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(50994)
kMessageTypeVolume "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1011943838 1688934088172 kPlayStatusStop
Input volume 52018 mapped to: 24.06%
Sending status to server: [kPlayStatusPlay]
command=VolumeSet(52018)
File 5f0aaa581562e3f262946eb0a0f3bea28926f4ea complete, saving to cache
Session[0] strong=4 weak=4
Session[0] strong=4 weak=4
command=Preload(SpotifyId { id: 167321687604233567883118153120670003807, audio_type: Track })
Preloading track
Loading <PARACHUTE> with Spotify URI <spotify:track:3PwRgUiwHZhMCHau2a32Dt>
Downloading file 2473e492a693fe13e6ff745b7d66c98c0cd2441b
<PARACHUTE> (157846 ms) loaded
File 2473e492a693fe13e6ff745b7d66c98c0cd2441b complete, saving to cache
At track 2 of 81 <"spotify:playlist:6gqEdHsiou4E6r6s9nxXy6"> update [false]
Sending status to server: [kPlayStatusPlay]
command=Load(SpotifyId { id: 167321687604233567883118153120670003807, audio_type: Track }, true, 0)
Sending status to server: [kPlayStatusPlay]
==> kPlayStatusPlay
Session[0] strong=4 weak=4
command=Preload(SpotifyId { id: 103003678789033772735432298280142679549, audio_type: Track })
Preloading track
Loading <Fading> with Spotify URI <spotify:track:2mdTqpIA6Eg0FD0keJB5Fj>
Downloading file 59c32e1d985729787d9f10ceaa64671dcfad4a1b
<Fading> (267403 ms) loaded
File 59c32e1d985729787d9f10ceaa64671dcfad4a1b complete, saving to cache
At track 3 of 81 <"spotify:playlist:6gqEdHsiou4E6r6s9nxXy6"> update [false]
Sending status to server: [kPlayStatusPlay]
command=Load(SpotifyId { id: 103003678789033772735432298280142679549, audio_type: Track }, true, 0)
Sending status to server: [kPlayStatusPlay]
==> kPlayStatusPlay
Session[0] strong=4 weak=4
Session[0] strong=4 weak=4
command=Preload(SpotifyId { id: 10546148292162820933981633473827680727, audio_type: Track })
Preloading track
Loading <Wounds That Heal> with Spotify URI <spotify:track:0eYdKFUTGIXoWRQtSTQ5D1>
Downloading file f29a4e98f1823d05c33e11f3fba4e5f6fce7a0f2
<Wounds That Heal> (235555 ms) loaded
File f29a4e98f1823d05c33e11f3fba4e5f6fce7a0f2 complete, saving to cache
Session[0] strong=4 weak=4
At track 4 of 81 <"spotify:playlist:6gqEdHsiou4E6r6s9nxXy6"> update [false]
Sending status to server: [kPlayStatusPlay]
command=Load(SpotifyId { id: 10546148292162820933981633473827680727, audio_type: Track }, true, 0)
Sending status to server: [kPlayStatusPlay]
==> kPlayStatusPlay
unknown subscription uri=social-connect/v2/session_update
unknown subscription uri=social-connect/v2/session_update
command=Preload(SpotifyId { id: 312038829275263739681142417518241054217, audio_type: Track })
Preloading track
Invalidating session[0]
subscription terminated
drop Spirc[0]
Shutting down player thread ...
Unable to load audio item: MercuryError
drop Dispatch
deregistering event source from poller
Connection reset by peer (os error 104)
drop PlayerInternal[0]
PlayerInternal thread finished.
drop Session[0]
drop AudioKeyManager
drop ChannelManager
drop MercuryManager
registering event source with poller: token=Token(33554432), interests=READABLE | WRITABLE
signal: Want
signal found waiting giver, notifying
poll_want: taker wants!
signal: Want
signal: Want
poll_want: taker wants!
Ignoring blacklisted access point ap-gew4.spotify.com:4070
Ignoring blacklisted access point ap-gew4.spotify.com:443
Ignoring blacklisted access point ap-gew4.spotify.com:80
Ignoring blacklisted access point ap-gue1.spotify.com:443
deregistering event source from poller
Failed to resolve Access Point: Unable to resolve any viable access points.
signal: Closed
Using fallback "ap.spotify.com:443"
Connecting to AP "ap.spotify.com:443"
registering event source with poller: token=Token(50331648), interests=READABLE | WRITABLE
Authenticated as "0bzabjufeuoh2wmg0n912ftgw" !
new Session[1]
Mixing with softvol and volume control: Log(60.0)
Session[1] strong=2 weak=1
Country: "NL"
new Spirc[1]
canonical_username: 0bzabjufeuoh2wmg0n912ftgw
new MercuryManager
new Player[1]
Converting with ditherer: tpdf
Using AlsaSink with format: S16
Input volume 45874 mapped to: 12.59%
command=AddEventSender
command=VolumeSet(45874)
subscribed uri=hm://remote/user/0bzabjufeuoh2wmg0n912ftgw/ count=0
kMessageTypeNotify "Web Player (Firefox)" 28ce822ac5abd43b382d08900cbd3fe07c00fd52 1012804918 1688934951460 kPlayStatusStop
kMessageTypeNotify "Fairphone 3" d428227995fff43af0abc7e4620bfd4c804409a4 1012804918 1688934951460 kPlayStatusStop
unknown subscription uri=social-connect/v2/session_update
^Cdrop Spirc[1]
Shutting down player thread ...
drop PlayerInternal[1]
PlayerInternal thread finished.
drop Session[1]
drop MercuryManager
drop Dispatch
deregistering event source from poller

This is the part of the log that appears the most relevant:

Invalidating session[0]
subscription terminated
drop Spirc[0]
Shutting down player thread ...
Unable to load audio item: MercuryError
drop Dispatch
deregistering event source from poller
Connection reset by peer (os error 104)

Compilation flags

I built Spotifyd myself, at 1c14982 using cargo build -j1 --release.

• dbus_mpris
• dbus_keyring
• alsa_backend
• portaudio_backend
• pulseaudio_backend
• rodio_backend

Versions (please complete the following information):

• OS: Raspberry Pi OS Lite 64-bit, bullseye, fresh image with only a small number of extra packages installed
• Spotifyd: 1c14982 (current master)
• cargo: cargo 1.70.0 (ec8a8a0ca 2023-04-25)

Additional context
The bug appears similar to #1154, but I don't think it's the same issue. As far as I know, nothing changed about my internet connection - Spotifyd just stopped working properly at some point (AFAIK with the same binary I was running for months). And my internet connection seems pretty stable and fast - well, at least the ethernet connection which it should pick (I hope).

[aykevl]

I did some further testing, and it appears that it really is my own network.

• Spotifyd master + LAN: broken
• Spotifyd 0.3.4 + LAN: broken
• Spotifyd 0.3.4 + wifi (same network): broken
• Spotifyd 0.3.4 + wifi (tethered from my phone, 4G): works

I'll need to investigate why it says "connection reset by peer", I guess the NAT doesn't like connections that are open for a long time or something.
Still, this is a bug in my opinion: it should reestablish the connection without interrupting the music. But probably a duplicate of #1154.

[eladyn]

Sorry to hear that. Unfortunately, to fix this issue, proper reconnection support would need to be implemented in librespot (the library that spotifyd is relying on), which is probably not an easy task. So until someone finds the time to implement that over there, we're stuck with spotifyd being quite annoying to use on “less stable” connections.

The other issue you're mentioning is (I think) about a slightly different problem. Since a recent release, spotifyd does no longer quit upon encountering a broken connection, but at least tries to relogin. That relogin probably gets stuck due to the connection not yet being up again, and thus spotifyd becomes unusable.

[aykevl]

So until someone finds the time to implement that over there, we're stuck with spotifyd being quite annoying to use on “less stable” connections.

The weird thing is that this is actually a really stable connection, I've had less problems on a network that was way, way worse. Spotifyd is really the only thing that's causing me problems here.

Also, I've found it seems to be failing at whole minutes. I tested three times and once it failed at 8:01 and two times at 6:00. This might suggest a timeout of some sort. But it could also be that the server side pings the connection every minute and finds it in a broken state on these whole minutes.

Since a recent release, spotifyd does no longer quit upon encountering a broken connection, but at least tries to relogin. That relogin probably gets stuck due to the connection not yet being up again, and thus spotifyd becomes unusable.

I guess? But again, the network appears very stable - if anything, I would assume it's a timeout of some sort.

[aykevl]

Unfortunately, to fix this issue, proper reconnection support would need to be implemented in librespot (the library that spotifyd is relying on), which is probably not an easy task. So until someone finds the time to implement that over there, we're stuck with spotifyd being quite annoying to use on “less stable” connections.

I wish I could help. I have very little experience with Rust (I'm a Go person) and I'm not sure I want to put so much effort into getting to know the codebase.
If you give me some hints where to start looking, I might try though.

[aykevl]

It appears that librespot-org/librespot#1176 improves things slightly. Or at least, with current librespot dev (librespot-org/librespot@f037e46) it appears to keep the connection alive when not playing music, and when it breaks while playing a song it will continue playing until the end instead of 30 seconds before the end - which was kind of frustrating. Also, reconnecting after a lost connection seems to work in the dev branch.

Still hoping for a complete fix though.

[aykevl]

I have now switched to librespot-java which works reliably on my network (and as an added bonus also reports played tracks to "recently played" which is nice). It looks like librespot-java is able to automatically reconnect without interrupting the music.

[utkucha]

Hi there,
I have the same issue :
Connection reset by peer (os error 104) Unable to load audio item: MercuryError
This happens after a few minutes as you described.

I am running Spotifyd on a Pi Zero W which is only used as a Spotify connect device.
I also tried to install Balena audio on the same device and was not having any deconnection issue, but I had other issues with the sound since the cpu was all the time at 100%

I have a raspberry Pi 3 running with raspotify (on the same network) which is also based on librespot and it works perfectly now. I had the exact same issue a couple of years ago with raspotify, but I think it has been fixed on librespot, and updated on raspotify.

Not sure I can help you but I can make some tests to help resolving the issue if it is possible.
By the way I am not sure which version of librespot is used on spotifyd. Is is the latest one?

[aykevl]

This issue has resolved itself magically somehow, for both my Raspberry Pi and my laptop (with different distro, and the Pi running librespot while my laptop uses spotifyd). This again points to some weirdness in my network that now appears to be resolved.

[stlehmann]

I can confirm the same problem:

[2024-12-26T19:38:55Z ERROR librespot_playback::player] Unable to load audio item: MercuryError
[2024-12-26T19:38:55Z ERROR librespot_core::session] Connection reset by peer (os error 104)
[2024-12-26T19:38:55Z ERROR librespot_connect::spirc] subscription terminated
[2024-12-26T19:38:55Z WARN  librespot] Spirc shut down unexpectedly