Spotify Connect failures on Moode 4.4

[TheOldPresbyope]

It looks like we are in violent agreement here. 

Something is causing librespot to stop. We don't know what it is. The librespot issues log shows this is happening to others who aren't moOde users ("crash" is the same as "unexpectedly stops"). A possible cause of some of the stoppages has been suggested: an interruption in communications which disrupts the session with the Spotify server. The librespot developers have acknowledged there are problems with connect and reconnection. You find that on your system an invocation of librespot with credentials from the CLI solves your problem.

At this point, we need data to give to the librespot developers. Since I don't suffer these stoppages, I can't provide it. Someone who does suffer the stoppages needs to follow Tim's suggestion to capture the librespot log.

What follows are several excerpts from my log with a fresh install of moOde r4.4.

1. Enable Spotify renderer in moOde. Then start Spotify app on an Android Nexus 9 tablet. [I have replaced instances of my 25-char Spotify username with strings of "#". It must have been obtained from credentials in my Spotify app since no credentials have been entered into moOde.]

Code:

pi@moode:~ $ tail -f librespot.txt
INFO:librespot: librespot  (). Built on 2018-10-31. Build ID: No392Ult
DEBUG:librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:0
WARN:mdns::fsm: error sending packet Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" }
DEBUG:librespot_connect::discovery: Post "/" {}
INFO:librespot_core::session: Connecting to AP "guc3-accesspoint-b-rrl6.ap.spotify.com:4070"
INFO:librespot_core::session: Authenticated as "#########################" !
DEBUG:librespot_core::session: new Session[0]
DEBUG:librespot_connect::spirc: new Spirc[0]
DEBUG:librespot_core::mercury: new MercuryManager
DEBUG:librespot_playback::player: new Player[0]
INFO:librespot_playback::audio_backend::alsa: Using alsa sink
DEBUG:librespot_connect::spirc: input volume:0 to mixer: 65
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
INFO:librespot_core::session: Country: "US"
DEBUG:librespot_core::mercury: unknown subscription uri=hm://remote/3/user/#########################/a88bc7dfd2d3aa335b010e1866f5832aa4d3d761
DEBUG:librespot_core::mercury: subscribed uri=hm://remote/3/user/#########################/ count=0
DEBUG:librespot_connect::spirc: kMessageTypeLoad "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 2 1545139995762
DEBUG:librespot_playback::player: command=Load(SpotifyId(u128!(118357896696284136152162826536614594909)), false, 235428)
INFO:librespot_playback::player: Loading track "Symphony No. 1 in C, Op. 21: II. Andante cantible con moto" with Spotify URI "spotify:track:2I1iyamsrxb6sG1NEzybOR"
DEBUG:librespot_core::audio_key: new AudioKeyManager
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1099253992 1545139996185
DEBUG:librespot_audio::fetch: Downloading file 2bab1fa305b61bffea79487a9d200fb75ef2527a
TRACE:librespot_audio::fetch: requesting chunk 0
DEBUG:librespot_core::channel: new ChannelManager
TRACE:librespot_audio::fetch: chunk 0 / 77 complete
TRACE:librespot_audio::fetch: requesting chunk 1
DEBUG:librespot_playback::player: Normalisation Data: NormalisationData { track_gain_db: -2.6900024, track_peak: 0.8800364, album_gain_db: -5.169998, album_peak: 1.0334876 }
DEBUG:librespot_playback::player: Applied normalisation factor: 0.7336685
TRACE:librespot_audio::fetch: requesting chunk 76
TRACE:librespot_audio::fetch: requesting chunk 74
TRACE:librespot_audio::fetch: chunk 74 / 77 complete
<<deleted more TRACE:librespot_audio::fetch: lines>>
INFO:librespot_playback::player: Track "Symphony No. 1 in C, Op. 21: II. Andante cantible con moto" loaded
INFO:librespot::player_event_handler: Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"PLAYER_EVENT": "stop", "TRACK_ID": "590ae6d8723848438edb3d10574b895d"}
TRACE:librespot_audio::fetch: chunk 48 / 77 complete
TRACE:librespot_audio::fetch: requesting chunk 50
<<deleted many more TRACE:librespot_audio::fetch: lines>>
DEBUG:librespot_audio::fetch: File 2bab1fa305b61bffea79487a9d200fb75ef2527a complete, saving to cache
DEBUG:librespot_connect::spirc: kMessageTypePrev "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 3 1545139996185
DEBUG:librespot_playback::player: command=Seek(0)
DEBUG:librespot_connect::spirc: kMessageTypeSeek "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 4 1545140033279
DEBUG:librespot_playback::player: command=Seek(74420)
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1099307477 1545140049670
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1099313888 1545140056081
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1099313888 1545140056081
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1099313994 1545140056187
DEBUG:librespot_connect::spirc: kMessageTypeVolume "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 5 1545140056187
DEBUG:librespot_connect::spirc: input volume:1024 to mixer: 73
DEBUG:librespot_connect::spirc: kMessageTypeVolume "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 6 1545140065503
DEBUG:librespot_connect::spirc: kMessageTypePlay "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 14 1545140068929
DEBUG:librespot_playback::player: command=Play
INFO:librespot::player_event_handler: Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"TRACK_ID": "590ae6d8723848438edb3d10574b895d", "PLAYER_EVENT": "start"}
^C

