Sometimes it fails to switch tracks and Mopidy stops playing anything

[PureTryOut]

This happens relatively often and the only way to "fix" it is to restart Mopidy entirely. This doesn't happen with other audio sources so it seems to be Spotify-specific.

With GST_DEBUG=3 not much is logged:

WARNING  2024-05-23 07:24:45,676 [2:MainThread] mopidy.audio.gst
  GStreamer warning: Wav stream not finished properly

[kingosticks]

I've not noticed this one, and I've logged many, many hours now. Is this suddenly in the middle of a playback or in response to anything in particular? What GST sink do you have ?

[PureTryOut]

It's after a track is done playing. I can't particularly tell you what specifically causes it, the majority of times things just play normally.

I have the following configured for audio output:

[audio]
output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/run/snapserver/snapfifo

So I'm playing the audio to a fifo file for Snapcast to pick it up.

[PureTryOut]

It just happened again, but this time more is logged.

1:40:01.470480188     2 0x7f017c9bb0c0 ERROR        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:238:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> failed to start: Authentication failed: bytes remaining on stream

Caused by:
    bytes remaining on stream
1:40:01.470642574     2 0x7f017c9bb0c0 WARN                 basesrc gstbasesrc.c:3177:gst_base_src_loop:<source> error: Internal data stream error.
1:40:01.470656181     2 0x7f017c9bb0c0 WARN                 basesrc gstbasesrc.c:3177:gst_base_src_loop:<source> error: streaming stopped, reason error (-5)
1:40:01.470709486     2 0x7f017c9bb0c0 WARN                oggdemux gstoggdemux.c:4775:gst_ogg_demux_send_event:<oggdemux26> error: EOS before finding a chain
1:40:01.470741640     2 0x7f017c9bb0c0 WARN                oggdemux gstoggdemux.c:2550:gst_ogg_demux_sink_event:<oggdemux26> EOS while trying to retrieve chain, seeking disabled
ERROR    2024-05-23 09:06:39,493 [2:MainThread] mopidy.audio.gst
  GStreamer error: Could not get/set settings from/on resource.
1:40:01.623221180     2 0x7f017e314160 WARN                  wavenc gstwavenc.c:1115:gst_wavenc_change_state:<wavenc0> warning: Wav stream not finished properly
1:40:01.623424231     2 0x7f017e314160 WARN                  wavenc gstwavenc.c:1115:gst_wavenc_change_state:<wavenc0> warning: Wav stream not finished properly, no EOS received before shutdown

[PureTryOut]

It took about 2 weeks, but it happened again today.

[PureTryOut]

Interestingly it's not just that it stops playing something, the whole server stops responding entirely. Normally I use Iris to control it but refreshing the page at that point means it'll load until a time out happens. This time it took 16 hours of playing music (I forgot to turn it off at night :sweat_smile:) before it happened and I had to restart it again (and thus lose my queue) to get it to work again.

EDIT: it just happened again, only like 3 songs after restarting it from before. How is no one else experiencing this?

[BasVanBoven]

Just wanted to pitch in to say I have experienced the same issue multiple (~8) times. Same setup with Iris as frontend and no response on Mopidy end and often comparable logging. Occurred two times last week. Only (anecdotical) pointer I have is that it quite seems to happen either directly or some time/tracks after a track skip within a Spotify playlist.

Please let me know if there is anything I could do to assist a debugging this issue.

[scotthraban]

Happens to me too - but not Spotify.

Really reduces the SPAF when the media server just stops working for no apparent reason.

Let me know if there is anything I can do to help debug.

My audio output is:

    output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! tcpclientsink host=snapcast-server port=4900

[PureTryOut]

So after finally getting credentials working again from https://github.com/mopidy/mopidy-spotify/issues/394, this instantly happened again, twice. Even worse, a third time it happened before even playing 1 track in the queue, it just failed instantly.

0:00:24.636100991     2 0x7f2fa0bdb580 WARN                oggdemux gstoggdemux.c:4775:gst_ogg_demux_send_event:<oggdemux0> error: EOS before finding a chain
0:00:24.636230670     2 0x7f2fa0bdb580 WARN                oggdemux gstoggdemux.c:2550:gst_ogg_demux_sink_event:<oggdemux0> EOS while trying to retrieve chain, seeking disabled

This is getting close to making Spotify unusable :cry:

[kingosticks]

Presumably you're also using the latest release of gst-pluign-spotfy? That latest release is required going forwards but I expect we'll hit some bumps along the way. Feel free to tell Spotify what you think of their inability to communicate important changes or produce a public native SDK.

[PureTryOut]

0.13.0. I know 0.13.1 is out so I'll try again with that one soon, but honestly I don't expect much :sweat_smile:

[kingosticks]

Is that one you've built yourself ? The new (custom) builds at https://github.com/kingosticks/gst-plugins-rs-build/releases/tag/gst-plugin-spotify_0.13.1-1 are based on the latest dev branch of librespot so it might perform differently.

p.s. if this is for Snapcast, do you need the wavenc in there?

[PureTryOut]

It's from the Alpine repositories. To run this whole thing I'm using https://github.com/jaedb/Iris/blob/master/Dockerfile.alpine which installs py3-mopidy-spotify from the Alpine repositories which pulls in gst-plugins-rs.

The output is piped into Snapcast yes.

[kingosticks]

I see. You'll have to wait for gst-plugins-rs to update then.

I wonder why they are pointlessly adding the wav encoder.