Often doesn't switch to next track

General
1

In my raspberry-mopidy-Iris installation, it often happens that the playlist doesn’t switch to the next track, but it keeps playing blank at the end of current track. If I manually act on Iris interface to go to next track, it does, but not automatically.
I have to restart mopidy to fix things.
What could it be?

2

Is it connected to WiFi? I get strange behaviour like that if the network connection drops out.
Is anything happening in the logs? I often see “Spotify is disconnected” “Spotify is connected” as the connection drops and comes back.

3

Thanks for answering.
Yes, it is connected via WiFi, but the weird thing is that nothing wrong is in the logs. When Spotify gets disconnected (sometimes it happens) I cannot play any Spotify’s playlist at all. This issue instead is only related to “go to next track when current ends”. It doesn’t proceed automatically. (not always, only randomly).

4

If there is nothing in the logs, turn up the verbosity until we can see what is going on during the track change: Configuration — Mopidy 3.1.1-1-gf17acacf documentation

Does it happen with all backends or only Spotify (I assume this is happening with Spotify tracks, you did not specify).

Having to restart Mopidy is odd. Are you sure you cannot recover by issuing a “stop” command? Or clearing the playlist? I’m not saying those are reasonable workarounds but I am trying to understand what could possibly be so stateful that a restart is required.

5

Hi Nick. I will make tests as you suggest and come back. In the meantime, this is happening either with Spotify and with local tracks. But, as I said, this behavior is not persistent, it happens randomly that’s why I am trying to figure out the cause.

6

I understand it’s not persistent between Mopidy restarts but I want to know is it persistent between clearing the tracklist. If you issue a “stop” command it will clear down the tracklist and all the play state. I want to know if that is sufficient to fix the issue.

I also understand from what you say that it’s not consistent. It sounds like it is not track dependent and presumably you’ve done experiments to confirm that. If it’s also happening with local tracks then it’s obviously nothing to do with network connections or Spotify connection status so we can totally ignore that.

7

This morning it happened again. I then stopped and cleared, then reload the playlist but after the first track it didn’t continue to the next one.
As I have increased logging verbosity, this is what I found in the log:

2021-06-08 09:32:00,223 ERROR [516:HttpServer] asyncio: Future exception was never retrieved
future: <Future finished exception=WebSocketClosedError()>
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/tornado/websocket.py", line 874, in wrapper
    yield fut
  File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1133, in run
    value = future.result()
tornado.iostream.StreamClosedError: Stream is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/usr/lib/python3/dist-packages/tornado/websocket.py", line 876, in wrapper
    raise WebSocketClosedError()
tornado.websocket.WebSocketClosedError
8

Now I had to restart mopidy, so I need to wait for the next failing event to report more

9

Can we have the full log please, that websocket exception is likely to be a consequence rather than a cause.

10

here it is:

11

Can you do a DEBUG level one pleaese. It’ll be big so I suggest you put the verbosity back to something higher afterwards.

I’m wondering if it’s related to

2021-06-07 18:18:12,976 ERROR [516:MainThread] mopidy.audio.gst: GStreamer error: Server does not support seeking.

but I guess it can’t be because you said there was nothing in the log previously so this must be something else going on…

12

what do you mean by “DEBUG level one”?

[logging]
verbosity = 4

?
In the meantime, I have discovered that this problem is limited to Spotify’s playlists.

13

I meant, give me a log with DEBUG level verbosity. The log you provided had (EDIT: no) DEBUG logging present. Limited to just Spotify’s playlists? So playing back through a queue of search results is fine?

14

Just tried with the Search, but I can’t load tracks. This is the error:

2021-06-23 15:01:53,203 INFO [514:SpotifyBackend-9] mopidy_spotify.lookup: Failed to lookup 'spotify:track:2r1FiNXh5mDNEP8K07YRVp': Session must be logged in and online to load objects: <ConnectionState.DISCONNECTED: 2>

…but I am logged in and online!

EDIT:
Only Radio Streams are working. I tried to restart mopidy, but the problems with Spotify remains.

15

I think you are running into Spotify login error: <ErrorType.UNABLE_TO_CONTACT_SERVER: 8> - #7 by 01tot10 as well now

16

Yes, without any doubt. And this is confusing my troubleshooting!

17

It stops from a queue of search results too…
How to set the logging level to DEBUG for mopidy-spotify? I am running it as a service.

(P.S…: could it be an Iris issue?)

18

You would add this to your config.

[loglevels]
mopidy_spotify = debug

But I want a full debug log because we need to see the track change occuring (or not), for which you would add

[logging]
verbosity = 1

as per the docs.

maybe. Try a different frontend and see.

19

Did it. After restarting mopidy the tracks are now changing. I have to wait (maybe one or more days) for the issue. Thanks @kingosticks .

20

Got it! The issue came up soon. I am pasting here latest lines from the log. The failing event is around the last 2 or 3 lines:

Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [MpdFrontend-21] mopidy.listener Sending playlist to MpdSession: {}
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Sent WebSocket message to 192.168.1.5: '{"jsonrpc": "2.0", "i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received RPC message from 192.168.1.90: b'{"jsonrpc":"2.0","i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received RPC message from 192.168.1.90: b'{"jsonrpc":"2.0","i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received RPC message from 192.168.1.90: b'{"jsonrpc":"2.0","i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy_iris.handlers Iris websocket message received: {"jsonrpc":"2.0","id":162549
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy_iris.core {'method': 'queue_metadata_changed', 'params': {'queue_metadata':
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy_iris.core {'id': 162549146541172, 'jsonrpc': '2.0', 'method': 'add_queue_me
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received WebSocket message from 192.168.1.5: '{"method":"core
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Sent WebSocket message to 192.168.1.5: '{"jsonrpc": "2.0", "i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received WebSocket message from 192.168.1.5: '{"method":"core
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Sent WebSocket message to 192.168.1.5: '{"jsonrpc": "2.0", "i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Received WebSocket message from 192.168.1.5: '{"method":"core
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Sent WebSocket message to 192.168.1.5: '{"jsonrpc": "2.0", "i
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy_iris.core {'method': 'connection_removed', 'params': {'connection': {'conne
Jul 05 15:24:25 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers Closed WebSocket connection from 192.168.1.5
Jul 05 15:27:39 pab mopidy[3965]: DEBUG    [SpotifyEventLoop] mopidy_spotify.playback End of track reached
Jul 05 15:27:39 pab mopidy[3965]: DEBUG    [Audio-2] mopidy.audio.gst Sending appsrc end-of-stream event.
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [Dummy-26] mopidy.audio.gst Got about-to-finish event.
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [Dummy-26] mopidy.audio.actor Running about-to-finish callback.
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [SpotifyBackend-9] mopidy_spotify.playback Audio requested change of track; loading and startin
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [Audio-2] mopidy.audio.gst Sending TAG event for track 'spotify:track:7Kc3hZoCRTs5dNHU7GqT9x': 
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [Dummy-26] mopidy.audio.gst Got source-setup signal: element=GstAppSrc
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [Dummy-26] mopidy.audio.gst Enabling live stream mode
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [SpotifyBackend-9] mopidy_spotify.playback Audio requested seek to 0
Jul 05 15:27:45 pab mopidy[3965]: DEBUG    [SpotifyBackend-9] mopidy_spotify.playback Skipping seek due to issue mopidy/mopidy#300
Jul 05 15:31:08 pab mopidy[3965]: DEBUG    [HttpServer] mopidy.http.handlers New WebSocket connection from 192.168.1.5