Timeout? Librespot-enabled device disappears from Spotify device list after a while

[codethief]

My RaspberryPi with Librespot has been running for a couple hours now and, earlier today, everything was working fine and I could listen to songs on Spotify through the speakers connected to the RPi. At some point this afternoon I paused the music, though, and now, hours later, I wanted to unpause it. However, Spotify didn't list my RPi among the available devices anymore.

So I ssh'd into the RPi and took a look at the logs. They seemed fine:

[…]
INFO:librespot_playback::player: Loading track "XY" with Spotify URI "spotify:track:4H6qtMPzKYRCsf7bT2DcBP"
INFO:librespot_playback::player: Track "XY" loaded
INFO:librespot::player_event_handler: Running ["/opt/musicbox/mpc_stop.sh"] with environment variables {"OLD_TRACK_ID": "foo", "TRACK_ID": "bar", "PLAYER_EVENT": "change"}
INFO:librespot::player_event_handler: Running ["/opt/musicbox/mpc_stop.sh"] with environment variables {"PLAYER_EVENT": "stop", "TRACK_ID": "bla"}

I then restarted librespot through service librestart stop/start and this fixed the issue—the RPi reappeared in Spotify's device list. Meanwhile, the logs are:

INFO:librespot: librespot 1e69138 (2018-05-18). Built on 2018-05-29. Build ID: Ptc4Ggyb
INFO:librespot_core::session: Connecting to AP "gew1-accesspoint-b-psjr.ap.spotify.com:4070"
INFO:librespot_core::session: Authenticated as "ABCDEFG" !
INFO:librespot_playback::audio_backend::alsa: Using alsa sink
INFO:librespot_core::session: Country: "CO"

So it seems that there is some kind of timeout causing Spotify to forget about a device with Librespot after a while?

[cortegedusage]

I have seen this behaviour too. Most of the time Restarting the app on my phone restores the connection.

Op di 11 sep. 2018 01:19 schreef codethief notifications@github.com:

My RaspberryPi with Librespot has been running for a couple hours now and, earlier today, everything was working fine and I could listen to songs on Spotify through the speakers connected to the RPi. At some point this afternoon I paused the music, though, and now, hours later, I wanted to unpause it. However, Spotify didn't list my RPi among the available devices anymore.

So I ssh'd into the RPi and took a look at the logs. They seemed fine:

[…] INFO:librespot_playback::player: Loading track "XY" with Spotify URI "spotify:track:4H6qtMPzKYRCsf7bT2DcBP" INFO:librespot_playback::player: Track "XY" loaded INFO:librespot::player_event_handler: Running ["/opt/musicbox/mpc_stop.sh"] with environment variables {"OLD_TRACK_ID": "foo", "TRACK_ID": "bar", "PLAYER_EVENT": "change"} INFO:librespot::player_event_handler: Running ["/opt/musicbox/mpc_stop.sh"] with environment variables {"PLAYER_EVENT": "stop", "TRACK_ID": "bla"}

I then restarted librespot through service librestart stop/start and this fixed the issue—the RPi reappeared in Spotify's device list. Meanwhile, the logs are:

INFO:librespot: librespot 1e69138 (2018-05-18). Built on 2018-05-29. Build ID: Ptc4Ggyb INFO:librespot_core::session: Connecting to AP "gew1-accesspoint-b-psjr.ap.spotify.com:4070" INFO:librespot_core::session: Authenticated as "ABCDEFG" ! INFO:librespot_playback::audio_backend::alsa: Using alsa sink INFO:librespot_core::session: Country: "CO"

So it seems that there is some kind of timeout causing Spotify to forget about a device with Librespot after a while?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/librespot-org/librespot/issues/247, or mute the thread https://github.com/notifications/unsubscribe-auth/AV69TdcpCDOa9FDvG80kTz5Znk4kzU36ks5uZuBLgaJpZM4WiPxQ .

[codethief]

@cortegedusage I tried that, too (both on my phone and my laptop), but unfortunately it didn't do the trick.

[Shuro]

I have the same behaviour, just with Moodeaudio for Raspberry Pi. I can't provide any logs sadly.

At some Point, the music stops and when I check Spotify on PC or on my Smartphone, there is no available device. I have to open Moode in browser and select to restart librespot to make it available again.

[codethief]

At some Point, the music stops

This is not the behavior I'm seeing. Music playback works flawlessly. It's only when librespot has been idling for hours that the device will disappear from the Spotify app.