What this shows early on is that my Spotify app has passed my credentials (or at least my Spotify username) to librespot and the Spotify server has authenticated me. The rest is all niff-naff associated with making a track selection, fetching it, changing volume, and starting to play the track. The log continues with these sorts of messages for as long as I have the Spotify renderer on and I'm playing tracks.

2. Turn off the Spotify app on my tablet and turn off the Spotify renderer in moOde.

3. Turn on the Spotify renderer in moOde. Since this reinvokes the librespot startup it starts the logfile afresh. Later, start the Spotify app on my tablet again. 

Code:

pi@moode:~ $ cat librespot.txt
NFO:librespot: librespot  (). Built on 2018-10-31. Build ID: No392Ult
DEBUG:librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:0
WARN:mdns::fsm: error sending packet Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" }
INFO:librespot_core::session: Connecting to AP "guc3-accesspoint-b-7frq.ap.spotify.com:4070"
INFO:librespot_core::session: Authenticated as "#########################" !
DEBUG:librespot_core::session: new Session[0]
DEBUG:librespot_connect::spirc: new Spirc[0]
DEBUG:librespot_core::mercury: new MercuryManager
DEBUG:librespot_playback::player: new Player[0]
DEBUG:librespot_connect::spirc: input volume:0 to mixer: 65
INFO:librespot_playback::audio_backend::alsa: Using alsa sink
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
INFO:librespot_core::session: Country: "US"
DEBUG:librespot_core::mercury: subscribed uri=hm://remote/3/user/#########################/ count=0
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1100938461 1545141680654
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1100984582 1545141726775
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
DEBUG:librespot_core::session: Session[0] strong=3 weak=2
<<turn Spotify app back on>>
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1101619446 1545142361639
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1101620928 1545142363121
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1101622206 1545142364399
DEBUG:librespot_connect::spirc: kMessageTypeNotify "Nexus 9" a88bc7dfd2d3aa335b010e1866f5832aa4d3d761 1101622312 1545142364505
^C

What this shows early on is that librespot must have cached my credentials or else some sort of session cookie since it was able to reauthenticate without getting credentials from the Spotify app. Turning on the Spotify app merely triggered more kMessageTypeNotify's.

The behavior shown in 1. and 3. make it hard for me to understand why restarting the Spotify renderer from within moOde isn't sufficient for recovery of the service. Something else must be happening at times.

So what do folks see in their logs when their Spotify service is lost?

Regards,
Kent


PS - I don't know the first thing about Rust so I can't read through the librespot codebase even if I wanted to.

[Tim Curtis]

Refer to post #5 http://moodeaudio.org/forum/showthread.p...34#pid6234 for the procedure to enable librespot debug logging that is shown in Kent's post.

Until we can get log output for failure cases that can be submitted to the librespot dev's, nothing much is going to happen.

-Tim

[andyc]

My first post so apologies if the formatting isn't right.

I’ve also been having some issues with spotify connect via moode and thought I would post my findings here in case it helps anyone.

Spotify connect was all working fine for a while (about a week), but then it stop working.  By checking the processes running I managed to determine that librespot started and then pretty much stoped straight away.  This was consistent behaviour.

I then enabled the debug in the playerlib.php as suggested by Tim, and got the following output.

Code:

INFO:librespot_core::session: Connecting to AP "gew1-accesspoint-b-kvtg.ap.spotify.com:4070"
thread 'main' panicked at 'Authentication failed with reason: BadCredentials', core/src/connection/mod.rs:93:21
stack backtrace:

I have a premium account so thats not the issue.
From the moode log I saw the command that was being run was

Code:

20190104 194642 worker: (librespot --name "PiSpotify3" --bitrate 320 --initial-volume 0 --cache /var/local/www/spotify_cache --disable-audio-c
ache --backend alsa --device "plughw:0" --onevent /var/local/www/commandw/spotevent.sh -v > /home/pi/librespot.txt 2>&1 &)

I then ran this command from the shell direct and go the same error.

I had previously run librespot with minimal parameters from the shell OK, so I thought the issue might be the parameters.  I started removing the parameters one by one (starting with the last).
Eventually I got to 

