0

We recently found an interesting case where posix_spawnp hangs until the child process it spawned terminates on Debian 9. This is not reproducible on other distros like Ubuntu(18.04) or CentOS(7.3). You could use the snippet at the end to reproduce it. Just compile it and run ./test_posix_spawnp sleep 30, assuming you named the executable as test_posix_spawnp. We passed in sleep 30 just to keep the child process running for a short while. You would see PID of child: xxx is not printed immediately as an indicator.

The sample code below is to mock our real code, the key of which is to close all the file descriptors in the child process except stdin/stdout/stderr and the one that opened for logging and redirect stdout/stderr to the logging file. In either the real case or this mocking one, it seems that the child process has been spawned and it has started running the executable being passed.

Our questions:

Has anyone came across this issue before? Does it sound like a libc(2.24) bug? If not, how can we fix our code? If so, what are we supposed to do?

P.S. not sure if it matters but we observed that when it's reproducible or when on Debian, there is an extra pipe created during the execution of posix_spawnp, the parent has the read end and the child the write end.

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <spawn.h>
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include <string.h>
#include <wait.h>
#include <errno.h>

#define errExit(msg)    do { perror(msg); \
                            exit(EXIT_FAILURE); } while (0)

#define errExitEN(en, msg) \
                       do { errno = en; perror(msg); \
                            exit(EXIT_FAILURE); } while (0)

char **environ;

int
main(int argc, char *argv[])
{
  pid_t child_pid;
  int s, status;
  sigset_t mask;
  posix_spawnattr_t attr;
  posix_spawnattr_t *attrp;
  posix_spawn_file_actions_t file_actions;
  posix_spawn_file_actions_t *file_actionsp;

  attrp = NULL;
  file_actionsp = NULL;
  long open_max = sysconf(_SC_OPEN_MAX);
  printf("sysconf says: max open file descriptor %ld\n", open_max);
  if (open_max > 32768) {
    open_max = 32768;
    printf("bump max open file desriptor to %ld\n", open_max);
  }
  int flags = O_WRONLY | O_CREAT | O_APPEND;
  mode_t mode = S_IRUSR | S_IWUSR | S_IRGRP | S_IRGRP;
  int log_fd = open("test_posix_spawnp.log", flags, mode);

  printf("opened output file \"test_posix_spawnp.log\", fd=%d\n", log_fd);

  /* Close all fds except log_fd to which stdout and stderr are redirected */

  s = posix_spawn_file_actions_init(&file_actions);
  if (s != 0)
    errExitEN(s, "posix_spawn_file_actions_init");

  s = posix_spawn_file_actions_adddup2(&file_actions, log_fd, STDOUT_FILENO);
  if (s != 0)
    errExitEN(s, "posix_spawn_file_actions_adddup2");

  s = posix_spawn_file_actions_adddup2(&file_actions, log_fd, STDERR_FILENO);
  if (s != 0)
    errExitEN(s, "posix_spawn_file_actions_adddup2");

  for (int i = 3; i < open_max; ++i) {
    if (i == log_fd) continue;
    s = posix_spawn_file_actions_addclose(&file_actions, i);
    if (s != 0)
      errExitEN(s, "posix_spawn_file_actions_addclose");
  }

  file_actionsp = &file_actions;

  s = posix_spawnp(&child_pid, argv[optind], file_actionsp, attrp,
                   &argv[optind], environ);
  if (s != 0)
    errExitEN(s, "posix_spawn");

  printf("PID of child: %ld\n", (long) child_pid);

  /* Clean up after ourselves */

  if (file_actionsp != NULL) {
    s = posix_spawn_file_actions_destroy(file_actionsp);
    if (s != 0)
      errExitEN(s, "posix_spawn_file_actions_destroy");
  }

  exit(EXIT_SUCCESS);
}
3
  • (1) Please post an MCVE — emphasis on the M (minimal). As a trivial example, how can file_actionsp possibly be NULL at the point where your code tests for it? More seriously, do you still have the issue if you don’t close file descriptors 3-_SC_OPEN_MAX? If you duplicate the log file descriptor to stdout but not stderr? If you don’t use the log file at all? If you use posix_spawn instead of posix_spawnp? 85 lines is awfully long to use the word “snippet”. … (Cont’d) May 9, 2019 at 3:13
  • (Cont’d) …  (2) The fact that it is creating a pipe that it shouldn’t be creating is probably about as important as the mere fact that it blocks until the child process exits, and should be mentioned earlier. (3) If the parent process is reading from the pipe, that would explain a lot. Have you tried using strace or something similar? Have you tried doing something to see exactly what state the parent process is in while the child process is alive? Have you tried closing the pipe from within the child? (4) Typo: S_IRGRP | S_IRGRP. May 9, 2019 at 3:13
  • Please do not respond in comments; edit your question to make it clearer and more complete. May 9, 2019 at 4:56

