#Tracing the shell: SHISH_TRACE

shish can write a trace of what its evaluator decides: which command was looked up, how a word expanded, which descriptors a child inherits, when a job forked or a trap ran. One event is one line. You choose the subsystems to follow with an environment variable and filter the file with grep.

The trace is built into debug builds only. Without DEBUG_OUTPUT every trace point is compiled away, so a release binary is unchanged and slower by nothing.

• Building a shell with tracing
• Choosing what is traced
• Reading a trace
• Modules
• Finding a bug with it
• Tools
• Adding a trace point
• Event index

#Building a shell with tracing

cmake -S . -B build/dbg -DCMAKE_BUILD_TYPE=Debug -DDEBUG_OUTPUT=ON     # or RelWithDebInfo
cmake --build build/dbg -j

DEBUG_OUTPUT is only declared when the build type contains Deb (Debug, RelWithDebInfo) or -DBUILD_DEBUG=ON is given. With the default MinSizeRel it is silently ignored and no trace is compiled in; an empty or missing log then means the trace is off, not that nothing happened. Rebuild after every source change, or you trace yesterday's code.

A debug build also defines _DEBUG, which force-enables the dump builtin.

#Choosing what is traced

Two environment variables, read once when the first event is about to be written:

rm -f trace.log
SHISH_TRACE=exec,fdtable build/dbg/shish -c 'echo hi | /bin/cat'

• The variable has to be in the environment when shish starts. export SHISH_TRACE=... inside a running script is not seen: put it in front of the command.
• The log is opened with O_APPEND and never truncated. Remove it before each run or runs concatenate. Child processes append to the same file.
• The file is moved to a descriptor of 200 or above and marked close-on-exec, so a script that redirects descriptors 1 and 2 cannot swallow it and no program inherits it. Do not use SHISH_TRACE_FILE=- when the script under test redirects standard error.
• One event is one write(2) of at most 8192 bytes; a longer line ends in ~. errno is preserved across an event.

#Reading a trace

[2100940:1] fdtable.dup(from=4, to=1)                       a call or decision
[2100940:1] fdtable.gap => r=-3                              its result
[2100940:1] fdtable.exec.fds { 0="/dev/null", 3="pipe:[5184717]" }   a snapshot of state

Each line starts with [pid:depth], then module.event, then the payload:

• module.event(key=value, ...) is a call or a decision with its inputs,
• module.event => value is a result,
• module.event { key=value, ... } is a snapshot of some state.

Values are integers, hexadecimal numbers, quoted strings (a missing string is NULL), argument vectors ["echo", "hi"], flag sets E_ROOT|E_LOOP, source locations "file:line:col", node kinds simple_command, and nested { } and [ ] groups for a descriptor or a list of commands.

pid tells the processes apart. ( ... ) and $( ... ) run in the same process (only the depth grows); an external command, a pipeline stage and a background job each have their own pid. So the pid column says on which side of a fork an event happened.

depth is the nesting of the evaluator: it grows by one inside a function call, a subshell, a command substitution, an eval or a sourced file.

A sample, SHISH_TRACE=eval,expand,exec,sh, for x=5 echo hi >/dev/null; f() { echo in f; }; f (trimmed):

[976472:1] eval.simple_command(loc="<string>:1:1", nassign=1, nredir=1, bgnd=0)
[976472:1] exec.lookup(name="echo", mask=0, cache=miss, kind=H_BUILTIN, path=NULL, errno=0)
[976472:1] eval.prefix_scope.enter()
[976472:1] eval.assign(var="x=5", export=1, temp=1)
[976472:1] expand.args(argv=["echo", "hi"])
[976472:1] exec.command(kind=H_BUILTIN, name="echo", path=NULL, argc=2, argv=["echo", "hi"], flag=0)
[976472:1] eval.prefix_scope.leave()
[976472:1] eval.function.define(name="f")
[976472:1] exec.function.call(name="f", argc=1, argv=["f"])
[976472:2] sh.push(cwd="/tmp/tr", argc=0, monitor=0)
[976472:2] eval.push(flags=E_FUNCTION)
[976472:2] exec.command(kind=H_BUILTIN, name="echo", path=NULL, argc=3, argv=["echo", "in", "f"], flag=0)
[976472:2] eval.pop(flags=E_FUNCTION, status=0)
[976472:1] exec.function.return(name="f", status=0)