Code:

librespot --name "PiSpotify3" --bitrate 320 --initial-volume 0

which was the first one that ran OK.  So my thought was that the issue was with the --cache parameter.

I then went back to the code in playerlib.php and removed the —cache parameter.  rebooted.

the spotify now works fine :-)

I have a theory.  I did change my spotify account soon before I started using moose with spotify connect. My old account was not premium, but my new account is premium.  I wonder if I connect with an old device (phone) and it had the old account details, and somehow the cache was using the old account.  This might be similar to users that had a similar issue and found that running librespot direct from the shell with the user name and password sorted their problem.  This is just a theory though.  I have not gone back and try to prove it.

Andy

S Y S T E M    P A R A M E T E R S  

Date and time = 2019-01-04 19:56:01
System uptime = up 9 minutes
Timezone = Europe/London
moOde = Release 4.4 2018-12-09

HDWR REV = Pi-1B+ 512MB
A U D I O    P A R A M E T E R S  

Audio device = HiFiBerry DAC+ Pro
Interface = I2S
Hdwr volume = Controller detected
Mixer name = Digital
Output stream = S16_LE / 44100
ALSA version = 1.1.3-5+rpi3
SoX version = 0.1.2-2

[Tim Curtis]

Hi Andy,

Good analysis :-)

If you still have the original cache intact, try the following:

1. If u modified the launch params in playerlib.php then revert to original launch params and reboot
2. Save the credentials file

Code:

sudo mv /var/local/www/spotify_cache/files/credentials.json ./

3. Turn on librespot from moOde UI to launch it

If it launches ok then i might have to add a "Clear cache" option.

-Tim

[TheOldPresbyope]

@PeteT

Good stuff.

If you look at the librespot repo (https://github.com/librespot-org/librespot) you'll see this same high-level error message ("ERROR:librespot_core:ession: Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }") shows up in a number of the issues. I'm not good enough at Rust tracebacks to figure out if your issue is identical to one of the ones already posted. It wouldn't hurt to post yours.

Several things have been changed in the code base to try to ameliorate one or another aspect of the problem but it appears not completely solved. See in particular issue #134 which is their placekeeper for the discussion. Some of the discussion in the various issues seem to implicate hiccups in Internet-connectivity; some not.

Since the most recent code change which might be relevant is dated November 18, 2018, which is two months newer than the version of the librespot repo used in moOde r4.4, you could try pulling and building the latest version. 

This may or may not resolve your problem. Please let the moOde community know either way.

Regards,
Kent


PS - don't forget to include the version of moOde you're working with when you post a bug report.

[Tim Curtis]

moOde uses the a4e0f58 librespot commit dated August 17 2018. (there are no releases yet)
https://github.com/librespot-org/libresp...1c06ad532d

This commit seems to be pretty robust but we could go with the latest ???

-Tim

[TheOldPresbyope]

moOde uses the a4e0f58 librespot commit dated August 17 2018. (there are no releases yet)
https://github.com/librespot-org/libresp...1c06ad532d

This commit seems to be pretty robust but we could go with the latest ???

-Tim

Yeah, we could, but I'd be happier if I could repro the problem so I could test that the November commit solves it.

[added in edit] I suppose I could build the current master and test that it works as well as a4e0f58 does for me.

Regards,
Kent

[sjoerdju]

Hi there all! I've been using librespot for a long time, used to compile it myself and run it as a service. It never was very stable in my opinion, but a quick reset of the service worked and sometimes it ran wel for a couple of days. The last compile I did was after the 19th November update, which seemed more stable than the current version Moode is using – apparently there were some tracks which made it crash. I could of course compile it and replace the current version in Moode v4.4 and let you know if it, in general, feels more stable. I'll try this anyways somewhere this week and report back.

Besides that; I made a simple script which reset the service:

cat /usr/local/bin/raspotifyre
#!/bin/sh
ssh pi@blackboxstreamer sudo systemctl restart raspotify

This doesn't really work in the new setup, but switching the service on and off thru the website it tedious at best... Is there anyway to do this from the CLI?

[Tim Curtis]

You could try this simple php script

Code:

#!/usr/bin/php
<?php

set_include_path('/var/www/inc');
require_once 'playerlib.php';

stopSpotify();
startSpotify();

sudo nano ./restartSpot.php
paste script code into file
save the file
chmod 0755 ./restartSpot.php

./restartSpot.php

[sjoerdju]

Ok, I updated librespot to the new version. I will not be able to make a hard comparison between two versions, but will report my general findings.

Thnx for the script! The stopSpotify(); function doesn't seem to exist. I browsed thru the code, but cannot really find the proper function. I'll keep looking, but if you have an idea, it would be great.