search

savonet / liquidsoap

Liquidsoap is a statically typed scripting general-purpose language with dedicated operators and backend for all thing media, streaming, file generation, automation, HTTP backend and more.
http://liquidsoap.info
GNU General Public License v2.0
1.41k stars 130 forks source link

Newly Ready Sources Have No Resolved Items #1982

Closed Kerosel closed 3 years ago

Kerosel commented 3 years ago

Describe the bug A source that was not ready and then becomes ready (playlist reload, queue push) does not resolve its first item until it is taken. It is considered to be ready/un-failed and functions such as fallback or random will attempt to use it. When it is taken it fails (fallback moves on, random re-selects), but it does resolve its first item. Subsequent attempts to play from the queue/playlist behave as expected.

To Reproduce A request queue with a fallback to a playlist will demonstrate this behavior:

list=playlist(prefix="replaygain:","/mnt/media/audio/MP3s/Aqua^2/")
rlist=request.queue(id="requests")
radio=mksafe(crossfade(smart=true,replaygain(fallback([rlist,list]))))
output.icecast(%mp3, host = "*", port = *, password = "*", mount = "*", radio)

Push an item into the queue via telnet. Trace the RID and note that the item is pushed but not resolved. Skip to the next track in the output. Trace the RID and observe that the item in the queue has resolved and will play at next track change:

