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

Scheduled playlist inside switch won't start playing (non-deterministic behaviour) #1156

Closed gammaw closed 3 years ago

gammaw commented 4 years ago

We have a strange non-reproducible behavior that we can't explain. Scheduled playbacks usually start as expected but sometimes they do not, although we don't change anything (no configuration, no new files).

We have a configuration which is essentially this: 

radio = switch(track_sensitive=false, transitions=[
    transition_into_show(playlist_jingle),
    transition_into_show(playlist_jingle),
    transition_into_show(playlist_jingle),
    ...
    transition_into_off(playlist_jingle_after_show) ], 
    transition_length=60., #max duration of jingle (60s)
    [
    #Live DJ
    ({!live_enabled}, live),
    #Monday
    ({1w and 5h-5h59m}, once(playlist_show1)),
    ({1w and 9h11m-10h11m}, once(playlist_show2)),
    ({1w and 11h-11h59m}, once(playlist_show3)),
    ...
    ({true}, radio) ])

When a show starts (good case, works most of the time) the log looks like this: 

2020/04/13 11:00:00 [playlist_show3:4] Remaining: 0.0s, queued: 3712.0s, taking: 3712.0s
2020/04/13 11:00:00 [playlist_show3:3] Prepared "/var/azuracast/stations/my_radio/media/session-239.mp3" (RID 13).
... //this is where the transition takes place (ca. 7 seconds, depending on the jingle)
2020/04/13 11:00:07 [playlist_show3:4] Remaining: 2419.0s, queued: 0.0s, adding: 3712.0s (RID 5)
...

As you can see, the playlist will be prepared, a transition with a jingle will take place, and the show will be played. All good!

In cases when a show won't start (bad case, happens every once in a while), the log looks like this: 

2020/04/13 09:11:00 [switch_8146:3] Switch to sequence_8053 with transition.
2020/04/13 09:11:00 [sequence_13816:4] Activations changed: static=[], dynamic=[].
... //this is where the transition takes place (ca. 17 seconds, depending on the jingle)
2020/04/13 09:11:17 [playlist_transverszia:4] Finished with "/var/azuracast/stations/lahmacun_radio/media/session-235_some_text.mp3".
...

As you can see, the preparation is missing, the jingle will be played, and then, wrongly, Liquidsoap will declare the stream as finished. A restart of the Liquidsoap service will fix things, the show will start as expected.

As you can imagine, these non-deterministic outages make our service fragile. We run Liquidsoap v1.4.1 inside Azuracast.

Any idea?

toots commented 4 years ago

Thanks for reporting. I understand the severity of the issue for y'all. Let's try to see if we can fix this for the upcoming 1.4.2.

This report is great for a start but do you think that you could run with more debug? In particular with log.level set to 5? I know that this generates a lot of verbosity but that could possibly help surface the issue for us.

The second this is to harness local caching. By default,playlist will only download one track at a time. If the show is long or take a while to download, it is possible that the track isn't ready in time for the transition. You can force the operator to have at least 2 files in queue at any time this way:

s = playlist(length60., ...)

This and the default_duration parameter. Their meaning is kinda weird and I definitely think we should update them in the next release to make more sense.

Let me know what you find!

gammaw commented 4 years ago

@toots thanks! We were already using log level 5, the excerpts above are from a log with this level. We saved the relevant parts of the logs and they should be still accessible in the running instance too. They are a bit lengthy so I'm not sure where and how to share it with you. Do you have a preferred way?

For the scheduled shows our convention and structure is that we have exactly one track in each playlist, which is the current episode of the show. Every time a new episode is ready, we replace the files in the corresponding playlist. So I don't think that caching would help in this case, would it?

Btw, here is our full configuration.

gammaw commented 4 years ago

@toots any chance that the new 1.4.2 will fix this one too? I see the release notes don't explicitly list this one but maybe as a side effect. I thought I ask. Thanks

toots commented 4 years ago

@gammaw I'm not sure. If not, I'll work on this next.

gammaw commented 4 years ago

Thanks. Let's see when Azuracast will integrate the new version so that we can start testing. The problem with this issue is that it's hard to debug (indeterministic and scarce) but when it manifests it hits big (a scheduled show won't start). If you have any hint in the meanwhile let us know (maybe ways to trigger it).

gammaw commented 4 years ago

@toots do you have any idea about this problem? Unfortunately, the issue is still there (with v1.4.2.) and it affects us heavily as it (sporadically) results in shows that wouldn't start. In such cases, we manually need to restart the Liquidsoap service, which fixes things (but sounds very strange on the user's end).

We had it today again and with default verbosity, I could see no trace of it (see log snippet). In this case, the show is scheduled to start at 10:00, which did not happen. The entry you see at 10:01 is the first entry upon restarting Liquidsoap. Then, the scheduled show started correctly. As I said, this happens from time to time, we don't know when, and with which show. 

2020/07/22 09:28:04 [lang:3] AzuraCast Feedback Response: OK
2020/07/22 10:01:14 [playlist_off_air_ambient:3] Loading playlist...
gammaw commented 4 years ago