#Modules

Start with the module of the symptom, not with all. For a descriptor problem use fd,fdtable, add fdstack,redir, then exec. all,-parse is the widest selection that is still readable.

#Descriptors in the exec path

Two events tell the truth about descriptors:

• fdtable.exec.table(vfd=, shadow=, fd={n=, e=, level=, mode=}) is what the shell believes every script descriptor maps to just before a fork, one line per shadowed descriptor.
• fdtable.exec.fds { N=target } is what the child really has just before execve, read from /proc/self/fd.

A bug is where the two differ. In a sample for echo hi | /bin/cat >/dev/null, the child's real descriptors are:

[976578:1] fdtable.exec.fds { 0="pipe:[1934834]", 1="/dev/null", 2="...", 128="pipe:[1934833]", 129="pipe:[1934833]" }
[976578:1] exec.program.execve(path="/bin/cat", argv=["/bin/cat"], nenv=91)
[976576:1] exec.program.status(path="/bin/cat", pid=976578, wait=0x0, exit=0)

Descriptors 128 and above are the shell's own internal pipe ends.

#Start-up events

sh.start(argc=5, argv=[".../shish", "-c", "echo x", "zero", "p1"], pid=49324, ppid=49272)
sh.input(kind=string, script=NULL, command="echo x", argv0="zero", args=["p1"])
sh.mode(interactive=0, monitor=0, term=0, forced=0, no_interactive=0)

#Finding a bug with it

1. Reduce the failure to a one-line -c script and check what bash or dash does.

2. Trace the module of the symptom and find the first event that is wrong. Compare the fdtable.exec.table with fdtable.exec.fds, or compare a passing and a failing run.

3. Filter before reading:

   grep -a '^\[2100940:' trace.log                 # one process (the child you care about)
   grep -a -E 'fdtable\.(dup|gap|wish)|fd\.setfd'   # one family of events
   grep -v exec.table trace.log | cut -c1-200       # drop snapshots, cut long lines
   sed -n '/redir.dup(/,/exec.program.execve/p' trace.log   # a window between two events

4. Diff a good and a bad variant after normalising what changes between runs:

   norm() { sed -E 's/^\[[0-9]+:/[P:/; s/0x[0-9a-f]+/0xX/g; s/pipe:\[[0-9]+\]/pipe:[N]/g'; }
   norm <good.log >good.norm
   norm <bad.log >bad.norm
   diff good.norm bad.norm

   The same script traced twice must give an empty diff; if it does not, normalise more. The first line that differs is usually the decision that went wrong.

5. See what the kernel saw with strace. The trace's own writes show up in it (they go to descriptors 200 and up), so the two logs interleave:

   SHISH_TRACE=fdtable SHISH_TRACE_FILE=/tmp/t.log \
     strace -f -o st.txt -s 120 -e trace=write,dup,dup2,dup3,close,fcntl,pipe2,execve shish -c '...'
   grep -a -E 'write\(2[0-9][0-9]|dup|close|execve' st.txt

   A close(3) right after execve means descriptor 3 was close-on-exec; a dup2(a, b) with no earlier relocation of b clobbered a live descriptor; a missing close() in a child is a leaked pipe end.

