spotify-connect-web icon indicating copy to clipboard operation
spotify-connect-web copied to clipboard

Playback stops after a few songs and spotify-connect needs to be restarted

Open arigit opened this issue 8 years ago • 28 comments

First off - thanks for this project, it's awesome.

I am using the current chroot version as of today, on a raspberry PI 2 with a HiFiBerry DAC and OSMC (similar to raspbian). I had to do a tweak in connect.py to get this to work, described here: https://support.hifiberry.com/hc/en-us/community/posts/201863051-hifiberry-digi-spotify-connect

The problem is that this works fantastic for a few minutes of playback. After anywhere from 5 to 20 minutes, playback suddenly stops and the raspberry is no longer seen by the spotify clients (android, IOS etc), spotify-connect-web needs to be killed and restarted, it's kind of annoying.

I tried building this app locally (finally I succeeded) and 3 different versions of the library, but they all behave in the same way, same problem.

In debug mode I see similar patterns every time: .... Requesting Bytes: 3658k => 3790k +132k (used: 495k, buf: 627k, thres: 499k, rate: 320k) Requesting Bytes: 3790k => 3930k +140k (used: 487k, buf: 627k, thres: 499k, rate: 320k) WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0] ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0] ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0]

Sometimes there is no "underrun buffer" message shown. Also, I monitor the raspberry connectivity continously and there are ZERO connectivity problems. I do streaming with other apps as well, including DLNA, for hours at a time, with no issues.

Any hint?

arigit avatar Mar 06 '16 02:03 arigit

Have you tried to run it with docker? Or preferred, directly with python and without chroot? I'm using it (without digi+) on pi 2 with osmc and it works flawless.

maumi avatar Mar 06 '16 07:03 maumi

Yes this is happening with Python (without chroot), and also with the latest chroot as of yesterday. What osmc version are you using, and if you recall what git version of spotify-connect-web?

Also I am new to docker, is there a difference between docker and chroot? Thought the same code would actually run

I tried (none of this helped, it always stops working after a song or two):

  • overclocking the Pi, going back to normal clock,
  • running spotify connect as root directly with python
  • stopping OSMC (hence kodi) before launching spotify connect
  • running top to see if any process is hogging the system; load average stays in 0.23 (python consuming no more than 7% of CPU), nothing weird found

I do notice now that the "Underrun in download buffer!" is always present before the music output stops; it looks like suddenly the spotify connect library loses connectivity and cannot restablish it (not only the music stops, also the Clients stop listing in the raspberry as a spotify device, until the app is restarted).

ps. is there a way to increase the buffer or threshold? seems limited to 627k/500k - just to eliminate the possibility of long network latency interfering with the library - I don't know what else to try... I added a script to the raspberry pinging google every 1 second and I don't see any packet loss after three days, latency always within 70ms (30ms average, with very rare 70ms peaks)

arigit avatar Mar 06 '16 16:03 arigit

Have you tried to run it with builtin sound card? I always do apt-get updates so I think I'm on newest osmc version. You are running spotify-connect with -d (debug mode)?

maumi avatar Mar 06 '16 20:03 maumi

Thanks. Not yet - all my tests so far have been on hifiberry, and always using debug mode.

Continued trying things, in the last test I didn't get the underrun warning.

Requesting Bytes: 1518k => 1658k +140k (used: 404k, buf: 627k, thres: 416k, rate: 320k) ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0]

Sound stopped as usual and the raspberry disappeared from the list of available devices in the client, as usual as well.

Will try forcing spotify-connect to use the internal audio instead of the DAC+ and see what happens

arigit avatar Mar 06 '16 20:03 arigit