1 Answer 1

1

I looked at glibc 2.24, which comes with Debian 9.

posix_spawnp (and posix_spawn) is implemented as user-mode C code rather than a system call. It does the following:

  1. makes a pipe with the O_CLOEXEC flag.
  2. calls clone with the CLONE_VFORK flag. vfork limits the communication between child and parent - this is where the pipe comes into play.
  3. the parent closes the write end of the pipe and tries to read from the read end.
  4. the child closes the read end of the pipe and performs all the file actions.
  5. the child calls execvp. If successful, the pipe ought to be closed. If it fails, the child will write an error code to the pipe.
  6. The parent's read returns. If the execvp in the child succeeded, the read should fail because the write end of the pipe should have been closed, and the parent sets the variable ec to 0. If the read succeeds, ec is the error code sent to it by the child.
  7. posix_spawnp in the parent returns ec.

I italicized those words because there's a bug.

When posix_spawnp does all those posix_spawn_file_actions_addclose actions, the glibc code is smart enough to do a dup of the write end of the pipe when it sees a file action that affects that file descriptor.

int p = args->pipe[1];
...
/* Dup the pipe fd onto an unoccupied one to avoid any file
   operation to clobber it.  */
if ((action->action.close_action.fd == p)
    || (action->action.open_action.fd == p)
    || (action->action.dup2_action.fd == p))
  {
    if ((ret = __dup (p)) < 0)
      goto fail;
    p = ret;
  }

Problem is, dup doesn't duplicate the O_CLOEXEC flag, so the fd is leaked to the process that the child has execed, and won't be closed until that process exits. The read in the parent won't return until that happens.

The bug was fixed in this commit. Now, the child communicates its success or failure to the parent by using a shared variable instead of a pipe.

If you're stuck with this version of glibc, there isn't much you can do except not to tell posix_spawnp to close the write end of the pipe (likely logfd+2 in your sample code).

6
  • Great research! May 10, 2019 at 2:35
  • Hi Mark, excellent analysis. Thank you! It was done on purpose, but we are seeking a solution to see if we could loose the condition to close ALL fds. Also how likely or how easy is it to ask the Debian community to bump the version of glibc, including at least this fix? Do you have any rough idea? Last but not least, maybe not directly related to my original question though, what technique did you use to get the details of the child process, to be precise item 4 and 5. I've tried something like strace ./test_posix_spawnp /bin/strace sleep 10 but didn't get what you found :(
    – Johnny Yan
    May 13, 2019 at 16:12
  • @xcode I ran strace -f -o x.log ./psp sleep 30, then opened the x.log file in an editor. I saw the parent was doing a read(4, <unfinished ...> on the pipe and it wasn't finishing until the child exited. I saw that fd 4 was created with a call to pipe2. I didn't see the child writing anything to fd 5. The child duped it to 4 but didn't do anything with that fd, either. I then pulled down the source with apt source glibc and read through the posix_spawn code to see what was going on. May 13, 2019 at 16:47
  • I don't know the process Debian goes through to move to newer glibc versions, but they do make patches to glibc (the apt source command will pull them down). The bug reporter is debian.org/Bugs/Reporting May 13, 2019 at 16:58
  • @MarkPlotnick Oh, I see. I guess it's probably too late to call strace, in my case, to see what happened in the child. Thank you for the explanation :)
    – Johnny Yan
    May 13, 2019 at 17:00

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .