search

DynamoRIO / dynamorio

Dynamic Instrumentation Tool Platform
Other
2.64k stars 560 forks source link

HANG after failed clone3 with CLONE_VFORK (infinite sched_yield loop) #5903

Open nsz-arm opened 1 year ago

nsz-arm commented 1 year ago

Similar to #5898 but this time vfork child execs and parent hangs at a sigaction call.

The hang only happens if there was a clone3 that fails (with EINVAL) followed by an equivalent clone (with CLONE_VM|CLONE_VFORK). this is a common case because new glibc posix_spawn and system tries clone3 first and if the used clone flags (CLONE_CLEAR_SIGHAND) are not supported by the kernel then it falls back to old clone. So on some kernel and glibc version combinations a simple int main(){ system("/bin/true"); } hangs under drrun. the reproducer below should hang independently of glibc/kernel version. (note: under some containers clone3 is filtered so it always fails with ENOSYS, then the bug is not reproducible).

#include <signal.h>
#include <unistd.h>
#include <stdint.h>
#include <errno.h>

#define CLONE_VM             0x00000100ULL
#define CLONE_VFORK          0x00004000ULL
#define CLONE_bad        0x800000000000ULL

struct clone_args
{
  uint64_t flags;
  uint64_t pidfd;
  uint64_t child_tid;
  uint64_t parent_tid;
  uint64_t exit_signal;
  uint64_t stack;
  uint64_t stack_size;
  uint64_t tls;
  uint64_t set_tid;
  uint64_t set_tid_size;
  uint64_t cgroup;
};

static char stack[65536];

static void clone3_fail(void)
{
  struct clone_args clone_args =
    {
      // invalid flags
      .flags = CLONE_VM | CLONE_VFORK | CLONE_bad,
      .exit_signal = SIGCHLD,
      .stack = (uint64_t)&stack,
      .stack_size = sizeof(stack),
    };
  register long x8 __asm__("x8") = 435; // SYS_clone3
  register long x0 __asm__("x0") = (long)&clone_args;
  register long x1 __asm__("x1") = sizeof(clone_args);
  asm volatile ("svc 0" : "=r"(x0) : "r"(x8), "0"(x0), "r"(x1) : "memory");
  if (x0 != -EINVAL) _exit(-1);
}

int main ()
{
  int r;
  struct sigaction sa;
  sigaction(SIGUSR1, 0, &sa);
  clone3_fail();
  r = vfork();
  if (r == 0)
    execv("/bin/true", (char*[]){"/bin/true", 0});
  sigaction(SIGUSR1, &sa, 0);  // hang
  return 0;
}

the output is not very informative, but it hangs forever (needs kill -9 to stop):

$ DynamoRIO-AArch64-Linux-9.0.1/bin64/drrun -debug -- ./a.out
<Starting application /tmp/a.out (596945)>
<Initial options = -no_dynamic_options -code_api -stack_size 56K -signal_stack_size 32K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/tmp/DynamoRIO-AArch64-Linux-9.0.1/lib64/debug/libdynamorio.so' 0x0000000071015e18
>
<(1+x) Handling our fault in a TRY at 0x000000007137726c>
<Undefined HINT instruction found: encoding 0xd503245f (CRm:op2 0x22)
>
<Undefined HINT instruction found: encoding 0xd503245f (CRm:op2 0x22)
>
<-- execve /bin/true -->
<Starting application /bin/true (596946)>
<Initial options = -code_api -stack_size 56K -signal_stack_size 32K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/tmp/DynamoRIO-AArch64-Linux-9.0.1/lib64/debug/libdynamorio.so' 0x0000000071015e18
>
<(1+x) Handling our fault in a TRY at 0x000000007137726c>
<Undefined HINT instruction found: encoding 0xd503245f (CRm:op2 0x22)
>
<Undefined HINT instruction found: encoding 0xd503245f (CRm:op2 0x22)
>
<Stopping application /bin/true (596946)>

relevant strace without drrun:

