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

Failed to use process.run with timeout in thread.run #3242

Open rsp4jack opened 1 year ago

rsp4jack commented 1 year ago

Describe the bug Liquidsoap crashes when use process.run in thread.run

To Reproduce

log.file.path.set("radio.log")
log.stdout.set(true)
settings.server.telnet.set(true)
settings.server.telnet.port.set(8763)
settings.server.log.level.set(6)
settings.scheduler.log.set(true)
settings.scheduler.fast_queues.set(1)

BEET = "beetc"

src_defaultpl = playlist.list(id="src_defaultpl", mode="randomize", timeout=3., [])
def reloadpl() =
    command = "#{BEET} ls -f \"$path\""
    p = process.run(timeout=5.0, command)
    if p.status != "exit" or p.status.code != 0 then
        log.critical("Failed to execute #{command}: #{p.status} (#{p.status.code}) #{p.stderr}")
    else
        src_defaultpl.reload(empty_queue=true, string.split(separator="\\n", string.trim(p.stdout)))
    end
end
thread.run(fast=false, reloadpl) # caution

final_src = mksafe(
    src_defaultpl
)

output.ao(fallible=true, final_src)

Also, if I set fast=false to true in the thread.run call, it will run properly.

Version details

Install method Rolling release from GitHub Releases

toots commented 1 year ago

Hi @rsp4jack and thanks for reporting. Do you have a log of the error?

rsp4jack commented 1 year ago

I just forget to upload it.

Edit: sometimes this script runs properly (only few times).

When it runs improperly, hangs up:

2023/07/19 21:50:01 >>> LOG START
2023/07/19 21:49:59 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/07/19 21:49:59 [main:3] Liquidsoap 2.2.0+dev
2023/07/19 21:49:59 [main:3] Using: angstrom=0.15.0 ao=0.2.4 bigarray=[distributed with OCaml] bigstringaf=0.9.0 bytes=[distributed with OCaml] camlp-streams camomile.lib=2.0 cry=1.0.1 ctypes=0.17.1 ctypes.foreign=0.17.1 ctypes.foreign.base=0.17.1 ctypes.foreign.threaded=0.17.1 ctypes.stubs=0.17.1 curl=0.9.2 dtools=0.4.5 dune-build-info=3.2.0 dune-private-libs.dune-section=3.2.0 dune-site=3.2.0 duppy=0.9.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 gen=1.1 integers lastfm=0.3.3 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_ao liquidsoap_builtins liquidsoap_core liquidsoap_ffmpeg liquidsoap_lastfm liquidsoap_mem_usage liquidsoap_memtrace liquidsoap_optionals liquidsoap_portaudio liquidsoap_runtime liquidsoap_samplerate liquidsoap_srt liquidsoap_ssl liquidsoap_stereotool liquidsoap_taglib liquidsoap_xmlplaylist mem_usage=0.0.3 memtrace=v0.2.2 menhirLib=20210929 metadata=0.2.0 mm=0.8.4 mm.audio=0.8.4 mm.base=0.8.4 mm.image=0.8.4 mm.midi=0.8.4 mm.video=0.8.4 pcre=7.5.0 portaudio=0.2.3 posix-base=2.0.0 posix-socket=2.0.0 posix-socket.constants=2.0.0 posix-socket.stubs=2.0.0 posix-socket.types=2.0.0 samplerate=0.1.6 sedlex=3.2 seq=[distributed with OCaml 4.07 or above] 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.7.0 stdlib-shims=0.3.0 stereotool str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] unix=[distributed with OCaml] uri=4.2.0 winsvc=1.0.1 xmlm=v1.3.0 xmlplaylist=0.1.5
2023/07/19 21:49:59 [clock:3] Using builtin (low-precision) implementation for latency control
2023/07/19 21:50:01 [main:3] Standard library loaded in 1.80 seconds.
2023/07/19 21:50:01 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:50:01 [frame:4] frame.video.framerate set to: 25
2023/07/19 21:50:01 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/07/19 21:50:01 [frame:3] Video frame size set to: 1280x720
2023/07/19 21:50:01 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/07/19 21:50:01 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/07/19 21:50:01 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/07/19 21:50:01 [frame:4] frame.audio.channels set to: 2
2023/07/19 21:50:01 [frame:4] frame.video.default set to: false
2023/07/19 21:50:01 [frame:4] frame.midi.channels set to: 0
2023/07/19 21:50:01 [frame:4] frame.video.width set to: 1280
2023/07/19 21:50:01 [frame:4] frame.video.height set to: 720
2023/07/19 21:50:01 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:50:01 [clock:4] Currently 1 clock(s) allocated.
2023/07/19 21:50:01 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2023/07/19 21:50:01 [startup:3] FFmpeg filters registration: 0.03s
2023/07/19 21:50:01 [startup:3] FFmpeg bitstream filters registration: 0.00s
2023/07/19 21:50:01 [startup:3] Typechecking: 1.42s
2023/07/19 21:50:01 [startup:3] Evaluation: 0.01s
2023/07/19 21:50:01 [startup:3] Typechecking: 0.05s
2023/07/19 21:50:01 [startup:3] Evaluation: 0.00s
2023/07/19 21:50:01 [startup:3] Typechecking: 0.01s
2023/07/19 21:50:01 [startup:3] Evaluation: 0.00s
2023/07/19 21:50:01 [startup:3] Loaded .\minial.liq: 0.01s
2023/07/19 21:50:01 [video.converter:3] Using preferred video converter: ffmpeg.
2023/07/19 21:50:01 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/07/19 21:50:01 [clock.ao:4] Starting 1 source(s)...
2023/07/19 21:50:01 [source:4] Source output.ao gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:50:01 [ao:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:50:01 [source:4] Source mksafe gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:50:01 [source:4] Source src_defaultpl gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:50:01 [src_defaultpl:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:50:01 [source:4] Source safe_blank gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:50:01 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:50:01 [threads:4] Created thread "ao" (1 total).
2023/07/19 21:50:01 [threads:4] Created thread "clock_ao" (2 total).
2023/07/19 21:50:01 [clock:4] Main phase starts.
2023/07/19 21:50:01 [threads:4] Created thread "generic queue #1" (1 total).
2023/07/19 21:50:01 [threads:4] Created thread "generic queue #2" (2 total).
2023/07/19 21:50:01 [threads:4] Created thread "fast queue #1" (3 total).
2023/07/19 21:50:01 [threads:4] Created thread "non-blocking queue #1" (4 total).
2023/07/19 21:50:01 [threads:4] Created thread "non-blocking queue #2" (5 total).
2023/07/19 21:50:01 [clock.ao:3] Streaming loop starts in auto-sync mode
2023/07/19 21:50:01 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/19 21:50:01 [generic queue #1:4] Queue #1 starting...
2023/07/19 21:50:01 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:01 [generic queue #1:4] Enter select at 1689774601.857950, timeout 0.000000 (6/0/0).
2023/07/19 21:50:01 [fast queue #1:4] Queue #2 starting...
2023/07/19 21:50:01 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:01 [generic queue #2:4] Queue #3 starting...
2023/07/19 21:50:01 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:01 [non-blocking queue #2:4] Queue #4 starting...
2023/07/19 21:50:01 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:01 [non-blocking queue #1:4] Queue #5 starting...
2023/07/19 21:50:01 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:01 [generic queue #1:4] Left select at 1689774601.858701 (2/0/0).
2023/07/19 21:50:01 [generic queue #1:4] There are 3 ready tasks.
2023/07/19 21:50:01 [process:3] Command beetc ls -f "$path" cannot be executed with timeout 5.00 because the internal scheduler is not running. Most likely, this call is made at the beginning of your script. We suggest that you wrap this call in an asynchronous task using `thread.run`. If you really need this value immediately as your script is starting, you should implement the timeout within the process call itself.
2023/07/19 21:50:01 [process:4] Starting process
2023/07/19 21:50:01 [process:4] Closing process's stdin
2023/07/19 21:50:01 [non-blocking queue #1:4] There are 2 ready tasks.
2023/07/19 21:50:01 [non-blocking queue #1:4] Enter select at 1689774601.863200, timeout -1.000000 (8/0/0).
2023/07/19 21:50:01 [non-blocking queue #2:4] There are 2 ready tasks.
2023/07/19 21:50:01 [generic queue #2:4] There are 2 ready tasks.
2023/07/19 21:50:01 [src_defaultpl:4] Playlist stopped.
2023/07/19 21:50:01 [generic queue #2:4] There are 1 ready tasks.
2023/07/19 21:50:01 [video.text:3] Using native implementation
2023/07/19 21:50:01 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:01 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:01 [non-blocking queue #1:4] Left select at 1689774601.882704 (1/0/0).
2023/07/19 21:50:01 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:01 [non-blocking queue #1:4] Enter select at 1689774601.882704, timeout -1.000000 (9/0/0).
2023/07/19 21:50:01 [mksafe:3] Switch to safe_blank.
2023/07/19 21:50:02 [ao:3] Opening WMM audio driver output  (2 channels)...
2023/07/19 21:50:02 [clock.ao:3] Delegating synchronization to active sources
2023/07/19 21:50:03 [non-blocking queue #1:4] Left select at 1689774603.548250 (1/0/0).
2023/07/19 21:50:03 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/19 21:50:03 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:03 [fast queue #1:4] Enter select at 1689774603.548250, timeout -1.000000 (6/0/0).
2023/07/19 21:50:03 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:03 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:03 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:03 [fast queue #1:4] Left select at 1689774603.549002 (1/0/0).
2023/07/19 21:50:03 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:03 [fast queue #1:4] Enter select at 1689774603.549002, timeout -1.000000 (9/0/0).
2023/07/19 21:50:03 [fast queue #1:4] Left select at 1689774603.702009 (3/0/0).
2023/07/19 21:50:03 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/19 21:50:03 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:03 [generic queue #2:4] Enter select at 1689774603.702009, timeout -1.000000 (6/0/0).
2023/07/19 21:50:03 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:03 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:06 [lang:1] Failed to execute beetc ls -f "$path": timeout (-1) 
2023/07/19 21:50:06 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:50:06 [generic queue #2:4] Left select at 1689774606.870037 (1/0/0).
2023/07/19 21:50:06 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:50:06 [generic queue #2:4] Enter select at 1689774606.870037, timeout -1.000000 (6/0/0).
(^C)
2023/07/19 21:51:49 [main:3] Shutdown signal received.
2023/07/19 21:51:49 [threads:3] Main loop exited
2023/07/19 21:51:49 [main:3] Shutdown started!
2023/07/19 21:51:49 [threads:3] Waiting for main threads to terminate...
2023/07/19 21:51:49 [threads:4] Waiting for thread ao to shutdown
2023/07/19 21:51:49 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/19 21:51:49 [source:4] Source ao gets down.
2023/07/19 21:51:50 [threads:4] Thread "ao" terminated (1 remaining).
2023/07/19 21:51:50 [source:4] Source mksafe gets down.
2023/07/19 21:51:50 [source:4] Source src_defaultpl gets down.
2023/07/19 21:51:50 [src_defaultpl:4] Waiting for feeding task to stop...
2023/07/19 21:51:50 [threads:4] Waiting for thread clock_ao to shutdown
2023/07/19 21:51:50 [generic queue #2:4] Left select at 1689774710.314960 (1/0/0).
2023/07/19 21:51:50 [generic queue #2:4] There are 1 ready tasks.
2023/07/19 21:51:50 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:51:50 [fast queue #1:4] Enter select at 1689774710.314960, timeout -1.000000 (5/0/0).
2023/07/19 21:51:50 [src_defaultpl:4] Cleaning up request queue...
2023/07/19 21:51:50 [clock.ao:3] Streaming loop stopped.
2023/07/19 21:51:50 [threads:4] Thread "clock_ao" terminated (0 remaining).
2023/07/19 21:51:50 [threads:3] Main threads terminated.
2023/07/19 21:51:50 [threads:3] Shutting down scheduler...
2023/07/19 21:51:50 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:51:50 [fast queue #1:4] Left select at 1689774710.314960 (1/0/0).
2023/07/19 21:51:50 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:51:50 [generic queue #2:4] Enter select at 1689774710.315622, timeout -1.000000 (1/0/0).
2023/07/19 21:51:50 [threads:4] Thread "non-blocking queue #2" terminated (4 remaining).
2023/07/19 21:51:50 [threads:4] Thread "generic queue #1" terminated (3 remaining).
2023/07/19 21:51:50 [threads:4] Thread "fast queue #1" terminated (2 remaining).
2023/07/19 21:51:50 [generic queue #2:4] Left select at 1689774710.317122 (1/0/0).
2023/07/19 21:51:50 [threads:4] Thread "generic queue #2" terminated (1 remaining).
2023/07/19 21:51:50 [process:4] Process exited with code 0
2023/07/19 21:51:50 [process:4] Cleaning up process
2023/07/19 21:51:50 [threads:4] Thread "non-blocking queue #1" terminated (0 remaining).
2023/07/19 21:51:50 [threads:3] Scheduler shut down.
2023/07/19 21:51:50 [main:3] Cleaning downloaded files...
2023/07/19 21:51:50 [main:3] Freeing memory...
2023/07/19 21:51:50 >>> LOG END

When it runs unproperly, crashes (most of the times):

2023/07/19 21:53:10 >>> LOG START
2023/07/19 21:53:08 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/07/19 21:53:08 [main:3] Liquidsoap 2.2.0+dev
2023/07/19 21:53:08 [main:3] Using: angstrom=0.15.0 ao=0.2.4 bigarray=[distributed with OCaml] bigstringaf=0.9.0 bytes=[distributed with OCaml] camlp-streams camomile.lib=2.0 cry=1.0.1 ctypes=0.17.1 ctypes.foreign=0.17.1 ctypes.foreign.base=0.17.1 ctypes.foreign.threaded=0.17.1 ctypes.stubs=0.17.1 curl=0.9.2 dtools=0.4.5 dune-build-info=3.2.0 dune-private-libs.dune-section=3.2.0 dune-site=3.2.0 duppy=0.9.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 gen=1.1 integers lastfm=0.3.3 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_ao liquidsoap_builtins liquidsoap_core liquidsoap_ffmpeg liquidsoap_lastfm liquidsoap_mem_usage liquidsoap_memtrace liquidsoap_optionals liquidsoap_portaudio liquidsoap_runtime liquidsoap_samplerate liquidsoap_srt liquidsoap_ssl liquidsoap_stereotool liquidsoap_taglib liquidsoap_xmlplaylist mem_usage=0.0.3 memtrace=v0.2.2 menhirLib=20210929 metadata=0.2.0 mm=0.8.4 mm.audio=0.8.4 mm.base=0.8.4 mm.image=0.8.4 mm.midi=0.8.4 mm.video=0.8.4 pcre=7.5.0 portaudio=0.2.3 posix-base=2.0.0 posix-socket=2.0.0 posix-socket.constants=2.0.0 posix-socket.stubs=2.0.0 posix-socket.types=2.0.0 samplerate=0.1.6 sedlex=3.2 seq=[distributed with OCaml 4.07 or above] 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.7.0 stdlib-shims=0.3.0 stereotool str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] unix=[distributed with OCaml] uri=4.2.0 winsvc=1.0.1 xmlm=v1.3.0 xmlplaylist=0.1.5
2023/07/19 21:53:08 [clock:3] Using builtin (low-precision) implementation for latency control
2023/07/19 21:53:10 [main:3] Standard library loaded in 1.89 seconds.
2023/07/19 21:53:10 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:53:10 [frame:4] frame.video.framerate set to: 25
2023/07/19 21:53:10 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/07/19 21:53:10 [frame:3] Video frame size set to: 1280x720
2023/07/19 21:53:10 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/07/19 21:53:10 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/07/19 21:53:10 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/07/19 21:53:10 [frame:4] frame.audio.channels set to: 2
2023/07/19 21:53:10 [frame:4] frame.video.default set to: false
2023/07/19 21:53:10 [frame:4] frame.midi.channels set to: 0
2023/07/19 21:53:10 [frame:4] frame.video.width set to: 1280
2023/07/19 21:53:10 [frame:4] frame.video.height set to: 720
2023/07/19 21:53:10 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:53:10 [clock:4] Currently 1 clock(s) allocated.
2023/07/19 21:53:10 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2023/07/19 21:53:10 [startup:3] FFmpeg filters registration: 0.01s
2023/07/19 21:53:10 [startup:3] FFmpeg bitstream filters registration: 0.00s
2023/07/19 21:53:10 [startup:3] Typechecking: 1.56s
2023/07/19 21:53:10 [startup:3] Evaluation: 0.00s
2023/07/19 21:53:10 [startup:3] Typechecking: 0.05s
2023/07/19 21:53:10 [startup:3] Evaluation: 0.00s
2023/07/19 21:53:10 [startup:3] Typechecking: 0.02s
2023/07/19 21:53:10 [startup:3] Evaluation: 0.00s
2023/07/19 21:53:10 [startup:3] Loaded .\minial.liq: 0.02s
2023/07/19 21:53:10 [video.converter:3] Using preferred video converter: ffmpeg.
2023/07/19 21:53:10 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/07/19 21:53:10 [clock.ao:4] Starting 1 source(s)...
2023/07/19 21:53:10 [source:4] Source output.ao gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:53:10 [ao:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:53:10 [source:4] Source mksafe gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:53:10 [source:4] Source src_defaultpl gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:53:10 [src_defaultpl:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:53:10 [source:4] Source safe_blank gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:53:10 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:53:10 [threads:4] Created thread "ao" (1 total).
2023/07/19 21:53:10 [threads:4] Created thread "clock_ao" (2 total).
2023/07/19 21:53:10 [clock:4] Main phase starts.
2023/07/19 21:53:10 [threads:4] Created thread "generic queue #1" (1 total).
2023/07/19 21:53:10 [threads:4] Created thread "generic queue #2" (2 total).
2023/07/19 21:53:10 [threads:4] Created thread "fast queue #1" (3 total).
2023/07/19 21:53:10 [threads:4] Created thread "non-blocking queue #1" (4 total).
2023/07/19 21:53:10 [threads:4] Created thread "non-blocking queue #2" (5 total).
2023/07/19 21:53:10 [clock.ao:3] Streaming loop starts in auto-sync mode
2023/07/19 21:53:10 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/19 21:53:10 [generic queue #2:4] Queue #1 starting...
2023/07/19 21:53:10 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:53:10 [generic queue #2:4] Enter select at 1689774790.673851, timeout 0.000000 (6/0/0).
2023/07/19 21:53:10 [generic queue #1:4] Queue #2 starting...
2023/07/19 21:53:10 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:10 [fast queue #1:4] Queue #3 starting...
2023/07/19 21:53:10 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:10 [non-blocking queue #1:4] Queue #4 starting...
2023/07/19 21:53:10 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:10 [non-blocking queue #2:4] Queue #5 starting...
2023/07/19 21:53:10 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:53:10 [generic queue #2:4] Left select at 1689774790.676101 (2/0/0).
2023/07/19 21:53:10 [generic queue #2:4] There are 3 ready tasks.
2023/07/19 21:53:10 [process:3] Command beetc ls -f "$path" cannot be executed with timeout 5.00 because the internal scheduler is not running. Most likely, this call is made at the beginning of your script. We suggest that you wrap this call in an asynchronous task using `thread.run`. If you really need this value immediately as your script is starting, you should implement the timeout within the process call itself.
2023/07/19 21:53:10 [process:4] Starting process
2023/07/19 21:53:10 [non-blocking queue #2:4] There are 2 ready tasks.
2023/07/19 21:53:10 [non-blocking queue #2:4] Enter select at 1689774790.676101, timeout -1.000000 (5/0/0).
2023/07/19 21:53:10 [process:4] Closing process's stdin
2023/07/19 21:53:10 [non-blocking queue #1:4] There are 2 ready tasks.
2023/07/19 21:53:10 [generic queue #1:4] There are 2 ready tasks.
2023/07/19 21:53:10 [src_defaultpl:4] Playlist stopped.
2023/07/19 21:53:10 [fast queue #1:4] There are 1 ready tasks.
2023/07/19 21:53:10 [video.text:3] Using native implementation
2023/07/19 21:53:10 [non-blocking queue #2:4] Left select at 1689774790.682101 (1/0/0).
2023/07/19 21:53:10 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:10 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:10 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:53:10 [non-blocking queue #2:4] Enter select at 1689774790.682853, timeout -1.000000 (9/0/0).
2023/07/19 21:53:10 [mksafe:3] Switch to safe_blank.
2023/07/19 21:53:10 [ao:3] Opening WMM audio driver output  (2 channels)...
2023/07/19 21:53:11 [clock.ao:3] Delegating synchronization to active sources
2023/07/19 21:53:12 [non-blocking queue #2:4] Left select at 1689774792.143513 (1/0/0).
2023/07/19 21:53:12 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Enter select at 1689774792.143513, timeout -1.000000 (6/0/0).
2023/07/19 21:53:12 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Left select at 1689774792.143513 (1/0/0).
2023/07/19 21:53:12 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Enter select at 1689774792.143513, timeout -1.000000 (9/0/0).
2023/07/19 21:53:12 [non-blocking queue #1:4] Left select at 1689774792.367773 (3/0/0).
2023/07/19 21:53:12 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Enter select at 1689774792.367773, timeout -1.000000 (6/0/0).
2023/07/19 21:53:12 [process:4] Process exited with code 0
2023/07/19 21:53:12 [process:4] Cleaning up process
2023/07/19 21:53:12 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Left select at 1689774792.367773 (1/0/0).
2023/07/19 21:53:12 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:53:12 [non-blocking queue #1:4] Enter select at 1689774792.367773, timeout -1.000000 (6/0/0).
2023/07/19 21:53:12 [decoder.midi:4] Unsupported file extension for "C:\\library\\Molchat Doma\\etazhi (2018)\\06 prognoz.mp3"!
2023/07/19 21:53:12 [decoder.srt:4] Unsupported file extension for "C:\\library\\Molchat Doma\\etazhi (2018)\\06 prognoz.mp3"!        
2023/07/19 21:53:12 [decoder.aiff:4] Unsupported file extension for "C:\\library\\Molchat Doma\\etazhi (2018)\\06 prognoz.mp3"!       
2023/07/19 21:53:12 [decoder.wav:4] Unsupported file extension for "C:\\library\\Molchat Doma\\etazhi (2018)\\06 prognoz.mp3"!        
2023/07/19 21:53:12 [decoder:4] Available decoders: ffmpeg (priority: 10), image (priority: 1)
2023/07/19 21:53:12 [decoder:4] Trying decoder "ffmpeg"
2023/07/19 21:53:12 [non-blocking queue #1:4] Left select at 1689774792.416513 (1/0/0).

(Crashed)

The return val is 0.

When it runs properly:

2023/07/19 21:49:07 >>> LOG START
2023/07/19 21:49:05 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/07/19 21:49:05 [main:3] Liquidsoap 2.2.0+dev
2023/07/19 21:49:05 [main:3] Using: angstrom=0.15.0 ao=0.2.4 bigarray=[distributed with OCaml] bigstringaf=0.9.0 bytes=[distributed with OCaml] camlp-streams camomile.lib=2.0 cry=1.0.1 ctypes=0.17.1 ctypes.foreign=0.17.1 ctypes.foreign.base=0.17.1 ctypes.foreign.threaded=0.17.1 ctypes.stubs=0.17.1 curl=0.9.2 dtools=0.4.5 dune-build-info=3.2.0 dune-private-libs.dune-section=3.2.0 dune-site=3.2.0 duppy=0.9.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 gen=1.1 integers lastfm=0.3.3 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_ao liquidsoap_builtins liquidsoap_core liquidsoap_ffmpeg liquidsoap_lastfm liquidsoap_mem_usage liquidsoap_memtrace liquidsoap_optionals liquidsoap_portaudio liquidsoap_runtime liquidsoap_samplerate liquidsoap_srt liquidsoap_ssl liquidsoap_stereotool liquidsoap_taglib liquidsoap_xmlplaylist mem_usage=0.0.3 memtrace=v0.2.2 menhirLib=20210929 metadata=0.2.0 mm=0.8.4 mm.audio=0.8.4 mm.base=0.8.4 mm.image=0.8.4 mm.midi=0.8.4 mm.video=0.8.4 pcre=7.5.0 portaudio=0.2.3 posix-base=2.0.0 posix-socket=2.0.0 posix-socket.constants=2.0.0 posix-socket.stubs=2.0.0 posix-socket.types=2.0.0 samplerate=0.1.6 sedlex=3.2 seq=[distributed with OCaml 4.07 or above] 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.7.0 stdlib-shims=0.3.0 stereotool str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] unix=[distributed with OCaml] uri=4.2.0 winsvc=1.0.1 xmlm=v1.3.0 xmlplaylist=0.1.5
2023/07/19 21:49:05 [clock:3] Using builtin (low-precision) implementation for latency control
2023/07/19 21:49:07 [main:3] Standard library loaded in 1.83 seconds.
2023/07/19 21:49:07 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:49:07 [frame:4] frame.video.framerate set to: 25
2023/07/19 21:49:07 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/07/19 21:49:07 [frame:3] Video frame size set to: 1280x720
2023/07/19 21:49:07 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/07/19 21:49:07 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/07/19 21:49:07 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/07/19 21:49:07 [frame:4] frame.audio.channels set to: 2
2023/07/19 21:49:07 [frame:4] frame.video.default set to: false
2023/07/19 21:49:07 [frame:4] frame.midi.channels set to: 0
2023/07/19 21:49:07 [frame:4] frame.video.width set to: 1280
2023/07/19 21:49:07 [frame:4] frame.video.height set to: 720
2023/07/19 21:49:07 [frame:4] frame.audio.samplerate set to: 44100
2023/07/19 21:49:07 [clock:4] Currently 1 clock(s) allocated.
2023/07/19 21:49:07 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2023/07/19 21:49:07 [startup:3] FFmpeg filters registration: 0.03s
2023/07/19 21:49:07 [startup:3] FFmpeg bitstream filters registration: 0.00s
2023/07/19 21:49:07 [startup:3] Typechecking: 1.47s
2023/07/19 21:49:07 [startup:3] Evaluation: 0.00s
2023/07/19 21:49:07 [startup:3] Typechecking: 0.03s
2023/07/19 21:49:07 [startup:3] Evaluation: 0.02s
2023/07/19 21:49:07 [startup:3] Typechecking: 0.02s
2023/07/19 21:49:07 [startup:3] Evaluation: 0.00s
2023/07/19 21:49:07 [startup:3] Loaded .\minial.liq: 0.02s
2023/07/19 21:49:07 [video.converter:3] Using preferred video converter: ffmpeg.
2023/07/19 21:49:07 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/07/19 21:49:07 [clock.ao:4] Starting 1 source(s)...
2023/07/19 21:49:07 [source:4] Source output.ao gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:49:07 [ao:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:49:07 [source:4] Source mksafe gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:49:07 [source:4] Source src_defaultpl gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:49:07 [src_defaultpl:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:49:07 [source:4] Source safe_blank gets up with content type: {audio=pcm(stereo)}.
2023/07/19 21:49:07 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/07/19 21:49:07 [threads:4] Created thread "ao" (1 total).
2023/07/19 21:49:07 [threads:4] Created thread "clock_ao" (2 total).
2023/07/19 21:49:07 [clock:4] Main phase starts.
2023/07/19 21:49:07 [threads:4] Created thread "generic queue #1" (1 total).
2023/07/19 21:49:07 [threads:4] Created thread "generic queue #2" (2 total).
2023/07/19 21:49:07 [threads:4] Created thread "fast queue #1" (3 total).
2023/07/19 21:49:07 [threads:4] Created thread "non-blocking queue #1" (4 total).
2023/07/19 21:49:07 [threads:4] Created thread "non-blocking queue #2" (5 total).
2023/07/19 21:49:07 [clock.ao:3] Streaming loop starts in auto-sync mode
2023/07/19 21:49:07 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/19 21:49:07 [generic queue #1:4] Queue #1 starting...
2023/07/19 21:49:07 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:07 [generic queue #1:4] Enter select at 1689774547.791107, timeout 0.000000 (6/0/0).
2023/07/19 21:49:07 [fast queue #1:4] Queue #2 starting...
2023/07/19 21:49:07 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:07 [generic queue #2:4] Queue #3 starting...
2023/07/19 21:49:07 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #1:4] Queue #4 starting...
2023/07/19 21:49:07 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #2:4] Queue #5 starting...
2023/07/19 21:49:07 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:07 [generic queue #1:4] Left select at 1689774547.797859 (2/0/0).
2023/07/19 21:49:07 [generic queue #1:4] There are 3 ready tasks.
2023/07/19 21:49:07 [process:3] Command beetc ls -f "$path" cannot be executed with timeout 5.00 because the internal scheduler is not running. Most likely, this call is made at the beginning of your script. We suggest that you wrap this call in an asynchronous task using `thread.run`. If you really need this value immediately as your script is starting, you should implement the timeout within the process call itself.
2023/07/19 21:49:07 [process:4] Starting process
2023/07/19 21:49:07 [process:4] Closing process's stdin
2023/07/19 21:49:07 [non-blocking queue #2:4] There are 2 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #2:4] Enter select at 1689774547.800856, timeout -1.000000 (5/0/0).
2023/07/19 21:49:07 [non-blocking queue #1:4] There are 2 ready tasks.
2023/07/19 21:49:07 [generic queue #2:4] There are 2 ready tasks.
2023/07/19 21:49:07 [src_defaultpl:4] Playlist stopped.
2023/07/19 21:49:07 [non-blocking queue #2:4] Left select at 1689774547.801606 (1/0/0).
2023/07/19 21:49:07 [fast queue #1:4] There are 1 ready tasks.
2023/07/19 21:49:07 [video.text:3] Using native implementation
2023/07/19 21:49:07 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:07 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #2:4] Enter select at 1689774547.801606, timeout -1.000000 (9/0/0).
2023/07/19 21:49:07 [non-blocking queue #2:4] Left select at 1689774547.801606 (1/0/0).
2023/07/19 21:49:07 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:07 [non-blocking queue #2:4] Enter select at 1689774547.801606, timeout -1.000000 (9/0/0).
2023/07/19 21:49:07 [mksafe:3] Switch to safe_blank.
2023/07/19 21:49:08 [ao:3] Opening WMM audio driver output  (2 channels)...
2023/07/19 21:49:08 [clock.ao:3] Delegating synchronization to active sources
2023/07/19 21:49:09 [non-blocking queue #2:4] Left select at 1689774549.682534 (1/0/0).
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] Enter select at 1689774549.682534, timeout -1.000000 (6/0/0).
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] Left select at 1689774549.682534 (1/0/0).
2023/07/19 21:49:09 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] Enter select at 1689774549.682534, timeout -1.000000 (9/0/0).
2023/07/19 21:49:09 [generic queue #2:4] Left select at 1689774549.915315 (2/0/0).
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #1:4] Enter select at 1689774549.915315, timeout -1.000000 (6/0/0).
2023/07/19 21:49:09 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #1:4] Left select at 1689774549.916066 (1/0/0).
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #1:4] Enter select at 1689774549.916066, timeout -1.000000 (9/0/0).
2023/07/19 21:49:09 [non-blocking queue #1:4] Left select at 1689774549.916066 (3/0/0).
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] Enter select at 1689774549.916066, timeout -1.000000 (6/0/0).
2023/07/19 21:49:09 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [process:4] Process exited with code 0
2023/07/19 21:49:09 [process:4] Cleaning up process
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] Left select at 1689774549.917568 (1/0/0).
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] Enter select at 1689774549.917568, timeout -1.000000 (6/0/0).
2023/07/19 21:49:09 [decoder.midi:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 
Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.srt:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.aiff:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 
Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.wav:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder:4] Available decoders: ffmpeg (priority: 10), image (priority: 1)
2023/07/19 21:49:09 [decoder:4] Trying decoder "ffmpeg"
2023/07/19 21:49:09 [decoder.ffmpeg:3] Requested content-type for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3": {audio=pcm(stereo)}
2023/07/19 21:49:09 [decoder.ffmpeg:3] FFmpeg recognizes "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}, video: {codec: mjpeg, 640x640, yuvj420p}
2023/07/19 21:49:09 [decoder.ffmpeg:3] Decoded content-type for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3": {audio=pcm(stereo)}
2023/07/19 21:49:09 [decoder:4] Selected decoder ffmpeg for file "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3" with expected kind {audio=pcm(stereo)} and detected content {audio=pcm(stereo)}
2023/07/19 21:49:09 [decoder.video.metadata:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.ogg.metadata:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.image.metadata:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [decoder.flac.metadata:4] Unsupported file extension for "C:\\library\\Canzoni Strumentale\\Driving Through Night 
City\\01 Driving Through Night City.mp3"!
2023/07/19 21:49:09 [src_defaultpl:4] Queued 1 requests
2023/07/19 21:49:09 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] Left select at 1689774549.945315 (1/0/0).
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #2:4] Enter select at 1689774549.945315, timeout -1.000000 (6/0/0).
2023/07/19 21:49:09 [src_defaultpl:4] Remaining 0 requests
2023/07/19 21:49:09 [src_defaultpl:3] Prepared "C:\\library\\Canzoni Strumentale\\Driving Through Night City\\01 Driving Through Night City.mp3" (RID 0).
2023/07/19 21:49:09 [mksafe:3] Switch to src_defaultpl with transition.
[mp3float @ 0000018f3df0c040] Could not update timestamps for skipped samples.
2023/07/19 21:49:09 [non-blocking queue #2:4] Left select at 1689774549.994064 (1/0/0).
2023/07/19 21:49:09 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/19 21:49:09 [non-blocking queue #1:4] Enter select at 1689774549.994064, timeout -1.000000 (5/0/0).
2023/07/19 21:49:09 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:09 [generic queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:10 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [decoder.midi:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!       
2023/07/19 21:49:10 [decoder.srt:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!
2023/07/19 21:49:10 [decoder.aiff:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!       
2023/07/19 21:49:10 [decoder.wav:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!        
2023/07/19 21:49:10 [decoder:4] Available decoders: ffmpeg (priority: 10), image (priority: 1)
2023/07/19 21:49:10 [decoder:4] Trying decoder "ffmpeg"
2023/07/19 21:49:10 [decoder.ffmpeg:3] Requested content-type for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3": {audio=pcm(stereo)}
2023/07/19 21:49:10 [decoder.ffmpeg:3] FFmpeg recognizes "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3" as audio: {codec: 
mp3, 44100Hz, 2 channel(s)}, video: {codec: png, 640x640, rgba}
2023/07/19 21:49:10 [decoder.ffmpeg:3] Decoded content-type for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3": {audio=pcm(stereo)}
2023/07/19 21:49:10 [decoder:4] Selected decoder ffmpeg for file "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3" with expected kind {audio=pcm(stereo)} and detected content {audio=pcm(stereo)}
2023/07/19 21:49:10 [decoder.video.metadata:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!
2023/07/19 21:49:10 [decoder.ogg.metadata:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!
2023/07/19 21:49:10 [decoder.image.metadata:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!
2023/07/19 21:49:10 [decoder.flac.metadata:4] Unsupported file extension for "C:\\library\\Non-Album\\Laura Branigan\\Self Control.mp3"!
2023/07/19 21:49:10 [src_defaultpl:4] Queued 1 requests
2023/07/19 21:49:10 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:10 [non-blocking queue #1:4] Left select at 1689774550.171837 (1/0/0).
2023/07/19 21:49:10 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [non-blocking queue #1:4] Enter select at 1689774550.171837, timeout 0.492480 (6/0/0).
2023/07/19 21:49:10 [non-blocking queue #1:4] Left select at 1689774550.172568 (1/0/0).
2023/07/19 21:49:10 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/19 21:49:10 [non-blocking queue #1:4] Enter select at 1689774550.173320, timeout -1.000000 (5/0/0).
2023/07/19 21:49:10 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:10 [generic queue #2:4] There are 1 ready tasks.
2023/07/19 21:49:10 [fast queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [generic queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [generic queue #2:4] There are 0 ready tasks.
2023/07/19 21:49:10 [non-blocking queue #1:4] Left select at 1689774550.176317 (1/0/0).
2023/07/19 21:49:10 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/19 21:49:10 [non-blocking queue #1:4] Enter select at 1689774550.176317, timeout -1.000000 (6/0/0).
(^C)
2023/07/19 21:49:48 [main:3] Shutdown signal received.
2023/07/19 21:49:48 [threads:3] Main loop exited
2023/07/19 21:49:48 [main:3] Shutdown started!
2023/07/19 21:49:48 [threads:3] Waiting for main threads to terminate...
2023/07/19 21:49:48 [threads:4] Waiting for thread ao to shutdown
2023/07/19 21:49:48 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/19 21:49:48 [source:4] Source ao gets down.
2023/07/19 21:49:48 [threads:4] Thread "ao" terminated (1 remaining).
2023/07/19 21:49:48 [threads:4] Waiting for thread clock_ao to shutdown
2023/07/19 21:49:48 [source:4] Source mksafe gets down.
2023/07/19 21:49:48 [source:4] Source safe_blank gets down.
2023/07/19 21:49:48 [clock.ao:3] Streaming loop stopped.
2023/07/19 21:49:48 [threads:4] Thread "clock_ao" terminated (0 remaining).
2023/07/19 21:49:48 [threads:3] Main threads terminated.
2023/07/19 21:49:48 [threads:3] Shutting down scheduler...
2023/07/19 21:49:48 [threads:4] Thread "non-blocking queue #2" terminated (4 remaining).
2023/07/19 21:49:48 [threads:4] Thread "generic queue #2" terminated (3 remaining).
2023/07/19 21:49:48 [threads:4] Thread "fast queue #1" terminated (2 remaining).
2023/07/19 21:49:48 [threads:4] Thread "generic queue #1" terminated (1 remaining).
2023/07/19 21:49:48 [non-blocking queue #1:4] Left select at 1689774588.958208 (1/0/0).
2023/07/19 21:49:48 [threads:4] Thread "non-blocking queue #1" terminated (0 remaining).
2023/07/19 21:49:48 [threads:3] Scheduler shut down.
2023/07/19 21:49:48 [main:3] Cleaning downloaded files...
2023/07/19 21:49:48 [main:3] Freeing memory...
2023/07/19 21:49:48 >>> LOG END
rsp4jack commented 1 year ago

I also tried to increase the timeout of process.run but it will still time out.

toots commented 1 year ago

There was an error with the process.run logic. main and rolling-release-v2.2.x should have updated builds imminently. Build for rolling-release-v2.2.x can be tracked here: https://github.com/savonet/liquidsoap/actions/runs/5600415177

Hopefully this fixes this issue.

rsp4jack commented 1 year ago

Unfortunately, this doesn't work. I tried the newest one https://github.com/savonet/liquidsoap/actions/runs/5605207025 but it still crashes.

Log:

2023/07/20 19:58:34 >>> LOG START
2023/07/20 19:58:32 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2023/07/20 19:58:32 [main:3] Liquidsoap 2.2.0+dev
2023/07/20 19:58:32 [main:3] Using: angstrom=0.15.0 ao=0.2.4 bigarray=[distributed with OCaml] bigstringaf=0.9.0 bytes=[distributed with OCaml] camlp-streams camomile.lib=2.0 cry=1.0.1 ctypes=0.17.1 ctypes.foreign=0.17.1 ctypes.foreign.base=0.17.1 ctypes.foreign.threaded=0.17.1 ctypes.stubs=0.17.1 curl=0.9.2 dtools=0.4.5 dune-build-info=3.2.0 dune-private-libs.dune-section=3.2.0 dune-site=3.2.0 duppy=0.9.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 gen=1.1 integers lastfm=0.3.3 liquidsoap-lang=2.2.0 liquidsoap-lang.console=2.2.0 liquidsoap_ao 
liquidsoap_builtins liquidsoap_core liquidsoap_ffmpeg liquidsoap_lastfm liquidsoap_mem_usage liquidsoap_memtrace liquidsoap_optionals liquidsoap_portaudio liquidsoap_runtime liquidsoap_samplerate liquidsoap_srt liquidsoap_ssl liquidsoap_stereotool liquidsoap_taglib liquidsoap_xmlplaylist mem_usage=0.0.3 memtrace=v0.2.2 menhirLib=20210929 metadata=0.2.0 mm=0.8.4 mm.audio=0.8.4 mm.base=0.8.4 mm.image=0.8.4 mm.midi=0.8.4 mm.video=0.8.4 pcre=7.5.0 portaudio=0.2.3 posix-base=2.0.0 posix-socket=2.0.0 posix-socket.constants=2.0.0 posix-socket.stubs=2.0.0 posix-socket.types=2.0.0 samplerate=0.1.6 sedlex=3.2 seq=[distributed with OCaml 4.07 or above] 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.7.0 stdlib-shims=0.3.0 stereotool str=[distributed with OCaml] stringext=1.6.0 taglib=0.3.10 threads=[distributed with OCaml] threads.posix=[distributed with OCaml] unix=[distributed with OCaml] uri=4.2.0 winsvc=1.0.1 xmlm=v1.3.0 xmlplaylist=0.1.5
2023/07/20 19:58:32 [clock:3] Using builtin (low-precision) implementation for latency control
2023/07/20 19:58:34 [main:3] Standard library loaded in 1.91 seconds.
2023/07/20 19:58:34 [frame:4] frame.audio.samplerate set to: 44100
2023/07/20 19:58:34 [frame:4] frame.video.framerate set to: 25
2023/07/20 19:58:34 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2023/07/20 19:58:34 [frame:3] Video frame size set to: 1280x720
2023/07/20 19:58:34 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2023/07/20 19:58:34 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2023/07/20 19:58:34 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2023/07/20 19:58:34 [frame:4] frame.audio.channels set to: 2
2023/07/20 19:58:34 [frame:4] frame.video.default set to: false
2023/07/20 19:58:34 [frame:4] frame.midi.channels set to: 0
2023/07/20 19:58:34 [frame:4] frame.video.width set to: 1280
2023/07/20 19:58:34 [frame:4] frame.video.height set to: 720
2023/07/20 19:58:34 [frame:4] frame.audio.samplerate set to: 44100
2023/07/20 19:58:34 [clock:4] Currently 1 clock(s) allocated.
2023/07/20 19:58:34 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2023/07/20 19:58:34 [startup:3] FFmpeg filters registration: 0.01s
2023/07/20 19:58:34 [startup:3] FFmpeg bitstream filters registration: 0.02s
2023/07/20 19:58:34 [startup:3] Typechecking: 1.58s
2023/07/20 19:58:34 [startup:3] Evaluation: 0.01s
2023/07/20 19:58:34 [startup:3] Typechecking: 0.03s
2023/07/20 19:58:34 [startup:3] Evaluation: 0.00s
2023/07/20 19:58:34 [startup:3] Typechecking: 0.02s
2023/07/20 19:58:34 [startup:3] Evaluation: 0.00s
2023/07/20 19:58:34 [startup:3] Loaded .\minial.liq: 0.02s
2023/07/20 19:58:34 [video.converter:3] Using preferred video converter: ffmpeg.
2023/07/20 19:58:34 [audio.converter:3] Using samplerate converter: libsamplerate.
2023/07/20 19:58:34 [clock.ao:4] Starting 1 source(s)...
2023/07/20 19:58:34 [source:4] Source output.ao gets up with content type: {audio=pcm(stereo)}.
2023/07/20 19:58:34 [ao:3] Content type is {audio=pcm(stereo)}.
2023/07/20 19:58:34 [source:4] Source mksafe gets up with content type: {audio=pcm(stereo)}.
2023/07/20 19:58:34 [source:4] Source src_defaultpl gets up with content type: {audio=pcm(stereo)}.
2023/07/20 19:58:34 [src_defaultpl:3] Content type is {audio=pcm(stereo)}.
2023/07/20 19:58:34 [source:4] Source safe_blank gets up with content type: {audio=pcm(stereo)}.
2023/07/20 19:58:34 [safe_blank:3] Content type is {audio=pcm(stereo)}.
2023/07/20 19:58:34 [threads:4] Created thread "ao" (1 total).
2023/07/20 19:58:34 [threads:4] Created thread "clock_ao" (2 total).
2023/07/20 19:58:34 [clock:4] Main phase starts.
2023/07/20 19:58:34 [threads:4] Created thread "generic queue #1" (1 total).
2023/07/20 19:58:34 [threads:4] Created thread "generic queue #2" (2 total).
2023/07/20 19:58:34 [threads:4] Created thread "fast queue #1" (3 total).
2023/07/20 19:58:34 [threads:4] Created thread "non-blocking queue #1" (4 total).
2023/07/20 19:58:34 [threads:4] Created thread "non-blocking queue #2" (5 total).
2023/07/20 19:58:34 [clock.ao:3] Streaming loop starts in auto-sync mode
2023/07/20 19:58:34 [clock.ao:3] Delegating synchronization to CPU clock
2023/07/20 19:58:34 [generic queue #1:4] Queue #1 starting...
2023/07/20 19:58:34 [generic queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:34 [generic queue #1:4] Enter select at 1689854314.900594, timeout 0.000000 (6/0/0).
2023/07/20 19:58:34 [generic queue #2:4] Queue #2 starting...
2023/07/20 19:58:34 [generic queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:34 [non-blocking queue #1:4] Queue #3 starting...
2023/07/20 19:58:34 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:34 [fast queue #1:4] Queue #4 starting...
2023/07/20 19:58:34 [fast queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:34 [non-blocking queue #2:4] Queue #5 starting...
2023/07/20 19:58:34 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:34 [generic queue #1:4] Left select at 1689854314.902845 (2/0/0).
2023/07/20 19:58:34 [generic queue #1:4] There are 3 ready tasks.
2023/07/20 19:58:34 [process:4] Starting process
2023/07/20 19:58:34 [process:4] Closing process's stdin
2023/07/20 19:58:34 [non-blocking queue #2:4] There are 2 ready tasks.
2023/07/20 19:58:34 [non-blocking queue #2:4] Enter select at 1689854314.905843, timeout -1.000000 (8/0/0).
2023/07/20 19:58:34 [fast queue #1:4] There are 2 ready tasks.
2023/07/20 19:58:34 [src_defaultpl:4] Playlist stopped.
2023/07/20 19:58:34 [non-blocking queue #1:4] There are 1 ready tasks.
2023/07/20 19:58:34 [generic queue #2:4] There are 1 ready tasks.
2023/07/20 19:58:34 [video.text:3] Using native implementation
2023/07/20 19:58:34 [generic queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:34 [fast queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:34 [non-blocking queue #2:4] Left select at 1689854314.911845 (1/0/0).
2023/07/20 19:58:34 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:34 [non-blocking queue #2:4] Enter select at 1689854314.911845, timeout -1.000000 (9/0/0).
2023/07/20 19:58:34 [mksafe:3] Switch to safe_blank.
2023/07/20 19:58:35 [ao:3] Opening WMM audio driver output  (2 channels)...
2023/07/20 19:58:35 [clock.ao:3] Delegating synchronization to active sources
2023/07/20 19:58:36 [non-blocking queue #2:4] Left select at 1689854316.234875 (1/0/0).
2023/07/20 19:58:36 [non-blocking queue #2:4] There are 1 ready tasks.
2023/07/20 19:58:36 [fast queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:36 [fast queue #1:4] Enter select at 1689854316.234875, timeout -1.000000 (6/0/0).
2023/07/20 19:58:36 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:36 [generic queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:36 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:36 [fast queue #1:4] Left select at 1689854316.234875 (1/0/0).
2023/07/20 19:58:36 [fast queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:36 [fast queue #1:4] Enter select at 1689854316.234875, timeout -1.000000 (9/0/0).
2023/07/20 19:58:36 [fast queue #1:4] Left select at 1689854316.387875 (3/0/0).
2023/07/20 19:58:36 [generic queue #2:4] There are 1 ready tasks.
2023/07/20 19:58:36 [non-blocking queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:36 [non-blocking queue #2:4] Enter select at 1689854316.387875, timeout -1.000000 (6/0/0).
2023/07/20 19:58:36 [process:4] Process exited with code 0
2023/07/20 19:58:36 [fast queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:36 [process:4] Cleaning up process
2023/07/20 19:58:36 [non-blocking queue #1:4] There are 0 ready tasks.
2023/07/20 19:58:36 [generic queue #2:4] There are 0 ready tasks.
2023/07/20 19:58:36 [non-blocking queue #2:4] Left select at 1689854316.389376 (1/0/0).
2023/07/20 19:58:36 [non-blocking queue #2:4] There are 0 ready tasks.
toots commented 1 year ago

Thanks for this. Do you have a reproduction script I could test?

rsp4jack commented 1 year ago

https://github.com/savonet/liquidsoap/issues/3242#issue-1811444548, on the top.

toots commented 1 year ago

Thanks. I'll see if I can reproduce.

rsp4jack commented 1 year ago

Well, I didn't find that my OS makes minidumps when it crashes. I tested it again using https://github.com/savonet/liquidsoap/commit/6eba12641e468c435114b2afc8763211f41b168a. liquidsoap.exe.4576.dmp.gz

rsp4jack commented 1 year ago

Also I debugged it with gdb. This is the whole record: https://gist.github.com/rsp4jack/1e3e2443319d9bbddb68d132a7868c7d

toots commented 1 year ago

Thanks for this, this is really helpful. I looks like an issue inside ffmpeg's code handling file opening. The file name seems to contain non utf-8 characters.

If that a new issue for you? If so, can you point to a version that used to work?

rsp4jack commented 1 year ago

It works in Liquidsoap 2.1.4.

toots commented 1 year ago

@rsp4jack I'm looking at this again. Is the original description still valid in that the process runs when setting fast=true but not otherwise?