Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

request.dynamic invoked when not expected #3134

Closed
danbo opened this issue Jun 9, 2023 · 3 comments · Fixed by #4076
Closed

request.dynamic invoked when not expected #3134

danbo opened this issue Jun 9, 2023 · 3 comments · Fixed by #4076

Comments

@danbo
Copy link

danbo commented Jun 9, 2023

Describe the bug

Requests are being made when they shouldn't need to be during bad / error states. Related to #3026.

To Reproduce

Test script:

def get_request()
    log.important("got request", label="app")
    request.create("/test.mp3")
end

jukebox = request.dynamic(id="jukebox", prefetch=1, retry_delay=5., get_request)

radio = mksafe(fallback(track_sensitive=false, [jukebox, sine()]))

def handle_reopen(~metadata, ~error) =
  if null.defined(error) then
    print("Reloading on error: #{error}")
    5.
  elsif null.defined(metadata) then
    print("Reloading on metadata")
    null()
  else
    null()
  end
end

output.dummy(fallible=true, radio)

output.external(
   fallible=true,
   self_sync=true,
   should_reopen=handle_reopen,
   %wav,
   "ffmpeg -hide_banner -nostats -re -i pipe:0 -f u16le -acodec pcm_s16le -ac 2 -ar 44100 tcp://1.2.3.4:12345",
   radio
)

Expected behavior

Case 1

State: tcp endpoint down, no script changes, test mp3 file available

Expected behaviour: get_request should only be called when required, ie pre-fetch or the previous one is finishing, vs on error - only a reconnection should be happening on failure and not also a get_request. Streaming should just resume on the reconnected output once it becomes available if the request has already been made and is playing on the other output, ie dummy.

Log:

