Restore state not working for DLNA extension

General
1

I’ve just started using Mopidy-dLeyna and I’ve noticed that it doesn’t seem to add tracks back into the tracklist when restoring state.
It looks like it’s trying to validate whether the track is playable when it tries to add it to the tracklist, but it doesn’t discover the DLNA server until after it’s tried to restored the state.

Restore state seems to work well for the other backends I’ve used. Any ideas? Is it fixable?

Thanks.

INFO     2020-10-09 09:17:08,903 [1:MainThread] mopidy.commands
  Starting Mopidy core
INFO     2020-10-09 09:17:09,093 [1:Core-11] mopidy.core.actor
  Loading state from /root/.local/share/mopidy/core/state.json.gz
ERROR    2020-10-09 09:17:09,645 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303533: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,651 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303533
ERROR    2020-10-09 09:17:09,676 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303534: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,682 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303534
ERROR    2020-10-09 09:17:09,706 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303535: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,714 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303535
ERROR    2020-10-09 09:17:09,737 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303536: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,744 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303536
ERROR    2020-10-09 09:17:09,767 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303537: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,773 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313339303532243133393035322440313339303537
ERROR    2020-10-09 09:17:09,799 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313334323230243133343335302440313334333530: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:09,805 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313334323230243133343335302440313334333530
...
WARNING  2020-10-09 09:17:10,394 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313334323230243133343335302440313334333730
ERROR    2020-10-09 09:17:10,414 [1:dLeynaBackend-7] mopidy_dleyna.playback
  Error translating dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313334323230243133343335302440313334333731: Unknown media server UDN uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100
WARNING  2020-10-09 09:17:10,420 [1:Core-11] mopidy.core.tracklist
  Track is not playable: dleyna://uuid%3a0011320b-0c6d-0011-6d0c-6d0c0b321100/333024313334323230243133343335302440313334333731
INFO     2020-10-09 09:17:10,440 [1:MainThread] mopidy.commands
  Starting Mopidy frontends: ScrobblerFrontend, MpdFrontend, IrisFrontend, HttpFrontend, GMusicScrobblerFrontend
INFO     2020-10-09 09:17:10,474 [1:MainThread] mopidy_mpd.actor
  MPD server running at [::ffff:0.0.0.0]:6600
INFO     2020-10-09 09:17:10,497 [1:IrisFrontend-14] mopidy_iris.core
  Starting Iris 3.52.4
INFO     2020-10-09 09:17:10,523 [1:HttpFrontend-16] mopidy.http.actor
  HTTP server running at [::ffff:0.0.0.0]:6680
INFO     2020-10-09 09:17:10,546 [1:MainThread] mopidy.commands
  Starting GLib mainloop
INFO     2020-10-09 09:17:11,211 [1:MainThread] mopidy_dleyna.client
  Found digital media server JJ-NAS [uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100]
2

Good spot, this may also apply to other backends. I don’t think we’d want Mopidy-dLeyna to block everything from starting while it finds the available DLNA servers, sounds potentially slow. Are the track URIs for the dleyna backend guaranteed to be the same between boots?

3

Hmm. Don’t know. You can see the UUID of the server is the same, but I’ll have to check about the track IDs.

If they are the same, would the fix be to just add the tracks without checking to see if the server is there?

4

I think we already do restore the tracks regardless of the track availability and it’s the restoration of the playback state that causes the issue. i.e. If Mopidy was playing/paused when it was shutdown then it restarts playback from wherever it got to as part of the startup state restoration. You’d get the same thing if you removed/disabled a backend that had tracks in the saved state. But if you stop (not pause) before shutting down then I don’t think this issue occurs - is that right? (note that some clients/frontends will clear the queue as part of the stop request.) Do the tracks actually get removed from the tracklist or is it just the errors and if you wait for the DLNA server to turn up can you then play the tracklist?

5

That’s right. I pause playback before shutting down the computer.
The tracks all get removed from the tracklist (or don’t get re-added in the first place).

6

Do you have consume mode on? In that case it will remove each track in turn when it fails to play it.

7

Yes. That makes sense.

8

Do you have any thoughts on a better way to handle this situation? If we had a config to force playback to stop, or a config mechanism to skip restoring specific things i.e. playback, would that work better? It would mean you’d always have to manually resume playback yourself on startup but personally I think that sounds better. However, I don’t know if people use the playback resume feature as it is. Even if it’s potentially unreliable for any media not immediately available once it’s backend has supposedly started. Part of that problem is there’s no way in Mopidy to distinguish between when a backend has started when it is actually ready for use.

Or maybe it’d be enough just to temporarily disable consume, at least until the playback state has began restored.

9

Just did a bit of a test and it seems to behave exactly like you said.

  • I added some tracks, without playing, then restarted. There were no errors and the tracklist was still there.
  • I added tracks, then played, then paused, restarted. The errors showed up, but the tracklist remained intact.
  • Did the same, with consume enabled. The errors showed and the tracklist was empty.
10

Are the track URIs for the dleyna backend guaranteed to be the same between boots?

I added the same tracks for each of those tests and the error messages showed the same URIs.

I don’t think we’d want Mopidy-dLeyna to block everything from starting while it finds the available DLNA servers, sounds potentially slow.

I’m pretty used to slow start ups as I’ve been using gmusic (RIP) on a Pi. It hangs for about 5 minutes while it refreshes the library.

