Request leak using playlist watch reload mode

[GermanCascales]

Describe the bug
When the playlist file is modified only once, sometimes Liquidsoap watches the file up to 1000 times, leading to request leaks that produces silent output and needing to restart. Is there a way to avoid this? Thanks!

To Reproduce

list1 = playlist(mode="randomize", reload_mode="watch", "list1.m3u")
list2 = playlist(mode="randomize", reload_mode="watch", "list2.m3u")
s = rotate.merge(weights=[1,1],[list1, list2])
s2 = fallback([ switch([( {7h00m-23h00m} , s)]), blank(duration=1.0) ])
output.ao(fallible=true,normalize(s2))

Log shows like this:

2020/05/22 00:00:00 [list1(dot)m3u:3] Loading playlist...
2020/05/22 00:00:01 [list1(dot)m3u:3] No mime type specified, trying autodetection.
2020/05/22 00:00:01 [list1(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/05/22 00:00:01 [list1(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/05/22 00:00:01 [list1(dot)m3u:3] Loading playlist...
2020/05/22 00:00:01 [list1(dot)m3u:3] No mime type specified, trying autodetection.
2020/05/22 00:00:01 [list1(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/05/22 00:00:01 [list1(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/05/22 00:00:01 [list1(dot)m3u:3] Loading playlist...
2020/05/22 00:00:01 [list1(dot)m3u:3] No mime type specified, trying autodetection.
2020/05/22 00:00:01 [list1(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/05/22 00:00:01 [list1(dot)m3u:3] Successfully loaded a playlist of 2 tracks.

[...]

2020/05/22 00:00:03 [request:2] There are currently 900 RIDs, possible request leak! Please check that you don't have a loop on empty/unavailable requests, or creating requests without destroying them. Decreasing request.grace_time can also help.
2020/05/22 00:00:03 [list1(dot)m3u:3] No mime type specified, trying autodetection.
2020/05/22 00:00:03 [list1(dot)m3u:3] No mime type specified, trying autodetection.
2020/05/22 00:00:03 [list1(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/05/22 00:00:03 [list1(dot)m3u:3] Playlist treated as format application/x-mpegURL

Version details

• OS: Windows 10 x64
• Version: Liquidsoap 1.4.2

[toots]

Thanks for this report & sorry for the delayed response, I've been busy on new code lately. I'll try to have a look at asap.

[GermanCascales]

Thanks for the reply. It works okay on the first 6-7 days, but any other playlist updates after this time makes Liquidsoap stop playing without any crash (tried log at level 5 and it doesn't show anything weird when this happens). Next file of ads playlist that should be played after first song it's not even prepared.

Attached last part of the log until the moment that the playback stops.

2020/06/29 00:10:07 [ads(dot)m3u:3] Loading playlist...
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:10:07 [ads(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/06/29 00:10:07 [ads(dot)m3u:3] Loading playlist...
2020/06/29 00:10:07 [ads(dot)m3u:3] No mime type specified, trying autodetection.
2020/06/29 00:10:07 [playlist parser:4] Trying youtube-dl parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-cue parser
2020/06/29 00:10:07 [playlist parser:4] Trying audio/x-scpls parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-mpegURL parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:10:07 [ads(dot)m3u:3] No mime type specified, trying autodetection.
2020/06/29 00:10:07 [playlist parser:4] Trying youtube-dl parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-cue parser
2020/06/29 00:10:07 [playlist parser:4] Trying audio/x-scpls parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-mpegURL parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Loading playlist...
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:10:07 [ads(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/06/29 00:10:07 [ads(dot)m3u:3] Loading playlist...
2020/06/29 00:10:07 [ads(dot)m3u:3] No mime type specified, trying autodetection.
2020/06/29 00:10:07 [playlist parser:4] Trying youtube-dl parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-cue parser
2020/06/29 00:10:07 [playlist parser:4] Trying audio/x-scpls parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-mpegURL parser
2020/06/29 00:10:07 [ads(dot)m3u:3] No mime type specified, trying autodetection.
2020/06/29 00:10:07 [playlist parser:4] Trying youtube-dl parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-cue parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:10:07 [playlist parser:4] Trying audio/x-scpls parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-mpegURL parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Successfully loaded a playlist of 2 tracks.
2020/06/29 00:10:07 [ads(dot)m3u:3] Loading playlist...
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:10:07 [ads(dot)m3u:3] No mime type specified, trying autodetection.
2020/06/29 00:10:07 [playlist parser:4] Trying youtube-dl parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-cue parser
2020/06/29 00:10:07 [playlist parser:4] Trying audio/x-scpls parser
2020/06/29 00:10:07 [playlist parser:4] Trying application/x-mpegURL parser
2020/06/29 00:10:07 [ads(dot)m3u:3] Playlist treated as format application/x-mpegURL
2020/06/29 00:15:00 [fallback_8133:3] Switch to switch_8131 with forgetful transition.
2020/06/29 00:15:00 [sequence_95448:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:15:00 [source:4] Source sequence_95448 gets down.
2020/06/29 00:15:00 [max_duration_95447:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:15:00 [source:4] Source max_duration_95447 gets down.
2020/06/29 00:15:00 [blank_8132:4] Activations changed: static=[sequence_95448:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:00 [blank_8132:4] Disabling caching mode.
2020/06/29 00:15:00 [blank_8132:4] Activations changed: static=[], dynamic=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:00 [source:4] Source sequence_95457 gets up.
2020/06/29 00:15:00 [source:4] Source max_duration_95456 gets up.
2020/06/29 00:15:00 [switch_8131:4] Activations changed: static=[max_duration_95456:sequence_95457:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:00 [max_duration_95456:4] Activations changed: static=[sequence_95457:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[].
2020/06/29 00:15:00 [switch_8131:4] Activations changed: static=[sequence_95457:fallback_8133:on_metadata_8135:normalize_8137:ao:ao, max_duration_95456:sequence_95457:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:00 [switch_8131:4] Enabling caching mode: two static activations.
2020/06/29 00:15:00 [sequence_95457:4] Activations changed: static=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[].
2020/06/29 00:15:00 [switch_8131:3] Switch to switch_8129.
2020/06/29 00:15:00 [switch_8129:4] Activations changed: static=[switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:00 [on_metadata_8135:5] Got metadata at position 0: calling handler...
2020/06/29 00:15:00 [on_metadata_8135:5] Got metadata at position 0: calling handler...
2020/06/29 00:15:00 [on_metadata_8135:5] Got metadata at position 864: calling handler...
2020/06/29 00:15:05 [sequence_95423:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:15:05 [source:4] Source sequence_95423 gets down.
2020/06/29 00:15:05 [blank_95422:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:15:05 [source:4] Source blank_95422 gets down.
2020/06/29 00:15:05 [music(dot)m3u:4] Activations changed: static=[sequence_95425:rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:05 [music(dot)m3u:4] Disabling caching mode.
2020/06/29 00:15:05 [source:4] Source empty_95464 gets up.
2020/06/29 00:15:05 [empty_95464:4] Content kind is {audio=2;video=0;midi=0}.
2020/06/29 00:15:05 [empty_95464:4] Activations changed: static=[max_duration_95424], dynamic=[].
2020/06/29 00:15:05 [sequence_8128:4] Activations changed: static=[sequence_95439:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao, switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:05 [sequence_8128:4] Disabling caching mode.
2020/06/29 00:15:05 [source:4] Source empty_95468 gets up.
2020/06/29 00:15:05 [empty_95468:4] Content kind is {audio=2;video=0;midi=0}.
2020/06/29 00:15:05 [empty_95468:4] Activations changed: static=[max_duration_95438], dynamic=[].
2020/06/29 00:15:05 [switch_8131:4] Activations changed: static=[sequence_95457:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:15:05 [switch_8131:4] Disabling caching mode.
2020/06/29 00:15:05 [source:4] Source empty_95472 gets up.
2020/06/29 00:15:05 [empty_95472:4] Content kind is {audio=2;video=0;midi=0}.
2020/06/29 00:15:05 [empty_95472:4] Activations changed: static=[max_duration_95456], dynamic=[].
2020/06/29 00:17:59 [decoder:4] Decoding "C:\Program Files\xx\xx\xx\xx\xx.aac" ended: Aac_decoder.End_of_stream.
2020/06/29 00:18:00 [music(dot)m3u:4] Finished with "C:\Program Files\xx\xx\xx\xx\xx.aac".
2020/06/29 00:18:00 [music(dot)m3u:4] Remaining: 0.0s, queued: 30.0s, taking: 30.0s
2020/06/29 00:18:00 [music(dot)m3u:3] Prepared "C:\Program Files\xx\xx\xx\xx\xx.aac" (RID 0).
2020/06/29 00:18:00 [rotate_8127:3] Switch to ads(dot)m3u with forgetful transition.
2020/06/29 00:18:00 [sequence_95425:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:18:00 [source:4] Source sequence_95425 gets down.
2020/06/29 00:18:00 [max_duration_95424:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:18:00 [source:4] Source max_duration_95424 gets down.
2020/06/29 00:18:00 [empty_95464:4] Activations changed: static=[], dynamic=[].
2020/06/29 00:18:00 [source:4] Source empty_95464 gets down.
2020/06/29 00:18:00 [music(dot)m3u:4] Activations changed: static=[], dynamic=[rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:18:00 [source:4] Source sequence_95478 gets up.
2020/06/29 00:18:00 [source:4] Source max_duration_95477 gets up.
2020/06/29 00:18:00 [ads(dot)m3u:4] Activations changed: static=[max_duration_95477:sequence_95478:rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:18:00 [max_duration_95477:4] Activations changed: static=[sequence_95478:rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[].
2020/06/29 00:18:00 [ads(dot)m3u:4] Activations changed: static=[sequence_95478:rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao, max_duration_95477:sequence_95478:rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao].
2020/06/29 00:18:00 [ads(dot)m3u:4] Enabling caching mode: two static activations.
2020/06/29 00:18:00 [sequence_95478:4] Activations changed: static=[rotate_8127:sequence_8128:switch_8129:switch_8131:fallback_8133:on_metadata_8135:normalize_8137:ao:ao], dynamic=[].
2020/06/29 00:18:00 [sequence_8128:4] End of track: merging.

[toots]

Couple of details regarding this issue:

• Since you are on windows, the file watcher mechanism has to be our own implementation
• This implementation checks for the file's latest change time each second

Thus, I am a little bit surprised that it could be fired multiple times at once. The most likely culprit would be the task scheduler itself or else an issue with the task itself.

I have pushed some minor changes that may or may not fix the issue. Could you try them? You should be able to test by grabbing the windows build that should be attached to this CI run once it terminates: https://github.com/savonet/liquidsoap/actions/runs/158399940

[GermanCascales]

Apologies for the delayed response. Still firing many times per second with that pre-release.

[toots]

Thanks.

[toots]

I'll be looking at this one next. The reproduction script is much appreciated! Have you tried to narrow it down even more? Like this for instance:

s = playlist(mode="randomize", reload_mode="watch", "list1.m3u")
output.ao(fallible=true, s)

[toots]

I got the minimal script above running on a virtual windows machine. If I understand well the issue, I would wait for some time to see if I can reproduce the issue..

[GermanCascales]

s = playlist(mode="randomize", reload_mode="watch", "list1.m3u")
output.ao(fallible=true, s)

That simple script works like a charm!

[toots]

Very interesting, thanks. To reproduce, I need to keep updating the playlists?

[toots]

Ok, two good news:

• I can reproduce
• I can reproduce on my local OS!

Hopefully, now I should be able to track this down!

[toots]

Fixed in 3d1e3d6! Watch the build at https://github.com/savonet/liquidsoap/actions/runs/200580309 to get an updated build. Thanks for reporting!!