How to trace file descriptor duplication?

Question

I am learning to use redirection. the typical operation is like below:

    command > file 2>&1

Refer to APUE 3.10 and 3.12, I think the critical syscall sequence is like below:

    open(file) == 3
    dup2(3,1)
    dup2(1,2)

To test my idea, I create shell script and execute it with strace command, my test.sh is below:

    #!/bin/sh
    echo 'hello'
    whatfuckis # For get a stderr

then I use strace command to trace system calls and signals

    strace -y -o trace.log ./test.sh > tmp.txt 2>&1

tmp.txt get the error message as expected. I can see many syscalls like(read, write, close, fcntl..etc) in trace.log, I even saw the result that file descriptor 2(stderr) is pointed to tmp.txt.

The problem is that I don't see the specific operation of file descriptor duplication like dup2, this is weired. How can I trace file descriptor duplication? the main information of the trace.log is as follows:

read(10</home/madhouse/Applications/Lab/test.sh>, "#!/bin/sh\n\necho 'hello'\nwhatfuck"..., 8192) = 54
write(1</home/madhouse/Applications/Lab/tmp.txt>, "hello\n", 6) = 6
stat("/home/MATLAB/R2016b/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/home/madhouse/Qt5.14.2/5.14.2/gcc_64//whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/home/madhouse/Qt5.14.2/Tools/QtCreator/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/local/lib/nodejs/node-v12.22.5-linux-x64/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/home/madhouse/.local/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/local/sbin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/local/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/sbin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/sbin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/games/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/usr/local/games/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
stat("/snap/bin/whatfuckis", 0x7ffc61f2a380) = -1 ENOENT (No such file or directory)
write(2</home/madhouse/Applications/Lab/tmp.txt>, "./test.sh: 4: ", 14) = 14
write(2</home/madhouse/Applications/Lab/tmp.txt>, "whatfuckis: not found", 21) = 21
write(2</home/madhouse/Applications/Lab/tmp.txt>, "\n", 1) = 1
read(10</home/madhouse/Applications/Lab/test.sh>, "", 8192) = 0
exit_group(127)                         = ?
+++ exited with 127 +++

The log for aviro

167936 execve("/usr/bin/sh", ["sh", "-c", "./test.sh > tmp.txt 2>&1"], 0x7ffc000ac898 /* 76 vars */) = 0
167936 dup2(3</home/madhouse/Applications/Lab/tmp.txt>, 1) = 1</home/madhouse/Applications/Lab/tmp.txt>
167936 close(3</home/madhouse/Applications/Lab/tmp.txt>) = 0
167936 dup2(1</home/madhouse/Applications/Lab/tmp.txt>, 2) = 2</home/madhouse/Applications/Lab/tmp.txt>
167936 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f67e121d850) = 167937
167937 execve("./test.sh", ["./test.sh"], 0x55855ac8c2d8 /* 76 vars */) = 0
167937 write(1</home/madhouse/Applications/Lab/tmp.txt>, "hello\n", 6) = 6
167937 write(2</home/madhouse/Applications/Lab/tmp.txt>, "./test.sh: 4: ", 14) = 14
167937 write(2</home/madhouse/Applications/Lab/tmp.txt>, "whatfuckis: not found", 21) = 21
167937 write(2</home/madhouse/Applications/Lab/tmp.txt>, "\n", 1) = 1
167936 dup2(10</dev/pts/2>, 1</home/madhouse/Applications/Lab/tmp.txt>) = 1</dev/pts/2>
167936 dup2(11</dev/pts/2>, 2</home/madhouse/Applications/Lab/tmp.txt>) = 2</dev/pts/2>

Answer 1

You have two issues:

1. You're performing the redirection on the strace command, so the redirection will be performed by your interactive shell, and strace will not be able to see relevant system calls.
2. The dup2 system call is performed inside of the child before the command execution. By default, strace will not follow children of your commands, so you won't be able to see the trace of the child itself. You will need to add the -f flag to your strace to make sure it also follows the children.

Bottom line, in order to perform the intended check, you need to run:

strace -yf -o trace.log sh -c './test.sh > tmp.txt 2>&1'

Then you'll see your expected sequence:

$ grep -E 'dup2\(|clone\(|execve\(|(open|write|close)\(.*tmp.txt' trace.log 
31769 execve("/usr/bin/sh", ["sh", "-c", "./test.sh > tmp.txt 2>&1"], [/* 124 vars */]) = 0
31769 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffff7fd19d0) = 31770
31770 open("tmp.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3</tmp/tmp.txt>
31770 dup2(3</tmp/tmp.txt>, 1</dev/pts/445>) = 1</tmp/tmp.txt>
31770 close(3</tmp/tmp.txt>)            = 0
31770 dup2(1</tmp/tmp.txt>, 2</dev/pts/445>) = 2</tmp/tmp.txt>
31770 execve("./test.sh", ["./test.sh"], [/* 123 vars */]) = 0
31770 dup2(3</tmp/test.sh>, 255)        = 255</tmp/test.sh>
31770 write(1</tmp/tmp.txt>, "hello\n", 6) = 6
31770 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffff7fd19d0) = 31771
31771 write(2</tmp/tmp.txt>, "./test.sh: line 3: whatfuckis: c"..., 49) = 49

Notice the open and dup2 system calls are performed inside pid 31770, the child of the sh -c... command, before actually executing test.sh.

Duplicating the file descriptors in the parent instead of the child

It is possible (depending on the implementation of your shell) that the duplication will be performed on the parent level before performing the clone. In that case, the parent will need to save the original STDOUT and STDERR file descriptors, and restore them after the child terminates.

$ grep -E 'dup2\(|clone\(|execve\(|(open|write|close|openat)\(.*tmp.txt|F_DUPFD|exit_group' trace.log
1094  execve("/usr/bin/sh", ["sh", "-c", "./test.sh > tmp.txt 2>&1"], 0x7fffd0324118 /* 20 vars */) = 0
1094  openat(AT_FDCWD, "tmp.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3</tmp/tmp.txt>
1094  fcntl(1</dev/pts/0>, F_DUPFD, 10) = 10</dev/pts/0>
1094  dup2(3</tmp/tmp.txt>, 1)          = 1</tmp/tmp.txt>
1094  close(3</tmp/tmp.txt>)            = 0
1094  fcntl(2</dev/pts/0>, F_DUPFD, 10) = 11</dev/pts/0>
1094  dup2(1</tmp/tmp.txt>, 2)          = 2</tmp/tmp.txt>
1094  clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f844aa71690) = 1095
1095  execve("./test.sh", ["./test.sh"], 0x7f844aa9dc08 /* 20 vars */) = 0
1095  fcntl(3</tmp/test.sh>, F_DUPFD, 10) = 10</tmp/test.sh>
1095  write(1</tmp/tmp.txt>, "hello\n", 6) = 6
1095  write(2</tmp/tmp.txt>, "./test.sh: 3: ", 14) = 14
1095  write(2</tmp/tmp.txt>, "whatfuckis: not found", 21) = 21
1095  write(2</tmp/tmp.txt>, "\n", 1)   = 1
1095  exit_group(127)                   = ?
1094  dup2(10</dev/pts/0>, 1</tmp/tmp.txt>) = 1</dev/pts/0>
1094  dup2(11</dev/pts/0>, 2</tmp/tmp.txt>) = 2</dev/pts/0>
1094  exit_group(127) 

See how before running each dup2 at the beginning, the parent (pid 1094) duplicates file descriptors 1 and 2 into file descriptors 10 and 11 respectively (using the fcntl system call and the F_DUPFD command) .

Then after the child (pid 1095) completes, the parent restores file descriptors 10 and 11 (the original STDOUT and STDERR) back to file descriptors 1 and 2.