This is the startup on my laptop with Spotify, GMusic and DLNA enabled. Spotify and gmusic both start refreshing their libraries and playlists, and everything else appears to wait until those complete (I don’t actually know how that works, in terms of threading). Then, once those are done, it restores the state.
I think it would be fair enough to scan for media servers and make other things wait, in the same way. It doesn’t seem to take any significant amount of time, anyway.

INFO     2020-10-09 23:57:53,975 [1:MainThread] mopidy.commands
  Starting Mopidy backends: SpotifyBackend, PodcastBackend, dLeynaBackend, GMusicBackend
INFO     2020-10-09 23:57:54,005 [1:MainThread] mopidy_dleyna.backend
  Starting Mopidy-dLeyna D-Bus daemon
INFO     2020-10-09 23:57:54,011 [1:Audio-2] mopidy.audio.actor
  Audio output set to "autoaudiosink"
INFO     2020-10-09 23:57:54,646 [1:SpotifyEventLoop] mopidy_spotify.backend
  Logged in to Spotify in online mode
INFO     2020-10-09 23:57:54,713 [1:SpotifyBackend-3] mopidy_spotify.web
  Logged into Spotify Web API as j*********
INFO     2020-10-09 23:57:55,090 [1:GMusicBackend-7] mopidy_gmusic.session
  Logged in to Google Play Music
INFO     2020-10-09 23:57:55,092 [1:Thread-9] mopidy_gmusic.library
  Refreshing library
INFO     2020-10-09 23:58:07,598 [1:Thread-10] mopidy_gmusic.playlists
  Loaded 5 playlists from Google Play Music
INFO     2020-10-09 23:58:08,810 [1:Thread-9] mopidy_gmusic.library
  Loaded 442 artists, 1030 albums, 8439 tracks from Google Play Music
INFO     2020-10-09 23:58:45,427 [1:SpotifyBackend-3] mopidy_spotify.playlists
  Refreshed 411 Spotify playlists
INFO     2020-10-09 23:58:45,437 [1:MainThread] mopidy.commands
  Starting Mopidy core
INFO     2020-10-09 23:58:45,460 [1:Core-11] mopidy.core.actor
  Loading state from /root/.local/share/mopidy/core/state.json.gz
INFO     2020-10-09 23:58:45,467 [1:MainThread] mopidy.commands
  Starting Mopidy frontends: ScrobblerFrontend, MpdFrontend, IrisFrontend, HttpFrontend, GMusicScrobblerFrontend
INFO     2020-10-09 23:58:45,470 [1:MainThread] mopidy_mpd.actor
  MPD server running at [::ffff:0.0.0.0]:6600
INFO     2020-10-09 23:58:45,473 [1:IrisFrontend-14] mopidy_iris.core
  Starting Iris 3.52.4
INFO     2020-10-09 23:58:45,628 [1:HttpFrontend-16] mopidy.http.actor
  HTTP server running at [::ffff:0.0.0.0]:6680
INFO     2020-10-09 23:58:45,633 [1:MainThread] mopidy.commands
  Starting GLib mainloop
INFO     2020-10-09 23:58:45,715 [1:MainThread] mopidy_dleyna.client
  Found digital media server JJ-NAS [uuid:0011320b-0c6d-0011-6d0c-6d0c0b321100]
INFO     2020-10-09 23:58:46,701 [1:ScrobblerFrontend-12] mopidy_scrobbler.frontend
  Scrobbler connected to Last.fm
11

I’ve had a fair amount of complaints/comments about Mopidy-Spotify’s slow startup behaviour and I’ve been sitting on a branch to do the refresh in the background instead. That’s kind of why I was quite interested in this issue, to see if this might also be a problem with my potential change.

12

Does the Spotify library need to have loaded in order to be able to play a track from a URI? I’m guessing it probably doesn’t. So can you restore the state and start playing, or pause it, and then have the library load later.
I guess it makes sense that it would work, as they’re just URLs to things in the internet.

I think for DLNA it will have to have the scan happen before restoring the state as they’re URIs to things that don’t exist until the local server has been discovered.

I suppose the DLNA scan is the equivalent of signing into a service like Spotify or Gmusic.

13

What’s the best way forward with this?

I’m not sure why Spotify and Gmusic both happen before the state is restored, but DLNA doesn’t do it’s scan until afterwards. The only difference I can see in how they’re working it that Spotify and Gmusic both implement on_start() and that’s where they do the log in and library refresh, whereas DLNA does it’s equivalent setup straight in the __init__() of the backend class. If anything, I would’ve thought that would cause the opposite behaviour.

14

Basically, backends start first and the simplest way to implement a backend is to have it block until it has finished starting. I’m not very familiar with the DLNA backend but it looks like the scan technically starts when the backend is created (i.e. before it’s actor actually starts) but the scan results come back asynchronously so the backend does not block Mopidy’s startup. Compare that to Mopidy-Spotify where the playlist refreshing runs in the actor’s on_start() method and therefore blocks Mopidy’s startup until the refresh finishes.

Mopidy does not mandate what state an extension should be in after it’s on_start() has returned. You can imagine that a backend extension may be restricted by what its underlying media source provides, so this seems reasonable. In the case of Mopidy-Dleyna, it looks like there is a synchronous way to get the servers and maybe it makes sense to use that? Do you have any thoughts, @tkem ?

15

I spent a while looking into how Mopidy-Dleyna works but couldn’t understand all the libraries involved.
If its just a case of moving the current code into on_start(), then I can definitely give that a go, but if its changing the call to dbus to make it synchronous, then I could do with someone pointing me to some documentation.