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 130 forks source link

`request.dynamic` invoked when not expected #3134

Closed danbo closed 2 months ago

danbo commented 1 year ago

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

Install method Official docker images

vitoyucepi commented 7 months ago

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

Install method

savonet/liquidsoap:v2.2.4

danbo commented 2 months ago

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 commented 2 months ago

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