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

Request leak using playlist watch reload mode #1246

Closed GermanCascales closed 4 years ago

GermanCascales commented 4 years ago

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

toots commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

Couple of details regarding this issue:

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 commented 4 years ago

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

toots commented 4 years ago

Thanks.

toots commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago 
s = playlist(mode="randomize", reload_mode="watch", "list1.m3u")
output.ao(fallible=true, s)

That simple script works like a charm!

toots commented 4 years ago

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

toots commented 4 years ago

Ok, two good news:

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

toots commented 4 years ago

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