[dangerfish96]

I am experiencing the same problem. I am also using a RaspberryPi (raspotify).

[mherger]

As I’ve had similar reports for my Spotty implementation (based on librespot), I am currently investigating a few ideas. Could it be that your internet connection goes down every now and then? Some ISPs do this regularly, like every night. I have a feeling that librespot doesn’t like that.

[michaelherger]

Just to confirm my theory (don't know why my previous comment was posted by my other account...): I run librespot/spotty in a VM. It showed up on Spotify. Then I cut the VM's network connection for a few seconds. Moments later the device disappeared from Spotify.

Unfortunately spotty/librespot didn't log anything when this happened, not even in verbose mode. It just sat there doing nothing.

[kingosticks]

Losing Internet connection is different to losing the entire network connection. Can you narrow it down?

On Sat, 6 Oct 2018, 16:56 michaelherger, notifications@github.com wrote:

Just to confirm my theory: I run librespot/spotty in a VM. It showed up on Spotify. Then I cut the VM's network connection for a few seconds. Moments later the device disappeared from Spotify.

Unfortunately spotty/librespot didn't log anything when this happened, not even in verbose mode. It just sat there doing nothing.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/librespot-org/librespot/issues/247#issuecomment-427584820, or mute the thread https://github.com/notifications/unsubscribe-auth/AA5DqN2MqNODaEDatifJXVa0SXT1HecZks5uiNKrgaJpZM4WiPxQ .

[michaelherger]

Didn't make any difference.

[kingosticks]

librespot's verbose mode sets mdns logging to info level (the same as in the normal logging). You can force your own logging config with something like:

RUST_LOG=mdns=trace ./target/debug/librespot

When I do that and I take away the network connection I see

WARN:mdns::fsm: error sending packet Os { code: 101, kind: Other, message: "Network is unreachable" }

And when I restore the connection it goes back to normal, no issues.

[michalfita]

Isn't it a long standing problem, of the connection lost that doesn't stop librespot, hence it cannot be restarted by systemd? I face the same symptoms few times a day.

[sashahilton00]

I've noticed this too, but not just restricted to librespot, I see similar behaviour from my Mu-So, and occasionally my phone.. I have a feeling spotify changed something behind the scenes, which inadvertently makes things more patchy. Relaunching app fixes the problem for me though, on both phone and desktop. It would be good if we could work out what causes this, though given it's unclear what steps one must take to reproduce it, I suspect that could be difficult.

[dnr]

I usually have to restart librespot a few times a day if I'm listening for a while also.

Spotify Connect is overall really buggy in my experience. I have lots of problems with queue syncing when switching among the linux desktop app, mac desktop app, android, and web players.

However, the other ones don't seem to disappear from the devices list like librespot does, they just sometimes get out of sync with other active apps. It would be great if librespot could detect when it's gotten into this situation and reconnect.

[StopMotionCuber]

I also used to have some problems with librespot (as having to restart it often), but recently it is working quite stable. I guess the thing that changed for me was that I disabled the firewall in my router (probably this was blocking some packages when reconnecting to the Pi)

[codethief]

For what it's worth, I've forgotten to turn off my Raspberry PI with librespot before going to bed a couple times now, so it was running the entire night. In the morning, when I tried to play a song through Spotify, it was still working perfectly, so it seems the issue is very hard to reproduce.

[sashahilton00]

My gut feeling is that this is a combination of Connect being buggy, and also is not handling reconnections. I suspect if/when we get around to implementing reconnection logic, the frequency of this bug should significantly decrease, and any remaining occurrences will likely be chalked up to server side errors

[dangerfish96]

This problem does not happen anymore for me since one of last commits

[capt-marc]

Still have this issue (running on latest build)- It happens randomly - sometimes librespot runs for ages - sometimes a few times a week. Tonight it happened on both my Pi's - connected on 2 different locations and networks. (same city thou) It must be something with the handshake with the server that fails. If the connection between librespot and the Spotify server is unavailable at that exact time it fails and panic.

librespot d2cadec (2018-11-19). Built on 2018-12-14. Build ID: ITqtjWoj 
...
DEBUG:librespot_core::session: Session[0] strong=3 weak=4
thread 'main' panicked at 'connection closed', libcore/option.rs:1000:5
stack backtrace:
   0:   0x8af167 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h63a67ac893ab31ec                                                                                                           
                       at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49                                                                                                                                   
   1:   0x89e423 - std::sys_common::backtrace::print::ha8f26509b9ff262c                                                                                                                                   
                       at libstd/sys_common/backtrace.rs:71                                                                                                                                               
                       at libstd/sys_common/backtrace.rs:59                                                                                                                                               
   2:   0x89bca7 - std::panicking::default_hook::{{closure}}::hd7e08be4e57c3548                                                                                                                           
                       at libstd/panicking.rs:211                                                                                                                                                         
   3:   0x89b91f - std::panicking::default_hook::h216d888df769ef77                                                                                                                                        
                       at libstd/panicking.rs:227                                                                                                                                                         
   4:   0x89c3cf - std::panicking::rust_panic_with_hook::h7d39a7695d8da98f                                                                                                                                
                       at libstd/panicking.rs:477                                                                                                                                                         
   5:   0x89bf93 - std::panicking::continue_panic_fmt::ha287897123d4a956                                                                                                                                  
                       at libstd/panicking.rs:391                                                                                                                                                         
   6:   0x89be7b - rust_begin_unwind                                                                                                                                                                      
                       at libstd/panicking.rs:326                                                                                                                                                         
   7:   0x8ef047 - core::panicking::panic_fmt::h2155aa66b67fe83c                                                                                                                                          
                       at libcore/panicking.rs:77                                                                                                                                                            8:   0x8ef0b7 - core::option::expect_failed::h0ee1e896fd083f84                                                                                                                                                                at libcore/option.rs:1000                                                                                                                                                          
   9:   0x56d15f - <librespot_core::session::DispatchTask<S> as futures::future::Future>::poll::hadd618cad1963c66                                                                                           10:   0x5c87ff - <futures::future::join::Join<A, B> as futures::future::Future>::poll::hafcc638c50362462                                                                                                
  11:   0x5ed6ab - <futures::future::map::Map<A, F> as futures::future::Future>::poll::h9879fc113e6dd59c                                                                                                  
  12:   0x5791b3 - <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll::h630c333e5183bb1a                                                                                           
  13:   0x7e2e2f - futures::task_impl::std::set::hb64b5e1c0cc56bbe                                                                                                                                        
  14:   0x7e648f - tokio::executor::current_thread::CurrentRunner::set_spawn::h3b1b60459bea935d                                                                                                           
  15:   0x7eaaaf - <tokio::executor::current_thread::scheduler::Scheduler<U>>::tick::hdb9927f46af9d364                                                                                                    
  16:   0x7ec6bf - <scoped_tls::ScopedKey<T>>::set::ha4e15547481b5bf8                                                                                                                                     
  17:   0x7ebbff - <std::thread::local::LocalKey<T>>::with::had55b97dcf1a1023                                                                                                                             
  18:   0x7eb77f - <std::thread::local::LocalKey<T>>::with::h1761e86c7f8b584a                                                                                                                             
  19:   0x7ec1b7 - <std::thread::local::LocalKey<T>>::with::hbda6d445ae1bf9e8                                                                                                                             
  20:   0x7e6f4b - tokio_core::reactor::Core::poll::hbae1363e66332d87                                                                                                                                     
  21:   0x4873bb - tokio_core::reactor::Core::run::hf9c93dd339db2f7e                                                                                                                                      
  22:   0x492bff - librespot::main::h72f979f6b833cfad                                                                                                                                                     
  23:   0x46b353 - std::rt::lang_start::{{closure}}::h9cdb8adbbe2a93a7                                                                                                                                    
  24:   0x89bdf3 - std::panicking::try::do_call::he4497885895661a8                                                                                                                                        
                       at libstd/rt.rs:59                                                                                                                                                                 
                       at libstd/panicking.rs:310                                                                                                                                                         
  25:   0x8b9f5f - __rust_maybe_catch_panic                                                                                                                                                               
                       at libpanic_unwind/lib.rs:103                                                                                                                                                      
  26:   0x89ae9f - std::panic::catch_unwind::hdd9654d0e8ee1176                                                                                                                                            
                       at libstd/panicking.rs:289                                                                                                                                                         
                       at libstd/panic.rs:392                                                                                                                                                             
  27:   0x897cdb - std::rt::lang_start_internal::h4ec5eae1ccf41136                                                                                                                                        
                       at libstd/rt.rs:58                                                                                                                                                                 
  28:   0x4938a7 - main                                                                                                                                                                                   
  29: 0x76bc8677 - __libc_start_main                                                                                                                                                                      
DEBUG:librespot_core::session: drop Dispatch                                                                                                                                                              
DEBUG:librespot_connect::spirc: drop Spirc[0]                                                                                                                                                             
DEBUG:librespot_playback::player: Shutting down player thread ...                                                                                                                                         
DEBUG:librespot_playback::player: drop Player[0]                                                                                                                                                          
DEBUG:librespot_core::session: drop Session[0]                                                                                                                                                            DEBUG:librespot_core::audio_key: drop AudioKeyManager                                                                                                                                                     
DEBUG:librespot_core::channel: drop ChannelManager                                                                                                                                                        
DEBUG:librespot_core::mercury: drop MercuryManager      

[codethief]

Update on my earlier comment: I've now had my Pi running for 4-5 days. The first few days it was working perfectly but this morning the device suddenly wasn't showing up among the "Other devices" in the Spotify app anymore. So I'm with @capt-marc here, the issue is neither fixed nor is it occurring deterministically.

[aykevl]

I have the same issue when using spotifyd. When I pause music, it will disappear after a while (closing and re-opening the Android app doesn't help). When I hit Ctrl+C, I get an error message "Connection reset by peer" but somehow it doesn't quit. When I hit Ctrl+C again, it quits. This is the output (see ^C for Ctrl+C):

^C16:27:56 [ERROR] Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }                  
^C                                                                                                      

Note that the connection here is rather flaky and sometimes disappears for a while (I don't have a choice of ISP...). However, it seems that, when doing a Ctrl+C, something detects that the connection is broken. It would be very useful to reconnect in this case. If someone knows how to debug this further to see where the error comes from, I'm happy to help.

Also see #276 which might be related.

[michalfita]

I don't know the code. But that's interesting observation from my C background experience. For me it smells some stale select() not returning on error, but awaken by SIGINT (coming from Ctrl+C sent to terminal).

[dougestey]

This happens for me with every project I've used based on this library (volumio, raspotify, etc.) Even if librespot can't handle reconnections yet, if we could at least have it crash it would be easier to programmatically restart it.

[tofalck]

I see this issue intermittently.

My RPI is placed in a closet very close to my main wifi access point, but I think the issue is wifi connection loss due to the rather bad wifi onboard the RPI.

It's been stable outside its casing for the past 24 hours and I normally see the issue well within that timespan.

I can confirm the issue exists on at least Moode, Ropieee and Volumio. Ropieee seems a little more stable than the other two.

A workaround could perhaps be a kind of networkd-dispatcher monitoring script to restart librespot when either network connection resumes from a previous connection loss and librespot was running before the script was dispatched.

This should somehow be baked in or installed by the librespot library to make it as friction free as possible.

[ashthespy]

A workaround could perhaps be a kind of networkd-dispatcher monitoring script to restart librespot when either network connection resumes from a previous connection loss and librespot was running before the script was dispatched.

Maybe we could check connectivity by using AsterNovi-belgii-flower-1mb.jpg? https://phabricator.wikimedia.org/T273741 😁

[codethief]

Update to my previous comments: I recently switched from PiMusicBox to HiFiBerryOS (using the same Raspberry Pi) and things have been running perfectly ever since – the RaspberryPi shows up in Spotify's device list every single time! Not sure what the people at HiFiBerry are doing differently (apart from using (a custom build of) spotifyd whereas PiMusicBox uses raspotify(?)) but, in any case, it works! :)

[kingosticks]

The difference is PiMusicbox uses a very old build of librespot, probably still the same one it had back in 2018. I'm not sure HifiBerryOS even existed back in 2018!

[codethief]

I'm not sure HifiBerryOS even existed back in 2018!

I'm pretty sure it didn't. :)

The difference is PiMusicbox uses a very old build of librespot, probably still the same one it had back in 2018

True, but I'm not convinced yet this is what made the crucial difference. Because why are people still experiencing this issue with (I assume) recent builds? It's either because there is still a bug in librespot or, as I was hinting at in my previous comment, maybe it's not librespot itself that is at fault but rather the librespot wrapper (in this case raspotify)?

[kingosticks]

To be clear, Pimusicbox does not use raspotify. It uses librespot as is. Sorry, I should have been explicit.

[codethief]

Oh well, then I take everything back. :)

[roderickvd]

Tracked by #609.