Tested with the internal audio card (bcm2835) - exact same problem. This may not be related to hifiberry at all. am running out of ideas :(

arigit avatar Mar 06 '16 21:03 arigit

If you have a second sd card, maybe try for testing a fresh installed osmc where you only run spotify connect. I also have no real idea whats happening on your machine. Otherwise try to pull again spotify connect on an extra folder and try it fresh. There are also newer spotify libs, look in one of the issues. You also need to change then one header file. Or you can also try my fork of spotify connect. There are only slightly changes to this repo.

maumi avatar Mar 06 '16 21:03 maumi

Will try your fork in a new folder. Which library is working for you, is it the one here:

https://github.com/maumi/spotify-connect-web/tree/master/usr/lib ?

if otherwise can you post a link? also in your use case, do you use the library inside chroot or directly on python / outside?

Also - do you see anything abnormal in this config.txt:

gpu_mem_1024=256
dtoverlay=hifiberry-dacplus-overlay
dtparam=audio=off disable_splash=1 start_x=1
sdtv_aspect=1
disable_overscan=1 hdmi_ignore_cec_init=1
hdmi_force_hotplug=1 hdmi_edid_file=1
#hdmi_edid_file=1
hdmi_group=1

mode 4 is 720p 60hz; mode 16 is 1080p 60hz

hdmi_mode=4
max_usb_current=1
gpu_mem_256=112
gpu_mem_512=144
arm_freq=1000
core_freq=500
over_voltage=2
sdram_freq=500

arigit avatar Mar 06 '16 23:03 arigit

I use the library from #25 but it should be the same like in my repo. I put it in /usr/lib and call directly Python main.py ...

maumi avatar Mar 07 '16 07:03 maumi

I have exactly the same problem. After a few songs I need to restart the service (by using daemontools). The daemontools service is still running when the problem appears. Soon I 'll look at the debug messages.

arjen8 avatar Mar 08 '16 06:03 arjen8

are you both using osmc? running jarvis (16.0)?

maumi avatar Mar 08 '16 07:03 maumi

No, I'm using a fresh install of jessie lite (with a Hifiberry Digi+). At this moment, only Spotify Connect runs on this system (see issue #37).

arjen8 avatar Mar 08 '16 08:03 arjen8

my main system is not my pi. But I updated osmc on my pi 2 to jarvis and listen now on an external usb sound card till 20 minutes to music. no stop and still visible. will extend to 60 minutes, but I won't think it will stop.

maumi avatar Mar 08 '16 09:03 maumi

The first couple of times I played some playlists in Spotify for about a couple of hours, there were no problems at all. But since last weekend I had several connection problems like mentioned in this thread. The music stops abrupt and the service is no longer available in the network (by using the Android app Fing I still see the pi2 in the network, and pinging the pi still works). Soon I'll check if a wired connection from my router to the pi solves the problem.Now, the pi is connected over wifi.

At this moment, I'm monitoring the debug output while playing music. So hopefully I can show you what's going wrong (till now I listen to music :) ).

Edit: Oh and besides that. When the service is no longer available in the network, I can't stop the daemon by using the command svc -d spotify-connect-web. Svstat shows a message ".... wants down". When the service is up and running I can shutdown the service without any problems. Perhaps, this has something to do with the issue.

Now I'm monitoring the debug output by executing the command "python main.py ... &", without using Daemontools.

arjen8 avatar Mar 08 '16 09:03 arjen8

I think we need from both of you more logs. Would also be easier if you add timestamps to logs. @arigit what do you get when there is no underrun message? No error message? Only stop of Requesting bytes and only pump events from time to time?

maumi avatar Mar 08 '16 09:03 maumi

How can I add timestamps to the debug output by using python main.py command? When the problem occurs, I'll create a text file of the debug output for you.

arjen8 avatar Mar 08 '16 09:03 arjen8

not that easy because of submodules. if you use multilog it should be possible only by add t (for timestamp)

maumi avatar Mar 08 '16 09:03 maumi

@arigit what do you get when there is no underrun message? No error message? Only stop of Requesting bytes and only pump events from time to time?

yes exactly. I tail logs & monitor connectivity continuously and nothing shows up there. It just stops requesting bytes and the Rpi disappears from the list of the spotify clients, I tried restarting the clients, using different clients (android, linux, IOS), no difference.