6. Find the caller with a debugger. The event name is the breakpoint: break in trace_begin on that event and the backtrace names the code that emitted it.

   SHISH_TRACE=fdtable gdb -q -batch \
     -ex 'set follow-fork-mode child' -ex 'set detach-on-fork on' \
     -ex 'break trace_begin if $_streq(event, "dup") && mod == TRACE_FDTABLE' \
     -ex run -ex 'bt 6' --args build/dbg/shish -c 'exec 3>&1; /bin/true'

   Follow the child to debug what happens after a fork, the parent to debug the code that forks. After the child execs, gdb's "Error in re-setting breakpoint" is harmless.

Timing-sensitive races (sig, wait) change under strace and a debugger; tracing alone disturbs them least, so compare a run with and without strace.

#Tools

tools/trace2seq turns a log into something shorter to read. It needs exec and sh in SHISH_TRACE.

tools/trace2seq trace.log            # process tree: who forked whom, what each pid exec'd, how it exited
tools/trace2seq -c EVENT trace.log   # number of lines of one event, e.g. exec.program.execve
tools/trace2seq -s trace.log         # Mermaid sequence diagram of forks, execs and exits

pid 976576 shell exit=0
  pid 976577 shell exit=0
  pid 976578 exec /bin/cat ["/bin/cat"] exit=0

tests/trace2seq.sh uses it as an oracle: it asserts that a script forks and execves the expected number of programs.

dump (builtin, enabled by a debug build or -DBUILTIN_DUMP=ON) prints internal state to a descriptor on request: -v the root variable table, -l the innermost local table, -F the defined functions, and in a debug build -t the descriptor table, -s the descriptor stack, -f the descriptor list, -j the jobs. -u fd chooses where the dump goes.

shparse2ast (-DBUILD_SHPARSE2AST=ON) prints the full syntax tree of a script as JSON. The trace only names node kinds and source text; use this when the whole tree matters.

ASan and UBSan (-DCMAKE_C_FLAGS="-fsanitize=address,undefined", run with ASAN_OPTIONS=detect_leaks=0 unless hunting leaks) find memory errors; valgrind does for a build without a sanitizer.

#Adding a trace point

TRACE(TRACE_FDTABLE, "dup", trace_int("from", o), trace_int("to", e));   /* decision and inputs */
TRACE_RET(TRACE_FDTABLE, "gap", trace_int("r", r));                      /* result */
TRACE_STRUCT(TRACE_FDTABLE, "state", trace_fd("fd", d));                 /* snapshot */

• Name the event module.event. Put the inputs of a decision in the call and the outcome in a TRACE_RET; place the TRACE_RET after the operation, or the line appears before it finished. Prefer one event per branch that can go wrong over a dump of everything.
• The arguments are evaluated only when the module is selected, and they disappear without DEBUG_OUTPUT. Never put a side effect in them. A variable used only inside a trace point may need a (void) cast to stay warning-free in a release build.
• Value writers: trace_int, trace_hex, trace_str (a null string prints NULL), trace_strn, trace_raw, trace_argv, trace_flags(key, bits, names, n), trace_loc, trace_kind, trace_node, trace_nodes, trace_fd, and trace_open / trace_close for a nested group. trace_fdtable(event) and trace_fdmap(event) dump a whole table. A new type gets its writer in src/trace/trace_value.c.
• Never call TRACE from a signal handler. Use TRACE_DEFER(mod, ev, key, val) there and trace_flush() from normal context.
• A new module is an entry in enum trace_module (src/trace.h) and its name in trace_names[] in src/trace/trace_begin.c, in the same order.
• Leave useful trace points in. Do not leave fprintf, write(2, ...) or abort() debugging in a commit, and keep trace.log, strace output and core files out of git add.

#Event index

Every trace point in src/, by module, with the keys of its payload. A TRACE_RET event is printed as => value and a TRACE_STRUCT event as { ... }, as described above. Add a row when you add a trace point (grep -rn 'TRACE.*(TRACE_<MODULE>, "event"' src shows its keys).

exec

builtin

fd

fdstack

fdtable

eval

expand

redir

var

sh

job

sig

parse