...
596976 11:09:25.387577 rt_sigaction(SIGUSR1, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
596976 11:09:25.387652 clone3({flags=CLONE_VM|CLONE_VFORK|0x800000000000, exit_signal=SIGCHLD, stack=0xaaaab75e8018, stack_size=0x10000}, 88) = -1 EINVAL (Invalid argument)
596976 11:09:25.387745 clone(child_stack=0xffffc58232d0, flags=CLONE_VM|CLONE_VFORK|SIGCHLD <unfinished ...>
596977 11:09:25.387863 execve("/bin/true", ["/bin/true"], 0xffffc5823508 /* 36 vars */ <unfinished ...>
596976 11:09:25.388148 <... clone resumed>) = 596977
596976 11:09:25.388199 rt_sigaction(SIGUSR1, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
596976 11:09:25.388298 exit_group(0)    = ?
596977 11:09:25.388347 <... execve resumed>) = 0
596977 11:09:25.388425 brk(NULL <unfinished ...>
596976 11:09:25.388478 +++ exited with 0 +++
596977 11:09:25.388505 <... brk resumed>) = 0xaaab021ab000
...
596977 11:09:25.390414 exit_group(0)    = ?
596977 11:09:25.390569 +++ exited with 0 +++

strace with drrun $ strace -o s.log -f -tt -yy -s 222 DynamoRIO-AArch64-Linux-9.0.1/bin64/drrun -- ./a.out:

...
596992 11:11:49.597920 clone3({flags=CLONE_VM|CLONE_VFORK|0x800000000000, exit_signal=SIGCHLD, stack=0xfffd48ad3000, stack_size=0xd950}
, 88) = -1 EINVAL (Invalid argument)
596992 11:11:49.598135 mprotect(0xfffd48ae3000, 57344, PROT_READ|PROT_WRITE) = 0
596992 11:11:49.598229 clone(child_stack=0xfffd48af0950, flags=CLONE_VM|CLONE_VFORK|SIGCHLD <unfinished ...>
596992 11:11:49.598135 mprotect(0xfffd48ae3000, 57344, PROT_READ|PROT_WRITE) = 0
596992 11:11:49.598229 clone(child_stack=0xfffd48af0950, flags=CLONE_VM|CLONE_VFORK|SIGCHLD <unfinished ...>
596993 11:11:49.598362 gettid()         = 596993
596993 11:11:49.598432 gettid()         = 596993
596993 11:11:49.598518 gettid()         = 596993
596993 11:11:49.598588 gettid()         = 596993
596993 11:11:49.598665 gettid()         = 596993
596993 11:11:49.598738 mprotect(0xfffd48af3000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.598833 gettid()         = 596993
596993 11:11:49.598897 gettid()         = 596993
596993 11:11:49.598959 gettid()         = 596993
596993 11:11:49.599020 gettid()         = 596993
596993 11:11:49.599080 gettid()         = 596993
596993 11:11:49.599141 mprotect(0xfffd48af6000, 8192, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599207 getpid()         = 596993
596993 11:11:49.599271 gettid()         = 596993
596993 11:11:49.599336 getpid()         = 596993
596993 11:11:49.599398 getpid()         = 596993
596993 11:11:49.599461 mprotect(0xfffd48afa000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599533 mprotect(0xffff48a0f000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599605 mprotect(0xfffd48b02000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599677 mprotect(0xfffd48b07000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599747 mprotect(0xfffd48b13000, 32768, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599812 sigaltstack({ss_sp=0xfffd48b13000, ss_flags=0, ss_size=32768}, {ss_sp=0xfffd48a6f000, ss_flags=0, ss_size=32768}) = 0
596993 11:11:49.599898 mprotect(0xfffd48a34000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.599972 mprotect(0xfffd48b03000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.600050 rt_sigprocmask(SIG_SETMASK, [], [], 8) = 0
596993 11:11:49.600147 mprotect(0xfffd48ab0000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.600286 mprotect(0xfffd48afb000, 4096, PROT_READ|PROT_WRITE) = 0
596993 11:11:49.600428 openat(AT_FDCWD, "/bin/true", O_RDONLY) = 3</bin/true>
596993 11:11:49.600579 read(3</bin/true>, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0@\30\0\0\0\0\0\0@\0\0\0\0\0\0\0 r\0\0\0\0\0\0\0\0\0\0@\08\0\t\0@\0\33\0\32\0\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0\370\1\0\0\0\0\0\0\370\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\3\0\0\0\4\0\0", 127) = 127
596993 11:11:49.600690 close(3</bin/true>) = 0
596993 11:11:49.600782 openat(AT_FDCWD, "/bin/true", O_RDONLY) = 3</bin/true>
596993 11:11:49.600886 read(3</bin/true>, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0@\30\0\0\0\0\0\0@\0\0\0\0\0\0\0 r\0\0\0\0\0\0\0\0\0\0@\08\0\t\0@\0\33\0\32\0", 64) = 64
596993 11:11:49.600979 close(3</bin/true>) = 0
596993 11:11:49.601063 getpid()         = 596993
596993 11:11:49.601141 openat(AT_FDCWD, "/home/szabolcs/.dynamorio/true.596993.1config64", O_RDONLY) = -1 ENOENT (No such file or directory)
596993 11:11:49.601253 openat(AT_FDCWD, "/home/szabolcs/.dynamorio/true.config64", O_RDONLY) = -1 ENOENT (No such file or directory)
596993 11:11:49.601336 openat(AT_FDCWD, "/home/szabolcs/.dynamorio/default.0config64", O_RDONLY) = -1 ENOENT (No such file or directory)
596993 11:11:49.601418 openat(AT_FDCWD, "/etc/dynamorio/true.config64", O_RDONLY) = -1 ENOENT (No such file or directory)
596993 11:11:49.601499 openat(AT_FDCWD, "/etc/dynamorio/default.0config64", O_RDONLY) = -1 ENOENT (No such file or directory)
596993 11:11:49.601667 execve("/tmp/DynamoRIO-AArch64-Linux-9.0.1/lib64/release/libdynamorio.so", ["/bin/true"], 0xfffd48afb5b0 /* 42 vars */ <unfinished ...>
596992 11:11:49.601929 <... clone resumed>) = 596993
596992 11:11:49.602070 sched_yield()    = 0
596993 11:11:49.602130 <... execve resumed>) = 0
596992 11:11:49.602159 sched_yield()    = 0
596992 11:11:49.602220 sched_yield()    = 0
596992 11:11:49.602281 sched_yield()    = 0
596992 11:11:49.602341 sched_yield()    = 0
596993 11:11:49.602397 openat(AT_FDCWD, "/bin/true", O_RDONLY <unfinished ...>
596992 11:11:49.602436 sched_yield( <unfinished ...>
596993 11:11:49.602464 <... openat resumed>) = 3</bin/true>
596992 11:11:49.602516 <... sched_yield resumed>) = 0
596993 11:11:49.602546 read(3</bin/true>,  <unfinished ...>
596992 11:11:49.602586 sched_yield( <unfinished ...>
596993 11:11:49.602612 <... read resumed>"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0@\30\0\0\0\0\0\0@\0\0\0\0\0\0\0 r\0\0\0\0\0\0\0\0\0\0@\08\0\t\0@\0\33\0\32\0\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0\370\1\0\0\0\0\0\0\370\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\3\0\0\0\4\0\0\08\2\0\0\0\0\0\08\2\0\0\0\0\0\08\2\0\0\0\0\0\0\33\0\0\0\0\0\0\0\33\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\1\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0(^\0\0\0\0\0\0(^\0\0\0\0"..., 736) = 736
596992 11:11:49.602687 <... sched_yield resumed>) = 0
596993 11:11:49.602726 getpid( <unfinished ...>
596992 11:11:49.602755 sched_yield( <unfinished ...>
596993 11:11:49.602780 <... getpid resumed>) = 596993
596992 11:11:49.602806 <... sched_yield resumed>) = 0
596993 11:11:49.602832 openat(AT_FDCWD, "/home/szabolcs/.dynamorio/true.596993.1config64", O_RDONLY <unfinished ...>
596992 11:11:49.602871 sched_yield( <unfinished ...>
596993 11:11:49.602899 <... openat resumed>) = -1 ENOENT (No such file or directory)
596992 11:11:49.602931 <... sched_yield resumed>) = 0
596993 11:11:49.602958 openat(AT_FDCWD, "/home/szabolcs/.dynamorio/true.config64", O_RDONLY <unfinished ...>
596992 11:11:49.602991 sched_yield( <unfinished ...>
596993 11:11:49.603017 <... openat resumed>) = -1 ENOENT (No such file or directory)
596992 11:11:49.603045 <... sched_yield resumed>) = 0
...
596992 11:11:50.207040 sched_yield()    = 0
596992 11:11:50.207101 sched_yield( <unfinished ...>
596993 11:11:50.207132 +++ exited with 0 +++
596992 11:11:50.207154 <... sched_yield resumed>) = 0
596992 11:11:50.207195 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=596993, si_uid=1000, si_status=0, si_utime=4, si_stime
=3} ---
596992 11:11:50.207274 mprotect(0xfffd48a64000, 4096, PROT_READ|PROT_WRITE) = 0
596992 11:11:50.207356 rt_sigreturn({mask=[]}) = 0
596992 11:11:50.207447 sched_yield()    = 0
596992 11:11:50.207513 sched_yield()    = 0
...
596992 11:11:51.052952 sched_yield()    = 0
596992 11:11:51.053012 sched_yield()    = 0
...
derekbruening commented 1 year ago

Thank you for the detailed report. If you would like to work on the fix that would be much appreciated.