INFO: Loading Sdl_image, Target = linux
INFO: Loading Sdl_ttf, Target = linux
2023/06/09 00:37:36 >>> LOG START
2023/06/09 00:37:23 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/06/09 00:37:23 [main:3] Liquidsoap 2.2.0+git@39717ae41
2023/06/09 00:37:23 [main:3] Using: alsa=0.3.0 angstrom=0.15.0 ao=0.2.4 asetmap=0.8.1 asn1-combinators=0.2.6 astring=0.8.5 base.caml=v0.15.1 base64=3.5.1 bigarray=[distributed with OCaml] bigarray-compat=1.1.0 bigstringaf=0.9.1 bjack=0.1.6 bos=0.2.1 bytes=[distributed with OCaml] ca-certs=v0.2.3 camlimages.all_formats=4.2.6 camlimages.core=5.0.4 camlimages.exif=5.0.4 camlimages.gif=5.0.4 camlimages.jpeg=5.0.4 camlimages.png=5.0.4 camlimages.tiff=5.0.4 camlimages.xpm=5.0.4 camlp-streams camomile=d3773ec camomile.lib=d3773ec cohttp=5.1.0 cohttp-lwt=5.1.0 cohttp-lwt-unix=5.1.0 conduit=6.2.0 conduit-lwt=6.2.0 conduit-lwt-unix=6.2.0 cry=1.0.0 cstruct=6.2.0 ctypes=0.20.2 ctypes.foreign=0.20.2 ctypes.stubs=0.20.2 curl=0.9.2 domain-name=0.4.0 dssi=0.1.5 dtools=0.4.5 dune-build-info=3.7.1 dune-private-libs.dune-section=3.7.1 dune-site=3.7.1 dune-site.private=3.7.1 duppy=0.9.3 eqaf=0.9 eqaf.bigstring=0.9 eqaf.cstruct=0.9 faad=0.5.2 fdkaac=0.3.3 ffmpeg-av=1.1.8 ffmpeg-avcodec=1.1.8 ffmpeg-avdevice=1.1.8 ffmpeg-avfilter=1.1.8 ffmpeg-avutil=1.1.8 ffmpeg-swresample=1.1.8 ffmpeg-swscale=1.1.8 fileutils=0.6.4 flac=0.4.0 flac.decoder=0.4.0 flac.ogg=0.4.0 fmt=0.9.0 fpath=0.7.3 frei0r=0.1.2 gd=1.0a5 gen=1.1 gmap=0.3.0 hkdf=1.0.4 inotify=2.4.1 integers ipaddr=5.5.0 ipaddr-sexp=5.5.0 ipaddr.unix=5.5.0 irc-client irc-client-unix ladspa=0.2.2 lame=0.3.7 lastfm=0.3.3 lilv=0.1.0 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_alsa=rolling-release-v2.2.x-72-g39717ae liquidsoap_ao=rolling-release-v2.2.x-72-g39717ae liquidsoap_bjack=rolling-release-v2.2.x-72-g39717ae liquidsoap_builtins=rolling-release-v2.2.x-72-g39717ae liquidsoap_camlimages=rolling-release-v2.2.x-72-g39717ae liquidsoap_core=rolling-release-v2.2.x-72-g39717ae liquidsoap_dssi=rolling-release-v2.2.x-72-g39717ae liquidsoap_faad=rolling-release-v2.2.x-72-g39717ae liquidsoap_fdkaac=rolling-release-v2.2.x-72-g39717ae liquidsoap_ffmpeg=rolling-release-v2.2.x-72-g39717ae liquidsoap_flac=rolling-release-v2.2.x-72-g39717ae liquidsoap_frei0r=rolling-release-v2.2.x-72-g39717ae liquidsoap_gd=rolling-release-v2.2.x-72-g39717ae liquidsoap_irc=rolling-release-v2.2.x-72-g39717ae liquidsoap_ladspa=rolling-release-v2.2.x-72-g39717ae liquidsoap_lame=rolling-release-v2.2.x-72-g39717ae liquidsoap_lastfm=rolling-release-v2.2.x-72-g39717ae liquidsoap_lilv=rolling-release-v2.2.x-72-g39717ae liquidsoap_lo=rolling-release-v2.2.x-72-g39717ae liquidsoap_mad=rolling-release-v2.2.x-72-g39717ae liquidsoap_magic=rolling-release-v2.2.x-72-g39717ae liquidsoap_mem_usage=rolling-release-v2.2.x-72-g39717ae liquidsoap_memtrace=rolling-release-v2.2.x-72-g39717ae liquidsoap_ogg=rolling-release-v2.2.x-72-g39717ae liquidsoap_ogg_flac=rolling-release-v2.2.x-72-g39717ae liquidsoap_optionals=rolling-release-v2.2.x-72-g39717ae liquidsoap_opus=rolling-release-v2.2.x-72-g39717ae liquidsoap_osc=rolling-release-v2.2.x-72-g39717ae liquidsoap_oss=rolling-release-v2.2.x-72-g39717ae liquidsoap_portaudio=rolling-release-v2.2.x-72-g39717ae liquidsoap_posix_time=rolling-release-v2.2.x-72-g39717ae liquidsoap_prometheus=rolling-release-v2.2.x-72-g39717ae liquidsoap_pulseaudio=rolling-release-v2.2.x-72-g39717ae liquidsoap_runtime=rolling-release-v2.2.x-72-g39717ae liquidsoap_samplerate=rolling-release-v2.2.x-72-g39717ae liquidsoap_sdl=rolling-release-v2.2.x-72-g39717ae liquidsoap_shine=rolling-release-v2.2.x-72-g39717ae liquidsoap_soundtouch=rolling-release-v2.2.x-72-g39717ae liquidsoap_speex=rolling-release-v2.2.x-72-g39717ae liquidsoap_srt=rolling-release-v2.2.x-72-g39717ae liquidsoap_ssl=rolling-release-v2.2.x-72-g39717ae liquidsoap_stereotool=rolling-release-v2.2.x-72-g39717ae liquidsoap_taglib=rolling-release-v2.2.x-72-g39717ae liquidsoap_theora=rolling-release-v2.2.x-72-g39717ae liquidsoap_tls=rolling-release-v2.2.x-72-g39717ae liquidsoap_vorbis=rolling-release-v2.2.x-72-g39717ae liquidsoap_xmlplaylist=rolling-release-v2.2.x-72-g39717ae liquidsoap_yaml=rolling-release-v2.2.x-72-g39717ae lo=0.2.0 logs=0.7.0 logs.fmt=0.7.0 logs.lwt=0.7.0 lwt=5.6.1 lwt.unix=5.6.1 macaddr=5.5.0 mad=0.5.3 magic=0.7.3 magic-mime=1.3.0 mem_usage=0.0.4 memtrace=0.2.3 menhirLib=20230415 metadata=0.2.0 mirage-crypto=0.11.1 mirage-crypto-ec=0.11.1 mirage-crypto-pk=0.11.1 mirage-crypto-rng=0.11.1 mirage-crypto-rng.unix=0.11.1 mm=0.8.3 mm.audio=0.8.3 mm.base=0.8.3 mm.image=0.8.3 mm.midi=0.8.3 mm.video=0.8.3 ocplib-endian ocplib-endian.bigstring ogg=0.7.4 ogg.decoder=0.7.4 opus=0.2.3 opus.decoder=0.2.3 osc osc-unix parsexp=v0.15.0 pbkdf pcre=7.5.0 portaudio=0.2.3 posix-base=b516d46 posix-socket=b516d46 posix-socket.constants=b516d46 posix-socket.stubs=b516d46 posix-socket.types=b516d46 posix-time2=b516d46 posix-time2.constants=b516d46 posix-time2.stubs=b516d46 posix-time2.types=b516d46 posix-types=b516d46 posix-types.constants=b516d46 ppx_sexp_conv.runtime-lib=v0.15.0 prometheus=1.2 prometheus-app=1.2 ptime=1.1.0 ptime.clock.os=1.1.0 pulseaudio=0.1.6 re=1.10.4 result=1.5 rresult=0.7.0 samplerate=0.1.6 sedlex=3.1 seq=[distributed with OCaml 4.07 or above] sexplib=v0.15.1 sexplib0=v0.15.0 shine=0.2.3 soundtouch=0.1.9 speex=0.4.2 speex.decoder=0.4.2 srt=0.3.0 srt.constants=0.3.0 srt.stubs=0.3.0 srt.stubs.locked=0.3.0 srt.types=0.3.0 ssl=0.5.13 stdlib-shims=0.3.0 stereotool=rolling-release-v2.2.x-72-g39717ae str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 theora=0.4.1 theora.decoder=0.4.1 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] tls=0.17.0 tsdl=v1.0.0 tsdl-image=0.5 tsdl-ttf=0.5 unix=[distributed with OCaml] unix-errno=0.6.2 unix-errno.errno_bindings=0.6.2 unix-errno.errno_types=0.6.2 unix-errno.errno_types_detected=0.6.2 unix-errno.unix=0.6.2 uri=4.2.0 uri-sexp=4.2.0 uri.services=4.2.0 vorbis=0.8.1 vorbis.decoder=0.8.1 x509=0.16.4 xmlm=1.4.0 xmlplaylist=0.1.5 yaml=3.1.0 yaml.bindings=3.1.0 yaml.bindings.types=3.1.0 yaml.c=3.1.0 yaml.ffi=3.1.0 yaml.types=3.1.0 zarith=1.12
2023/06/09 00:37:23 [clock:3] Using native (high-precision) implementation for latency control
2023/06/09 00:37:36 [main:3] Standard library loaded in 13.21 seconds.
2023/06/09 00:37:36 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/06/09 00:37:36 [frame:3] Video frame size set to: 1280x720
2023/06/09 00:37:36 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/06/09 00:37:36 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/06/09 00:37:36 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/06/09 00:37:36 [sandbox:3] Running inside a docker container, disabling sandboxing.
2023/06/09 00:37:36 [startup:3] DSSI plugins registration: 0.00s
2023/06/09 00:37:36 [startup:3] FFmpeg filters registration: 0.03s
2023/06/09 00:37:36 [startup:3] FFmpeg bitstream filters registration: 0.01s
2023/06/09 00:37:36 [startup:3] Lilv plugins registration: 0.00s
2023/06/09 00:37:36 [startup:3] Frei0r plugin registration: 0.00s
2023/06/09 00:37:36 [startup:3] LADSPA plugins registration: 0.00s
2023/06/09 00:37:36 [startup:3] Typechecking: 12.98s
2023/06/09 00:37:36 [startup:3] Evaluation: 0.02s
2023/06/09 00:37:36 [startup:3] Typechecking: 0.04s
2023/06/09 00:37:36 [startup:3] Evaluation: 0.00s
2023/06/09 00:37:36 [startup:3] Typechecking: 0.00s
2023/06/09 00:37:36 [startup:3] Evaluation: 0.00s
2023/06/09 00:37:36 [startup:3] Loaded retry-bug.liq: 0.00s
2023/06/09 00:37:36 [video.converter:3] Using preferred video converter: ffmpeg.
2023/06/09 00:37:36 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/06/09 00:37:36 [dummy:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:37:36 [jukebox:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:37:36 [sine:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:37:36 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:37:36 [output_external:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:37:36 [video.text:3] Using sdl implementation
2023/06/09 00:37:36 [app:3] got request
2023/06/09 00:37:36 [clock.main:3] Streaming loop starts in auto-sync mode
2023/06/09 00:37:36 [clock.main:3] Delegating synchronization to active sources
2023/06/09 00:37:36 [mksafe:3] Switch to switch.
2023/06/09 00:37:36 [switch:3] Switch to sine.
[mp3 @ 0x7ff418008000] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:36 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:36 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:36 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff418024c40] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff410014f80] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff41001d6c0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:37 [jukebox:3] Prepared "/test.mp3" (RID 0).
2023/06/09 00:37:37 [switch:3] Switch to jukebox with transition.
Reloading on metadata
2023/06/09 00:37:37 [app:3] got request
[mp3 @ 0x7ff40c005880] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:37 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:37 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:37 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff40c020a80] Estimating duration from bitrate, this may be inaccurate
Guessed Channel Layout for Input Stream #0.0 : stereo
Input #0, wav, from 'pipe:0':
  Duration: N/A, bitrate: 1411 kb/s
  Stream #0:0: Audio: pcm_s16le ([1][0][0][0] / 0x0001), 44100 Hz, 2 channels, s16, 1411 kb/s
[tcp @ 0x55d809159900] Connection to tcp://1.2.3.4:12345 failed: Connection timed out
tcp://1.2.3.4:12345: Connection timed out
Reloading on error: error(kind="system",message="Sys_error(\"Broken pipe\")",positions="at src/core/outputs/pipe_output.ml, line 384, char 36-36, at stdlib.ml, line 379, char 33-33")
2023/06/09 00:37:42 [output_external:3] Error while streaming: Lang.Runtime_error { kind: "system", msg: "Sys_error(\"Broken pipe\")", pos: [at stdlib.ml, line 379, char 33-33, at src/core/outputs/pipe_output.ml, line 384, char 36-36] }, will re-open in 5.00s
2023/06/09 00:37:43 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff410037e00] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff410065c80] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:43 [jukebox:3] Prepared "/test.mp3" (RID 1).
Reloading on metadata
2023/06/09 00:37:43 [app:3] got request
[mp3 @ 0x7ff40c020680] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:43 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:43 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:43 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff40c027bc0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:45 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff41005d000] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff410093780] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:45 [jukebox:3] Prepared "/test.mp3" (RID 2).
Reloading on metadata
2023/06/09 00:37:45 [app:3] got request
[mp3 @ 0x7ff418022d00] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:45 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:45 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:45 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff418023200] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:46 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff4100943c0] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff41007ad00] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:46 [jukebox:3] Prepared "/test.mp3" (RID 3).
Reloading on metadata
2023/06/09 00:37:46 [app:3] got request
[mp3 @ 0x7ff40c00efc0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:46 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:46 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:46 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff40c00c140] Estimating duration from bitrate, this may be inaccurate
[adp @ 0x55f046df0a80] Format adp detected only with low score of 25, misdetection possible!
Input #0, adp, from 'pipe:0':
  Duration: N/A, start: 0.000000, bitrate: N/A
  Stream #0:0: Audio: adpcm_dtk, 48000 Hz, stereo, s16p
