Raspotify restart right after I connect

Question

Raspotify restart right after I connect

shumafuk opened this issue 4 months ago · 6 comments

shumafuk commented 4 months ago

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 Pi v1 or Pi Zero

Due Diligence

I have done my due diligence

What happened?

Raspotify suddenly stop playing anything. It disconnect right after I connect with any client at network, restart and after while I can connect again but again it disconnect, restart... so on. Any help from logs are appreciated. Thanks.

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 )

my@rpi:~ $ sudo journalctl -u raspotify -b
-- Journal begins at Wed 2023-05-03 05:11:24 CEST, ends at Fri 2024-02-23 10:03:36 CET. --
Feb 22 09:17:07 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 22 09:17:18 rpi librespot[479]: [2024-02-22T08:17:18Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 22 09:17:18 rpi librespot[479]: [2024-02-22T08:17:18Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 22 09:17:18 rpi librespot[479]: [2024-02-22T08:17:18Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 22 09:17:18 rpi librespot[479]: [2024-02-22T08:17:18Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Feb 23 09:01:19 rpi librespot[479]: [2024-02-23T08:01:19Z WARN  librespot_connect::spirc] No autoplay_uri found
Feb 23 09:01:19 rpi librespot[479]: [2024-02-23T08:01:19Z ERROR librespot_connect::spirc] AutoplayError: MercuryError
Feb 23 09:01:20 rpi librespot[479]: [2024-02-23T08:01:20Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_ope>
Feb 23 09:01:20 rpi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 23 09:01:20 rpi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 23 09:01:20 rpi systemd[1]: raspotify.service: Triggering OnFailure= dependencies.
Feb 23 09:01:20 rpi systemd[1]: raspotify.service: Consumed 2.356s CPU time.
Feb 23 09:01:32 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:01:33 rpi librespot[2056]: [2024-02-23T08:01:33Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:01:33 rpi librespot[2056]: [2024-02-23T08:01:33Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:01:33 rpi librespot[2056]: [2024-02-23T08:01:33Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:01:33 rpi librespot[2056]: [2024-02-23T08:01:33Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Feb 23 09:01:44 rpi librespot[2056]: [2024-02-23T08:01:44Z WARN  librespot_connect::spirc] No autoplay_uri found
Feb 23 09:01:44 rpi librespot[2056]: [2024-02-23T08:01:44Z ERROR librespot_connect::spirc] AutoplayError: MercuryError
Feb 23 09:01:45 rpi librespot[2056]: [2024-02-23T08:01:45Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_op>
Feb 23 09:01:45 rpi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 23 09:01:45 rpi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 23 09:01:45 rpi systemd[1]: raspotify.service: Triggering OnFailure= dependencies.
Feb 23 09:01:56 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:01:57 rpi librespot[2504]: [2024-02-23T08:01:57Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:01:57 rpi librespot[2504]: [2024-02-23T08:01:57Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:01:57 rpi librespot[2504]: [2024-02-23T08:01:57Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:42:13 rpi librespot[2504]: [2024-02-23T08:42:13Z WARN  librespot_connect::spirc] No autoplay_uri found
Feb 23 09:42:13 rpi librespot[2504]: [2024-02-23T08:42:13Z ERROR librespot_connect::spirc] AutoplayError: MercuryError
Feb 23 09:42:16 rpi librespot[2504]: [2024-02-23T08:42:16Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_op>
Feb 23 09:42:16 rpi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 23 09:42:16 rpi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 23 09:42:16 rpi systemd[1]: raspotify.service: Triggering OnFailure= dependencies.
Feb 23 09:42:28 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:42:29 rpi librespot[5622]: [2024-02-23T08:42:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:42:29 rpi librespot[5622]: [2024-02-23T08:42:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:42:29 rpi librespot[5622]: [2024-02-23T08:42:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:42:29 rpi librespot[5622]: [2024-02-23T08:42:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Feb 23 09:46:30 rpi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Feb 23 09:46:30 rpi systemd[1]: raspotify.service: Succeeded.
Feb 23 09:46:30 rpi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Feb 23 09:46:30 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:46:31 rpi librespot[5644]: [2024-02-23T08:46:31Z WARN  librespot] Without the `--enable-volume-normalisation` / `-N` flag normalisation options have no effect.
Feb 23 09:46:31 rpi librespot[5644]: [2024-02-23T08:46:31Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:46:31 rpi librespot[5644]: [2024-02-23T08:46:31Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:46:31 rpi librespot[5644]: [2024-02-23T08:46:31Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:46:31 rpi librespot[5644]: [2024-02-23T08:46:31Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Feb 23 09:52:40 rpi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Feb 23 09:52:40 rpi systemd[1]: raspotify.service: Succeeded.
Feb 23 09:52:40 rpi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Feb 23 09:52:40 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:52:40 rpi librespot[5670]: [2024-02-23T08:52:40Z WARN  librespot] Without the `--enable-volume-normalisation` / `-N` flag normalisation options have no effect.
Feb 23 09:52:40 rpi librespot[5670]: [2024-02-23T08:52:40Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:52:40 rpi librespot[5670]: [2024-02-23T08:52:40Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:52:40 rpi librespot[5670]: [2024-02-23T08:52:40Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:52:40 rpi librespot[5670]: [2024-02-23T08:52:40Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Feb 23 09:53:34 rpi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Feb 23 09:53:34 rpi systemd[1]: raspotify.service: Succeeded.
Feb 23 09:53:34 rpi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Feb 23 09:53:34 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
Feb 23 09:53:34 rpi librespot[5688]: [2024-02-23T08:53:34Z WARN  librespot] Without the `--enable-volume-normalisation` / `-N` flag normalisation options have no effect.
Feb 23 09:53:34 rpi librespot[5688]: [2024-02-23T08:53:34Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Feb 23 09:53:34 rpi librespot[5688]: [2024-02-23T08:53:34Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Feb 23 09:53:34 rpi librespot[5688]: [2024-02-23T08:53:34Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Feb 23 09:53:34 rpi librespot[5688]: [2024-02-23T08:53:34Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443

my@rpi:~ $ sudo cat /etc/raspotify/crash_report
-- System Info --

Linux rpi 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64 GNU/Linux
PRETTY_NAME="Debian GNU/Linux 11 (bullseye)"
NAME="Debian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

-- Logs --

Feb 23 10:04:07 rpi librespot[5688]: [2024-02-23T09:04:07Z WARN  librespot_connect::spirc] No autoplay_uri found
Feb 23 10:04:07 rpi librespot[5688]: [2024-02-23T09:04:07Z ERROR librespot_connect::spirc] AutoplayError: MercuryError
Feb 23 10:04:09 rpi librespot[5688]: [2024-02-23T09:04:09Z 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 'UnknownErrno: Unknown errno'
Feb 23 10:04:09 rpi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Feb 23 10:04:09 rpi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Feb 23 10:04:09 rpi systemd[1]: raspotify.service: Triggering OnFailure= dependencies.

-- Config --

LIBRESPOT_QUIET=
LIBRESPOT_AUTOPLAY=
LIBRESPOT_DISABLE_AUDIO_CACHE=
LIBRESPOT_DISABLE_CREDENTIAL_CACHE=
LIBRESPOT_NAME="RPi"
LIBRESPOT_BITRATE="320"
LIBRESPOT_FORMAT="S32"
LIBRESPOT_SAMPLE_RATE="48kHz"
LIBRESPOT_INTERPOLATION_QUALITY="High"
LIBRESPOT_USERNAME=XXXXXXXX
LIBRESPOT_PASSWORD=XXXXXXXX
LIBRESPOT_INITIAL_VOLUME="100"
LIBRESPOT_VOLUME_CTRL="log"
LIBRESPOT_NORMALISATION_PREGAIN="-3.0"
LIBRESPOT_NORMALISATION_THRESHOLD="-2.0"

-- Ouput of aplay -l --

**** List of PLAYBACK Hardware Devices ****
card 0: Headphones [bcm2835 Headphones], device 0: bcm2835 Headphones [bcm2835 Headphones]
  Subdevices: 8/8
  Subdevice #0: subdevice #0
  Subdevice #1: subdevice #1
  Subdevice #2: subdevice #2
  Subdevice #3: subdevice #3
  Subdevice #4: subdevice #4
  Subdevice #5: subdevice #5
  Subdevice #6: subdevice #6
  Subdevice #7: subdevice #7
card 1: vc4hdmi [vc4-hdmi], device 0: MAI PCM i2s-hifi-0 [MAI PCM i2s-hifi-0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: UR22mkII [Steinberg UR22mkII], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

-- Ouput of aplay -L --

null
    Discard all samples (playback) or generate zero samples (capture)
default
hw:CARD=Headphones,DEV=0
    bcm2835 Headphones, bcm2835 Headphones
    Direct hardware device without any conversions
plughw:CARD=Headphones,DEV=0
    bcm2835 Headphones, bcm2835 Headphones
    Hardware device with all software conversions
sysdefault:CARD=Headphones
    bcm2835 Headphones, bcm2835 Headphones
    Default Audio Device
dmix:CARD=Headphones,DEV=0
    bcm2835 Headphones, bcm2835 Headphones
    Direct sample mixing device
hw:CARD=vc4hdmi,DEV=0
    vc4-hdmi, MAI PCM i2s-hifi-0
    Direct hardware device without any conversions
plughw:CARD=vc4hdmi,DEV=0
    vc4-hdmi, MAI PCM i2s-hifi-0
    Hardware device with all software conversions
sysdefault:CARD=vc4hdmi
    vc4-hdmi, MAI PCM i2s-hifi-0
    Default Audio Device
hdmi:CARD=vc4hdmi,DEV=0
    vc4-hdmi, MAI PCM i2s-hifi-0
    HDMI Audio Output
dmix:CARD=vc4hdmi,DEV=0
    vc4-hdmi, MAI PCM i2s-hifi-0
    Direct sample mixing device
hw:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    Direct hardware device without any conversions
plughw:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    Hardware device with all software conversions
sysdefault:CARD=UR22mkII
    Steinberg UR22mkII, USB Audio
    Default Audio Device
front:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    Front output / input
surround21:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    2.1 Surround output to Front and Subwoofer speakers
surround40:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    4.0 Surround output to Front and Rear speakers
surround41:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    4.1 Surround output to Front, Rear and Subwoofer speakers
surround50:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    5.0 Surround output to Front, Center and Rear speakers
surround51:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    5.1 Surround output to Front, Center, Rear and Subwoofer speakers
surround71:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
iec958:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    IEC958 (S/PDIF) Digital Audio Output
dmix:CARD=UR22mkII,DEV=0
    Steinberg UR22mkII, USB Audio
    Direct sample mixing device

-- Ouput of librespot -d ? --


        Compatible alsa device(s):

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

        Device:

                hw:CARD=Headphones,DEV=0

        Description:

                bcm2835 Headphones, bcm2835 Headphones
                Direct hardware device without any conversions

        Supported Format & Sample Rate Combinations:

                Format: S16   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz

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

        Device:

                plughw:CARD=Headphones,DEV=0

        Description:

                bcm2835 Headphones, bcm2835 Headphones
                Hardware device with all software conversions

        Supported Format & Sample Rate Combinations:

                Format: S16   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S24   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S24_3 Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: F32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: F64   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz

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

        Device:

                sysdefault:CARD=Headphones

        Description:

                bcm2835 Headphones, bcm2835 Headphones
                Default Audio Device

        Supported Format & Sample Rate Combinations:

                Format: S16   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S24   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S24_3 Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: S32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: F32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
                Format: F64   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz

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

        Device:

                dmix:CARD=Headphones,DEV=0

        Description:

                bcm2835 Headphones, bcm2835 Headphones
                Direct sample mixing device

        Supported Format & Sample Rate Combinations:

                Format: S16   Sample Rate(s): 48kHz

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

        Device:

                iec958:CARD=UR22mkII,DEV=0

        Description:

                Steinberg UR22mkII, USB Audio
                IEC958 (S/PDIF) Digital Audio Output

        Supported Format & Sample Rate Combinations:

                Format: S32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz

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

        Device:

                dmix:CARD=UR22mkII,DEV=0

        Description:

                Steinberg UR22mkII, USB Audio
                Direct sample mixing device

        Supported Format & Sample Rate Combinations:

                Format: S32   Sample Rate(s): 48kHz

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

Answer 1 · 2024-02-26T08:55:20.000Z

Somehow its working now, not sure why. Problem solved.

Answer 2 · 2024-03-03T10:46:49.000Z

I have exactly the same problem.

I had this problem in the past with another client. The problem with that one was that an image output had to be connected. Unfortunately, it didn't work with raspotify to simply connect a monitor via HDMI

Answer 3 · 2024-05-01T20:04:47.000Z

I also had the ERROR

Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_op>

Could fix it by defining the device (LIBRESPOT_DEVICE) name in /etc/raspotify/conf to an actual device, not default. I could list possible devices with librespot -d ?. Maybe you will also need to define the format (LIBRESPOT_FORMAT) in the same file.

So annoying, because simply running librespot in a ssh session works without defining the exact device, not when starting it with systemd though.

Answer 4 · 2024-05-04T21:26:11.000Z

I also had the ERROR

Audio Sink Error Connection Refused: <AlsaSink> Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_op>

Could fix it by defining the device (LIBRESPOT_DEVICE) name in /etc/raspotify/conf to an actual device, not default. I could list possible devices with librespot -d ?. Maybe you will also need to define the format (LIBRESPOT_FORMAT) in the same file.

So annoying, because simply running librespot in a ssh session works without defining the exact device, not when starting it with systemd though.

@leonnicolas I am also having this issue... can you explain better how you solved it?

Answer 5 · 2024-05-05T13:26:33.000Z

For example on my raspberry pi 4: I type

librespot -d ?

to find possible alsa devices. In my case the first one is called hw:CARD=Headphones,DEV=0.

I open the file /etc/raspotify/conf and uncomment the entry LIBRESPOT_DEVICE and set its value to hw:CARD=Headphones,DEV=0.

I also had to set the format to S16. Maybe for your pi this can be another format. The format can be defined in /etc/raspotify/conf as well. The entry is called LIBRESPOT_FORMAT.

I restart the systemd unit.

systemctl restart raspotify

Check the logs with

journalctl -fu raspotify

while trying to play a song. Hopefully it works.