Spotify went crazy!!

[TheOldPresbyope]

@oasis1701

Sorry I'm late to the game but I've now repro'd your issue running 64-bit moOde 8.1.2 on an RPi3A. I'm located in Maryland/USA using Comcast ISP services and librespot is connecting with a different server: ap-guc3.spotify.com:4070. I'm using the Spotify app on my iPad. Everything worked fine for enough longer than 2 minutes that I thought I was in the clear but then saw the same error

Code:

[2022-08-30T15:09:24Z ERROR librespot_playback::player] Unable to load audio item: MercuryError
[2022-08-30T15:09:24Z ERROR librespot_core::session] Connection reset by peer (os error 104)
[2022-08-30T15:09:24Z ERROR librespot_connect::spirc] subscription terminated
[2022-08-30T15:09:24Z WARN  librespot] Spirc shut down unexpectedly
[2022-08-30T15:09:24Z INFO  librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"

moOde  8.1.2 incorporates librespot 0.4.1.

The test team is now wringing bugs out of a pre-release version of moOde 8.2.0 which incorporates librespot 0.4.2. As you've seen in other posts, the librespot maintainer has said this is the last, most stable version of the 0.4 series. 

I've just spun up a copy of moOde 8.2.0 pre1 on the same RPi3A. Things started off on the right foot

Code:

pi@m820pre1:~ $ sudo librespot --name "Moode Spotify" --bitrate 160 --format S16 --mixer softvol --initial-volume 50 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device "_audioout" --onevent /var/local/www/commandw/spotevent.sh
[2022-08-30T15:18:25Z INFO  librespot] librespot 0.4.2 22f8aed (Built on 2022-08-18, Build ID: LQ4hikXT, Profile: release)
[2022-08-30T15:18:25Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2022-08-30T15:18:25Z INFO  librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"
[2022-08-30T15:18:25Z INFO  librespot_core::session] Authenticated as "<--elided-->" !
[2022-08-30T15:18:25Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2022-08-30T15:18:25Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2022-08-30T15:18:25Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[2022-08-30T15:18:25Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"VOLUME": "32767", "PLAYER_EVENT": "volume_set"}
[2022-08-30T15:18:25Z INFO  librespot_core::session] Country: "US"
[2022-08-30T15:19:08Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"PLAYER_EVENT": "started", "TRACK_ID": "05YcMrnmypzN34kfDy01Vc"}
...

A long track played to the end, nearly 10 minutes. Then I tried to start playing a new set of tracks and kerplooey

Code:

[2022-08-30T15:29:01Z INFO  librespot_playback::player] Loading <Changing the Way> with Spotify URI <spotify:track:5aUAsHcy5yKC0j6TIKOJyL>
[2022-08-30T15:29:01Z INFO  librespot_playback::player] <Changing the Way> (508466 ms) loaded
[2022-08-30T15:29:01Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"TRACK_ID": "5aUAsHcy5yKC0j6TIKOJyL", "PLAYER_EVENT": "preloading"}
[2022-08-30T15:29:31Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"OLD_TRACK_ID": "1FMYNBIfIA8p5IxPU2wiBu", "TRACK_ID": "5aUAsHcy5yKC0j6TIKOJyL", "PLAYER_EVENT": "changed"}
[2022-08-30T15:29:31Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"DURATION_MS": "508466", "TRACK_ID": "5aUAsHcy5yKC0j6TIKOJyL", "PLAYER_EVENT": "playing", "POSITION_MS": "0"}
[2022-08-30T15:37:18Z ERROR librespot_core::session] Connection reset by peer (os error 104)
[2022-08-30T15:37:18Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 9195520 (+16384).
[2022-08-30T15:37:18Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 9244672 (+16384).
[2022-08-30T15:37:18Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 9211904 (+16384).
[2022-08-30T15:37:18Z WARN  librespot_audio::fetch::receive] Error from channel for data receiver for range 9228288 (+16384).
[2022-08-30T15:37:18Z ERROR librespot_connect::spirc] subscription terminated
[2022-08-30T15:37:18Z WARN  librespot] Spirc shut down unexpectedly
[2022-08-30T15:37:19Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2022-08-30T15:37:19Z INFO  librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"
[2022-08-30T15:37:19Z INFO  librespot_core::session] Authenticated as "uj2jxg6mwq5qds68p1xg9yksd" !
[2022-08-30T15:37:19Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2022-08-30T15:37:19Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2022-08-30T15:37:19Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[2022-08-30T15:37:19Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"PLAYER_EVENT": "volume_set", "VOLUME": "32767"}
[2022-08-30T15:37:19Z INFO  librespot_core::session] Country: "US"

The Spotify app has disconnected from moOde and reverted to playing via the iPad speaker.

Effectively the same behavior showed up in the librespot issues log (Issue #1035) 29 days ago, to which the maintainer commented "Typical case of temporary channel errors. If you search this repo you will find many cases like it." He asked the issue poster for verbose debugging output which was not provided so that particular issue was closed. I'll have to gen up some of my own and post it.

Regards,
Kent