[tcp @ 0x55f046e0acc0] Connection to tcp://1.2.3.4:12345 failed: Connection timed out
tcp://1.2.3.4:12345: Connection timed out
Reloading on error: error(kind="system",message="Sys_error(\"Broken pipe\")",positions="at src/core/outputs/pipe_output.ml, line 384, char 36-36, at stdlib.ml, line 379, char 33-33")
2023/06/09 00:37:52 [output_external:3] Error while streaming: Lang.Runtime_error { kind: "system", msg: "Sys_error(\"Broken pipe\")", pos: [at stdlib.ml, line 379, char 33-33, at src/core/outputs/pipe_output.ml, line 384, char 36-36] }, will re-open in 5.00s
2023/06/09 00:37:54 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff41005af80] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff410089ec0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:54 [jukebox:3] Prepared "/test.mp3" (RID 4).
Reloading on metadata2023/06/09 00:37:54 [app:3] got request

[mp3 @ 0x7ff41802a6c0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:54 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:54 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:54 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff4180203c0] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:55 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff41005a540] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff41005a540] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:55 [jukebox:3] Prepared "/test.mp3" (RID 5).
Reloading on metadata
2023/06/09 00:37:55 [app:3] got request
[mp3 @ 0x7ff40c00bb80] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:55 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:55 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:55 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff40c01ec80] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:57 [decoder:2] Decoding "/test.mp3" ended: Ffmpeg_decoder.End_of_file.
[mp3 @ 0x7ff410073100] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7ff41007ac40] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:57 [jukebox:3] Prepared "/test.mp3" (RID 6).
Reloading on metadata
2023/06/09 00:37:57 [app:3] got request
[mp3 @ 0x7ff418025e40] Estimating duration from bitrate, this may be inaccurate
2023/06/09 00:37:57 [decoder.ffmpeg:3] Requested content-type for "/test.mp3": {audio=pcm(stereo)}
2023/06/09 00:37:57 [decoder.ffmpeg:3] FFmpeg recognizes "/test.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2023/06/09 00:37:57 [decoder.ffmpeg:3] Decoded content-type for "/test.mp3": {audio=pcm(stereo)}
[mp3 @ 0x7ff418026480] Estimating duration from bitrate, this may be inaccurate
[adp @ 0x564070caea80] Format adp detected only with low score of 25, misdetection possible!
Input #0, adp, from 'pipe:0':
  Duration: N/A, start: 0.000000, bitrate: N/A
  Stream #0:0: Audio: adpcm_dtk, 48000 Hz, stereo, s16p
