Thank you for your donation!


Cloudsmith graciously provides open-source package management and distribution for our project.


Spotify Connect failures on Moode 4.4
#11
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.
Reply


Messages In This Thread
Spotify Connect failures on Moode 4.4 - by abyrd - 12-13-2018, 05:51 PM
RE: Spotify Connect failures on Moode 4.4 - by TheOldPresbyope - 12-18-2018, 03:07 PM

Forum Jump: