Connection issues after some hours of idle time

[TimHausmann]

Hi, I have a Raspberry 2 with an Hifiberry Digi+ working with the latest Volumio (2.555) and the latest volspotconnect2 (0.8.6).

The issue is, if Spotify Connect is idle for a couple of hours (no playback), Spotify Connect is trying to connect and fails, making the Spotify Connect target disappear in the Soptify App. I need to deactivate the plugin in the webinterface of volumio and activate it again to get it working again.

Please let me know if you need any more information. I'm new to this.

[skraburski]

I've the same issue.

[aceholgi]

Yep, same here. When ssh into volumio, issuing

sudo systemctl status volspotconnect2.service

gives different results:

When working OK, there is the line Mar 18 15:23:41 volumio volumio[29050]: [Vollibrespot] : Metadata pipe established

This line is missing in the result, when not working properly, all other lines are identical.

I'm running 0.9.0, by the way

[TimHausmann]

Yep, I can confirm this behavior.

[ashthespy]

Could you post logs of the daemon alone by running: sudo journalctl -f -o cat -u volspotconnect2.service

The underlying library doesn't handle disconnects gracefully - and I suspect you guys are running into problems due to this.

[TimHausmann]

[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }

Here I tried to connect to the Spotify Connect target via Android App

[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-l2td.ap.spotify.com:4070"
[Vollibrespot] : Authenticated as "bademantelblues" !
[Vollibrespot] : Shutting down MetaPipe ... Some(JoinHandle { .. })
[Vollibrespot] : Using alsa sink
thread '<unnamed>' panicked at 'Error starting Metadata pipe: : Os { code: 98, kind: AddrInUse, message: "Address already in use" }', libcore/result.rs:1009:5
stack backtrace:
0:   0xa30a73 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h3608b871673a8803
at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
1:   0xa20003 - std::sys_common::backtrace::print::hef947be8cf8e8f55
at libstd/sys_common/backtrace.rs:71
at libstd/sys_common/backtrace.rs:59
2:   0xa1db37 - std::panicking::default_hook::{{closure}}::haac47ed356699ffe
at libstd/panicking.rs:211
3:   0xa1d797 - std::panicking::default_hook::h95ba73384225983b
at libstd/panicking.rs:227
4:   0xa1e25f - std::panicking::rust_panic_with_hook::ha1106c0ce43cea72
at libstd/panicking.rs:477
5:   0xa1de23 - std::panicking::continue_panic_fmt::h875c7946721c05c9
at libstd/panicking.rs:391
6:   0xa1dd0b - rust_begin_unwind
at libstd/panicking.rs:326
7:   0xa7feb3 - core::panicking::panic_fmt::h429a06507aba9228
at libcore/panicking.rs:77
8:   0x53ac2f - core::result::unwrap_failed::hed968dfd37ddc0a3
9:   0x5150eb - vollibrespot::meta_pipe::MetaPipeThread::run::had2c4700369a222a
10:   0x53d77f - std::sys_common::backtrace::__rust_begin_short_backtrace::h54b144712bf89338
11:   0x52d187 - std::panicking::try::do_call::hcf6001526dcf213a
12:   0xa3becb - __rust_maybe_catch_panic
at libpanic_unwind/lib.rs:103
13:   0x539647 - <F as alloc::boxed::FnBox<A>>::call_box::hc5d61e19da108dbf
14:   0xa1cdd7 - std::sys_common::thread::start_thread::hd1b180dd2fa4010c
at liballoc/boxed.rs:656
at libstd/sys_common/thread.rs:24
15:   0xa1f997 - std::sys::unix::thread::Thread::new::thread_start::h63a610b507ecb711
at libstd/sys/unix/thread.rs:90

Here I restarted the plug-in

Stopping Volspotconnect2 Daemon...
Stopped Volspotconnect2 Daemon.
Starting Volspotconnect2 Daemon...
Started Volspotconnect2 Daemon.
vollibrespot v0.1.3 48346b7 2019-02-25 (librespot 57c9ab5 2019-02-22) -- Built On 2019-02-25
[Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-w84j.ap.spotify.com:4070"
[Vollibrespot] : Authenticated as "bademantelblues" !
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Country: "DE"
[Vollibrespot] : Metadata pipe established

[TimHausmann]

Sorry, I've hit the wrong button...

[aceholgi]

When no connection is possible

volumio@volumio:~$ sudo journalctl -f -o cat -u volspotconnect2.service [Vollibrespot] : Authenticated as "d5p96x9xlznhd0rjfxxxx2283" ! [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:SoftMaster index:0 [Vollibrespot] : Alsa min: 0 (MilliBel(0)[dB]) -- max: 99 (MilliBel(0)[dB]) HW: false [Vollibrespot] : Using Alsa linear volume [Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!! [Vollibrespot] : Using alsa sink [Vollibrespot] : Current alsa volume: 64[i64] MilliBel(9999999) [Vollibrespot] : Mapping (lin) volume [60.000%] 39321 [u16] ->> Alsa [59.596%] 59 [i64] [Vollibrespot] : Metadata pipe established [Vollibrespot] : Country: "DE"

After restarting:

volumio@volumio:~$ sudo journalctl -f -o cat -u volspotconnect2.service [Vollibrespot] : Authenticated as "d5p96x9xlznhd0rjfxxxx2283" ! [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:SoftMaster index:0 [Vollibrespot] : Alsa min: 0 (MilliBel(0)[dB]) -- max: 99 (MilliBel(0)[dB]) HW: false [Vollibrespot] : Using Alsa linear volume [Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!! [Vollibrespot] : Using alsa sink [Vollibrespot] : Current alsa volume: 59[i64] MilliBel(9999999) [Vollibrespot] : Mapping (lin) volume [60.000%] 39321 [u16] ->> Alsa [59.596%] 59 [i64] [Vollibrespot] : Metadata pipe established [Vollibrespot] : Country: "DE"

... so this looks identical ...

[ashthespy]

Could you guys enable verbose logging by uncommenting the --verbose in startconnect.sh and then check logs?

[TimHausmann]

I've changed the file, could you paste me a command for the logs? Sorry, I'm not so advanced.

[TimHausmann]

I have run

sudo journalctl -f -o cat -u volspotconnect2.service

[Vollibrespot] : Track "G Street" loaded
[Vollibrespot] : Loading track "Mai tai" with Spotify URI "spotify:track:3dOye6wwmwIZ9eZwD9tiqc"
[Vollibrespot] : Track "Mai tai" loaded
[Vollibrespot] : Loading track "These Are Just Places To Me Now" with Spotify URI "spotify:track:6M5IPW3c81qXicxsOGAJgf"
[Vollibrespot] : Track "These Are Just Places To Me Now" loaded
[Vollibrespot] : volStop
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-sjn4.ap.spotify.com:4070"
[Vollibrespot] : Authenticated as "bademantelblues" !
[Vollibrespot] : Shutting down MetaPipe ... Some(JoinHandle { .. })
[Vollibrespot] : Using alsa sink
thread '<unnamed>' panicked at 'Error starting Metadata pipe: : Os { code: 98, kind: AddrInUse, message: "Address already in use" }', libcore/result.rs:1009:5
stack backtrace:
0:   0x9d5a73 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h3608b871673a8803
at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
1:   0x9c5003 - std::sys_common::backtrace::print::hef947be8cf8e8f55
at libstd/sys_common/backtrace.rs:71
at libstd/sys_common/backtrace.rs:59
2:   0x9c2b37 - std::panicking::default_hook::{{closure}}::haac47ed356699ffe
at libstd/panicking.rs:211
3:   0x9c2797 - std::panicking::default_hook::h95ba73384225983b
at libstd/panicking.rs:227
4:   0x9c325f - std::panicking::rust_panic_with_hook::ha1106c0ce43cea72
at libstd/panicking.rs:477
5:   0x9c2e23 - std::panicking::continue_panic_fmt::h875c7946721c05c9
at libstd/panicking.rs:391
6:   0x9c2d0b - rust_begin_unwind
at libstd/panicking.rs:326
7:   0xa24eb3 - core::panicking::panic_fmt::h429a06507aba9228
at libcore/panicking.rs:77
8:   0x4dfc2f - core::result::unwrap_failed::hed968dfd37ddc0a3
9:   0x4ba0eb - vollibrespot::meta_pipe::MetaPipeThread::run::had2c4700369a222a
10:   0x4e277f - std::sys_common::backtrace::__rust_begin_short_backtrace::h54b144712bf89338
11:   0x4d2187 - std::panicking::try::do_call::hcf6001526dcf213a
12:   0x9e0ecb - __rust_maybe_catch_panic
at libpanic_unwind/lib.rs:103
13:   0x4de647 - <F as alloc::boxed::FnBox<A>>::call_box::hc5d61e19da108dbf
14:   0x9c1dd7 - std::sys_common::thread::start_thread::hd1b180dd2fa4010c
at liballoc/boxed.rs:656
at libstd/sys_common/thread.rs:24
15:   0x9c4997 - std::sys::unix::thread::Thread::new::thread_start::h63a610b507ecb711
at libstd/sys/unix/thread.rs:90
Stopping Volspotconnect2 Daemon...
Stopped Volspotconnect2 Daemon.
Starting Volspotconnect2 Daemon...
Started Volspotconnect2 Daemon.
vollibrespot v0.1.3 48346b7 2019-02-25 (librespot 57c9ab5 2019-02-22) -- Built On 2019-02-25
[Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-k48c.ap.spotify.com:4070"
[Vollibrespot] : Authenticated as "bademantelblues" !
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Country: "DE"
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : SessionActive!
[Vollibrespot] : Loading track "Strong" with Spotify URI "spotify:track:6k1I9gABiasGZiWWAosAEb"
[Vollibrespot] : Track "Strong" loaded
[Vollibrespot] : volStop

[ashthespy]

@TimHausmann Have tried to make it a little more robust when attempting to reconnect, let me know if this persists with v0.9.3

[isering]

I had the same issue and after a few hours it still works fine for me with 0.9.3. Thank you and keep up the great work!

[TimHausmann]

@ashthespy I installed v0.9.3, had it idle over night, tried to connect a few minutes ago and it didn't work. Restarted the plug-in and it works. So, no improvement. I will post logs tomorrow.

[ashthespy]

Reconnection is something that requires quite some restructuring of librespot, but is something on our todo list. But what the update to 0.9.3 brings is more graceful behaviour when a connection is dropped - don't panic, but reset the connection.

[TimHausmann]

Here are logs if they help. Have a nice weekend.

volumio@wohnzimmer:~$ sudo journalctl -f -o cat -u volspotconnect2.service      [Vollibrespot] : Track "Back in the Day - Original Mix" loaded
[Vollibrespot] : Loading track "Addicted" with Spotify URI "spotify:track:5dyf6lq66dzO9zLRkkWu9F"
[Vollibrespot] : Track "Addicted" loaded
[Vollibrespot] : volStop
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : API Token expired, refreshing...
[Vollibrespot] : Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-n4n5.ap.spotify.com:4070"
[Vollibrespot] : Authenticated as "bademantelblues" !
[Vollibrespot] : Shutting down MetaPipe ... Some(JoinHandle { .. })
[Vollibrespot] : Using alsa sink
thread '<unnamed>' panicked at 'Error starting Metadata pipe: : Os { code: 98, kind: AddrInUse, message: "Address already in use" }', src/libcore/result.rs:997:5
stack backtrace:
0:   0x9ef193 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::hdf951eb9f43ea27e
at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:39
1:   0x9eab97 - std::sys_common::backtrace::_print::h2b5fdbbb5020ccf8
at src/libstd/sys_common/backtrace.rs:70
2:   0x9ed233 - std::panicking::default_hook::{{closure}}::h18d8c59665918d69
at src/libstd/sys_common/backtrace.rs:58
at src/libstd/panicking.rs:200
3:   0x9ece6b - std::panicking::default_hook::h1fd1ad969274543a
at src/libstd/panicking.rs:215
4:   0x9ed9a3 - std::panicking::rust_panic_with_hook::h40a77253872948e8
at src/libstd/panicking.rs:478
5:   0x9ed523 - std::panicking::continue_panic_fmt::hec94fc8e5daf641b
at src/libstd/panicking.rs:385
6:   0x9ed40f - rust_begin_unwind
at src/libstd/panicking.rs:312
7:   0xa029db - core::panicking::panic_fmt::h74ee8034b317ceed
at src/libcore/panicking.rs:85
8:   0x4fdc87 - core::result::unwrap_failed::he505ea6b0a11dc89
9:   0x4dfc07 - vollibrespot::meta_pipe::MetaPipeThread::run::h29b279abaae0db7a
10:   0x4f9833 - std::sys_common::backtrace::__rust_begin_short_backtrace::h1c40e36de64fc85f
11:   0x4e2d1f - std::panicking::try::do_call::h9d637177e007ec02
12:   0x9f2097 - __rust_maybe_catch_panic
at src/libpanic_unwind/lib.rs:92
13:   0x4f64cb - <F as alloc::boxed::FnBox<A>>::call_box::h07f22b7d5813b620
14:   0x9f1537 - std::sys::unix::thread::Thread::new::thread_start::h561dd350a6a5bdaa
at /rustc/2aa4c46cfdd726e97360c2734835aa3515e8c858/src/liballoc/boxed.rs:744
at src/libstd/sys_common/thread.rs:14
at src/libstd/sys/unix/thread.rs:81

[MatthewMong]

Still having this issue with 0.9.3 on a pi zero w. Any chance the recent commit about updating librespot will fix this?

[ashthespy]

Still having this issue with 0.9.3 on a pi zero w. Any chance the recent commit about updating librespot will fix this?

Which commit?

[TimHausmann]

Is there a command which restarts the plugin? I am thinking about a cron job restarting the plugin regularly (every now and then) if no music is playing.

[aceholgi]

I put this in crontab:

0 9 * sudo /bin/systemctl restart volspotconnect2.service

But this doesn't solve the issue, as the restarts occurs never to the right time, according to Murphy's law....

[TimHausmann]

I will write a script which checks if volumio is playing and if not it restarts the plugin. I will schedule the job every three hours and see if it works. I know it's a crowbar workaround, but it's better than my girlfriend complaining all the time...

[ashthespy]

@TimHausmann, @aceholgi Made some tweaks - please test let me know it gets any better - binaries are at ashthespy/Vollibrespot/releases It should:

• if there is only a small hiccup, try continuing with the same session
• else error out and shutdown, making the systemmd service restart it - letting you attempt connecting again

Please turn on debugging/verbose mode to get some meaningful logs when(or hopefully if) it hangs.

PS: A simple way to install the new binary would be to edit package.json and update the version key under vollibrespot to v0.1.4-1-g0cf508c and then run install.sh again.

[aceholgi]

@ashthespy Thanks for your effort!

I (more or less total Unix dummy) managed to install the new binary after finding out the corresponding path in volumio installation. I switched on "debug mode" in the plugin section of volumio preferences, is this what you mean by turning on debugging/verbose mode?

[aceholgi]

(I removed my Spotify login info ...)

[aceholgi]

... within 1 hour of testing, the service was down once.

[ashthespy]

@aceholgi could you share the logs (https://github.com/balbuze/volumio-plugins/issues/217#issuecomment-474126514) to check why the connection is dropping? But - the service restarting is desired behaviour as it should allow you to reconnect?

[aceholgi]

I posted my log (3 messages above). The upper part (service down) was the result of "sudo systemctl status volspotconnect2.service" when the connection was lost. The lower part is the result after I manually restarted the service by switching the plugin off an on, again. Please advise, how to get more detailed logs.

[ashthespy]

Please advise, how to get more detailed logs.

https://github.com/balbuze/volumio-plugins/issues/217#issuecomment-474126514

[aceholgi]

That's it:

[aceholgi]

...when service is down

[ashthespy]

@aceholgi the logs don't really show any reason for the device to be unreachable - after how long does this usually happen?

[aceholgi]

@ashthespy I'm checking this quite frequently over the last 2 weeks. Sometimes it works for less than 1 hour, sometimes a few hours, never over night for 24h.

[aceholgi]

Maybe here is something interesting. The connection dropped after about 7 hours. These are the last lines in the log prior to dropping:

[ashthespy]

^^ Those last lines look promising - systemd should restart the service automatically after this, allowing you to reconnect?

[MatthewMong]

9: 0x45dc07 - vollibrespot::meta_pipe::MetaPipeThread::run::h29b279abaae0db7a 10: 0x477833 - std::sys_common::backtrace::__rust_begin_short_backtrace::h1c40e36de64fc85f 11: 0x460d1f - std::panicking::try::do_call::h9d637177e007ec02 12: 0x970097 - __rust_maybe_catch_panic at src/libpanic_unwind/lib.rs:92 13: 0x4744cb - <F as alloc::boxed::FnBox<A>>::call_box::h07f22b7d5813b620 14: 0x96f537 - std::sys::unix::thread::Thread::new::thread_start::h561dd350a6a5bdaa at /rustc/2aa4c46cfdd726e97360c2734835aa3515e8c858/src/liballoc/boxed.rs:744 at src/libstd/sys_common/thread.rs:14 at src/libstd/sys/unix/thread.rs:81

[ashthespy]

@MatthewMong Could you share the full stack trace along with what was going on when this occurred?

[aceholgi]

@ashthespy: Nope, I needed to de- and re-activate the plugin manually. Up to now still working properly.

Thanks!

[aceholgi]

Service is up and running without issues for more than 24 hours! Don't know why, but I love it! I can't rule out that, after installing the new binary, I didn't restart the plugin right away. Maybe it just kicked in after the latest drop of connection and manual restart of the plugin.

[ashthespy]

Alright, keep me posted! I am currently testing more tweaks for these connection issues - but since I don't face these issues here that often, progress is slow ;=)

[aceholgi]

Thank you very much for your effort! This morning the connection was lost for the first time in 40 hours. When the service is down, no log entries are written anymore, if it is up, there is a log entry about every other minute. The last 3 lines in the log are similar to the last time.

[ashthespy]

Just preparing a new release that should not require you manually have to restart the service. Please do test with v0.1.5

[ashthespy]

Just a heads up guys, v0.1.5 has an issue with high CPU usage, please update to v0.1.6 for the fix. @balbuze Could you bump up the version in package.json as well when you make the next release?

[balbuze]

Ok I will do! Tonight...

[balbuze]

done with version 0.9.5 of the plugin. You may need to reboot after installation.

[aceholgi]

@ashthespy & @balbuze: Thanx gentlemen, just saw the update, installed immediately!

[aceholgi]

@ashthespy & @balbuze: The latest changes solved the issue for my setup / installation. No connection losses at all over the last three days!

[aceholgi]

Still no disconnects. I think the issue should be closed.

[TimHausmann]

Hi, thank you for your efforts. I just installed the latest version and so far it works like a charm. I will test if it it's up and running tomorrow morning and if so, will close the issue. Thanks again to all.

[balbuze]

Ok !

[TimHausmann]

Hi there, I deleted and reinstalled the plugin and rebooted the Raspberry. It sais 0.9.5 now. I tried to connect to my Spotify Connect target this morning and it did not connect. Afterwards the target disappeared from the app. Restarting the plugin solved the issue. So, it's not working for me. Could you get me directrions how to check if everything is installed correctly?

[balbuze]

you wrote "restarting the plugin solved the issue", so it fails only after installation or it is still not working now?