Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sound output stops after working fine for a couple of songs #894

Closed
frank474 opened this issue Nov 28, 2021 · 13 comments
Closed

Sound output stops after working fine for a couple of songs #894

frank474 opened this issue Nov 28, 2021 · 13 comments

Comments

@frank474
Copy link

Hi,

at the beginning everything works fine for about 5-9 minutes. Then all of a sudden the sound gets interrupted. The Spotify app keeps connected and continues playing. On the rasperry there is no failure message in the verbose output. But instead continuously the following is being output:

Nov 28 16:19:09 raspberrypi librespot[1174]: [2021-11-28T15:19:09Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 16:19:09 raspberrypi librespot[1174]: [2021-11-28T15:19:09Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay

And this goes on forever. After a reboot sound works again but stops after a while like before. Does anybody have an idea how to solve this ? Thanxs in advance.

Frank

++++++++++++++++++++
Raspberry Pi 3 Model B Rev 1.2
Raspbian GNU/Linux 11 (bullseye)
librespot 0.3.1 bbd575e (Built on 2021-11-26, Build ID: a6e0Ery3, Profile: release)

/usr/bin/librespot --name Raspotify (raspberrypi) --device-type speaker --backend alsa --bitrate 160 --disable-audio-cache --enable-volume-normalisation --volume-ctrl linear --initial-volume 100 --verbose

Output device:
Karte 1: vc4hdmi [vc4-hdmi], Gerät 0: MAI PCM i2s-hifi-0 [MAI PCM i2s-hifi-0] Sub-Geräte: 0/1 Sub-Gerät #0: subdevice #0

@roderickvd
Copy link
Member

Please post the full verbose logs from start to finish.

When this "hang" occurs, what is happening with the CPU and RAM usage?
If you control playback (e.g. pause, select other/next track, etc.) what do you see in the logs?

@frank474
Copy link
Author

here is the log. At 17:46:40 the sound is off. Then I press next and stop and then the connection is lost. CPU usage is about 10% going up to 20% when fetching data. RAM is about 1%.

Nov 28 17:37:09 raspberrypi librespot[851]: [2021-11-28T16:37:09Z DEBUG librespot_discovery::server] POST "/" {}
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_core::session] Connecting to AP "gew1-accesspoint-c-lzsz.ap.spotify.com:4070"
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_core::session] Authenticated as "cq7zbehe72iwlqkydm402orib" !
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_core::session] new Session[0]
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Linear
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Type: Auto
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Pregain: 0.0 dB
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Threshold: -2.0 dBFS
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Method: Dynamic
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Attack: 5ms
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Release: 100ms
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] Normalisation Knee: 1.0
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_connect::spirc] new Spirc[0]
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_connect::spirc] canonical_username: cq7zbehe72iwlqkydm402orib
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_core::mercury] new MercuryManager
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] new Player[0]
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_playback::convert] Converting with ditherer: tpdf
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] command=AddEventSender
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_playback::player] command=VolumeSet(65535)
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_core::session] Session[0] strong=3 weak=2
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z INFO librespot_core::session] Country: "DE"
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/cq7zbehe72iwlqkydm402orib/ count=0
Nov 28 17:37:10 raspberrypi librespot[851]: [2021-11-28T16:37:10Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Galaxy S8" 3b42cdf22b5020cff23862de1eb670b188960a64 1734891746 1638117430760 kPlayStatusPlay
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_connect::spirc] kMessageTypeLoad "Galaxy S8" 3b42cdf22b5020cff23862de1eb670b188960a64 1734892397 1638117430760 kPlayStatusPlay
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:user:spotify:playlist:37i9dQZF1DZ06evO26voPu" index: 0 posit.............
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_connect::spirc] Frame has 50 tracks
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 172310612540386428389092238834088520055, audio_type: Track }, true, 37354)
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z INFO librespot_playback::player] Loading <The Cinema Show - Remastered 2008> with Spotify URI spotify:track:3WBXyS9Isg4aQBPCuX2GwL
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_audio::fetch] Downloading file 5d46cd4e9165d3b9e3d6bdced42d907f5ee7275d
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_core::channel] new ChannelManager
Nov 28 17:37:11 raspberrypi librespot[851]: [2021-11-28T16:37:11Z DEBUG librespot_core::audio_key] new AudioKeyManager
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Galaxy S8" 3b42cdf22b5020cff23862de1eb670b188960a64 1734893016 1638117432030 kPlayStatusStop
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z INFO librespot_playback::player] <The Cinema Show - Remastered 2008> (641320 ms) loaded
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -7.2300034, track_peak: 1.1413236, album_gain_db: -6.239998, album_peak: 1.1413236 }
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 43.50%
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_playback::player] == Starting sink ==
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_playback::audio_backend::alsa] Frames per Buffer: 22050
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_playback::audio_backend::alsa] Frames per Period: 4410
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 17640
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity: 17640
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:37:12 raspberrypi librespot[851]: [2021-11-28T16:37:12Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Nov 28 17:37:38 raspberrypi librespot[851]: [2021-11-28T16:37:38Z DEBUG librespot_audio::fetch] File 5d46cd4e9165d3b9e3d6bdced42d907f5ee7275d complete, saving to cache
Nov 28 17:39:10 raspberrypi librespot[851]: [2021-11-28T16:39:10Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
Nov 28 17:41:10 raspberrypi librespot[851]: [2021-11-28T16:41:10Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
Nov 28 17:43:10 raspberrypi librespot[851]: [2021-11-28T16:43:10Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
Nov 28 17:45:10 raspberrypi librespot[851]: [2021-11-28T16:45:10Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
Nov 28 17:46:40 raspberrypi librespot[851]: [2021-11-28T16:46:40Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:46:40 raspberrypi librespot[851]: [2021-11-28T16:46:40Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Nov 28 17:46:44 raspberrypi librespot[851]: [2021-11-28T16:46:44Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:46:44 raspberrypi librespot[851]: [2021-11-28T16:46:44Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Nov 28 17:46:48 raspberrypi librespot[851]: [2021-11-28T16:46:48Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:46:48 raspberrypi librespot[851]: [2021-11-28T16:46:48Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Nov 28 17:46:49 raspberrypi librespot[851]: [2021-11-28T16:46:49Z DEBUG librespot_connect::spirc] kMessageTypeNext "Galaxy S8" 3b42cdf22b5020cff23862de1eb670b188960a64 1735470269 1638118008125 kPlayStatusStop
Nov 28 17:46:49 raspberrypi librespot[851]: [2021-11-28T16:46:49Z DEBUG librespot_connect::spirc] At track 2 of 50 <"spotify:user:spotify:playlist:37i9dQZF1DZ06evO26voPu"> update [false]
Nov 28 17:46:49 raspberrypi librespot[851]: [2021-11-28T16:46:49Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:46:49 raspberrypi librespot[851]: [2021-11-28T16:46:49Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 157260908135966632960678697024285907059, audio_type: Track }, true, 0)
Nov 28 17:46:49 raspberrypi librespot[851]: [2021-11-28T16:46:49Z TRACE librespot_playback::player] == Stopping sink ==
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:3Bfm9m97HUCH9dXjME7NBN
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z DEBUG librespot_audio::fetch] Downloading file 6e4bcbd539a715c642d9577d542bac76a8b5484a
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z INFO librespot_playback::player] (132520 ms) loaded
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -7.1500015, track_peak: 1.0329142, album_gain_db: -8.260002, album_peak: 1.1733925 }
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 43.90%
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z TRACE librespot_playback::player] == Starting sink ==
Nov 28 17:46:50 raspberrypi librespot[851]: [2021-11-28T16:46:50Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'ENODEV: No such device'
Nov 28 17:46:50 raspberrypi kernel: [ 631.643209] hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: error at snd_soc_dai_startup on i2s-hifi: -19
Nov 28 17:46:50 raspberrypi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Nov 28 17:46:50 raspberrypi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Nov 28 17:46:50 raspberrypi systemd[1]: raspotify.service: Consumed 1min 4.690s CPU time.
Nov 28 17:47:00 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 2.
Nov 28 17:47:00 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Nov 28 17:47:00 raspberrypi systemd[1]: raspotify.service: Consumed 1min 4.690s CPU time.
Nov 28 17:47:00 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Nov 28 17:47:00 raspberrypi librespot[1204]: [2021-11-28T16:47:00Z INFO librespot] librespot 0.3.1 bbd575e (Built on 2021-11-26, Build ID: a6e0Ery3, Profile: release)
Nov 28 17:47:00 raspberrypi librespot[1204]: [2021-11-28T16:47:00Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:44573

@roderickvd
Copy link
Member

@JasonLG1979 only thing that comes to mind is hanging due to buffers not being filled or flushed, what do you think?

@frank474
Copy link
Author

Fetching and downloading/preloading works fine and the song starts. This sequence is ending with

librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
librespot_connect::spirc] ==> kPlayStatusPlay

The problem then occurs in the middle of playing the second, third track e.g. 1 min of 4:11. Then the above sequence is constantly repeated. Maybe somebody knows why the "Sending status to server" command could be triggered again thus then causing the connection to fail.

@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Nov 29, 2021

@JasonLG1979 only thing that comes to mind is hanging due to buffers not being filled or flushed, what do you think?

I'm not sure for the reason for the multiple kPlayStatusPlay's? That's not my area of expertise But as far as the audio is concerned everything looks fine except:

Audio Sink Error Connection Refused: Device default May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'ENODEV: No such device'

After that is log entry that's not from librespot but still interesting:

hdmi-audio-codec hdmi-audio-codec.1.auto: ASoC: error at snd_soc_dai_startup on i2s-hifi: -19

error at snd_soc_dai_startup is an upstream issue with Raspberry Pi audio over HDMI:

See this:

raspberrypi/linux#4575

And all the results if you Google error at snd_soc_dai_startup:

https://www.google.com/search?q=error+at+snd_soc_dai_startup

@JasonLG1979
Copy link
Contributor

In short I'd say you have possibly slightly less than ideal network/connection quality and you're suffering from an upstream driver bug.

@roderickvd
Copy link
Member

Even if librespot was sending illegal messages from spirc (the "Connect thing") to the player, the player should be immune to that. It would log when it received illegal messages in its current state.

@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Nov 29, 2021

Even if librespot was sending illegal messages from spirc (the "Connect thing") to the player, the player should be immune to that. It would log when it received illegal messages in its current state.

That is out of my wheel house. All I know is that this is really 2 (possibly unrelated?) issues:

  1. The spirc issue.

  2. The audio issue.

The audio issue is not a problem with librespot but is in fact an upstream issue.

@JasonLG1979
Copy link
Contributor

The upstream audio issue may be triggering the multiple kPlayStatusPlay messages I don't know?

@roderickvd
Copy link
Member

@JasonLG1979 hinted a couple times at it, but you haven't gone into it: what is the speed and quality of your network connection?

With reference to spirc it may be that messages are sent to early by the preloader but I've never seen this happen before. Also please don't jump to conclusions because this is a very early suspicion that would need more debugging to find out whether it's actually so.

I can't reproduce it, only you, so if you want to find out please sprinkle trace!("TRIGGERED AT LINE X"); and trace!("TRIGGERED AT LINE Y"); everywhere you see a set_status(PlayStatus::kPlayStatusPlay);, right before it and recompile.

@frank474
Copy link
Author

frank474 commented Dec 2, 2021

I have done a new installation. But this time the headless minimum image. Now I'm missing the second sound output (hdmi) completely. raspi-config shows only interface 0 (headphones).

Dec 2 16:52:47 raspberrypi librespot[626]: ALSA lib confmisc.c:1281:(snd_func_refer) Unable to find definition 'cards.vc4-hdmi.pcm.hdmi.1:CARD=1,AES0=4,AES1=130,AES2=0,AES3=2'

pi@raspberrypi:~ $ 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

pi@raspberrypi:~ $ lsmod | grep snd
snd_soc_hdmi_codec 20480 1
snd_soc_core 225280 2 vc4,snd_soc_hdmi_codec
snd_compress 20480 1 snd_soc_core
snd_pcm_dmaengine 16384 1 snd_soc_core
snd_bcm2835 24576 0
snd_pcm 110592 5 snd_compress,snd_pcm_dmaengine,snd_soc_hdmi_codec,snd_bcm2835,snd_soc_core
snd_timer 32768 1 snd_pcm
snd 77824 6 snd_compress,snd_soc_hdmi_codec,snd_timer,snd_bcm2835,snd_soc_core,snd_pcm

@JasonLG1979
Copy link
Contributor

I have done a new installation. But this time the headless minimum image. Now I'm missing the second sound output (hdmi) completely. raspi-config shows only interface 0 (headphones).

That's way out of scope of librespot you should file a bug with Raspberry Pi OS on that. I don't use the the HDMI nor headphone out so I usually just completely disable all built-in audio anyway.

Even if you manage to get them working neither is going to sound very good. The analog out is ofc garbage and audio over HDMI in general isn't the greatest so I'm told.

I would advise picking up a DAC HAT or a USB DAC. They'll sound better and probably work better than the built-in audio as you can already tell.

The HiFiBerry DAC+ Zero (that can be had for as little as $15 if you look around) is what I use most of the time and it is rock solid and doesn't sound too bad especially considering the price.

@roderickvd
Copy link
Member

Closing this for now. Feel free to reopen if you are sure this is a librespot issue and not with your host.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants