Sometimes it fails to switch tracks and Mopidy stops playing anything #389

PureTryOut · 2024-05-23T07:33:11Z

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

The text was updated successfully, but these errors were encountered:

kingosticks · 2024-05-23T08:35:53Z

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 · 2024-05-23T08:50:20Z

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 · 2024-05-23T09:08:27Z

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 · 2024-06-05T14:00:36Z

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

PureTryOut · 2024-06-13T07:46:26Z

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 😅) 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 · 2024-06-23T06:43:20Z

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 · 2024-07-03T17:23:21Z

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 · 2024-09-05T07:44:53Z

So after finally getting credentials working again from #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 😢

kingosticks · 2024-09-05T08:25:30Z

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 · 2024-09-05T16:29:37Z

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 😅

kingosticks · 2024-09-05T17:06:32Z

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 · 2024-09-05T17:15:35Z

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 · 2024-09-05T17:54:57Z

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

I wonder why they are pointlessly adding the wav encoder.

svanrossem · 2024-09-10T08:47:18Z

We're experiencing the same behaviour. Before gst-plugins-rs 0.13-dev (from @kingosticks ) we had this only after playing a track. When a track is 03:00 it doesn't play next after 03:00 but it plays infinitely.

The new behaviour is not exact as before (still sometimes after a track), but now sometimes when track is 01:30 it stops playing...

Can't find any usefull logs (even with full debug mode on).

kingosticks · 2024-09-10T09:10:25Z

You should be able to collect Gstreamer logs by setting env variable GST_DEBUG=4,*spotify*:6

svanrossem · 2024-09-10T09:40:24Z