Noting that like Radem I am using WiFi and this is the first thing I suspected. However I am not losing a single packet, as I said I am monitoring connectivity (with active pings, logging output), monitoring logs, and I have multiple ssh sessions live at the time the issue happens, none of which are affected.

I am going to test starting from scratch on a new SD card, using the latest OSMC, this week. Currently my main SD card has OSMC that started with last december's release and has been continuously updated. Hardware:

  • RPi2b
  • hifi berry DAC+ (tried switching to on-board audio and blacklisting the hifiberry module at boot time, no improvement)
  • EW-7811UTC on 5Ghz.

arigit avatar Mar 08 '16 15:03 arigit

New / fresh SDCard, latest OSMC, same problem :(

Radem205 - wondering, what wifi adapter /driver do you use? could this be a wifi router issue? (TomatoUSB/Shibby)

Requesting Bytes: 896k => 992k +96k (used: 64k, buf: 160k, thres: 64k, rate: 320k) Requesting Bytes: 992k => 1108k +116k (used: 76k, buf: 192k, thres: 80k, rate: 320k) Requesting Bytes: 1108k => 1248k +140k (used: 84k, buf: 224k, thres: 96k, rate: 320k) Requesting Bytes: 1248k => 1376k +128k (used: 112k, buf: 256k, thres: 112k, rate: 320k) Requesting Bytes: 1376k => 1504k +128k (used: 128k, buf: 288k, thres: 128k, rate: 320k) Requesting Bytes: 1504k => 1632k +128k (used: 144k, buf: 320k, thres: 144k, rate: 320k) Requesting Bytes: 1632k => 1763k +131k (used: 156k, buf: 352k, thres: 160k, rate: 320k) Requesting Bytes: 1763k => 1903k +140k (used: 164k, buf: 384k, thres: 176k, rate: 320k) Requesting Bytes: 1903k => 2031k +128k (used: 192k, buf: 416k, thres: 192k, rate: 320k) Requesting Bytes: 2031k => 2159k +128k (used: 208k, buf: 448k, thres: 208k, rate: 320k) Requesting Bytes: 2159k => 2295k +136k (used: 216k, buf: 480k, thres: 224k, rate: 320k) Requesting Bytes: 2295k => 2438k +143k (used: 224k, buf: 512k, thres: 240k, rate: 320k) Requesting Bytes: 2438k => 2566k +128k (used: 256k, buf: 544k, thres: 256k, rate: 320k) WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! WARNING: Underrun in download buffer! ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0] ESDK: SpPumpEvents() ESDK: SpPumpEvents [returned value: 0]

arigit avatar Mar 09 '16 06:03 arigit

Why not put a ethernet wire on it? For testing. On a fresh install connection issues semms to me the only left reason.

maumi avatar Mar 09 '16 06:03 maumi

I got this usb stick: https://www.sossolutions.nl/300-mbps (RTL8191SU chipset).

Yesterday, I run the Spotify Connect service using the "python main.py ... &" command (instead of using Daemontools). Since then I have no issues anymore. But this is not a garantuee that it won't happen again. In the next days I'll connect by a wire, to see if it makes any difference.

arjen8 avatar Mar 09 '16 07:03 arjen8

Do you mean the armhf spotify_embedded libraries in his github project site, or some librespot build? I tried the libraries but couldn't find actual builds.

Tried portforwarding rules for all Spotify IP blocks in my router, no joy.

Next I will try building librespot under osmc

arigit avatar Mar 09 '16 15:03 arigit

I wonder if this is the same problem as #12, except that the error is being swallowed somewhere

Fornoth avatar Mar 09 '16 19:03 Fornoth

the debug messages don't seem to be showing ALSA issues, and playback always starts (but doesn't last for long :( ).

FWIW - tried librespot and am getting a persistent crash on client launch, could be HiFiBerry DAC+ -related; for reference: link.

arigit avatar Mar 10 '16 15:03 arigit

For anybody that runs into this issue, and as suggested by maumi some posts above, this problem has nothing to do with a) libspotify or spotify-connect-web, b) the chroot, c) hifiberry DAC+, d) OSMC/Kodi. Edimax AC600 WiFi (likely the chipset driver RTL 8812AU rather than the dongle) was indeed the problem.

