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.4k stars 129 forks source link

request.dynamic with length > 30 leads to double-playback #639

Closed art1c0 closed 3 years ago

art1c0 commented 6 years ago

In my setup I have to use the length parameter for request.dynamic, otherwise long tracks (about 60 minutes) are getting prepared too late (actually they need about 45 seconds to prepare).

If I set "length" value to 30 seconds it works well, but if I try to increase (tried 60, 45, even 35) - strange thing is happening. According to the log, I can clearly see that the first track right after liquidsoap start is being "accepted" two times, and then it also plays two times in a row:

2018/10/01 10:33:46 [decoder:3] Method "MAD" accepted "...path.../Empty Cities.mp3".
2018/10/01 10:33:46 [decoder:3] Method "MAD" accepted "...path.../Empty Cities.mp3".

then it gets prepared:

2018/10/01 10:33:49 [request.dynamic_5350:3] Prepared "...path.../Empty Cities.mp3" (RID 2).

and then eventually finished, but immediately prepared again (skipping "accepted" phase):

2018/10/01 10:39:42 [request.dynamic_5350:3] Finished with "...path.../Empty Cities.mp3".
2018/10/01 10:39:42 [request.dynamic_5350:3] Prepared "...path.../Empty Cities.mp3" (RID 4).

This is unexpected and undesired behavior, as airplay gets un-synced with the playlist. How to fix this?

Liquidsoap 1.2.1 / Ubuntu 16

art1c0 commented 6 years ago

It seems that it has something to do with the "default_duration" param. If this parameter is insreased - issue is not reproducing. Maybe the issue only appears when "length" is more than "default_duration" ?

toots commented 5 years ago

How are those tracks fed to the streaming system? I think we'd need more info about your script to be able to help. This could be a normal behavior actually depending how your script is setup.

art1c0 commented 5 years ago

Tracks are coming via curl from a web service:

playlist = request.dynamic(default_duration=120., length = 60., { request.create(list.hd(get_process_lines("curl http://127.0.0.1:8102/rpc/next"))) })

playlist = audio_to_stereo(playlist)

playlist = amplify(1., override = "replay_gain", playlist)

playlist = crossfade(start_next = 5., fade_in = 5., fade_out = 5., playlist)

def update_title(m) = [ ("artist", get_process_output("curl http://127.0.0.1:8102/rpc/meta")), ("title", "Radio") ] end

playlist = map_metadata(update_title, playlist)

toots commented 5 years ago

Hey! I haven't forgotten about this issue. I'll get to it when I have a moment.

toots commented 5 years ago

Hi all. @articobandurini, is the issue still occurring? If so, could you share a bit of your script? I haven't been able to reproduce locally so far.

toots commented 5 years ago

Hi @articobandurini! I'm looking at this one now. One thing that seem important to notice in the logs is that the same file is played twice but with different request IDs. That would seem to indicate that the file got pushed through the streaming pipeline twice. Could it be possible that the api call in request.dynamic could return the same file twice?

toots commented 5 years ago

Also, any chance you could provide log extracts around the double play? And make sure that you're using the latest 1.4.0-rc1 or later. Thanks!!

RecursiveGreen commented 5 years ago

I just upgraded to 1.4.0 official and I'm now experiencing this same problem. It was working back during commit 49372f48 (around July 22nd).

Here's the log output:

2019/10/21 15:16:07 [change_meta:3] Request ID: "52306"
2019/10/21 15:16:07 [change_meta:3] Artist: Koichi Sugiyama -- Game: Dragon Quest IV: The Guided Ones -- Title: Menuet
2019/10/21 15:16:07 [just_played:3] Just played request ID: "52306"
2019/10/21 15:16:08 [cross_8633:3] Analysis: -25.911881dB / -24.882155dB (4.96s / 4.96s)
2019/10/21 15:16:08 [smart_cross:3] Transition: crossed, fade-in, fade-out.
2019/10/21 15:16:08 [next_song:3] "annotate:req_id=\"52307\",type=\"S\",artist=\"Yoko Shimomura\",title=\"Mystic City Geo\",game=\"Legend of Mana\",replay_gain=\"-5.43 dB\":s3://xxxxx.flac"
2019/10/21 15:16:09 [decoder:3] Method "FLAC" accepted "/tmp/liq-process6205b7.flac".
2019/10/21 15:18:51 [next_song:3] "annotate:req_id=\"52307\",type=\"S\",artist=\"Yoko Shimomura\",title=\"Mystic City Geo\",game=\"Legend of Mana\",replay_gain=\"-5.43 dB\":s3://xxxxx.flac"
2019/10/21 15:18:52 [decoder:3] Method "FLAC" accepted "/tmp/liq-processba6b3e.flac".
2019/10/21 15:19:01 [main:3] Prepared "/tmp/liq-process6205b7.flac" (RID 2).
2019/10/21 15:19:01 [change_meta:3] Request ID: "52307"
2019/10/21 15:19:01 [change_meta:3] Artist: Yoko Shimomura -- Game: Legend of Mana -- Title: Mystic City Geo
2019/10/21 15:19:01 [just_played:3] Just played request ID: "52307"
2019/10/21 15:19:02 [cross_8633:3] Analysis: -168.916294dB / -31.498839dB (4.96s / 4.96s)
2019/10/21 15:19:02 [smart_cross:3] new >= old + margin, old <= medium and new <= high.
2019/10/21 15:19:02 [smart_cross:3] Do not fade if it's already very low.
2019/10/21 15:19:02 [smart_cross:3] Transition: crossed, no fade.
2019/10/21 15:21:23 [next_song:3] "annotate:req_id=\"52308\",type=\"S\",artist=\"Ryuichi Takada\",title=\"Armed Hometown\",game=\"Ace Combat 6: Fires of Liberation\",replay_gain=\"+0.66 dB\":s3://xxxxx.flac"
2019/10/21 15:21:24 [decoder:3] Method "FLAC" accepted "/tmp/liq-processab5b45.flac".
2019/10/21 15:21:32 [main:3] Prepared "/tmp/liq-processba6b3e.flac" (RID 3).
2019/10/21 15:21:32 [change_meta:3] Request ID: "52307"
2019/10/21 15:21:32 [change_meta:3] Artist: Yoko Shimomura -- Game: Legend of Mana -- Title: Mystic City Geo
2019/10/21 15:21:32 [just_played:3] Just played request ID: "52307"
2019/10/21 15:21:33 [cross_8633:3] Analysis: -101.755199dB / -31.498839dB (4.96s / 4.96s)
2019/10/21 15:21:33 [smart_cross:3] new >= old + margin, old <= medium and new <= high.
2019/10/21 15:21:33 [smart_cross:3] Do not fade if it's already very low.
2019/10/21 15:21:33 [smart_cross:3] Transition: crossed, no fade.
2019/10/21 15:23:54 [next_song:3] "annotate:req_id=\"52308\",type=\"S\",artist=\"Ryuichi Takada\",title=\"Armed Hometown\",game=\"Ace Combat 6: Fires of Liberation\",replay_gain=\"+0.66 dB\":s3://xxxxx.flac"

My config can be seen here: https://github.com/savonet/liquidsoap/issues/865#issuecomment-508767754

Edit: Can also confirm that bumping "default_duration" and "length" to higher values fixes the issue for now.

stale[bot] commented 4 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 4 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 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.

toots commented 3 years ago

This should be fixed with the new prefetch parameter.