0:22:07.994424629     1 0x7fcfe0000dd0 ERROR        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:279:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> failed to start: Service unavailable { Connection refused (os error 111) }
0:22:07.994794784     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2281:gst_element_message_full_with_details:<source> posting message: Could not get/set settings from/on resource.
0:22:07.994981924     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2308:gst_element_message_full_with_details:<source> posted error message: Could not get/set settings from/on resource.
0:22:07.995101105     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2281:gst_element_message_full_with_details:<source> posting message: Internal data stream error.
0:22:07.995142803     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2308:gst_element_message_full_with_details:<source> posted error message: Internal data stream error.
0:22:07.995229961     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2281:gst_element_message_full_with_details:<oggdemux9> posting message: Could not demultiplex stream.
0:22:07.995269283     1 0x7fcfe0000dd0 INFO        GST_ERROR_SYSTEM gstelement.c:2308:gst_element_message_full_with_details:<oggdemux9> posted error message: Could not demultiplex stream.
ERROR    2024-09-10 09:35:53,559 [1:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Could not get/set settings from/on resource.', 'gst-resource-error-quark', 13) debug='audio/spotify/src/spotifyaudiosrc/imp.rs(280): <gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source:\nService unavailable { Connection refused (os error 111) }'

Looks like something is blocked...

kingosticks · 2024-09-10T09:56:14Z

failed to start: Service unavailable { Connection refused (os error 111) }

I don't understand your failure description. Are you saying that playback works up to a certain point and then stops? The log above suggests it doesn't work at all.

svanrossem · 2024-09-10T10:46:07Z

Are you saying that playback works up to a certain point and then stops?

Yes

The log above suggests it doesn't work at all.

It works, but maybe this is a problem. I have a strict firewall, I've whitelisted 80,443 and 4070 https://apresolve.spotify.com/.

kingosticks · 2024-09-10T11:40:32Z

I'm still pretty confused. The log shows spotifyaudiosrc cannot start. If it cannot start, it cannot be working. Or is this log showing it not working after some other track that did work (rather than the other case where it stops working up until a certain point in the track)?

BasVanBoven · 2024-09-13T14:03:10Z

This is what my log shows when failing to switch tracks (so, after the previous track has concluded, which did work), similar to @svanrossem . Running jaedb/iris:latest from Docker Hub with the Oauth workaround (but happening with old user/pass auth as well) on an Unraid server. After manually changing to the next track, playback resumes (skipping the track that it failed to play).

mopidy-spotify.log

kingosticks · 2024-09-13T16:23:31Z

That log shows the same connection error. And it's also using the old (current release) version of librespot/gst-plugin-spotify.

Is anyone able to replace the old gst-plugin-spotify in their image with the new custom one we recommend, and see if the issue is still present?

I appreciate this issue is very annoying but I'm focused on helping trying to get the new version of librespot released. This older version is on its last legs and we need to get everyone moved off it. And progress is being made, so hopefully won't be long.

svanrossem · 2024-09-13T16:27:56Z

That log shows the same connection error. And it's also using the old (current release) version of librespot/gst-plugin-spotify.

Is anyone able to replace the old gst-plugin-spotify in their image with the new custom one we recommend, and see if the issue is still present?

I appreciate this issue is very annoying but I'm focused on helping trying to get the new version of librespot released. This older version is on its last legs and we need to get everyone moved off it. And progress is being made, so hopefully won't be long.

I’m running the latest version of ‘mopidy-spotify’ and ‘gst-spotify’ from your ‘0.13-dev’-branch.

kingosticks · 2024-09-13T17:05:28Z

Sorry, yes, I forgot you said that. Can I assume your firewall changes had no impact?

Hmm. I'm going to build another which ramps up the debug logging, I can't think why you'd see connection issues just from being in a container.

svanrossem · 2024-09-16T06:09:54Z

Sorry, yes, I forgot you said that. Can I assume your firewall changes had no impact?

Hmm. I'm going to build another which ramps up the debug logging, I can't think why you'd see connection issues just from being in a container.

As far as I know we only need TCP port 4070, 443 and 80. Some people say when port 4070 is blocked it will fallback to port 443, when moving to gst-spotify I've tested this and found TCP port 4070 is necessary and spawn this connection refused instantly when blocking TCP port 4070.

I'm running Mopidy in a container in Kubernetes.

svanrossem · 2024-09-16T06:47:58Z

Got some logs after again having this issue.

121:15:39.235014474     1 0x7fe658002630 LOG          spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:298:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> got buffer of size 4189
121:15:39.487431129     1 0x7fe658002630 LOG          spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:298:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> got buffer of size 4186
121:15:39.701637747     1 0x7fe658002630 LOG          spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:298:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> got buffer of size 4144
121:15:39.955293609     1 0x7fe658002630 LOG          spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:298:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> got buffer of size 4066
121:15:40.168521968     1 0x7fe658002630 LOG          spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:298:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> got buffer of size 1536
121:15:40.296869653     1 0x7fe658002630 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:302:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> eos
DEBUG    2024-09-16 06:33:00,514 [1:Dummy-14] mopidy.audio.gst
  Got about-to-finish event.
DEBUG    2024-09-16 06:33:00,514 [1:Dummy-14] mopidy.audio.actor
  Running about-to-finish callback.
DEBUG    2024-09-16 06:33:00,518 [1:Audio-2 (_actor_loop)] mopidy.audio.actor
  Flags: 2
DEBUG    2024-09-16 06:33:00,520 [1:SoftwareMixer-1 (_actor_loop)] mopidy.mixer
  Mixer event: volume_changed(volume=24)
DEBUG    2024-09-16 06:33:00,521 [1:SoftwareMixer-1 (_actor_loop)] mopidy.listener
  Sending volume_changed to MixerListener: {'volume': 24}
DEBUG    2024-09-16 06:33:00,524 [1:Core-7 (_actor_loop)] mopidy.listener
  Sending volume_changed to CoreListener: {'volume': 24}
121:15:40.445835168     1 0x7fe658001010 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:212:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::base_src::BaseSrcImpl>::stop:<source> stopping
121:15:40.450680152     1 0x7fe658001010 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:354:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer::subclass::uri_handler::URIHandlerImpl>::set_uri:<source> set URI: spotify:track:083LM23MmqS8HTTYZQrYxG
DEBUG    2024-09-16 06:33:00,540 [1:Dummy-14] mopidy.audio.gst
  Got source-setup signal: element=GstSpotifyAudioSrc
DEBUG    2024-09-16 06:33:00,543 [1:Dummy-14] mopidy.audio.actor
  Running source-setup callback
121:15:40.457212718     1 0x7fe634019c20 DEBUG        spotifyaudiosrc audio/spotify/src/common.rs:144:gstspotify::common::Settings::connect_session::{{closure}}:<source> reuse cached credentials for user 5v24s1jms01pgj5svxdq1xpkx
121:15:40.604432804     1 0x7fe658001250 ERROR        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:279:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> failed to start: Service unavailable { Connection refused (os error 111) }
ERROR    2024-09-16 06:33:00,694 [1:MainThread] mopidy.audio.gst
  GStreamer error: Could not get/set settings from/on resource.
DEBUG    2024-09-16 06:33:00,694 [1:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Could not get/set settings from/on resource.', 'gst-resource-error-quark', 13) debug='audio/spotify/src/spotifyaudiosrc/imp.rs(280): <gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin109/GstSpotifyAudioSrc:source:\nService unavailable { Connection refused (os error 111) }'
121:15:40.610142202     1 0x562572a92fb0 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:354:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer::subclass::uri_handler::URIHandlerImpl>::set_uri:<source> set URI: spotify:track:083LM23MmqS8HTTYZQrYxG
DEBUG    2024-09-16 06:33:00,699 [1:MainThread] mopidy.audio.gst
  Got source-setup signal: element=GstSpotifyAudioSrc
DEBUG    2024-09-16 06:33:00,699 [1:MainThread] mopidy.audio.actor
  Running source-setup callback
121:15:40.613732030     1 0x7fe6300435f0 DEBUG        spotifyaudiosrc audio/spotify/src/common.rs:144:gstspotify::common::Settings::connect_session::{{closure}}:<source> reuse cached credentials for user 5v24s1jms01pgj5svxdq1xpkx
121:15:40.688754445     1 0x7fe658000d70 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:273:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create:<source> setup has been cancelled
121:15:40.692150009     1 0x562572a92fb0 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:212:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::base_src::BaseSrcImpl>::stop:<source> stopping
DEBUG    2024-09-16 06:33:00,784 [1:MainThread] mopidy.audio.gst
  Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS

I did some tests from the container

[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl https://apresolve.spotify.com/
{"ap_list":["ap-gew4.spotify.com:4070","ap-gew4.spotify.com:443","ap-gew4.spotify.com:80","ap-guc3.spotify.com:4070","ap-gue1.spotify.com:443","ap-gae2.spotify.com:80"]}
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ 
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gew4.spotify.com:4070 -v
* processing: telnet://ap-gew4.spotify.com:4070
*   Trying 34.158.1.133:4070...
* Connected to ap-gew4.spotify.com (34.158.1.133) port 4070
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl ap-gew4.spotify.com:443 -v
* processing: ap-gew4.spotify.com:443
*   Trying 34.158.1.133:443...
* connect to 34.158.1.133 port 443 failed: Connection refused
* Failed to connect to ap-gew4.spotify.com port 443 after 17 ms: Couldn't connect to server
* Closing connection
curl: (7) Failed to connect to ap-gew4.spotify.com port 443 after 17 ms: Couldn't connect to server
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl ap-gew4.spotify.com:80 -v
* processing: ap-gew4.spotify.com:80
*   Trying 34.158.1.133:80...
* connect to 34.158.1.133 port 80 failed: Connection refused
* Failed to connect to ap-gew4.spotify.com port 80 after 19 ms: Couldn't connect to server
* Closing connection
curl: (7) Failed to connect to ap-gew4.spotify.com port 80 after 19 ms: Couldn't connect to server
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-guc3.spotify.com:4070 -v
* processing: telnet://ap-guc3.spotify.com:4070
*   Trying 104.154.127.247:4070...
* Connected to ap-guc3.spotify.com (104.154.127.247) port 4070
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gue1.spotify.com:443 -v
* processing: telnet://ap-gue1.spotify.com:443
*   Trying 34.158.255.62:443...
* Connected to ap-gue1.spotify.com (34.158.255.62) port 443
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gae2.spotify.com:80 -v
* processing: telnet://ap-gae2.spotify.com:80
*   Trying 104.199.241.202:80...
* Connected to ap-gae2.spotify.com (104.199.241.202) port 80

svanrossem · 2024-09-16T07:19:49Z

So, after changing the track (just hit next) the track starts playing, and when checking the first endpoint ap-gew4.spotify.com again on port 80 and 443 both works...

[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gew4.spotify.com:443 -v
* processing: telnet://ap-gew4.spotify.com:443
*   Trying 34.158.1.133:443...
* Connected to ap-gew4.spotify.com (34.158.1.133) port 443
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gew4.spotify.com:4070 -v
* processing: telnet://ap-gew4.spotify.com:4070
*   Trying 34.158.1.133:4070...
* Connected to ap-gew4.spotify.com (34.158.1.133) port 4070
[mopidy@mopidy-iris-686b49d7ff-rqpnd ~]$ curl telnet://ap-gew4.spotify.com:80 -v
* processing: telnet://ap-gew4.spotify.com:80
*   Trying 34.158.1.133:80...
* Connected to ap-gew4.spotify.com (34.158.1.133) port 80

kingosticks · 2024-09-16T14:11:51Z

I wonder if this is related to using ap-gew4.spotify.com. librespot 0.4 used to have loads of problems with that particular access point and there was a change made to avoid using it. That change didn't make it into 0.5, I am told that was intentional but there's no detail on why. Can you try hacking your /etc/hosts to disrupt that AP and therefore force librespot it to use another one?

kingosticks · 2024-09-16T14:36:00Z

And what Spotify audio quality have you all got configured here?

kingosticks · 2024-09-16T15:41:14Z

There are some new packages/binaries at https://github.com/kingosticks/gst-plugins-rs-build/actions/runs/10886698789 with more logging. Run GST_DEBUG=3,*spot*:6 mopidy to see more of what librespot is doing.

BasVanBoven · 2024-09-16T15:42:18Z

No specific audio quality setting configured through mopidy-spotify config here, so assuming default bitrate of 160. Will block ap-gew4.spotify.com through /etc/hosts this evening and report back!

BasVanBoven · 2024-09-16T18:55:15Z

Blocked through /etc/hosts as indicated by:

$ curl telnet://[ap-gew4.spotify.com:80](http://ap-gew4.spotify.com/) -v
sh: 1: Syntax error: "(" unexpected
$ curl telnet://ap-gew4.spotify.com:443 -v
*   Trying 127.0.0.1:443...
* connect to 127.0.0.1 port 443 failed: Connection refused
* Failed to connect to ap-gew4.spotify.com port 443: Connection refused
* Closing connection 0
curl: (7) Failed to connect to ap-gew4.spotify.com port 443: Connection refused
$ curl telnet://ap-gew4.spotify.com:80 -v 
*   Trying 127.0.0.1:80...
* connect to 127.0.0.1 port 80 failed: Connection refused
* Failed to connect to ap-gew4.spotify.com port 80: Connection refused
* Closing connection 0
curl: (7) Failed to connect to ap-gew4.spotify.com port 80: Connection refused
$ curl telnet://ap-gew4.spotify.com:4070 -v
*   Trying 127.0.0.1:4070...
* connect to 127.0.0.1 port 4070 failed: Connection refused
* Failed to connect to ap-gew4.spotify.com port 4070: Connection refused
* Closing connection 0
curl: (7) Failed to connect to ap-gew4.spotify.com port 4070: Connection refused
$

Still experienced 6 stops over 2 hours of playtime, but that seems due to the way the block is handled as the log indicates:

GStreamer error: Panicked: called `Result::unwrap()` on an `Err` value: RecvError

mopidy-spotify-240916.log

Anecdotically, it does not seem it now fails more often then without hosts block, which might indicate you are on the right track here.

Will try and run the gst-plugin-spotify you built later (when I figure out where gstreamer loads it from)

svanrossem · 2024-09-17T06:25:16Z

I've build gst-spotify based on your latest commit @kingosticks ; https://gitlab.freedesktop.org/kingosticks/gst-plugins-rs/-/commit/c0a3f70ca097cb3d5eb6b35ea3e2a87ed4dad964.

When I block ap-gew4.spotify.com (just point it to 127.0.0.1) I got connection refused errors all the way. Playing a track doesn't work at all...

DEBUG    2024-09-17 06:09:55,498 [1:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Could not get/set settings from/on resource.', 'gst-resource-error-quark', 13) debug='audio/spotify/src/spotifyaudiosrc/imp.rs(280): <gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin10/GstSpotifyAudioSrc:source:\nService unavailable { Connection refused (os error 111) }'

How random is https://github.com/librespot-org/librespot/blob/338d8b90b295704c5d9945634b2548a6199f1af9/docs/connection.md#access-point-connection?

The ap_list from apresolve.spotify.com always returns the same first entry

"ap-gew4.spotify.com:4070",
"ap-gew4.spotify.com:443",
"ap-gew4.spotify.com:80",
...

As a workaround I've pointed ap-gew4.spotify.com to ap-gue1.spotify.com.

hostAliases:
  - ip: "34.158.255.62"
    hostnames:
      - "ap-gew4.spotify.com"

That's working fine. I'll report when I've got errors again...

svanrossem · 2024-09-17T07:05:24Z

Again connection refused errors...

DEBUG    2024-09-17 06:53:21,220 [1:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Could not get/set settings from/on resource.', 'gst-resource-error-quark', 13) debug='audio/spotify/src/spotifyaudiosrc/imp.rs(280): <gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source:\nService unavailable { Connection refused (os error 111) }'

Is it possible to output which ap the plugin is using?

kingosticks · 2024-09-19T10:09:36Z

Is it possible to output which ap the plugin is using?

Yes, it's in the logs if you use run with full librespot debuging using my branch: GST_DEBUG=*spot*:6 mopidy

0:00:20.505880810 281082 0x7ffa7c015d00 INFO               librespot session.rs:192:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:443"

But I'm not sure these domains always point to the same actual servers, it's likely based on load/location/whatever. For me:

PING ap-gew1.spotify.com (104.199.65.9) 56(84) bytes of data.
64 bytes from 9.65.199.104.bc.googleusercontent.com (104.199.65.9): icmp_seq=1 ttl=57 time=15.6 ms

PING ap-gew4.spotify.com (34.158.1.133) 56(84) bytes of data.
64 bytes from 133.1.158.34.bc.googleusercontent.com (34.158.1.133): icmp_seq=1 ttl=57 time=14.6 ms

PING ap-gue1.spotify.com (34.158.255.62) 56(84) bytes of data.
64 bytes from 62.255.158.34.bc.googleusercontent.com (34.158.255.62): icmp_seq=1 ttl=102 time=88.8 ms

svanrossem · 2024-09-20T06:25:23Z

Is it possible to output which ap the plugin is using?

Yes, it's in the logs if you use run with full librespot debuging using my branch: GST_DEBUG=*spot*:6 mopidy

I have exactly that value but don't get any AP information?

0:00:20.505880810 281082 0x7ffa7c015d00 INFO               librespot session.rs:192:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:443"

But I'm not sure these domains always point to the same actual servers, it's likely based on load/location/whatever. For me:

PING ap-gew1.spotify.com (104.199.65.9) 56(84) bytes of data.
64 bytes from 9.65.199.104.bc.googleusercontent.com (104.199.65.9): icmp_seq=1 ttl=57 time=15.6 ms

PING ap-gew4.spotify.com (34.158.1.133) 56(84) bytes of data.
64 bytes from 133.1.158.34.bc.googleusercontent.com (34.158.1.133): icmp_seq=1 ttl=57 time=14.6 ms

PING ap-gue1.spotify.com (34.158.255.62) 56(84) bytes of data.
64 bytes from 62.255.158.34.bc.googleusercontent.com (34.158.255.62): icmp_seq=1 ttl=102 time=88.8 ms

No I mean librespot checks apresolve.spotify.com, apresolve always returns

{
  "ap_list": [
    STATIC -> "ap-gew4.spotify.com:4070",
    STATIC -> "ap-gew4.spotify.com:443",
    STATIC -> "ap-gew4.spotify.com:80",
    "RANDOM",
    "RANDOM",
    "RANDOM"
  ]
}

and when I block ap-gew4.spotify.com with a redirect to 127.0.0.1 it won't work at all and I'll got connection refused errors all the way.

kingosticks · 2024-09-20T08:14:30Z

It turns out librespot doesn't retry with the other APs unless a very specific type of error occurs. These connection refused problems don't qualify so it doesn't do any retries! I'm submitting a PR to fix this, should make things more robust.

kingosticks · 2024-09-20T08:16:15Z

Are you sure you're building from latest https://gitlab.freedesktop.org/kingosticks/gst-plugins-rs/-/tree/0.13-librespot-dev for the extra logging?

svanrossem · 2024-09-24T06:39:56Z

Are you sure you're building from latest https://gitlab.freedesktop.org/kingosticks/gst-plugins-rs/-/tree/0.13-librespot-dev for the extra logging?

ARG GST_PLUGINS_RS_TAG=0.13-librespot-dev
RUN git clone -c advice.detachedHead=false \
        --single-branch --depth 1 \
        --branch ${GST_PLUGINS_RS_TAG} \
        https://gitlab.freedesktop.org/kingosticks/gst-plugins-rs.git ./ \
 && git reset --hard c05da5be655a84ec98b6100a1fef6cf1ebec01d9

EDIT: just replaced it with your latest commit...

kingosticks · 2024-09-24T09:16:56Z

That very latest commit pulls in the new connection retry mechanism in librespot. So it won't make a difference to logging, but it might help with our actual issue. Please do try it.

Sorry to bang on about this, but for the logging, are you also definitely setting the GST_DEBUG env variable ?

svanrossem · 2024-09-24T13:23:44Z

That very latest commit pulls in the new connection retry mechanism in librespot. So it won't make a difference to logging, but it might help with our actual issue. Please do try it.

Sorry to bang on about this, but for the logging, are you also definitely setting the GST_DEBUG env variable ?

With the latest version of bot gst-spotify and Mopidy-Spotify I'm experiencing errors

ERROR    2024-09-24 13:05:11,721 [1:Core-7 (_actor_loop)] mopidy.core.library
  SpotifyBackend backend returned bad data: Expected a list of Track, not {'spotify:track:2oYheX6lx92jmxzainoy6l': [Track(album=Album(artists=[Artist(name='Django Wagner', uri='spotify:artist:2onmCslqboJDdDoCo7ZPd2')], name='Kali', uri='spotify:album:3YOglX85pvc8ip0Bdy1eA9'), artists=[Artist(name='Django Wagner', uri='spotify:artist:2onmCslqboJDdDoCo7ZPd2')], bitrate=160, disc_no=1, length=206000, name='Kali', track_no=1, uri='spotify:track:2oYheX6lx92jmxzainoy6l')]}
ERROR    2024-09-24 13:05:11,796 [1:Core-7 (_actor_loop)] mopidy.core.library
  SpotifyBackend backend returned bad data: Expected a list of Track, not {'spotify:track:1dzQoRqT5ucxXVaAhTcT0J': [Track(album=Album(artists=[Artist(name='Lady Gaga', uri='spotify:artist:1HY2Jd0NmPuamShAr6KMms')], name='The Fame', uri='spotify:album:1qwlxZTNLe1jq3b0iidlue'), artists=[Artist(name='Lady Gaga', uri='spotify:artist:1HY2Jd0NmPuamShAr6KMms'), Artist(name="Colby O'Donis", uri='spotify:artist:7fObcBw9VM3x7ntWKCYl0z')], bitrate=160, disc_no=1, length=241933, name='Just Dance', track_no=1, uri='spotify:track:1dzQoRqT5ucxXVaAhTcT0J')]}

kingosticks · 2024-09-24T14:10:56Z

Urgh, right. There are too many evolving parts here, I've made a mess here and it's getting silly.

Latest version of 0.13-librespot-dev (c05da5be655a84ec98b6100a1fef6cf1ebec01d9) implements access token login instead of user and password login. But to use that you need unreleased version of mopidy-spotify. But to use that you need latest Mopidy code, which you're (very reasonably) not using.

I should have made a new branch for my access-token work, my bad. I'll fix 0.13-librespot-dev. You'll also need to make sure you're using Mopidy-Spotify==5.0.0a2.

kingosticks · 2024-09-24T14:20:04Z

OK, so 0.13-librespot-dev at 8f8c537cfb6e3fde8829a5b48d078034c74a6c68 should now be good with Mopidy-Spotify==5.0.0a2. Sorry about that.

svanrossem · 2024-09-24T20:26:42Z

OK, so 0.13-librespot-dev at 8f8c537cfb6e3fde8829a5b48d078034c74a6c68 should now be good with Mopidy-Spotify==5.0.0a2. Sorry about that.

When using that specific commit I've got a compile error

   Compiling librespot v0.5.0-dev (https://github.com/librespot-org/librespot.git?rev=e02e4ae224173fe63612e7542d656b0eadabc719#e02e4ae2)
error[E0277]: can't compare `std::string::String` with `Option<std::string::String>`
   --> audio/spotify/src/common.rs:135:59
    |
135 |             if !self.username.is_empty() && self.username != cached_cred.username {
    |                                                           ^^ no implementation for `std::string::String == Option<std::string::String>`
    |
    = help: the trait `PartialEq<Option<std::string::String>>` is not implemented for `std::string::String`
    = help: the following other types implement trait `PartialEq<Rhs>`:
              `std::string::String` implements `PartialEq<&'a VariantTy>`
              `std::string::String` implements `PartialEq<&'a str>`
              `std::string::String` implements `PartialEq<Cow<'a, str>>`
              `std::string::String` implements `PartialEq<GStr>`
              `std::string::String` implements `PartialEq<GStringPtr>`
              `std::string::String` implements `PartialEq<VariantTy>`
              `std::string::String` implements `PartialEq<VariantType>`
              `std::string::String` implements `PartialEq<bytes::bytes::Bytes>`
            and 11 others
error[E0277]: `Option<std::string::String>` doesn't implement `std::fmt::Display`
   --> audio/spotify/src/common.rs:140:21
    |
140 |                     cached_cred.username,
    |                     ^^^^^^^^^^^^^^^^^^^^ `Option<std::string::String>` cannot be formatted with the default formatter
    |
    = help: the trait `std::fmt::Display` is not implemented for `Option<std::string::String>`
    = note: in format strings you may be able to use `{:?}` (or {:#?} for pretty-print) instead
    = note: this error originates in the macro `format_args` which comes from the expansion of the macro `gst::info` (in Nightly builds, run with -Z macro-backtrace for more info)
error[E0277]: `Option<std::string::String>` doesn't implement `std::fmt::Display`
   --> audio/spotify/src/common.rs:148:21
    |
148 |                     cached_cred.username
    |                     ^^^^^^^^^^^^^^^^^^^^ `Option<std::string::String>` cannot be formatted with the default formatter
    |
    = help: the trait `std::fmt::Display` is not implemented for `Option<std::string::String>`
    = note: in format strings you may be able to use `{:?}` (or {:#?} for pretty-print) instead
    = note: this error originates in the macro `format_args` which comes from the expansion of the macro `gst::info` (in Nightly builds, run with -Z macro-backtrace for more info)
For more information about this error, try `rustc --explain E0277`.
error: could not compile `gst-plugin-spotify` (lib) due to 3 previous errors

kingosticks · 2024-09-24T22:17:54Z

I managed to lose a commit along the way earlier. Fixed now

svanrossem · 2024-09-30T11:58:34Z

I managed to lose a commit along the way earlier. Fixed now

Which commit is your latest version against Mopidy-Spotify v5.0.0a2?

kingosticks · 2024-09-30T12:55:25Z

Yes

svanrossem · 2024-10-01T07:15:59Z

Yes

I'm using commit f429d7dacbb77f6cc54d5ed29e724f57016a2005 but getting the same error

   Compiling librespot v0.5.0-dev (https://github.com/librespot-org/librespot.git?rev=e02e4ae224173fe63612e7542d656b0eadabc719#e02e4ae2)
error[E0277]: can't compare `std::string::String` with `&std::string::String`
   --> audio/spotify/src/common.rs:136:59
    |
136 |             if !self.username.is_empty() && self.username != cached_username {
    |                                                           ^^ no implementation for `std::string::String == &std::string::String`
    |
    = help: the trait `PartialEq<&std::string::String>` is not implemented for `std::string::String`
help: consider dereferencing here
    |
136 |             if !self.username.is_empty() && self.username != *cached_username {
    |                                                              +

For more information about this error, try `rustc --explain E0277`.

kingosticks · 2024-10-01T10:23:43Z

I swear I made that change and pushed it. Sorry for this mess. What is checked in definitely builds. I've moved on from this branch now and clearly this is too much juggling for me to cope.

svanrossem · 2024-10-02T08:59:02Z

I swear I made that change and pushed it. Sorry for this mess. What is checked in definitely builds. I've moved on from this branch now and clearly this is too much juggling for me to cope.

No problem! Made a build based on dfb52c5e1b0415f5accd7c25d39b1828dad285f0 and everything is ok. Thank you!

I'm running this build for a hour of 2 without any problems. It looks like you fixed the issue 🚀 ! If so, this would be the most stable release!

kingosticks · 2024-10-02T09:23:32Z

Brilliant. Thanks for persevering and providing the feedback, it's really helpful.

I'm ready for a v5.0.0a3 release (based on latest librespot and gst-plugins-rs ) as soon as librespot-org/librespot#1357 is merged since that should fix the remaining connection issues being reported.

svanrossem · 2024-10-04T08:02:26Z

You could close this issue, 2 days playing non-stop without any issues, thanks @kingosticks !

kingosticks · 2024-10-04T09:10:59Z

Super. I think I'll make another beta release today rather than wait for any further upstream fixes. I think I've demonstrated my inability to juggle multiple changes. At which point I'll close this with a link to the associated gst-plugin-spotify release. I'm glad we're making progress on all this.

kingosticks · 2024-10-07T14:19:23Z

I've released Mopidy-Spotify v5.0.0a3 and gst-plugin-spotify_0.14.0~alpha.1-1 with the fixes. Given how different this version is, let's start a new issue if there are still problems with track switching.

kingosticks added the A-spotifyaudiosrc Area: spotifyaudiosrc (GStreamer/librespot) label Aug 13, 2024

kingosticks added this to the 5.0 (Replace libspotify) milestone Sep 24, 2024

kingosticks closed this as completed Oct 7, 2024

Sometimes it fails to switch tracks and Mopidy stops playing anything #389

Sometimes it fails to switch tracks and Mopidy stops playing anything #389

Comments

PureTryOut commented May 23, 2024

kingosticks commented May 23, 2024

PureTryOut commented May 23, 2024

PureTryOut commented May 23, 2024

PureTryOut commented Jun 5, 2024

PureTryOut commented Jun 13, 2024 • edited Loading

BasVanBoven commented Jun 23, 2024 • edited Loading

scotthraban commented Jul 3, 2024 • edited Loading

PureTryOut commented Sep 5, 2024

kingosticks commented Sep 5, 2024

PureTryOut commented Sep 5, 2024

kingosticks commented Sep 5, 2024 • edited Loading

PureTryOut commented Sep 5, 2024 • edited Loading

kingosticks commented Sep 5, 2024

svanrossem commented Sep 10, 2024

kingosticks commented Sep 10, 2024

svanrossem commented Sep 10, 2024

kingosticks commented Sep 10, 2024

svanrossem commented Sep 10, 2024 • edited Loading

kingosticks commented Sep 10, 2024 • edited Loading

BasVanBoven commented Sep 13, 2024

kingosticks commented Sep 13, 2024

svanrossem commented Sep 13, 2024

kingosticks commented Sep 13, 2024

svanrossem commented Sep 16, 2024

svanrossem commented Sep 16, 2024

svanrossem commented Sep 16, 2024 • edited Loading

kingosticks commented Sep 16, 2024 • edited Loading

kingosticks commented Sep 16, 2024

kingosticks commented Sep 16, 2024

BasVanBoven commented Sep 16, 2024 • edited Loading

BasVanBoven commented Sep 16, 2024 • edited Loading

svanrossem commented Sep 17, 2024 • edited Loading

svanrossem commented Sep 17, 2024 • edited Loading

kingosticks commented Sep 19, 2024

svanrossem commented Sep 20, 2024

kingosticks commented Sep 20, 2024

kingosticks commented Sep 20, 2024 • edited Loading

svanrossem commented Sep 24, 2024 • edited Loading

kingosticks commented Sep 24, 2024

svanrossem commented Sep 24, 2024

kingosticks commented Sep 24, 2024

kingosticks commented Sep 24, 2024

svanrossem commented Sep 24, 2024

kingosticks commented Sep 24, 2024

svanrossem commented Sep 30, 2024

kingosticks commented Sep 30, 2024

svanrossem commented Oct 1, 2024

kingosticks commented Oct 1, 2024

svanrossem commented Oct 2, 2024

kingosticks commented Oct 2, 2024

svanrossem commented Oct 4, 2024

kingosticks commented Oct 4, 2024

kingosticks commented Oct 7, 2024

PureTryOut commented Jun 13, 2024 •

edited

Loading

BasVanBoven commented Jun 23, 2024 •

edited

Loading

scotthraban commented Jul 3, 2024 •

edited

Loading

kingosticks commented Sep 5, 2024 •

edited

Loading

PureTryOut commented Sep 5, 2024 •

edited

Loading

svanrossem commented Sep 10, 2024 •

edited

Loading

kingosticks commented Sep 10, 2024 •

edited

Loading

svanrossem commented Sep 16, 2024 •

edited

Loading

kingosticks commented Sep 16, 2024 •

edited

Loading

BasVanBoven commented Sep 16, 2024 •

edited

Loading

BasVanBoven commented Sep 16, 2024 •

edited

Loading

svanrossem commented Sep 17, 2024 •

edited

Loading

svanrossem commented Sep 17, 2024 •

edited

Loading

kingosticks commented Sep 20, 2024 •

edited

Loading

svanrossem commented Sep 24, 2024 •

edited

Loading