Deadlock when logging

[jdbuys]

Describe the bug
Liquidsoap runs for x amount of time and then just deadlocks.

To Reproduce

#!/usr/local/bin/liquidsoap
set("log.file.path","radio.log")
set("log.stdout", true)
set("server.telnet",false)
set("server.socket",true)
set("server.socket.path","lsoap.sock")
set("server.socket.permissions",511)
set("server.timeout",20.)
set("scheduler.generic_queues",2)
set("scheduler.non_blocking_queues",2)
set("scheduler.fast_queues",0)
set("scheduler.log",true)
set("init.catch_exn",true)

delay = ref 3.
#Add error handler
def error_handler(the_error)=
  ignore(interactive.string("error_value",the_error))
  if string.match(pattern="401",the_error) == true then
    delay := 30.
  else
    delay := !delay
  end
  !delay
end

enable_external_faad_decoder()
#Add ffmpeg
def test_ffmpeg(file) = -1 end
ffmpeg_p = "/usr/local/bin/ffmpeg -i - -f wav -"
add_decoder(name="FFMPEG",description="Decode files using the ffmpeg decoder binary",mimes=["audio/aacp","application/octet-stream","audio/x-wav"],test=test_ffmpeg,ffmpeg_p)


source=fallback(track_sensitive=false,[playlist("/tmp/playlist.pls"),request.queue(id="queue",length=10.0),request.equeue(id="equeue")])
source=mksafe(source)
add_skip_command(source)
source=audio_to_stereo(id="source",source)



output.icecast(%mp3(stereo=true,bitrate=64,samplerate=44100),id="icecast",host="127.0.0.1",port=80,user="source",password="hackme",fallible=true,on_error=error_handler,name="Test",description="Test",mount="idGreenMonkeyUnited",url="http://test.com",source)

Expected behavior
Expecting no deadlock.

Version details

• OS: Ubuntu
• Version 1.3.4

Install method
Installed from source

[jdbuys]

Here's the backtrace from the deadlocked process.

(gdb) inf thr
  11 Thread 0x2b06b3014940 (LWP 19795)  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
  10 Thread 0x2b06b3a15940 (LWP 19796)  0x00000035b86ce172 in select () from /lib64/libc.so.6
  9 Thread 0x2b06b4416940 (LWP 19797)  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  8 Thread 0x2b06b4e17940 (LWP 19798)  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
  7 Thread 0x2b06b5818940 (LWP 19799)  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  6 Thread 0x2b06b6219940 (LWP 19800)  0x00000035b86cc0b6 in poll () from /lib64/libc.so.6
  5 Thread 0x2b06b6c1a940 (LWP 19801)  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4 Thread 0x2b06b761b940 (LWP 19802)  0x00000035b86ce172 in select () from /lib64/libc.so.6
  3 Thread 0x2b06b801c940 (LWP 19803)  0x00000035b86ce172 in select () from /lib64/libc.so.6
  2 Thread 0x2b06b8b42940 (LWP 19804)  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
* 1 Thread 0x2b06b1035f40 (LWP 19771)  0x00000035b9a0e9c8 in do_sigwait () from /lib64/libpthread.so.0


warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff6e1cf000
0x00000035b9a0e9c8 in do_sigwait () from /lib64/libpthread.so.0
(gdb) thr apply all bt