First, the strange thing is that streaming HD Audio FLAC (192/24) from a NAS to OSMC/Raspberry over this dongle works perfect, zero issues when using NFS (but doesn't work well for SMB...). For some reason - spotify connect is too much for this dongle; even at 160Kbps, playback stops after a few songs and the spotify-connect has to be killed and restarted.

My solution: used Wired Ethernet in raspberry, wired to a "WiFi Range Extender" (netgear AC750, it has a wired port). I setup the extender as "Fast Lane" connecting it over 5Ghz to my router, and then I disabled the 2.4 radio. Meaning that it acts as a "Ethernet to WiFi converter" for the raspberry. As can be expected, performance is a LOT better than any dongle, and no need to use 3rd party half-working wireless drivers.

Zero problems - spotify connect works without an issue for days on end - using the CHROOT version.

For the HiFiBerry DAC+, I had to change connect.py:

from:

mixer_volume = int(mixer.getvolume()[0] * 655.35)

to:

mixer_volume = 65535 # int(mixer.getvolume()[0] * 655.35)

(people with HiFiBerry DIGI+ recommended setting "1", but that messed up volume in the DAC+).

arigit avatar Mar 19 '16 22:03 arigit

For the HiFiBerry DAC+, I had to change connect.py: ... to: mixer_volume = 65535 # int(mixer.getvolume()[0] * 655.35)

Thanks worked for me to start but nothing came out of my hifiberry dac+. I got this error: ALSA lib confmisc.c:768:(parse_card) cannot find card 'default' ALSA lib conf.c:4259:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings

tatoosh avatar Oct 01 '16 14:10 tatoosh

Awesome project indeed! I have the same issue unfortunately, my hardware/software is a bit different:

  • RPi3
  • IQ Audio DigiAmp+
  • Linux raspberrypi 4.4.26-v7+ #915 SMP Thu Oct 20 17:08:44 BST 2016 armv7l GNU/Linux (fresh install, based on jessie image from IQaudio: [http://www.iqaudio.com/downloads/IQ_1_jessie_iqaudio.img.zip]. Updated/upgraded to latest (apt-get update/dist-upgrade).

RPi is connected by cable, connection is ok. Music plays well, volume control is working, but the spotify-connect-web seems to crahs after some time. Why I have not been able to catch yet, is there a way see debug messages in some log file? The process also crashes when not playing music. The time before crashing varies, from 20 minutes to in some cases several hours of playing music.

This is how I start (non chrooted, latest 0.0.3 release) as user pi:

./spotify-connect-web --username XXXX --password XXXXX --bitrate 320 --device IQaudIODAC --name RPi3 -m Digital -d
Loading Spotify library...
min_volume_range: 0.0
Using libspotify_embedded version: release-esdk-1.20.0-v1.20.0-g594175d4
ESDK: SpRegisterDebugCallbacks [returned value: 0]
ESDK: Minimum required memory: 172248
ESDK: Reducing compressed audio buffer by 15 KB
ESDK: Compressed audio buffer uses 823 KB
SpInit: 0
ESDK: SpRegisterConnectionCallbacks(0x1af25d8, 0x1b69930)
ESDK: SpRegisterConnectionCallbacks [returned value: 0]
ESDK: SpRegisterPlaybackCallbacks(0x1a35718, 0x1b69930)
ESDK: SpRegisterPlaybackCallbacks [returned value: 0]
ESDK: SpPlaybackUpdateVolume(42597)
ESDK: callback context (nil), event 6, source: (nil), param (nil)

..... some output when playing

Requesting Bytes: 7769k => 7901k +132k (used: 556k, buf: 823k, thres: 560k, rate: 320k)
Requesting Bytes: 7901k => 8029k +128k (used: 576k, buf: 823k, thres: 576k, rate: 320k)
Requesting Bytes: 8029k => 8157k +128k (used: 592k, buf: 823k, thres: 592k, rate: 320k)
Requesting Bytes: 8157k => 8289k +132k (used: 604k, buf: 823k, thres: 608k, rate: 320k)
Requesting Bytes: 8289k => 8417k +128k (used: 624k, buf: 823k, thres: 624k, rate: 320k)
Requesting Bytes: 8417k => 8557k +139k (used: 628k, buf: 823k, thres: 640k, rate: 320k)
Requesting Bytes: 8557k => 8685k +128k (used: 656k, buf: 823k, thres: 656k, rate: 320k)
Requesting Bytes: 8685k => 8821k +136k (used: 664k, buf: 823k, thres: 672k, rate: 320k)
ESDK: SpPumpEvents()
ESDK: SpPumpEvents [returned value: 0]
Requesting Bytes: 8821k => 8953k +132k (used: 684k, buf: 823k, thres: 688k, rate: 320k)
Requesting Bytes: 8953k => 9088k +135k (used: 688k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9088k => 9220k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9220k => 9360k +140k (used: 683k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9360k => 9492k +131k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9492k => 9620k +128k (used: 695k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9620k => 9752k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 9752k => 9888k +136k (used: 687k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 12592k => 12724k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 12724k => 12856k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 12856k => 12992k +136k (used: 687k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 12992k => 13124k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 13124k => 13259k +135k (used: 687k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 13259k => 13395k +136k (used: 687k, buf: 823k, thres: 695k, rate: 320k)
Requesting Bytes: 13395k => 13523k +128k (used: 695k, buf: 823k, thres: 695k, rate: 320k)
Got Spirc Type 26
Track transition beginning on track index 3
ESDK: callback context (nil), event 29, source: (nil), param (nil)
ESDK: Notifying kSpPlaybackNotifyNext
kSpPlaybackNotifyNext
ESDK: callback context (nil), event 1000, source: (nil), param 0x76272e6c
ESDK: callback context (nil), event 7, source: (nil), param (nil)
ESDK: Notifying kSpPlaybackNotifyTrackChanged
kSpPlaybackNotifyTrackChanged
Requesting key...
Requesting Bytes: 0k => 128k +128k (used: 0k, buf: 128k, thres: 48k, rate: 320k)
ESDK: callback context (nil), event 1001, source: (nil), param 0x76195670
WARNING: Underrun in download buffer!
ESDK: Notifying kSpPlaybackEventAudioFlush
kSpPlaybackEventAudioFlush

I think that underrun is the problem, but how to prevent this? Any new ideas what might be the problem or how I can determine what the problem is?

niekosss avatar Nov 13 '16 08:11 niekosss

Finally captured something in logs, not sure if it is meaningful:

Requesting Bytes: 6585k => 6716k +131k (used: 691k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 6716k => 6844k +128k (used: 695k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 6844k => 6976k +132k (used: 691k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 6976k => 7104k +128k (used: 695k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 7104k => 7240k +136k (used: 687k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 7240k => 7376k +136k (used: 687k, buf: 823k, thres: 695k, rate: 320k) Requesting Bytes: 7376k => 7512k +135k (used: 687k, buf: 823k, thres: 695k, rate: 320k) Track transition beginning on track index 3 ESDK: callback context (nil), event 1000, source: (nil), para

This was the last entry before the process crashed. @Fornoth do you have any idea what this could be/mean?

niekosss avatar Nov 26 '16 12:11 niekosss

Hello, I had a similar issue, first with mpd then with audacious, I have pinpointed the problem by running audacious from terminal which showed the following error: "ALSA lib pcm.c:7843:(snd_pcm_recover) underrun" after a while playing music, so I googled a bit a found a tutorial here for fixing this issue: http://thehumble.ninja/2014/02/06/fixing-alsa-lib-pcmc7843snd_pcm_recover-underrun-occurred-while-keeping-pulseaudio-in-your-system/

That's about it, and I think this might be related to the problem discussed here. Good luck!

uhtel avatar Feb 01 '18 17:02 uhtel