@toots we had this issue today one more time. This time again, as described in my previous comment, there is no trace of any action in the Liquidsoap log at the time when the transition should happen. Maybe some addition to the issue is that ours later we added another file to one of the playlists (not the one that didn't start). The corresponding log entries of this addition are attached below.

Like always, when we restart the server, the scheduled playlist starts as expected. 

2020/08/25 08:11:13 [server:3] New client: 172.29.0.6.
2020/08/25 08:11:13 [playlist_azvlm:3] Loading playlist...
2020/08/25 08:11:13 [playlist_azvlm:3] No mime type specified, trying autodetection.
2020/08/25 08:11:13 [playlist parser:4] Trying youtube-dl parser
2020/08/25 08:11:13 [playlist parser:4] Trying application/x-cue parser
2020/08/25 08:11:13 [playlist parser:4] Trying audio/x-scpls parser
2020/08/25 08:11:13 [playlist parser:4] Trying application/x-mpegURL parser
2020/08/25 08:11:13 [playlist_azvlm:3] Playlist treated as format application/x-mpegURL
2020/08/25 08:11:13 [playlist_azvlm:4] Expirations made the queue too short, feeding...
2020/08/25 08:11:13 [playlist_azvlm:3] Successfully loaded a playlist of 0 tracks.
2020/08/25 08:11:13 [server:3] Client 172.29.0.6 disconnected.
2020/08/25 08:11:14 [playlist_azvlm:3] Loading playlist...
2020/08/25 08:11:14 [playlist_azvlm:3] No mime type specified, trying autodetection.
2020/08/25 08:11:14 [playlist parser:4] Trying youtube-dl parser
2020/08/25 08:11:14 [playlist parser:4] Trying application/x-cue parser
2020/08/25 08:11:14 [playlist parser:4] Trying audio/x-scpls parser
2020/08/25 08:11:14 [playlist parser:4] Trying application/x-mpegURL parser
2020/08/25 08:11:14 [playlist_azvlm:3] Playlist treated as format application/x-mpegURL
2020/08/25 08:11:14 [playlist_azvlm:3] Successfully loaded a playlist of 0 tracks.
2020/08/25 08:11:23 [server:3] New client: 172.29.0.6.
2020/08/25 08:11:23 [playlist_azvlm:3] Loading playlist...
2020/08/25 08:11:23 [playlist_azvlm:3] No mime type specified, trying autodetection.
2020/08/25 08:11:23 [playlist parser:4] Trying youtube-dl parser
2020/08/25 08:11:23 [playlist parser:4] Trying application/x-cue parser
2020/08/25 08:11:23 [playlist parser:4] Trying audio/x-scpls parser
2020/08/25 08:11:23 [playlist parser:4] Trying application/x-mpegURL parser
2020/08/25 08:11:23 [server:3] Client 172.29.0.6 disconnected.
2020/08/25 08:11:23 [playlist_azvlm:3] Playlist treated as format application/x-mpegURL
2020/08/25 08:11:23 [playlist_azvlm:3] Successfully loaded a playlist of 1 tracks.
2020/08/25 08:11:23 [decoder:4] Trying method "META" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "WAV" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.wav/aiff:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "AIFF" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.wav/aiff:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MIDI" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "IMAGE" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "FLAC" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.flac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "AAC" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.aac:4] Libfaad recognizes "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3" as AAC (44100Hz,2 channels).
2020/08/25 08:11:23 [decoder.aac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MP4" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Decoder "MP4" failed on "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3": Faad.Failed!
2020/08/25 08:11:23 [decoder:4] Trying method "OGG" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.ogg:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MAD" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3".
2020/08/25 08:11:23 [metadata.flac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [metadata.mp4:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder.ogg:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [playlist_azvlm:4] Dropping expired request.
2020/08/25 08:11:23 [playlist_azvlm:4] Remaining: 65.4s, queued: 0.0s, adding: 2758.0s (RID 63)
2020/08/25 08:11:23 [playlist_azvlm:3] Loading playlist...
2020/08/25 08:11:23 [playlist_azvlm:3] No mime type specified, trying autodetection.
2020/08/25 08:11:23 [playlist parser:4] Trying youtube-dl parser
2020/08/25 08:11:23 [playlist parser:4] Trying application/x-cue parser
2020/08/25 08:11:23 [playlist parser:4] Trying audio/x-scpls parser
2020/08/25 08:11:23 [playlist parser:4] Trying application/x-mpegURL parser
2020/08/25 08:11:23 [playlist_azvlm:3] Playlist treated as format application/x-mpegURL
2020/08/25 08:11:23 [playlist_azvlm:4] Expirations made the queue too short, feeding...
2020/08/25 08:11:23 [playlist_azvlm:3] Successfully loaded a playlist of 1 tracks.
2020/08/25 08:11:23 [decoder:4] Trying method "META" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "WAV" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.wav/aiff:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "AIFF" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.wav/aiff:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MIDI" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "IMAGE" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Trying method "FLAC" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.flac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "AAC" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.aac:4] Libfaad recognizes "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3" as AAC (44100Hz,2 channels).
2020/08/25 08:11:23 [decoder.aac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MP4" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:4] Decoder "MP4" failed on "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3": Faad.Failed!
2020/08/25 08:11:23 [decoder:4] Trying method "OGG" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder.ogg:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder:4] Trying method "MAD" for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"...
2020/08/25 08:11:23 [decoder:3] Method "MAD" accepted "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3".
2020/08/25 08:11:23 [metadata.flac:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [metadata.mp4:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [decoder.ogg:4] Invalid file extension for "/var/azuracast/stations/lahmacun_radio/media/csepel_gang_miaza.mp3"!
2020/08/25 08:11:23 [playlist_azvlm:4] Dropping expired request.
2020/08/25 08:11:23 [playlist_azvlm:4] Remaining: 65.4s, queued: 0.0s, adding: 2758.0s (RID 72)
stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 3 years ago

This issue was closed for lack of activity. If you believe that it is still relevant, please confirm that it applies to the latest released version of liquidsoap and re-open the ticket. Thanks!