Thread 11 (Thread 0x2b06b3014940 (LWP 19795)):
#0  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000035b9a10341 in _L_cond_lock_989 () from /lib64/libpthread.so.0
#2  0x00000035b9a1020f in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0
#3  0x00000035b9a0b0b4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#4  0x00000000007b9937 in caml_condition_wait ()
#5  0x00000000006d0d82 in camlDtools__fun_3375 () at dtools.ml:830
#6  0x00000000006d0b8c in camlDtools__mutexify_2192 () at dtools.ml:797
#7  0x00000000006d0d13 in camlDtools__f_2208 () at dtools.ml:825
#8  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#9  0x00000000007d7aae in caml_start_program ()
#10 0x00000000007ba694 in caml_thread_start ()
#11 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#12 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x2b06b3a15940 (LWP 19796)):
#0  0x00000035b86ce172 in select () from /lib64/libc.so.6
#1  0x00000000007ba34d in caml_thread_tick ()
#2  0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#3  0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x2b06b4416940 (LWP 19797)):
#0  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000007b9937 in caml_condition_wait ()
#2  0x00000000006c69e5 in camlDuppy__run_1588 () at duppy.ml:344
#3  0x00000000006c6b8d in camlDuppy__f_1594 () at duppy.ml:350
#4  0x00000000006c6715 in camlDuppy__queue_inner_3418 () at duppy.ml:356
#5  0x000000000067b352 in camlTutils__queue_1717 () at tools/tutils.ml:212
#6  0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#7  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#8  0x00000000007d7aae in caml_start_program ()
#9  0x00000000007ba694 in caml_thread_start ()
#10 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#11 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x2b06b4e17940 (LWP 19798)):
#0  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000035b9a08f4a in _L_lock_1034 () from /lib64/libpthread.so.0
#2  0x00000035b9a08e0c in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000007baa4d in caml_mutex_lock ()
#4  0x00000000006d0b37 in camlDtools__mutexify_2192 () at dtools.ml:795
#5  0x0000000000548935 in camlLang_builtins__fun_6960 () at lang/lang_builtins.ml:1809
#6  0x000000000064815e in camlLang_values__apply_2231 () at lang/lang_values.ml:971
#7  0x0000000000647767 in camlLang_values__eval_2230 () at lang/lang_values.ml:917
#8  0x000000000064815e in camlLang_values__apply_2231 () at lang/lang_values.ml:971
#9  0x000000000064815e in camlLang_values__apply_2231 () at lang/lang_values.ml:971
#10 0x000000000067a6cd in camlTutils__finalize_1361 () at tools/tutils.ml:85
#11 0x000000000064815e in camlLang_values__apply_2231 () at lang/lang_values.ml:971
#12 0x0000000000647767 in camlLang_values__eval_2230 () at lang/lang_values.ml:917
#13 0x000000000064815e in camlLang_values__apply_2231 () at lang/lang_values.ml:971
#14 0x000000000067a6cd in camlTutils__finalize_1361 () at tools/tutils.ml:85
#15 0x0000000000547289 in camlLang_builtins__fun_6736 () at lang/lang_builtins.ml:1481
---Type <return> to continue, or q <return> to quit--- 
#16 0x00000000006c582c in camlDuppy__fun_3287 () at duppy.ml:151
#17 0x00000000006c64c1 in camlDuppy__exec_1562 () at duppy.ml:279
#18 0x00000000006c6873 in camlDuppy__run_1588 () at duppy.ml:313
#19 0x00000000006c6b8d in camlDuppy__f_1594 () at duppy.ml:350
#20 0x00000000006c6715 in camlDuppy__queue_inner_3418 () at duppy.ml:356
#21 0x000000000067b352 in camlTutils__queue_1717 () at tools/tutils.ml:212
#22 0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#23 0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#24 0x00000000007d7aae in caml_start_program ()
#25 0x00000000007ba694 in caml_thread_start ()
#26 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#27 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x2b06b5818940 (LWP 19799)):
#0  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000007b9937 in caml_condition_wait ()
#2  0x00000000006c69e5 in camlDuppy__run_1588 () at duppy.ml:344
#3  0x00000000006c6b8d in camlDuppy__f_1594 () at duppy.ml:350
#4  0x00000000006c6715 in camlDuppy__queue_inner_3418 () at duppy.ml:356
#5  0x000000000067b30f in camlTutils__queue_1717 () at tools/tutils.ml:214
#6  0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#7  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#8  0x00000000007d7aae in caml_start_program ()
#9  0x00000000007ba694 in caml_thread_start ()
#10 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#11 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x2b06b6219940 (LWP 19800)):
#0  0x00000035b86cc0b6 in poll () from /lib64/libc.so.6
#1  0x00000000007b3e56 in caml_poll (_read=47307741856816, _write=13470432, _err=13470432, _timeout=<value optimized out>) at duppy_stubs.c:95
#2  0x00000000006c4ec0 in camlDuppy__poll_1414 () at duppy.ml:32
#3  0x00000000006c60d4 in camlDuppy__f_1522 () at duppy.ml:207
#4  0x00000000006c5c14 in camlDuppy__process_1513 () at duppy.ml:227
#5  0x00000000006c6947 in camlDuppy__run_1588 () at duppy.ml:328
#6  0x00000000006c6b8d in camlDuppy__f_1594 () at duppy.ml:350
#7  0x00000000006c6715 in camlDuppy__queue_inner_3418 () at duppy.ml:356
#8  0x000000000067b30f in camlTutils__queue_1717 () at tools/tutils.ml:214
#9  0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#10 0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#11 0x00000000007d7aae in caml_start_program ()
#12 0x00000000007ba694 in caml_thread_start ()
#13 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#14 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x2b06b6c1a940 (LWP 19801)):
#0  0x00000035b9a0b019 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000007b9937 in caml_condition_wait ()
#2  0x000000000067be0a in camlTutils__fun_2842 () at tools/tutils.ml:314
#3  0x000000000067a65c in camlTutils__mutexify_1350 () at tools/tutils.ml:80
#4  0x00000000006cfd29 in camlDtools__thread_1862 () at dtools.ml:556
#5  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#6  0x00000000007d7aae in caml_start_program ()
#7  0x00000000007ba694 in caml_thread_start ()
---Type <return> to continue, or q <return> to quit---
#8  0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#9  0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x2b06b761b940 (LWP 19802)):
#0  0x00000035b86ce172 in select () from /lib64/libc.so.6
#1  0x00000000007bdd48 in unix_select ()
#2  0x0000000000728bb8 in camlThread__delay_1290 () at thread.ml:75
#3  0x00000000006083eb in camlHttp_source__fun_4984 () at sources/http_source.ml:544
#4  0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#5  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#6  0x00000000007d7aae in caml_start_program ()
#7  0x00000000007ba694 in caml_thread_start ()
#8  0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#9  0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x2b06b801c940 (LWP 19803)):
#0  0x00000035b86ce172 in select () from /lib64/libc.so.6
#1  0x00000000007bdd48 in unix_select ()
#2  0x0000000000728bb8 in camlThread__delay_1290 () at thread.ml:75
#3  0x00000000006083eb in camlHttp_source__fun_4984 () at sources/http_source.ml:544
#4  0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#5  0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#6  0x00000000007d7aae in caml_start_program ()
#7  0x00000000007ba694 in caml_thread_start ()
#8  0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#9  0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x2b06b8b42940 (LWP 19804)):
#0  0x00000035b9a0d654 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000035b9a08f4a in _L_lock_1034 () from /lib64/libpthread.so.0
#2  0x00000035b9a08e0c in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000007baa4d in caml_mutex_lock ()
#4  0x00000000006d0b37 in camlDtools__mutexify_2192 () at dtools.ml:795
#5  0x00000000007d7aae in caml_start_program ()
#6  0x00000000007d5d52 in caml_final_do_calls () at finalise.c:201
#7  0x00000000007c4fec in caml_gc_dispatch () at minor_gc.c:443
#8  0x00000000007c2179 in caml_garbage_collection () at signals_asm.c:78
#9  0x00000000007d78cc in caml_call_gc ()
#10 0x0000000000744c62 in camlQueue__add_1219 () at queue.ml:49
#11 0x00000000006d0dda in camlDtools__fun_3380 () at dtools.ml:841
#12 0x00000000006d0b8c in camlDtools__mutexify_2192 () at dtools.ml:797
#13 0x000000000060f9ea in camlGenerated__fun_2098 () at sources/generated.ml:138
#14 0x000000000067a65c in camlTutils__mutexify_1350 () at tools/tutils.ml:80
#15 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#16 0x00000000005c02c5 in camlAdd__fun_2433 () at operators/add.ml:126
#17 0x0000000000733758 in camlList__fold_left_1286 () at list.ml:96
#18 0x00000000005bf8f9 in camlAdd__fun_2392 () at operators/add.ml:109
#19 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#20 0x00000000005bbe9b in camlCross__fun_2277 () at operators/cross.ml:203
#21 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#23 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#24 0x00000000005c59f3 in camlSwitch__fun_2619 () at operators/switch.ml:204
---Type <return> to continue, or q <return> to quit---
#25 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#26 0x00000000005f1e3c in camlMean__fun_1669 () at conversions/mean.ml:59
#27 0x00000000006583ae in camlSource__fun_2730 () at source.ml:526
#28 0x00000000005ee078 in camlOutput__fun_2301 () at outputs/output.ml:174
#29 0x000000000065577c in camlClock__fun_2790 () at clock.ml:160
#30 0x0000000000733758 in camlList__fold_left_1286 () at list.ml:96
#31 0x0000000000653c51 in camlClock__fun_2743 () at clock.ml:158
#32 0x0000000000656bf1 in camlClock__loop_1981 () at clock.ml:374
#33 0x00000000006543ad in camlClock__fun_2987 () at clock.ml:377
#34 0x000000000067adf2 in camlTutils__fun_2698 () at tools/tutils.ml:136
#35 0x0000000000728af9 in camlThread__fun_1570 () at thread.ml:39
#36 0x00000000007d7aae in caml_start_program ()
#37 0x00000000007ba694 in caml_thread_start ()
#38 0x00000035b9a0683d in start_thread () from /lib64/libpthread.so.0
#39 0x00000035b86d4fdd in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x2b06b1035f40 (LWP 19771)):
#0  0x00000035b9a0e9c8 in do_sigwait () from /lib64/libpthread.so.0
#1  0x00000035b9a0ea6d in sigwait () from /lib64/libpthread.so.0
#2  0x00000000007ba49c in caml_wait_signal ()
#3  0x00000000006cf9ec in camlDtools__wait_signal_1606 () at dtools.ml:527
#4  0x00000000006cfb36 in camlDtools__main_1857 () at dtools.ml:567
#5  0x00000000006cfe38 in camlDtools__catch_1869 () at dtools.ml:574
#6  0x0000000000539fb1 in camlMain__Make_1816 () at main.ml:658
#7  0x0000000000537630 in camlRunner__entry () at runner.ml:30
#8  0x000000000052eb59 in caml_program ()
#9  0x00000000007d7aae in caml_start_program ()
#10 0x00000000007c0cdc in caml_startup_exn (argv=0x7fff6e1a8498) at startup.c:144
#11 0x00000000007c0cee in caml_startup (argv=0x7fff6e1a8180) at startup.c:149
#12 0x00000000007c0d14 in caml_main (argv=0x7fff6e1a8180) at startup.c:158
#13 0x00000000007c0d28 in main (argc=<value optimized out>, argv=0x0) at main.c:37

