dtcooper/raspotify

Raspotify disconnects after being idle for some time

vguttmann opened this issue · 5 comments

vguttmann commented

Compatible Device

  • I'm running Raspotify on a compatible Device

Are you sure?

  • I'm not trying to run Raspotify on a ARMv6 device

Compatible OS

  • I'm running Raspotify on a compatible OS

Compatible Configuration

  • I'm running Raspotify on a compatible Configuration

Latest Version

  • I'm running the latest version of Raspotify

Are you sure?

  • I'm not running Raspotify 0.31.8.1 on a on a Pi v1 or Pi Zero

Due Diligence

  • I have done my due diligence

What happened?

Raspotify disappears from available devices in the Spotify Home assistant integration, however reappears when searching for available devices in Spotify.

This is an issue that happens with both zeroconf and credentials.

The same problem appears with other librespot-based clients, and it seems to be related to this librespot issue.

Relevant log output and/or the contents of /etc/raspotify/crash_report if any ( sudo journalctl -u raspotify -b and sudo cat /etc/raspotify/crash_report )

-- Journal begins at Tue 2022-11-01 04:12:47 CET, ends at Fri 2023-03-17 11:57:50 CET. --
Mar 13 20:04:07 osmc systemd[1]: Started Raspotify (Spotify Connect Client).
Mar 13 20:04:35 osmc librespot[380]: [2023-03-13T19:04:35Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Mar 13 20:04:35 osmc librespot[380]: [2023-03-13T19:04:35Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Mar 13 20:04:35 osmc librespot[380]: [2023-03-13T19:04:35Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Mar 13 20:04:35 osmc librespot[380]: [2023-03-13T19:04:35Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
Mar 16 13:05:52 osmc librespot[380]: [2023-03-16T12:05:52Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Mar 16 13:05:52 osmc librespot[380]: [2023-03-16T12:05:52Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Mar 16 13:05:52 osmc librespot[380]: [2023-03-16T12:05:52Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Mar 16 13:05:52 osmc librespot[380]: [2023-03-16T12:05:52Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Mar 16 13:13:53 osmc systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Mar 16 13:13:53 osmc systemd[1]: raspotify.service: Succeeded.
Mar 16 13:13:53 osmc systemd[1]: Stopped Raspotify (Spotify Connect Client).
Mar 16 13:13:53 osmc systemd[1]: raspotify.service: Consumed 46.895s CPU time.
Mar 16 13:13:53 osmc systemd[1]: Started Raspotify (Spotify Connect Client).
Mar 16 13:13:53 osmc librespot[10081]: [2023-03-16T12:13:53Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Mar 16 13:13:53 osmc librespot[10081]: [2023-03-16T12:13:53Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Mar 16 13:13:53 osmc librespot[10081]: [2023-03-16T12:13:53Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Mar 16 17:50:42 osmc librespot[10081]: [2023-03-16T16:50:42Z WARN  librespot_playback::player] Player::seek called from invalid state
Mar 16 20:10:17 osmc librespot[10081]: [2023-03-16T19:10:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Mar 16 20:10:17 osmc librespot[10081]: [2023-03-16T19:10:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Mar 16 20:10:17 osmc librespot[10081]: [2023-03-16T19:10:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Mar 16 20:10:38 osmc librespot[10081]: [2023-03-16T19:10:38Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Mar 16 20:10:38 osmc librespot[10081]: ALSA lib pcm.c:8545:(snd_pcm_recover) underrun occurred
Mar 16 20:25:45 osmc librespot[10081]: [2023-03-16T19:25:45Z ERROR librespot_core::session] Connection timed out (os error 110)
Mar 16 20:25:45 osmc librespot[10081]: [2023-03-16T19:25:45Z WARN  librespot_connect::spirc] Cannot flush spirc event sender.
Mar 16 21:11:11 osmc librespot[10081]: [2023-03-16T20:11:11Z WARN  librespot_playback::player] Player::play called from invalid state
Mar 16 21:54:39 osmc librespot[10081]: [2023-03-16T20:54:39Z WARN  librespot_connect::spirc] Skipping track <uri: "spotify:delimiter"> at position [1] of 11
Mar 16 21:55:09 osmc librespot[10081]: [2023-03-16T20:55:09Z WARN  librespot_connect::spirc] Skipping track <uri: "spotify:delimiter"> at position [1] of 11
Mar 16 21:58:00 osmc librespot[10081]: [2023-03-16T20:58:00Z WARN  librespot_connect::spirc] Skipping track <uri: "spotify:delimiter"> at position [3] of 11
Mar 16 21:58:30 osmc librespot[10081]: [2023-03-16T20:58:30Z WARN  librespot_connect::spirc] Skipping track <uri: "spotify:delimiter"> at position [3] of 11


-- System Info --

Linux osmc 5.10.78-7-osmc #1 SMP PREEMPT Fri Sep 2 03:06:27 UTC 2022 aarch64 GNU/Linux
PRETTY_NAME="Open Source Media Center"
NAME="OSMC"
VERSION="January 2023"
VERSION_ID="2023.01-1"
ID=osmc
ID_LIKE=debian

ANSI_COLOR="1;31"
HOME_URL="https://osmc.tv"
SUPPORT_URL="https://osmc.tv"
BUG_REPORT_URL="https://osmc.tv"

-- Logs --

Feb 13 17:56:19 osmc librespot[344]: [2023-02-13T16:56:19Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 13 17:56:19 osmc librespot[344]: [2023-02-13T16:56:19Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 13 17:56:19 osmc librespot[344]: [2023-02-13T16:56:19Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 13 17:56:33 osmc librespot[344]: [2023-02-13T16:56:33Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Feb 13 17:56:33 osmc systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 13 17:56:33 osmc systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 13 17:56:33 osmc systemd[1]: raspotify.service: Triggering OnFailure= dependencies.
Feb 13 17:56:49 osmc systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 13 17:56:49 osmc librespot[1183]: [2023-02-13T16:56:49Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 13 17:56:49 osmc librespot[1183]: [2023-02-13T16:56:49Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 13 17:56:49 osmc librespot[1183]: [2023-02-13T16:56:49Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 13 17:56:49 osmc librespot[1183]: [2023-02-13T16:56:49Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:80
Feb 13 17:57:17 osmc librespot[1183]: [2023-02-13T16:57:17Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Feb 13 17:57:17 osmc systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 13 17:57:17 osmc systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 13 17:57:17 osmc systemd[1]: raspotify.service: Triggering OnFailure= dependencies.

-- Config --

LIBRESPOT_QUIET=
LIBRESPOT_ENABLE_VOLUME_NORMALISATION=
LIBRESPOT_NAME="Lucifer"
LIBRESPOT_BITRATE="320"
LIBRESPOT_DEVICE_TYPE="speaker"
LIBRESPOT_USERNAME=XXXXXXXX
LIBRESPOT_PASSWORD=XXXXXXXX
LIBRESPOT_INITIAL_VOLUME="50"

-- Ouput of aplay -l --

**** List of PLAYBACK Hardware Devices ****
card 0: vc4hdmi0 [vc4-hdmi-0], device 0: MAI PCM i2s-hifi-0 [MAI PCM i2s-hifi-0]
  Subdevices: 0/1
  Subdevice #0: subdevice #0
card 1: vc4hdmi1 [vc4-hdmi-1], device 0: MAI PCM i2s-hifi-0 [MAI PCM i2s-hifi-0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

-- Ouput of aplay -L --

null
    Discard all samples (playback) or generate zero samples (capture)
default
    Default Audio Device
sysdefault
    Default Audio Device
bluealsa
    Bluetooth Audio Hub
btaudio
    Bluetooth Audio
hw:CARD=vc4hdmi0,DEV=0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    Direct hardware device without any conversions
plughw:CARD=vc4hdmi0,DEV=0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    Hardware device with all software conversions
default:CARD=vc4hdmi0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    Default Audio Device
sysdefault:CARD=vc4hdmi0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    Default Audio Device
hdmi:CARD=vc4hdmi0,DEV=0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    HDMI Audio Output
dmix:CARD=vc4hdmi0,DEV=0
    vc4-hdmi-0, MAI PCM i2s-hifi-0
    Direct sample mixing device
hw:CARD=vc4hdmi1,DEV=0
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    Direct hardware device without any conversions
plughw:CARD=vc4hdmi1,DEV=0
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    Hardware device with all software conversions
default:CARD=vc4hdmi1
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    Default Audio Device
sysdefault:CARD=vc4hdmi1
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    Default Audio Device
hdmi:CARD=vc4hdmi1,DEV=0
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    HDMI Audio Output
dmix:CARD=vc4hdmi1,DEV=0
    vc4-hdmi-1, MAI PCM i2s-hifi-0
    Direct sample mixing device

-- Ouput of librespot -d ? --


        Compatible alsa device(s):

        ------------------------------------------------------

osmc@osmc:~$
JasonLG1979 commented

You've got a couple things going on here:

Mar 16 20:10:38 osmc librespot[10081]: [2023-03-16T19:10:38Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EPIPE: Broken pipe'
Mar 16 20:10:38 osmc librespot[10081]: ALSA lib pcm.c:8545:(snd_pcm_recover) underrun occurred

This and the other audio sink errors seems to suggest that your audio device is disappearing if you're using HDMI as an output that's probably why. If the thing that the HDMI is connected to goes to sleep or whatever I could see this happening when you try to start playback while it's asleep maybe?

Mar 16 20:25:45 osmc librespot[10081]: [2023-03-16T19:25:45Z ERROR librespot_core::session] Connection timed out (os error 110)
Mar 16 20:25:45 osmc librespot[10081]: [2023-03-16T19:25:45Z WARN  librespot_connect::spirc] Cannot flush spirc event sender.

I don't think much can be done about this except maybe forcing librespot to exit and thus restart if this happens. The root cause seems to that the connection to Spotify is timing out?

vguttmann commented

Oh yeah, that was when I turned the TV off, but the thing still happens when I keep the TV on (and it's a confirmed issue in other projects using librespot).

It's less of a "Hey this is a problem that needs solving now", and more of a "Just FYI, there's an upstream problem you might want to keep an eye on" type issue.

JasonLG1979 commented

It's less of a "Hey this is a problem that needs solving now", and more of a "Just FYI, there's an upstream problem you might want to keep an eye on" type issue.

I'm aware. I keep a pretty close eye on librespot. I was a regular code contributor to librespot for a little while until a dispute because of them not wanting to do regular non-breaking dependency updates or bug fixes on the current release lead me to step away and fork librespot for use here in Raspotify.

The solution in theory is pretty simple. Basically if the connection times out just reconnect and that's sorta what already happens most of the time it just can very often lead to an inconsistent state in the player logic even if it's successful.

JasonLG1979 commented

I could and would submit a fix upstream but:

  1. It would lead to way more "discussion" then is reasonably necessary to fix an obvious bug.
  2. It would never get accepted into the 0.4x branch because they have basically abandoned the current stable version.

I could fix it in my fork but it would just mean more divergence from upstream which is not and never was my goal, and it would mean that I would have to port it over once 0.5 is released.

It looks to me as though development on the 0.5 branch has basically stalled? Who knows when it will be released as a stable version?

JasonLG1979 commented

@vguttmann the best I can do ATM without a substantial rewrite is make it so the version of librespot built for Raspotify exits when the player is in an inconsistent state.