requests.push replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT
2
END
request.trace 2
[2021/09/22 23:00:52] Pushed ["replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
END
request.trace 2
[2021/09/22 23:00:52] Pushed ["replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
END
stream.skip
Done
END
request.trace 2
[2021/09/22 23:00:52] Pushed ["replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
[2021/09/22 23:01:09] Resolving "replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT" (timeout 60s)...
END
request.trace 2
[2021/09/22 23:00:52] Pushed ["replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
[2021/09/22 23:01:09] Resolving "replaygain:/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT" (timeout 60s)...
[2021/09/22 23:01:17] Pushed ["annotate:replaygain_track_gain=\"+0.82 dB\":/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
[2021/09/22 23:01:17] Resolving "annotate:replaygain_track_gain=\"+0.82 dB\":/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT" (timeout 60s)...
[2021/09/22 23:01:17] Pushed ["/mnt/media/audio/tracker/Leviathn/K_SGROOV.IT";...].
END

For an alternative example, replace the "fallback" with a "random". Push an item into the queue and watch the log output. You should see the queue item prepare/resolve but not play until random calls on it a second time (annotated log available on request).

Expected behavior Newly ready queues and playlists should be ready to roll on the first call. When they become ready, they should make sure they have their first item resolved and if not, resolve their first item as part of becoming ready.

I believe this regressed in 1.4.x and worked as expected in 1.3.x. I'm debating if I want to go back to 1.3.x to verify that as fact...

(I did go back and test in versions previous to 2.0.0 and I was wrong, see comment below)

Version details Debian 11 Bullseye - Liquidsoap 2.0.0 (GitHib auto-build from CI #3245 September 25)

Install method Downloaded CI #3245 GitHub DEB package and installed manually via Apt.

Kerosel commented 3 years ago

Ta da, I was mistaken about it not working prior to 2.0.0. The request queue example works correctly in 1.3.3, 1.4.3 and 1.4.4 (with proper rewriting to be compatible with earlier versions, of course). Example telnet push from 1.4.4:

requests.push replay_gain:/mnt/media/audio/MP3s/dontwant.mp3
4
END
request.trace 4
[2021/09/26 20:26:55] Pushed ["replay_gain:/mnt/media/audio/MP3s/dontwant.mp3";...].
[2021/09/26 20:26:55] "replay_gain:/mnt/media/audio/MP3s/dontwant.mp3" entered the secondary queue : position #1.
[2021/09/26 20:26:55] Entering the primary queue.
[2021/09/26 20:26:55] Resolving "replay_gain:/mnt/media/audio/MP3s/dontwant.mp3" (timeout 60s)...
[2021/09/26 20:26:56] Pushed ["annotate:replay_gain=\"-3.18 dB\":/mnt/media/audio/MP3s/dontwant.mp3";...].
[2021/09/26 20:26:56] Resolving "annotate:replay_gain=\"-3.18 dB\":/mnt/media/audio/MP3s/dontwant.mp3" (timeout 60s)...
[2021/09/26 20:26:56] Pushed ["/mnt/media/audio/MP3s/dontwant.mp3";...].
END
stream.skip
Done
END
request.trace 4
[2021/09/26 20:26:55] Pushed ["replay_gain:/mnt/media/audio/MP3s/dontwant.mp3";...].
[2021/09/26 20:26:55] "replay_gain:/mnt/media/audio/MP3s/dontwant.mp3" entered the secondary queue : position #1.
[2021/09/26 20:26:55] Entering the primary queue.
[2021/09/26 20:26:55] Resolving "replay_gain:/mnt/media/audio/MP3s/dontwant.mp3" (timeout 60s)...
[2021/09/26 20:26:56] Pushed ["annotate:replay_gain=\"-3.18 dB\":/mnt/media/audio/MP3s/dontwant.mp3";...].
[2021/09/26 20:26:56] Resolving "annotate:replay_gain=\"-3.18 dB\":/mnt/media/audio/MP3s/dontwant.mp3" (timeout 60s)...
[2021/09/26 20:26:56] Pushed ["/mnt/media/audio/MP3s/dontwant.mp3";...].
[2021/09/26 20:27:04] Currently on air.
END

Notice after push the item is resolved and re-pushed immediately. After one stream,skip, the request queue item is now on air.

However I also note that previous to 2.0.0 the request queues were still using a primary/secondary queue format, which I believe has been removed (or at least deprecated) starting in 2.0.0. it could be this change that's causing queue/playlist items to not be ready until they're called on twice.

Anyway, this isn't a stream-breaker and I would consider it lower priority. It just means newly-ready playlists and queues take extra time to start playing, but eventually they do play.

toots commented 3 years ago

Thanks for this report. request.queue was completely reworked with the v2.0.0 work to be implemented on the scripting side.

I believe the bug should be fixed now. Would you mind confirming it with us?

Thanks!

Kerosel commented 3 years ago

(See Update in Next Comment)

I can confirm that the queue now plays on the track change immediately after an item is pushed to it! Success!

I did end up concentrating on the queue in the end, but this issue is still present with my playlist that watches a file that starts empty. I was kinda hoping that the fix would cover them both, but that doesn't seem to be the case.

The test code snippet:

album = merge_tracks(playlist(loop=false,reload_mode="watch",mode="normal","/mnt/media/audio/radiolists/albumlist"))
radio=mksafe(crossfade(smart=true,replaygain(fallback([rlist,album,list]))))
[output, etc etc etc]

When URIs are added to the watched file, the playlist picks it up:

2021/09/28 20:53:18 [albumlist:3] Reloading playlist with URI /mnt/media/audio/radiolists/albumlist.
2021/09/28 20:53:18 [albumlist:4] Reloading playlist.
2021/09/28 20:53:18 [playlist parser:4] Trying application/rss+xml parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/xspf+xml parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/smil+xml parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/smil parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/xml parser
2021/09/28 20:53:18 [playlist parser:4] Trying text/xml parser
2021/09/28 20:53:18 [playlist parser:4] Trying audio/x-ms-asx parser
2021/09/28 20:53:18 [playlist parser:4] Trying video/x-ms-asf parser
2021/09/28 20:53:18 [playlist parser:4] Trying youtube-dl parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/x-cue parser
2021/09/28 20:53:18 [playlist parser:4] Trying audio/x-scpls parser
2021/09/28 20:53:18 [playlist parser:4] Trying application/x-mpegURL parser

But there is nothing at the ready until the next track change. It takes another track change for playback to start:

albumlist.next

END
stream.skip
Done
END
albumlist.next
[ready] /mnt/media/audio/collection/soundtracks/cityofindustry/01 - Massive Attack - Three.flac
END
stream.skip
Done
END
albumlist.next
[playing] /mnt/media/audio/collection/soundtracks/cityofindustry/01 - Massive Attack - Three.flac
[ready] /mnt/media/audio/collection/soundtracks/cityofindustry/02 - Lush - Last Night (Darkest Hour mix).flac
END

Now it did occur to me that it might not be very nice behavior to send a playlist to an empty file. So I did some testing where I started the "album" playlist file with a single entry and let it play until it finished and the stream dropped back to the other playlist. I changed the URI in the album file and things behaved the same way: the file change is detected immediately, but "albumlist.next" is empty until a track change. At that point the URI shows up but it does not play until the following track change.

I'm willing to bet this affects any playlist when it is reloaded. It just might not be obvious if it's the currently selected playlist because it will fail and get re-selected immediately (and then will work). It may only show up if it's a situation where something else will play if the reloaded playlist isn't ready/fails.

Hopefully the fix is something similar to the queues (they certainly behave the same) and doesn't involve tearing up the code too much.

Kerosel commented 3 years ago

It dawned on me what you meant by request.queue being implemented on the scripting side, so I went hunting and looked at what you did with the fetch command on the request.queue. I added the same statements to playlist.list, triggering the fetch when the list was reloaded and it appears to work the way I think it should work. I will continue testing...

In the meantime, I could offer a diff of the changes I made. It's the addition of maybe four lines to the code (exactly what you added to request.queue). Heck, you could probably figure out what changes to make without seeing what I did.