^C2023/06/09 00:37:59 [main:3] Shutdown started!

Case 2

State: output.external commented out, test mp3 filename changed to non-existent one / bad uri

Expected behaviour: get_request should be throttled to the retry_delay value, in the script's case - 5 seconds.

Log:

INFO: Loading Sdl_image, Target = linux
INFO: Loading Sdl_ttf, Target = linux
2023/06/09 00:43:56 >>> LOG START
2023/06/09 00:43:43 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/06/09 00:43:43 [main:3] Liquidsoap 2.2.0+git@39717ae41
2023/06/09 00:43:43 [main:3] Using: alsa=0.3.0 angstrom=0.15.0 ao=0.2.4 asetmap=0.8.1 asn1-combinators=0.2.6 astring=0.8.5 base.caml=v0.15.1 base64=3.5.1 bigarray=[distributed with OCaml] bigarray-compat=1.1.0 bigstringaf=0.9.1 bjack=0.1.6 bos=0.2.1 bytes=[distributed with OCaml] ca-certs=v0.2.3 camlimages.all_formats=4.2.6 camlimages.core=5.0.4 camlimages.exif=5.0.4 camlimages.gif=5.0.4 camlimages.jpeg=5.0.4 camlimages.png=5.0.4 camlimages.tiff=5.0.4 camlimages.xpm=5.0.4 camlp-streams camomile=d3773ec camomile.lib=d3773ec cohttp=5.1.0 cohttp-lwt=5.1.0 cohttp-lwt-unix=5.1.0 conduit=6.2.0 conduit-lwt=6.2.0 conduit-lwt-unix=6.2.0 cry=1.0.0 cstruct=6.2.0 ctypes=0.20.2 ctypes.foreign=0.20.2 ctypes.stubs=0.20.2 curl=0.9.2 domain-name=0.4.0 dssi=0.1.5 dtools=0.4.5 dune-build-info=3.7.1 dune-private-libs.dune-section=3.7.1 dune-site=3.7.1 dune-site.private=3.7.1 duppy=0.9.3 eqaf=0.9 eqaf.bigstring=0.9 eqaf.cstruct=0.9 faad=0.5.2 fdkaac=0.3.3 ffmpeg-av=1.1.8 ffmpeg-avcodec=1.1.8 ffmpeg-avdevice=1.1.8 ffmpeg-avfilter=1.1.8 ffmpeg-avutil=1.1.8 ffmpeg-swresample=1.1.8 ffmpeg-swscale=1.1.8 fileutils=0.6.4 flac=0.4.0 flac.decoder=0.4.0 flac.ogg=0.4.0 fmt=0.9.0 fpath=0.7.3 frei0r=0.1.2 gd=1.0a5 gen=1.1 gmap=0.3.0 hkdf=1.0.4 inotify=2.4.1 integers ipaddr=5.5.0 ipaddr-sexp=5.5.0 ipaddr.unix=5.5.0 irc-client irc-client-unix ladspa=0.2.2 lame=0.3.7 lastfm=0.3.3 lilv=0.1.0 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_alsa=rolling-release-v2.2.x-72-g39717ae liquidsoap_ao=rolling-release-v2.2.x-72-g39717ae liquidsoap_bjack=rolling-release-v2.2.x-72-g39717ae liquidsoap_builtins=rolling-release-v2.2.x-72-g39717ae liquidsoap_camlimages=rolling-release-v2.2.x-72-g39717ae liquidsoap_core=rolling-release-v2.2.x-72-g39717ae liquidsoap_dssi=rolling-release-v2.2.x-72-g39717ae liquidsoap_faad=rolling-release-v2.2.x-72-g39717ae liquidsoap_fdkaac=rolling-release-v2.2.x-72-g39717ae liquidsoap_ffmpeg=rolling-release-v2.2.x-72-g39717ae liquidsoap_flac=rolling-release-v2.2.x-72-g39717ae liquidsoap_frei0r=rolling-release-v2.2.x-72-g39717ae liquidsoap_gd=rolling-release-v2.2.x-72-g39717ae liquidsoap_irc=rolling-release-v2.2.x-72-g39717ae liquidsoap_ladspa=rolling-release-v2.2.x-72-g39717ae liquidsoap_lame=rolling-release-v2.2.x-72-g39717ae liquidsoap_lastfm=rolling-release-v2.2.x-72-g39717ae liquidsoap_lilv=rolling-release-v2.2.x-72-g39717ae liquidsoap_lo=rolling-release-v2.2.x-72-g39717ae liquidsoap_mad=rolling-release-v2.2.x-72-g39717ae liquidsoap_magic=rolling-release-v2.2.x-72-g39717ae liquidsoap_mem_usage=rolling-release-v2.2.x-72-g39717ae liquidsoap_memtrace=rolling-release-v2.2.x-72-g39717ae liquidsoap_ogg=rolling-release-v2.2.x-72-g39717ae liquidsoap_ogg_flac=rolling-release-v2.2.x-72-g39717ae liquidsoap_optionals=rolling-release-v2.2.x-72-g39717ae liquidsoap_opus=rolling-release-v2.2.x-72-g39717ae liquidsoap_osc=rolling-release-v2.2.x-72-g39717ae liquidsoap_oss=rolling-release-v2.2.x-72-g39717ae liquidsoap_portaudio=rolling-release-v2.2.x-72-g39717ae liquidsoap_posix_time=rolling-release-v2.2.x-72-g39717ae liquidsoap_prometheus=rolling-release-v2.2.x-72-g39717ae liquidsoap_pulseaudio=rolling-release-v2.2.x-72-g39717ae liquidsoap_runtime=rolling-release-v2.2.x-72-g39717ae liquidsoap_samplerate=rolling-release-v2.2.x-72-g39717ae liquidsoap_sdl=rolling-release-v2.2.x-72-g39717ae liquidsoap_shine=rolling-release-v2.2.x-72-g39717ae liquidsoap_soundtouch=rolling-release-v2.2.x-72-g39717ae liquidsoap_speex=rolling-release-v2.2.x-72-g39717ae liquidsoap_srt=rolling-release-v2.2.x-72-g39717ae liquidsoap_ssl=rolling-release-v2.2.x-72-g39717ae liquidsoap_stereotool=rolling-release-v2.2.x-72-g39717ae liquidsoap_taglib=rolling-release-v2.2.x-72-g39717ae liquidsoap_theora=rolling-release-v2.2.x-72-g39717ae liquidsoap_tls=rolling-release-v2.2.x-72-g39717ae liquidsoap_vorbis=rolling-release-v2.2.x-72-g39717ae liquidsoap_xmlplaylist=rolling-release-v2.2.x-72-g39717ae liquidsoap_yaml=rolling-release-v2.2.x-72-g39717ae lo=0.2.0 logs=0.7.0 logs.fmt=0.7.0 logs.lwt=0.7.0 lwt=5.6.1 lwt.unix=5.6.1 macaddr=5.5.0 mad=0.5.3 magic=0.7.3 magic-mime=1.3.0 mem_usage=0.0.4 memtrace=0.2.3 menhirLib=20230415 metadata=0.2.0 mirage-crypto=0.11.1 mirage-crypto-ec=0.11.1 mirage-crypto-pk=0.11.1 mirage-crypto-rng=0.11.1 mirage-crypto-rng.unix=0.11.1 mm=0.8.3 mm.audio=0.8.3 mm.base=0.8.3 mm.image=0.8.3 mm.midi=0.8.3 mm.video=0.8.3 ocplib-endian ocplib-endian.bigstring ogg=0.7.4 ogg.decoder=0.7.4 opus=0.2.3 opus.decoder=0.2.3 osc osc-unix parsexp=v0.15.0 pbkdf pcre=7.5.0 portaudio=0.2.3 posix-base=b516d46 posix-socket=b516d46 posix-socket.constants=b516d46 posix-socket.stubs=b516d46 posix-socket.types=b516d46 posix-time2=b516d46 posix-time2.constants=b516d46 posix-time2.stubs=b516d46 posix-time2.types=b516d46 posix-types=b516d46 posix-types.constants=b516d46 ppx_sexp_conv.runtime-lib=v0.15.0 prometheus=1.2 prometheus-app=1.2 ptime=1.1.0 ptime.clock.os=1.1.0 pulseaudio=0.1.6 re=1.10.4 result=1.5 rresult=0.7.0 samplerate=0.1.6 sedlex=3.1 seq=[distributed with OCaml 4.07 or above] sexplib=v0.15.1 sexplib0=v0.15.0 shine=0.2.3 soundtouch=0.1.9 speex=0.4.2 speex.decoder=0.4.2 srt=0.3.0 srt.constants=0.3.0 srt.stubs=0.3.0 srt.stubs.locked=0.3.0 srt.types=0.3.0 ssl=0.5.13 stdlib-shims=0.3.0 stereotool=rolling-release-v2.2.x-72-g39717ae str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 theora=0.4.1 theora.decoder=0.4.1 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] tls=0.17.0 tsdl=v1.0.0 tsdl-image=0.5 tsdl-ttf=0.5 unix=[distributed with OCaml] unix-errno=0.6.2 unix-errno.errno_bindings=0.6.2 unix-errno.errno_types=0.6.2 unix-errno.errno_types_detected=0.6.2 unix-errno.unix=0.6.2 uri=4.2.0 uri-sexp=4.2.0 uri.services=4.2.0 vorbis=0.8.1 vorbis.decoder=0.8.1 x509=0.16.4 xmlm=1.4.0 xmlplaylist=0.1.5 yaml=3.1.0 yaml.bindings=3.1.0 yaml.bindings.types=3.1.0 yaml.c=3.1.0 yaml.ffi=3.1.0 yaml.types=3.1.0 zarith=1.12
2023/06/09 00:43:43 [clock:3] Using native (high-precision) implementation for latency control
2023/06/09 00:43:56 [main:3] Standard library loaded in 13.30 seconds.
2023/06/09 00:43:56 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/06/09 00:43:56 [frame:3] Video frame size set to: 1280x720
2023/06/09 00:43:56 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/06/09 00:43:56 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/06/09 00:43:56 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/06/09 00:43:56 [sandbox:3] Running inside a docker container, disabling sandboxing.
2023/06/09 00:43:56 [startup:3] DSSI plugins registration: 0.00s
2023/06/09 00:43:56 [startup:3] FFmpeg filters registration: 0.03s
2023/06/09 00:43:56 [startup:3] FFmpeg bitstream filters registration: 0.01s
2023/06/09 00:43:56 [startup:3] Lilv plugins registration: 0.00s
2023/06/09 00:43:56 [startup:3] Frei0r plugin registration: 0.00s
2023/06/09 00:43:56 [startup:3] LADSPA plugins registration: 0.00s
2023/06/09 00:43:56 [startup:3] Typechecking: 13.07s
2023/06/09 00:43:56 [startup:3] Evaluation: 0.02s
2023/06/09 00:43:56 [startup:3] Typechecking: 0.04s
2023/06/09 00:43:56 [startup:3] Evaluation: 0.00s
2023/06/09 00:43:56 [startup:3] Typechecking: 0.00s
2023/06/09 00:43:56 [startup:3] Evaluation: 0.00s
2023/06/09 00:43:56 [startup:3] Loaded retry-bug.liq: 0.00s
2023/06/09 00:43:56 [video.converter:3] Using preferred video converter: ffmpeg.
2023/06/09 00:43:56 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/06/09 00:43:56 [dummy:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:43:56 [jukebox:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:43:56 [sine:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:43:56 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:43:56 [output_external:3] Content type is {audio=pcm(stereo)}.
2023/06/09 00:43:56 [clock.main:3] Streaming loop starts in auto-sync mode
2023/06/09 00:43:56 [clock.main:3] Delegating synchronization to active sources
2023/06/09 00:43:56 [mksafe:3] Switch to switch.
2023/06/09 00:43:56 [switch:3] Switch to sine.
2023/06/09 00:43:56 [video.text:3] Using sdl implementation
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:56 [app:3] got request
2023/06/09 00:43:56 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
Guessed Channel Layout for Input Stream #0.0 : stereo
Input #0, wav, from 'pipe:0':
  Duration: N/A, bitrate: 1411 kb/s
  Stream #0:0: Audio: pcm_s16le ([1][0][0][0] / 0x0001), 44100 Hz, 2 channels, s16, 1411 kb/s
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
2023/06/09 00:43:57 [app:3] got request
2023/06/09 00:43:57 [request:3] Nonexistent file or ill-formed URI "/test2.mp3"!
^Ctcp://1.2.3.4:12345: Immediate exit requested
Exiting normally, received signal 2.
2023/06/09 00:43:57 [main:3] Shutdown started!

Version details

  • OS: Docker
  • Version 2.2.x rolling release / Liquidsoap 2.2.0+git@39717ae

Install method
Official docker images

@smimram smimram changed the title request.dynamic invoked when not expected request.dynamic invoked when not expected Jun 13, 2023
@vitoyucepi
Copy link
Collaborator

vitoyucepi commented Mar 5, 2024

I would like to bump this issue with a new reproduction and my explanation of the problem.

Summary

If the number of requests in request.dynamic is less than the prefetch value, but greater than 0, request.dynamic tries to get new requests as fast as possible every frame.

Reproduction

t = ref(true)
def next()
  print("Next called #{time.up()}")
  if t() then
    t := false
    request.create("/tmp/test/music/1.mp3")
  else
    null()
  end
end


q = request.dynamic(next, retry_delay=10.)
output.dummy(q, fallible=true)

Expected behavior

Log
liquidsoap-1  | Next called 4.01913905144
liquidsoap-1  | Next called 4.05933594704
liquidsoap-1  | Next called 14.018157959
liquidsoap-1  | Next called 24.0980420113

Current behavior

Log
liquidsoap-1  | Next called 4.01913905144
liquidsoap-1  | 2024/03/05 20:56:55 [dummy:3] Content type is {audio=pcm(stereo)}.
liquidsoap-1  | 2024/03/05 20:56:55 [request.dynamic:3] Content type is {audio=pcm(stereo)}.
liquidsoap-1  | 2024/03/05 20:56:55 [clock.main:3] Streaming loop starts in auto-sync mode
liquidsoap-1  | 2024/03/05 20:56:55 [clock.main:3] Delegating synchronization to CPU clock
liquidsoap-1  | 2024/03/05 20:56:55 [video.converter:3] Using preferred video converter: ffmpeg.
liquidsoap-1  | 2024/03/05 20:56:55 [audio.converter:3] Using samplerate converter: libsamplerate.
liquidsoap-1  | 2024/03/05 20:56:55 [video.text:3] Using sdl implementation
liquidsoap-1  | 2024/03/05 20:56:55 [decoder.ffmpeg:3] Requested content-type for "/tmp/test/music/1.mp3": {audio=pcm(stereo)}
liquidsoap-1  | 2024/03/05 20:56:55 [decoder.ffmpeg:3] FFmpeg recognizes "/tmp/test/music/1.mp3" as audio: {codec: mp3, 44100Hz, 1 channel(s)}
liquidsoap-1  | 2024/03/05 20:56:55 [decoder.ffmpeg:3] Decoded content-type for "/tmp/test/music/1.mp3": {audio=pcm(mono)}
liquidsoap-1  | [mp3float @ 0x78020ae70400] Could not update timestamps for skipped samples.
liquidsoap-1  | 2024/03/05 20:56:56 [request.dynamic:3] Prepared "/tmp/test/music/1.mp3" (RID 0).
liquidsoap-1  | Next called 4.05933594704
liquidsoap-1  | Next called 4.09793996811
liquidsoap-1  | Next called 4.13802289963
liquidsoap-1  | Next called 4.17827296257
liquidsoap-1  | Next called 4.21839809418
...
liquidsoap-1  | Next called 13.4983170033
liquidsoap-1  | [mp3float @ 0x78020ae70400] Could not update timestamps for discarded samples.
liquidsoap-1  | Next called 13.5384149551
liquidsoap-1  | 2024/03/05 20:57:05 [decoder:2] Decoding "/tmp/test/music/1.mp3" ended: Ffmpeg_decoder.End_of_file.
liquidsoap-1  | Next called 13.5783839226
liquidsoap-1  | Next called 13.6181299686
liquidsoap-1  | Next called 13.6582930088
liquidsoap-1  | Next called 13.6981089115
liquidsoap-1  | Next called 13.7381300926
liquidsoap-1  | Next called 13.7780900002
liquidsoap-1  | Next called 13.8181099892
liquidsoap-1  | Next called 13.8581500053
liquidsoap-1  | Next called 13.8980360031
liquidsoap-1  | Next called 13.9381120205
liquidsoap-1  | Next called 13.9780828953
liquidsoap-1  | Next called 14.018157959
liquidsoap-1  | 2024/03/05 20:57:06 [dummy:3] Source failed (no more tracks) stopping output...
liquidsoap-1  | Next called 14.0584609509
liquidsoap-1  | Next called 24.0980420113

Version

  • OS: debain:12 in docker
  • Version: 2.2.4-1

Install method

savonet/liquidsoap:v2.2.4

@danbo
Copy link
Author

danbo commented Aug 4, 2024

This is still an issue in 2.2.5 and 2.3.x rolling.

It appears to happen after the first successful request starts playing. If prefetch can't successfully queue up the next request, the function continues to be called repeatedly. In fact, I ran the summarized version above (thanks @vitoyucepi) and it looks like it's running on every frame (0.02s in 2.3.x):

Next called 2.22548508644
Next called 2.24156308174
Next called 2.26178503036
Next called 2.28161716461
Next called 2.30140519142

And every 0.04s in 2.2.5:

Next called 9.41492486
Next called 9.45046186447
Next called 9.49060988426
Next called 9.53048801422
Next called 9.57054781914

Notes:

  1. I see this problem with request.queue() as well since it uses request.dynamic under the hood.

  2. To ensure logic executes within the retry period, I've been using a time based throttle like this (of course the check is actually executing every 0.02s if there is a prefetch error)

lastTime = ref(0.)
...
def next()
  rid = ref(null())
  currentTime = time()
  elapsedSeconds = currentTime - lastTime()
  if (elapsedSeconds > 5) then
    lastTime.set(currentTime)
    ...
    r = request.create(...)
    rid.set(r)
  end
  rid()
end

@vitoyucepi
Copy link
Collaborator

The old frame interval is 0.04, the new one is 0.02. So liquidsoap tries to get a new request every frame.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants