Why does system() fail with error code 127?

c++ c system fork libc++

13,298

Solution 1

This is a weird one. strace understands that the arguments to execve are (pointers to) strings, so it prints out the pointed at strings UNLESS the pointer is invalid -- in which case it prints out the raw hex value of the pointer. So the strace line

[pid 16081] execve("/bin/sh", ["sh", "-c", 0xdda1d98], [/* 58 vars */]) = -1 EFAULT (Bad address)

makes perfect sense -- the 3rd argument to execve is the raw pointer 0xdda1d98, which strace thinks (and the kernel agrees) is invalid. So the question is, how is an invalid pointer getting here. This should be cmd, which just came back from new.

I would suggest putting the line

printf("cmd=%p\n", cmd);

just before the system call, to figure out what the C code thinks the pointer is.

Looking at the rest of the strace, it looks like you're running on a 64-bit system (from the pointers that are printed), and the invalid 0xdda1d98 looks like a 32 bit pointer, so it would seem to be some kind of 32/64 bit screwup (someone only saving and restoring 32 bits of a 64 bit register, or some such).

Solution 2

Piggybacking off / extending @Chris Dodd's answer, consider that system itself looks (oversimplified on purpose) like this:

int system(char *cmd) {
    pid_t pid = fork();
    char *argv[4];
    extern char **environ;

    if (pid == 0) { /* child */
        argv[0] = "sh";
        argv[1] = "-c";
        argv[2] = cmd;
        argv[3] = NULL;
        execve("/bin/sh", argv, environ);
        _exit(127);
    }
    if (pid < 0) ... handle error ...
    ... use OS wait() calls to wait for result from child process ...
    return status; /* as provided by sh -c, or from _exit(127) above */
}

Given "64 bit system" and "register appears to be lopped off at 32 bits" it might be worth doing an objdump on the code and seeing whether argv[2] is set from a register whose upper bits might be somehow lost during the clone call (where I have fork above, glibc is using clone for efficiency).

Update: per the strace output, the clone call is not using CLONE_VM and CLONE_VFORK (not sure why not, these should make the call a lot more efficient) so the child is a "normal" child (a la old-Unix-style fork). A colleague suggested that perhaps the failing address is in a map that is set not to be copied into the child process. The contents of /proc/self/maps would be interesting after the failure; we could look at how the failing address is mapped. Comparing those maps with the ones in the child would be even more interesting. To get the ones in the child, though, you'll need to override the glibc version of system, and add something to read /proc/self/maps after the execve fails, before doing the _exit.

13,298

Author by

ritter

Updated on June 04, 2022

Comments

ritter almost 2 years

On a Linux system I am trying to call a program at runtime with the system() call. The system call exits with an return code not equal zero.

Calling WEXITSTATUS on the error code gives "127".

According to the man page of system this code indicates that /bin/sh could not be called:

In case /bin/sh could not be executed, the exit status will be that of a command that does exit(127).

I checked: /bin/sh is a link to bash. bash is there. I can execute it from the shell.

Now, how can I find out why /bin/sh could not be called ? Any kernel history or something?

Edit:

After the very helpful tip (see below) i strace -f -p <PID> the process. This is what I get during the system call:

Process 16080 detached
[pid 11779] <... select resumed> )      = ? ERESTARTNOHAND (To be restarted)
[pid 11774] <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 127}], 0, NULL) = 16080
[pid 11779] --- SIGCHLD (Child exited) @ 0 (0) ---
[pid 11779] rt_sigaction(SIGCHLD, {0x2ae0ff898ae2, [CHLD], SA_RESTORER|SA_RESTART, 0x32dd2302d0},  <unfinished ...>
[pid 11774] rt_sigaction(SIGINT, {0x2ae1042070f0, [], SA_RESTORER|SA_SIGINFO, 0x32dd2302d0},  <unfinished ...>
[pid 11779] <... rt_sigaction resumed> {0x2ae0ff898ae2, [CHLD], SA_RESTORER|SA_RESTART, 0x32dd2302d0}, 8) = 0
[pid 11779] sendto(5, "a", 1, 0, NULL, 0 <unfinished ...>
[pid 11774] <... rt_sigaction resumed> NULL, 8) = 0
[pid 11779] <... sendto resumed> )      = 1
[pid 11779] rt_sigreturn(0x2 <unfinished ...>
[pid 11774] rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x32dd2302d0},  <unfinished ...>
[pid 11779] <... rt_sigreturn resumed> ) = -1 EINTR (Interrupted system call)
[pid 11779] select(16, [9 15], [], NULL, NULL <unfinished ...>
[pid 11774] <... rt_sigaction resumed> NULL, 8) = 0
[pid 11774] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 11774] write(1, "Problems calling nvcc jitter: ex"..., 49) = 49
[pid 11774] rt_sigaction(SIGINT, {0x1, [], SA_RESTORER, 0x32dd2302d0}, {0x2ae1042070f0, [], SA_RESTORER|SA_SIGINFO, 0x32dd2302d0}, 8) = 0
[pid 11774] rt_sigaction(SIGQUIT, {0x1, [], SA_RESTORER, 0x32dd2302d0}, {SIG_DFL, [], SA_RESTORER, 0x32dd2302d0}, 8) = 0
[pid 11774] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
[pid 11774] clone(Process 16081 attached (waiting for parent)
Process 16081 resumed (parent 11774 ready)
child_stack=0, flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0x7fff0177ab68) = 16081
[pid 16081] rt_sigaction(SIGINT, {0x2ae1042070f0, [], SA_RESTORER|SA_SIGINFO, 0x32dd2302d0},  <unfinished ...>
[pid 11774] wait4(16081, Process 11774 suspended
 <unfinished ...>
[pid 16081] <... rt_sigaction resumed> NULL, 8) = 0
[pid 16081] rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x32dd2302d0}, NULL, 8) = 0
[pid 16081] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 16081] execve("/bin/sh", ["sh", "-c", 0xdda1d98], [/* 58 vars */]) = -1 EFAULT (Bad address)
[pid 16081] exit_group(127)             = ?
Process 11774 resumed

When it comes to the call to /bin/sh it says bad address. Why that ?

Edit:

Here the whole part that involves the failing system (here already the safe copy to a buffer is in place):

  std::ostringstream jit_command;

  jit_command << string(CUDA_DIR) << "/bin/nvcc -v --ptxas-options=-v ";
  jit_command << "-arch=" << string(GPUARCH);
  jit_command << " -m64 --compiler-options -fPIC,-shared -link ";
  jit_command << fname_src << " -I$LIB_PATH/include -o " << fname_dest;

  string gen = jit_command.str();
  cout << gen << endl;

  char* cmd = new(nothrow) char[gen.size()+1];
  if (!cmd) ___error_exit("no memory for jitter command");
  strcpy(cmd,gen.c_str());

  int ret;

  if (ret=system(cmd)) {

    cout << "Problems calling nvcc jitter: ";

    if (WIFEXITED(ret)) {
      printf("exited, status=%d\n", WEXITSTATUS(ret));
    } else if (WIFSIGNALED(ret)) {
      printf("killed by signal %d\n", WTERMSIG(ret));
    } else if (WIFSTOPPED(ret)) {
      printf("stopped by signal %d\n", WSTOPSIG(ret));
    } else if (WIFCONTINUED(ret)) {
      printf("continued\n");
    } else {
      printf("not recognized\n");
    }

    cout << "Checking shell.. ";
    if(system(NULL))
      cout << "ok!\n";
    else
      cout << "nope!\n";

    __error_exit("Nvcc error\n");

  }
  delete[] cmd;
  return true;

Output:

/usr/local/cuda/bin/nvcc -v --ptxas-options=-v -arch=sm_20 -m64 --compiler-options -fPIC,-shared -link bench_cudp_Oku2fm.cu -I$LIB_PATH/include -o bench_cudp_Oku2fm.o
Problems calling nvcc jitter: exited, status=127
Checking shell.. ok!

Edit (first version of the code):

string gen = jit_command.str();
cout << gen << endl;
int ret;
if (ret=system(gen.c_str())) {
  ....

The complexity of the string creation is not the problem here. As strace shows a "bad address" is the problem. Its a legal string. A "bad address" should not occur.

As far as i know the std::string::c_str() returns a const char * that might point to a scratch space of libc++ where a read only copy of the string might be kept.

Unfortunately the error is not really reproduceable. The call to system succeeds several times before it fails.

I don't want to be hasty but it smells like a bug in either in the kernel, libc or the hardware.

Edit:

I produced a more verbose strace output (strace -f -v -s 2048 -e trace=process -p $!) of the failing execve system call:

First a succeeding call:

[pid  2506] execve("/bin/sh", ["sh", "-c", "/usr/local/cuda/bin/nvcc -v --ptxas-options=-v -arch=sm_20 -m64 --compiler-options -fPIC,-shared -link /home/user/toolchain/kernels-empty/bench_cudp_U11PSy.cu -I$LIB_PATH/include -o /home/user/toolchain/kernels-empty/bench_cudp_U11PSy.o"], ["MODULE_VERSION_STACK=3.2.8", ... ]) = 0

Now the failing one:

[pid 17398] execve("/bin/sh", ["sh", "-c", 0x14595af0], <list of vars>) = -1 EFAULT (Bad address)

Here <list of vars> is identical. It seems its not the list of environment variables that cause the bad address. As Chris Dodd mentioned the 3rd argument to execve is the raw pointer 0x14595af0, which strace thinks (and the kernel agrees) is invalid. strace does not recognize it as a string (so it prints the hex value and not the string).

Edit:

I inserted print out of the pointer value cmd to see what's the value of this pointer in the parent process:

  string gen = jit_command.str();
  cout << gen << endl;
  char* cmd = new(nothrow) char[gen.size()+1];
  if (!cmd) __error_exit("no memory for jitter command");
  strcpy(cmd,gen.c_str());
  cout << "cmd = " << (void*)cmd << endl;
  int ret;
  if (ret=system(cmd)) {
    cout << "failed cmd = " << (void*)cmd << endl;
    cout << "Problems calling nvcc jitter: ";

Output (for the failing call):

cmd = 0x14595af0
failed cmd = 0x14595af0
Problems calling nvcc jitter: exited, status=127
Checking shell.. ok!

Its the same pointer value as the 3rd argument from strace. (I updated the strace output above).

Regards the 32bit looking of the cmd pointer: I checked the value of the cmd pointer for a succeeding call. Can't see any difference in structure. That's one of the values of cmd when then system call succeeds:

cmd = 0x145d4f20

So, before the system call the pointer is valid. As the strace output from above suggests the child process (after calling fork) receives the correct pointer value. But, for some reason, the pointer value is marked invalid in the child process.

Right now we think its either:

libc/kernel bug
hardware problem

Edit:

Meanwhile let me post a workaround. Its so silly to be forced to implement something like that... but it works. So the following code block gets executed in case the system call fails. It allocates new command strings and retries until it succeeds (well not indefinitely).

    list<char*> listPtr;
    int maxtry=1000;
    do{
      char* tmp = new(nothrow) char[gen.size()+1];
      if (!tmp) __error_exit("no memory for jitter command");
      strcpy(tmp,gen.c_str());
      listPtr.push_back( tmp );
    } while ((ret=system(listPtr.back())) && (--maxtry>0));

    while(listPtr.size()) {
      delete[] listPtr.back();
      listPtr.pop_back();
    }

Edit:

I just saw that this workaround in one particular run did not work. It went the whole way, 1000 attempts, all with newly allocated cmd command strings. All 1000 failed. Not only this. I tried on a different Linux host (same Linux/software configuration tho).

Taking this into account one would maybe exclude a hardware problem. (Must be on 2 physically different hosts then). Remains a kernel bug ??

Edit:

torek, i will try and install a modified system call. Give me some time for that.

ritter about 12 years

This might be oversimplified here. cmd is not passed as just one argument. Take into account that strace understands it to be a char*[].
torek about 12 years

char **, actually, pointing to the first element of an array—in this case, &argv[0]. strace then extracts argv[0], argv[1], ..., argv[i] until argv[i] is NULL, and then treats each extracted value as a char * pointing to the first element of a C string, and extracts each char until reaching the 0 byte. Since it's not expanding 0xdda1d98 in its output, that says that 0xdda1d98 is the invalid address causing the EFAULT error.
ritter about 12 years

You are absolutely right. The system call succeeds several times before it fails. When it succeeds one can see the cmd string as 3rd argument. (I'll update the question). When it fails we see the hex number. I took your advice and printed the pointer values. (See question)
ritter about 12 years

Correct! Update: I had the value of pointer cmd to be printed. See question. Its the same value that enters as 3rd argument to execve and cannot be interpreted as the command string.
ritter about 12 years

Regards the 32bit looking of the cmd pointerL I checked the cmd pointer for a call that succeeds. Looks the same (difference value, but also 32bit value). See question
torek about 12 years

Well, this problem continues to be quite impressive. :-) The pointer is valid before the clone system call, the value is the same both before and after as well, but the address has become invalid. If it's not a kernel or hardware bug, the only remaining possibility is that the shared virtual address space is being altered by some other thread/process that has access to it. This seems exceedingly unlikely since that alteration would also affect the parent process. So ... kernel/hardware bug?
torek about 12 years

I added an update with an interesting point about maps, based on an "interesting problems" conversation I had at the gym today.
nos about 12 years

Smells like a simple buffer overrun somewhere. Have you run the program under valgrind ?