[os x] killing freshly started processes is unreliable

Sending a SIGTERM to a process that is still starting up kills it with SIGKILL on my OS X machine, not SIGTERM. It's making the kill test fail reliably for me locally.

Demonstrated with this patch:

diff --git a/test/test-spawn.c b/test/test-spawn.c
index 53a0369..6676101 100644
--- a/test/test-spawn.c
+++ b/test/test-spawn.c
@@ -90,6 +90,8 @@ static void kill_cb(uv_process_t* process,
 #else
   ASSERT(exit_status == 0);
 #endif
+  printf("no_term_signal=%d term_signal=%d exit_status=%d\n",
+         no_term_signal, term_signal, (int) exit_status);
   ASSERT(no_term_signal || term_signal == 15);
   uv_close((uv_handle_t*)process, close_cb);

When you run the test:

$ uname -a
Darwin hermes.local 16.4.0 Darwin Kernel Version 16.4.0: Thu Dec 22 22:53:21 PST 2016; root:xnu-3789.41.3~3/RELEASE_X86_64 x86_64

$ out/Debug/run-tests kill
not ok 1 - kill
# exit code 6
# Output from process `kill`:
# exit_cb
# no_term_signal=0 term_signal=9 exit_status=0
# Assertion failed in ../test/test-spawn.c on line 95: no_term_signal || term_signal == 15

Adding a small delay avoids it:

diff --git a/test/test-spawn.c b/test/test-spawn.c
index 53a0369..6676101 100644
--- a/test/test-spawn.c
+++ b/test/test-spawn.c
@@ -920,6 +922,7 @@ TEST_IMPL(kill) {
 
   r = uv_spawn(uv_default_loop(), &process, &options);
   ASSERT(r == 0);
+  usleep(1000);
 
   /* Sending signum == 0 should check if the
    * child process is still alive, not kill it.

Interestingly, sending a different signal works okay too (SIGINT here but e.g. SIGQUIT works too):

diff --git a/test/test-spawn.c b/test/test-spawn.c
index 53a0369..33467f6 100644
--- a/test/test-spawn.c
+++ b/test/test-spawn.c
@@ -90,7 +90,7 @@ static void kill_cb(uv_process_t* process,
 #else
   ASSERT(exit_status == 0);
 #endif
-  ASSERT(no_term_signal || term_signal == 15);
+  ASSERT(no_term_signal || term_signal == 15 || term_signal == SIGINT);
   uv_close((uv_handle_t*)process, close_cb);
 
   /*
@@ -930,7 +930,7 @@ TEST_IMPL(kill) {
   ASSERT(r == 0);
 
   /* Kill the process. */
-  r = uv_kill(process.pid, /* SIGTERM */ 15);
+  r = uv_kill(process.pid, SIGINT);
   ASSERT(r == 0);
 
   r = uv_run(uv_default_loop(), UV_RUN_DEFAULT);

Does this just happen on macOS? If so we can add the usleep surrounded with an ifdef and a comment, maybe?

It doesn't happen on any of my Linux machines and I think it didn't happen on my MBA either before the latest Apple update.

FWIW, I see this failure occasionally in the node test suite too now:

=== release test-child-process-exec-timeout ===
Path: parallel/test-child-process-exec-timeout
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: 'SIGKILL' === 'SIGTERM'
    at cp.exec.common.mustCall (/Users/bnoordhuis/src/v1.x/test/parallel/test-child-process-exec-timeout.js:21:10)
    at /Users/bnoordhuis/src/v1.x/test/common.js:446:15
    at ChildProcess.exithandler (child_process.js:238:5)
    at emitTwo (events.js:106:13)
    at ChildProcess.emit (events.js:194:7)
    at maybeClose (internal/child_process.js:892:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:226:5)
Command: out/Release/node /Users/bnoordhuis/src/v1.x/test/parallel/test-child-process-exec-timeout.js

The test sends a SIGTERM one millisecond after spawning the child. It doesn't fail as reliably as the libuv test suite but fail it does.

FWIW, the test fails in my OS X too. It fails like 5% of the time.

For a company that purports to have "It Just Works" as their motto, Apple has an amazing propensity for screwing up their operating system more with every update.

Anyone have suggestions on how to handle this? Just tweak the test suites and move on? I'd worry we'd be making it less flaky but not not flaky.

What about allowing SIGKILL as an acceptable signal only for OS X with an explaining comment? Even we could only allow it for some OS X specific version / range so we know when / if it is fixed?

This seems like something that should be raised against macOS, but I have no idea how that is done.

Maybe https://developer.apple.com/bug-reporting/ ?

Don't bother, Apple never seems to act on, or even acknowledge, bug reports.

What about allowing SIGKILL as an acceptable signal only for OS X with an explaining comment?

That seems reasonable.

What about allowing SIGKILL as an acceptable signal only for OS X with an explaining comment?

SGTM.

After the latest OS X update this got worse. It's failing 100% of the time. I'll create a PR.

test,osx: fix flaky kill test

I was trying to create a minimal C reproduction of this (partly to learn about how this all works), so far I'm on:

#include <stdio.h>
#include <unistd.h>
#include <signal.h>

void catcher(int sig) {
  printf("Caught: %i (%X)\n", sig, sig); // Shouldn't print if SIGKILL called.
}

int main() {
  printf("SIGKILL: %i (%X)\n", SIGKILL, SIGKILL);
  printf("SIGTERM: %i (%X)\n", SIGTERM, SIGTERM);

  signal(SIGTERM, catcher);

  int pid = fork();

  if (pid == 0) {
    usleep(20);
    printf("ok child\n");
  } else {
    int status = kill(pid, SIGTERM);
    printf("Parent: child pid: %i (0x%X)\n", pid, pid);
    printf("Parent: kill status: %i\n", status);
  }
}

Running with: clang -O3 test.c && ./a.out, I always get:

SIGKILL: 9 (9)
SIGTERM: 15 (F)
Parent: child pid: 92483 (0x16943)
Parent: kill status: 0
Caught: 15 (F)
zsh returned exit code 0
ok child

I assume I'm missing something.

I also ran with dtruss, but the kill syscall is always 0xF.

dtruss output:

➜ clang -O3 test.c && sudo dtruss ./a.out
Password:
dtrace: system integrity protection is on, some features will not be available

SYSCALL(args)            = return
SIGKILL: 9 (9)
SIGTERM: 15 (F)
Parent: child pid: 92511 (0x1695F)
Caught: 15 (F)
Parent: kill status: 0
ok child
open("/dev/dtracehelper\0", 0x2, 0x7FFF57C57950)                 = 3 0
ioctl(0x3, 0x80086804, 0x7FFF57C578D8)           = 0 0
close(0x3)               = 0 0
thread_selfid(0x3, 0x80086804, 0x7FFF57C578D8)           = 2989967 0
bsdthread_register(0x7FFFC3F5B1F0, 0x7FFFC3F5B1E0, 0x2000)               = 1073741919 0
ulock_wake(0x1, 0x7FFF57C56FFC, 0x0)             = -1 Err#2
issetugid(0x1, 0x7FFF57C56FFC, 0x0)              = 0 0
mprotect(0x107FAD000, 0x88, 0x1)                 = 0 0
mprotect(0x107FB5000, 0x1000, 0x0)               = 0 0
mprotect(0x107FCB000, 0x1000, 0x0)               = 0 0
mprotect(0x107FCC000, 0x1000, 0x0)               = 0 0
mprotect(0x107FE2000, 0x1000, 0x0)               = 0 0
mprotect(0x107FE3000, 0x1000, 0x1)               = 0 0
mprotect(0x107FAD000, 0x88, 0x3)                 = 0 0
mprotect(0x107FAD000, 0x88, 0x1)                 = 0 0
getpid(0x107FAD000, 0x88, 0x1)           = 92510 0
stat64("/AppleInternal/XBS/.isChrooted\0", 0x7FFF57C56EB8, 0x1)          = -1 Err#2
stat64("/AppleInternal\0", 0x7FFF57C56F50, 0x1)          = -1 Err#2
csops(0x1695E, 0x7, 0x7FFF57C569E0)              = -1 Err#22
dtrace: error on enabled probe ID 2158 (ID 561: syscall::sysctl:return): invalid kernel access in action #10 at DIF offset 40
csops(0x1695E, 0x7, 0x7FFF57C562C0)              = -1 Err#22
getrlimit(0x1008, 0x7FFF57C58858, 0x7FFF57C562C0)                = 0 0
fstat64(0x1, 0x7FFF57C58878, 0x7FFF57C562C0)             = 0 0
ioctl(0x1, 0x4004667A, 0x7FFF57C588BC)           = 0 0
dtrace: error on enabled probe ID 2133 (ID 951: syscall::write_nocancel:return): invalid kernel access in action #12 at DIF offset 92
dtrace: error on enabled probe ID 2133 (ID 951: syscall::write_nocancel:return): invalid kernel access in action #12 at DIF offset 92
sigaction(0xF, 0x7FFF57C58B58, 0x7FFF57C58B80)           = 0 0
fork()           = 92511 0
kill(0x1695F, 0xF, 0x1)          = 0 0
dtrace: error on enabled probe ID 2133 (ID 951: syscall::write_nocancel:return): invalid kernel access in action #12 at DIF offset 92
dtrace: error on enabled probe ID 2133 (ID 951: syscall::write_nocancel:return): invalid kernel access in action #12 at DIF offset 92

@gibfahn

@gibfahn I've modified your code a little to make it more similar to how that's implemented. Still, it does not reproduce the issue we see on the test...

#include <stdio.h>
#include <unistd.h>
#include <signal.h>
#include <sys/wait.h>
#include <assert.h>

void catcher(int sig) {
  // SIGCHLD handler. It should print when child process dies. In libuv, the main process
  // is notified by writing to a pipe when this signal is received.
  printf("Caught: %i (%X)\n", sig, sig);
  
}

int main() {
  printf("SIGKILL: %i (%X)\n", SIGKILL, SIGKILL);
  printf("SIGTERM: %i (%X)\n", SIGTERM, SIGTERM);

  signal(SIGCHLD, catcher);

  int status;
  int pid = fork();

  if (pid == 0) {
    printf("ok child\n");
  } else {
    int status = kill(pid, SIGTERM);
    printf("Parent: child pid: %i (0x%X)\n", pid, pid);
    printf("Parent: kill status: %i\n", status);

    // wait a little so the child process dies.
    sleep(1);

    // In libuv this is executed when the SIGCHLD notification is received
    int pid2 = waitpid(pid, &status, WNOHANG);
    assert(pid == pid2);
    if (WIFEXITED(status))
        fprintf(stderr, "Exit with status: %d\n", WEXITSTATUS(status));

    if (WIFSIGNALED(status))
        fprintf(stderr, "Exit with signal: %d\n", WTERMSIG(status));
  }
}

@gibfahn

@gibfahn @santigimeno The test only forks, it doesn't execve like libuv does.

@bnoordhuis

@bnoordhuis thanks for clearing that up.

test,osx: fix flaky kill test

test: fix flaky test-child-process-exec-timeout

Navigation Menu

Repository navigation

[os x] killing freshly started processes is unreliable #1226

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[os x] killing freshly started processes is unreliable #1226

Description

Activity

saghul commented on Feb 15, 2017

bnoordhuis commented on Feb 15, 2017

bnoordhuis commented on Feb 17, 2017

santigimeno commented on Feb 23, 2017

bnoordhuis commented on Feb 24, 2017

santigimeno commented on Feb 24, 2017

gibfahn commented on Feb 24, 2017

bnoordhuis commented on Feb 24, 2017

saghul commented on Feb 27, 2017

santigimeno commented on Apr 1, 2017

gibfahn commented on Apr 2, 2017

santigimeno commented on Apr 2, 2017

bnoordhuis commented on Apr 3, 2017

santigimeno commented on Apr 3, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions