mirror of
https://github.com/librespot-org/librespot.git
synced 2026-04-27 08:15:50 +03:00
[GH-ISSUE #894] Sound output stops after working fine for a couple of songs #442
Labels
No labels
A-Alsa
SpotifyAPI
Tokio 1.0
audio
bug
can't reproduce
compilation
dependencies
duplicate
enhancement
good first issue
help wanted
high priority
imported
imported
invalid
new api
pull-request
question
reverse engineering
wiki
wontfix
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
starred/librespot#442
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Originally created by @frank474 on GitHub (Nov 28, 2021).
Original GitHub issue: https://github.com/librespot-org/librespot/issues/894
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] ==> kPlayStatusPlayAnd 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 --verboseOutput 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 commented on GitHub (Nov 28, 2021):
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 commented on GitHub (Nov 28, 2021):
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 commented on GitHub (Nov 29, 2021):
@JasonLG1979 only thing that comes to mind is hanging due to buffers not being filled or flushed, what do you think?
@frank474 commented on GitHub (Nov 29, 2021):
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 commented on GitHub (Nov 29, 2021):
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:After that is log entry that's not from
librespotbut still interesting:error at snd_soc_dai_startupis an upstream issue with Raspberry Pi audio over HDMI:See this:
https://github.com/raspberrypi/linux/issues/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 commented on GitHub (Nov 29, 2021):
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 commented on GitHub (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.
@JasonLG1979 commented on GitHub (Nov 29, 2021):
That is out of my wheel house. All I know is that this is really 2 (possibly unrelated?) issues:
The
spircissue.The audio issue.
The audio issue is not a problem with
librespotbut is in fact an upstream issue.@JasonLG1979 commented on GitHub (Nov 29, 2021):
The upstream audio issue may be triggering the multiple
kPlayStatusPlaymessages I don't know?@roderickvd commented on GitHub (Dec 1, 2021):
@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
spircit 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");andtrace!("TRIGGERED AT LINE Y");everywhere you see aset_status(PlayStatus::kPlayStatusPlay);, right before it and recompile.@frank474 commented on GitHub (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 commented on GitHub (Dec 2, 2021):
That's way out of scope of
librespotyou 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 commented on GitHub (Dec 3, 2021):
Closing this for now. Feel free to reopen if you are sure this is a
librespotissue and not with your host.