Interrupted select() when using a timeout in process.read

[knyar]

Describe the bug

When I set a non-zero timeout value in process.read, I am getting liquidsoap crash with the following message:

2023/01/26 09:14:01 [clock.main:2] Source input.consumer_0 failed while streaming: Interrupted system call in select()!

Here's relevant part of the script:

def process_metadata(m) =
  title = m["title"]
  s = string.trim(process.read(timeout=3.0, env=[("ls_title", title)], "/config/scripts/metadata.py"))
  if (s == "") then
    [("title", title)]
  else
    [("title", s)]
  end
end

input = input.http("http://10.0.0.1:80/input.mp3", id="input")
input = metadata.map(process_metadata, input)
...

Removing the timeout value fixes the crashes.

Looking at strace, it looks like this is caused by the process getting a SIGCHLD when the script I am calling finishes its execution:

[pid 3612723] pselect6(25, [24], [], [], {tv_sec=1, tv_nsec=0}, NULL <unfinished ...>
[pid 3612723] <... pselect6 resumed>)   = ? ERESTARTNOHAND (To be restarted if no handler)
[pid 3612723] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=105, si_uid=10000, si_status=0, si_utime=0, si_stime=0} ---
[pid 3612723] rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [INT PIPE TERM CHLD], 8) = 0
[pid 3612723] write(3, "\1\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid 3612723] <... write resumed>)      = 8
[pid 3612723] rt_sigprocmask(SIG_SETMASK, [INT PIPE TERM CHLD],  <unfinished ...>
[pid 3612723] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 3612723] rt_sigreturn({mask=[INT PIPE TERM]}) = -1 EINTR (Interrupted system call)

I suspect the solution might be to handle Unix.EINTR in Tutils.wait_for.

Version details

• OS: Debian 11, liquidsoap in Docker. Kernel 5.10.158-2 (2022-12-13) x86_64 GNU/Linux
• Version: 2.1.3

Install method

Official docker container (savonet/liquidsoap:v2.1.3).

[toots]

Hi! Thanks for reporting. wait_for already has an exception handler for catching Unix.EINTR, as well as the duppy schedule.

Any chance you could reproduce with log.level.set(4)? This should give us the whole stack trace. Thanks!

[knyar]

Oh right, I think it's been fixed in main. I will wait for a new release then :)

Apologies for the noise.

2023/02/12 12:42:57 [process:4] Starting process
2023/02/12 12:42:57 [process:4] Closing process's stdin
2023/02/12 12:42:57 [clock.main:4] Source input_main_buffer.consumer_0 failed while streaming: Interrupted system call in select()!
2023/02/12 12:42:57 [clock.main:4] Raised by primitive operation at Tutils.wait_for.wait in file "tools/tutils.ml", line 358, characters 19-39
2023/02/12 12:42:57 [clock.main:4] Called from Builtins_process.(fun).asynchronous.(fun) in file "builtins/builtins_process.ml", line 228, characters 16-56
2023/02/12 12:42:57 [clock.main:4] Called from Tutils.finalize in file "tools/tutils.ml", line 105, characters 12-16
2023/02/12 12:42:57 [clock.main:4] Re-raised at Tutils.finalize in file "tools/tutils.ml", line 111, characters 4-38
2023/02/12 12:42:57 [clock.main:4] Called from Builtins_process.(fun).asynchronous in file "builtins/builtins_process.ml", line 198, characters 8-1023
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.apply.f in file "lang/evaluation.ml", line 317, characters 8-12
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.eval in file "lang/evaluation.ml", line 239, characters 16-26
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.apply.f in file "lang/evaluation.ml", line 317, characters 8-12
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.eval.ans.(fun) in file "lang/evaluation.ml", line 294, characters 46-56
2023/02/12 12:42:57 [clock.main:4] Called from Stdlib__List.map in file "list.ml", line 92, characters 20-23
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.eval.ans in file "lang/evaluation.ml", line 294, characters 18-60
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.eval in file "lang/evaluation.ml", line 239, characters 16-26
2023/02/12 12:42:57 [clock.main:4] Called from Evaluation.apply.f in file "lang/evaluation.ml", line 317, characters 8-12
2023/02/12 12:42:57 [clock.main:4] Called from Tutils.finalize in file "tools/tutils.ml", line 105, characters 12-16
2023/02/12 12:42:57 [clock.main:4] Re-raised at Tutils.finalize in file "tools/tutils.ml", line 111, characters 4-38
2023/02/12 12:42:57 [clock.main:4] Called from Map_metadata.map_metadata#rewrite in file "operators/map_metadata.ml", line 36, characters 15-59
2023/02/12 12:42:57 [clock.main:4] Called from Map_metadata.map_metadata#get_frame.(fun) in file "operators/map_metadata.ml", line 64, characters 12-26
2023/02/12 12:42:57 [clock.main:4] Called from Stdlib__List.iter in file "list.ml", line 110, characters 12-15
2023/02/12 12:42:57 [clock.main:4] Called from Source.operator#instrumented_get_frame in file "source.ml", line 589, characters 6-24
2023/02/12 12:42:57 [clock.main:4] Called from Source.operator#get in file "source.ml", line 660, characters 10-41
2023/02/12 12:42:57 [clock.main:4] Called from Output.output#output in file "outputs/output.ml", line 166, characters 10-30
2023/02/12 12:42:57 [clock.main:4] Called from Clock.clock#end_tick.(fun) in file "clock.ml", line 299, characters 14-22

[toots]

Thanks for reporting! This is fixed in main but was not in the upcoming bugfix release so it'll be great to have it in it!