[toots]

Hi,

Thanks for the report.

There's been some fairly significant amount of work done to fix bugs since 1.3.4. Any chance you would be able to test with 1.3.7 and, if the bug isn't fixed there, the latest master? Both of these branches might possibly already have a fix for your problem.

Thanks!
Romain

[jdbuys]

I am trying to upgrade to master just to make sure, but unfortunately now my crossfade does not work.
Will it be possible to quickly check the following code and see if you can maybe see an issue?

Before upgrade:

def crossfade(s)
  s = fade.in(type="lin", override_type="liq_fade_in_type",duration=0.1, s)
  s = fade.out(type="lin",override_type="liq_fade_out_type", duration=0.1, s)
  fader = fun (a,b) -> add(normalize=false,[b,a])
  cross(duration=0.1,conservative=false,fader,s)
end

After upgrade:

def crossfade(s)
  fade.in = fade.in(duration=0.1)
  fade.out = fade.out(duration=0.1)
  fader = fun (_,_,_,_,a,b) -> add(normalize=false,[fade.in(b),fade.out(a)])
  cross(duration=0.1,fader,s)
end

The fade type an duration and the cross duration is set via metadata and I have confirmed that it is actually set correctly.

Thanks

[toots]

Hi,

Metadata for changing duration is now called "liq_cross_duration". You can either change to this in your system of change it in cross() via the override_duration parameter.

Thanks for your effort to upgrade!

[jdbuys]

Sorry, I should have added that I did change the metadata for duration on my system side and still no cross unfortunately.
I load a new track via request.queue 20 seconds before the currently playing track finishes. Will that make any difference to how the cross is implemented?

[jdbuys]

Maybe this will help. This is the messages in the log every time a cross should happen.

2019/05/28 09:42:17 [cross_7536:3] Analysis: -31.987918dB / -nandB (4.18s / 0.00s)
2019/05/28 09:42:17 [cross_7536:3] Not enough data for crossing.

[jdbuys]

I found the crossfading problem.
Before the upgrade:

source_main = cue_cut(source_main)
source_main = crossfade(source_main)

After the upgrade:

source_main = crossfade(source_main)
source_main = cue_cut(source_main)

So it seems that now after upgrading the cue_cut must happen after the crossfade. In the songs I tested the cue_cut would be for e.g 3 seconds before the end to trim silence, but the fade was only 3 seconds, so it did not work.
It makes sense that the cue_cut should be after the cross operator, but that was the issue for me.
I will now proceed to see if I can replicate the deadlock again.

[toots]

Glad to hear that you've found a way to make the crossfade work. Internals of the cross operator have changed a lot so it's expected that these things might have to change but great to know that you can still have the same functionality..

Let us know if you can reproduce the deadlock.

[jdbuys]

Will do. If you like we can close this until I can reproduce it again. So far is has been running without issues.

[toots]

Sounds good!