Launching Runs and Capturing Output

Part II · Module 25 · Chapter 25.4 · Launching Runs and Capturing Output

1. What a Launch Must Leave Behind

After a run finishes, three questions come up, and the run directory must answer all three without anyone remembering anything:

None of these is optional. A log without the command cannot be reproduced. A command without the log cannot be checked. And the status is the one piece of evidence that does not come from the simulator's own text, so it is the one that catches a crash the log does not mention.

The registry's example for this chapter does all three in four lines:

my @cmd = ($SIM, '-f', $filelist, @args);
open my $cmdf, '>', "$run/cmd" and print {$cmdf} "@cmd\n";
system("@cmd > $run/logs/sim.log 2>&1");
my $status = $? >> 8;

That is the right shape, and it works for simple arguments. The rest of this chapter measures what happens when the arguments are not simple, and builds a launcher whose behaviour does not depend on luck.

2. The One-Line Launch, Measured

Here is the same idea against the fixture from Chapter 25.1: join the arguments into one string, add redirections, and pass it to system. The three extra arguments each contain one character that a shell treats specially — a space, a >, and a ;. Each one stands for something that really appears in plusargs: messages and paths with spaces, comparisons and patterns, and lists separated by punctuation. (UVM's command-line plusargs, for example, routinely contain * and ,.)

#!/usr/bin/perl
# string_launch.pl -- the one-line launch, given three arguments that each
# contain one character the shell treats specially.
use strict;
use warnings;
use File::Path qw(make_path);

system("bin/build") == 0 or die "build failed\n";
make_path("runs/rand_s2");
my @args = ("+test=rand", "+seed=2",
            "+tag=night run",            # a space
            "+cond=a>b",                 # a '>'
            "+note=x;echo INJECTED");    # a ';'

system("bin/simv @args > runs/rand_s2/sim.log 2>&1");
print "status: exit ", $? >> 8, "\n\n";

print "runs/rand_s2/sim.log contains:\n";
open my $log, "<", "runs/rand_s2/sim.log" or die; print "  $_" while <$log>;

print "\na new file called 'b' appeared next to the script:\n";
open my $b, "<", "b" or die "no file b\n"; print "  $_" while <$b>;
close $b; unlink "b";

status: exit 0

runs/rand_s2/sim.log contains:
  INJECTED

a new file called 'b' appeared next to the script:
  TEST rand SEED 2
  ERROR: a=64 b=192 y=0 expected=255
  TEST FAILED (1 errors)
  tb/tb.v:60: $finish called at 40 (1s)

Read that carefully, because every part of it is wrong and every part looks fine:

• The status is 0. The launch "succeeded".
• The run's log contains one word, INJECTED. No TEST line, no verdict. A classifier would call this UNKNOWN at best.
• The real simulation output is in a file called b, in the project's top directory, where nobody will look. And that output says TEST FAILED: seed 2 hits the adder's bug. The one failure in this run was sent to a stray file, and the evidence that should have been in the log was replaced by the output of a different command.

In a regression of a thousand runs, this does not look like a disaster. It looks like one UNKNOWN row that someone will "look at later", and a mysterious file called b that someone will eventually delete.

3. Why: the Shell Reads the String

system with one string that contains shell characters does not run your program. It runs /bin/sh -c "your string", and the shell reads the string with its own rules before anything else happens. Here is the string "bin/simv @args > runs/rand_s2/sim.log 2>&1" after Perl interpolated @args into it, and what the shell did with each piece:

The redirection at the end of the string applies only to the last command, the echo. The simulator never saw it. The status system reports is the status of the last command too — echo succeeded, so: exit 0.

Chapter 15.10 gives the rule that prevents all of this: pass a list, not a string. With a list, Perl starts the program directly, with each element as exactly one argument, and no shell ever reads them. The problem with the registry's example is that it also needs a redirection (> log 2>&1), and redirection is a shell feature. Section 8 shows how to redirect without a shell: open the log in a child process, then exec the simulator with a list.

Quoting the string by hand is not the fix. It works until the first argument contains the kind of quote you used, and every engineer who edits the list has to know the rule. The list form removes the problem instead of managing it.

4. What the Status Means Through a Shell

The shell also changes what $? means. Here are two events — a simulator that does not exist, and a simulator killed by signal 9 — seen through a shell and without one:

#!/usr/bin/perl
# status_forms.pl -- the same two events, seen through a shell and without one:
# a simulator that does not exist, and a simulator killed by signal 9.
use strict;
use warnings;
use Time::HiRes qw(sleep);

system("bin/build") == 0 or die "build failed\n";
open my $saved_err, ">&", \*STDERR or die;
open STDERR, ">", "shell_said.txt" or die;        # keep what sh prints aside

my $r = do { no warnings "exec"; system("bin/simv_old", "+test=smoke") };
printf "missing, list form:   system returned %d, \$! = %s\n", $r, $!;
$r = system("bin/simv_old +test=smoke > /dev/null 2>&1");
printf "missing, string form: system returned %d, exit %d, signal %d\n", $r, $? >> 8, $? & 127;

sub child_vvp {                                    # the vvp started by this pid
    my ($p) = @_;
    for (`ps -A -o pid= -o ppid= -o comm=`) {
        my ($pid, $ppid, $comm) = split ' ', $_, 3;
        return $pid if $ppid == $p && $comm =~ /vvp/;
    }
    return $p;                                     # no child: it is the simulator
}
for my $form ("string form", "fork + exec") {
    my $pid = fork // die "fork: $!\n";
    if ($pid == 0) {
        exec "bin/simv +test=stall > stall.log 2>&1" if $form eq "string form";
        open STDOUT, ">", "stall.log" or exit 126;
        open STDERR, ">&", \*STDOUT   or exit 126;
        { exec { "bin/simv" } "bin/simv", "+test=stall" }
        exit 127;
    }
    sleep 0.5;                                     # let the simulation start
    kill "KILL", child_vvp($pid);
    waitpid($pid, 0);
    printf "killed, %-11s   exit %d, signal %d\n", "$form:", $? >> 8, $? & 127;
}

open STDERR, ">&", $saved_err or die;
open my $said, "<", "shell_said.txt" or die;
while (<$said>) { s/^(sh: line \d+:)\s+\d+/$1 <pid>/; s/ {2,}/ /g; print "sh wrote to stderr: $_" }

missing, list form:   system returned -1, $! = No such file or directory
missing, string form: system returned 32512, exit 127, signal 0
killed, string form:   exit 137, signal 0
killed, fork + exec:   exit 0, signal 9
sh wrote to stderr: sh: line 1: <pid> Killed: 9 bin/simv +test=stall > stall.log 2>&1

Two differences, both measured:

A missing program. With a list, system returns -1 and $! says why: the program could not be started at all. Through a shell, the shell itself starts fine, fails to find the program, and exits 127. Now "127" could also be an exit code the simulator chose. The list form keeps "could not start" separate from "started and returned a number"; the shell merges them.

A killed simulator. Without a shell, $? & 127 is 9: the operating system tells the parent the process died from signal 9. Through a shell, the shell is the parent of the simulator; it sees the signal, prints Killed: 9 on the runner's standard error (not in the log!), and then exits with 137 = 128 + 9. The runner sees an ordinary exit code. The information "this was a signal" now depends on someone knowing the 128 + N convention and that the simulator itself never exits with 137. Chapter 26.1 measured the same conversion for Bash wrapper scripts, and Chapter 14.3 explains how $? is built.

One more detail from this machine: Icarus vvp wrote everything — the ERROR lines, the FATAL message, the WARNING about the bad seed, the $finish line — on standard output. Standard error carried nothing in any of these runs. Capture both into the same file anyway. Other tools write errors to standard error, the compiler does, and so does the launcher itself when it cannot start the program (Section 8). One file, both streams, means one place to look, in the order things happened.

5. A Fresh Log, Never an Appended One

Every run writes a new log. Using >> (append) instead of > looks harmless — "we keep the history" — until a run directory is reused. Here, yesterday's run of corner passed. Today the simulator binary is missing because the build step failed, and the launch appends to yesterday's log:

#!/usr/bin/perl
# append_demo.pl -- yesterday's log, today's failed launch, and '>>'.
use strict;
use warnings;
use File::Path qw(make_path);

make_path("runs/corner_s1");
open my $old, ">", "runs/corner_s1/sim.log" or die;      # yesterday: it passed
print {$old} "TEST corner SEED 1\nTEST PASSED\n";
close $old;

# Today the simulator binary is missing (say the build step failed).
system("bin/simv_old +test=corner +seed=1 >> runs/corner_s1/sim.log 2>&1");
print "today's launch: exit ", $? >> 8, "\n";

open my $log, "<", "runs/corner_s1/sim.log" or die;
my @lines = <$log>;
print "the log now holds:\n", map { "  $_" } @lines;
my $verdict = (grep { /^TEST PASSED$/ } @lines) ? "PASS" : "not PASS";
print "a classifier that looks for 'TEST PASSED' says: $verdict\n";

today's launch: exit 127
the log now holds:
  TEST corner SEED 1
  TEST PASSED
  sh: bin/simv_old: No such file or directory
a classifier that looks for 'TEST PASSED' says: PASS

Today's run never simulated anything, and the classifier says PASS, because yesterday's verdict is still in the file. This is the stale-artifact problem from Chapter 17.9 in its most direct form: old evidence answering a new question.

Two rules prevent it, and the launcher in Section 8 uses both:

• Open the log with >, so a launch always starts from an empty file.
• Refuse to launch into a directory that already exists. Reusing a directory means two runs share one place for evidence. Either start each regression in a fresh area, or move last night's area aside first. Chapter 17.5 covers creating run directories without overwriting the previous night's evidence.

6. Copy $? at Once

$? is a single global variable. It describes the most recent child process — system, backticks, or the close of a piped open (Chapter 15.11). Anything that runs another program between the launch and the moment you read $? replaces it:

#!/usr/bin/perl
# clobber_demo.pl -- $? describes the LAST child process, whichever it was.
use strict;
use warnings;

system("bin/build") == 0 or die "build failed\n";
system("bin/simv +test=bogus > /dev/null");       # the bench calls $fatal: exit 1
my $saved = $?;                                    # copied at once
my $version = `vvp -V 2>&1`;                       # any later command at all...
printf "status read immediately: exit %d\n", $saved >> 8;
printf "status read afterwards:  exit %d   (that is vvp -V's status)\n", $? >> 8;

status read immediately: exit 1
status read afterwards:  exit 0   (that is vvp -V's status)

In a short script this is obvious. In a runner it is not: someone adds a helper that records the tool version, or compresses the log, or asks the farm for the job's memory use, between the launch and the status check. The run's exit 1 becomes exit 0 and nobody changed the launch code. Copy $? into a variable on the very next line, and write it to the run's status file before doing anything else.

7. A Command Anyone Can Paste

The registry's example writes the command with "@cmd", which joins the words with spaces. That loses exactly the information Section 3 showed was important: where one argument ends and the next begins. +tag=night run written that way becomes two arguments when someone pastes it.

The fix is to quote each word for the shell that will read the file. The simplest correct rule for /bin/sh is: leave a word alone if it contains only safe characters; otherwise wrap it in single quotes. Inside single quotes the shell treats every character literally, with one exception — a single quote itself — which is written as '\'' (close the quotes, an escaped quote, open them again):

sub shell_quote {
    my ($w) = @_;
    return $w if $w =~ m{^[A-Za-z0-9_+=.,/:\@%-]+$};
    $w =~ s/'/'\\''/g;
    return "'$w'";
}

The safe set keeps ordinary plusargs readable — +test=rand stays as it is — and anything with a space, >, ;, *, $, a quote or anything else unexpected gets quoted. The launcher writes the command as a small shell script that changes to the project directory first, so it works no matter where it is run from:

#!/bin/sh
# runs/rand_s7/cmd.sh -- replays this run exactly; output goes to stdout
cd "$(dirname "$0")/../.." || exit 2
exec bin/simv +test=rand +seed=7 '+tag=night run' '+cond=a>b'

The file is written before the run starts. If the run hangs and has to be killed, or the runner itself is killed, the command is already on disk — and the hung run is exactly the one somebody will want to reproduce.

8. The Launcher

Here is the launcher. It takes a small plan in the shape Chapter 25.3 produced — including the awkward arguments from Section 2 and a run whose simulator binary is missing — and launches each run with all the rules above:

#!/usr/bin/perl
# launch.pl -- launch planned runs. Each run gets its own directory holding
# the re-runnable command (cmd.sh), the captured output (sim.log) and how the
# process ended (status).
use strict;
use warnings;
use File::Path qw(make_path remove_tree);

my @plan = (
    { id => "smoke_s1733883798",  args => ["+test=smoke",  "+seed=1733883798"] },
    { id => "corner_s1387083561", args => ["+test=corner", "+seed=1387083561"] },
    { id => "rand_s2",            args => ["+test=rand", "+seed=2", "+n=60"] },
    { id => "rand_s7",            args => ["+test=rand", "+seed=7", "+tag=night run", "+cond=a>b"] },
    { id => "bogus_s1",           args => ["+test=bogus", "+seed=1"] },
    { id => "rand_s3",            args => ["+test=rand", "+seed=3"], sim => "bin/simv_old" },
);

# Quote one word for /bin/sh: plain words stay readable, anything else is
# wrapped in single quotes (a ' inside becomes '\'').
sub shell_quote {
    my ($w) = @_;
    return $w if $w =~ m{^[A-Za-z0-9_+=.,/:\@%-]+$};
    $w =~ s/'/'\\''/g;
    return "'$w'";
}

sub write_cmd {
    my ($dir, @cmd) = @_;
    open my $fh, ">", "$dir/cmd.sh" or die "$dir/cmd.sh: $!\n";
    print {$fh} "#!/bin/sh\n",
                "# $dir/cmd.sh -- replays this run exactly; output goes to stdout\n",
                "cd \"\$(dirname \"\$0\")/../..\" || exit 2\n",
                "exec ", join(" ", map { shell_quote($_) } @cmd), "\n";
    close $fh or die "$dir/cmd.sh: $!\n";
    chmod 0755, "$dir/cmd.sh";
}

sub launch {
    my ($r) = @_;
    my $dir = "runs/$r->{id}";
    die "$dir already exists: refusing to mix two runs in one directory\n" if -e $dir;
    make_path($dir);
    my @cmd = ($r->{sim} // "bin/simv", @{ $r->{args} });
    write_cmd($dir, @cmd);                 # first: it must exist even if the run hangs

    my $pid = fork // die "fork: $!\n";
    if ($pid == 0) {
        open STDOUT, ">", "$dir/sim.log" or exit 126;    # '>' : a fresh log, never append
        open STDERR, ">&", \*STDOUT      or exit 126;    # both streams, one file, in order
        { no warnings "exec"; exec { $cmd[0] } @cmd }    # no shell: each word arrives intact
        print STDERR "launch: cannot run $cmd[0]: $!\n"; # this lands in sim.log
        exit 127;
    }
    waitpid($pid, 0);
    my $st = $?;                           # copy $? before anything can change it
    my %s  = (exit => $st >> 8, signal => $st & 127);

    open my $sf, ">", "$dir/status" or die "$dir/status: $!\n";
    print {$sf} "exit=$s{exit}\nsignal=$s{signal}\n";
    close $sf or die "$dir/status: $!\n";
    return \%s;
}

system("bin/build") == 0 or die "build failed\n";
remove_tree("runs");                       # a fresh regression area for this demo

printf "%-19s %4s %6s  %s\n", "RUN", "EXIT", "SIGNAL", "FIRST LINE OF sim.log";
for my $r (@plan) {
    my $s = launch($r);
    open my $log, "<", "runs/$r->{id}/sim.log" or die;
    my $first = <$log> // "(empty)\n";
    printf "%-19s %4d %6d  %s", $r->{id}, $s->{exit}, $s->{signal}, $first;
}

RUN                 EXIT SIGNAL  FIRST LINE OF sim.log
smoke_s1733883798      0      0  TEST smoke SEED 1733883798
corner_s1387083561     0      0  TEST corner SEED 1387083561
rand_s2                0      0  TEST rand SEED 2
rand_s7                0      0  TEST rand SEED 7
bogus_s1               1      0  TEST bogus SEED 1
rand_s3              127      0  launch: cannot run bin/simv_old: No such file or directory

The table is exactly what the launcher is responsible for: how each process ended, and where its evidence is. It does not say which runs passed. corner and rand_s2 exited 0 and both contain TEST FAILED; deciding that is the classifier's job (Chapter 25.7), from the log and this status together.

Walk through launch:

• The directory check comes first. If runs/rand_s2 exists, the launcher stops rather than mixing two runs' evidence.
• write_cmd runs before fork. The command is on disk before the simulator starts.
• In the child: standard output is reopened onto sim.log with >, standard error is duplicated onto it (>&), and then the simulator is started with the block form of exec, exec { $cmd[0] } @cmd. The block names the program to run; the list is its arguments, passed as-is. No shell is involved, so '+tag=night run' arrives as one argument and +cond=a>b is just text.
• If exec fails, the child is still running Perl. It prints a clear message — which goes into sim.log, because standard error now points there — and exits 127. That is why the rand_s3 row's log says launch: cannot run bin/simv_old: the evidence is in the place the classifier will look. (no warnings "exec" stops Perl printing its own, less clear, version of the same message first.)
• In the parent: waitpid waits for this child, and $? is copied on the next line. The status file records both the exit code and the signal, because Section 4 showed they are different facts.

Exit 126 and 127 are the shell's conventions for "found but could not run" and "not found". The launcher borrows them for its own two child failures so that a person reading status recognises them — but notice that the classifier must still read the log to tell "the launcher could not start it" from "the simulator chose to exit 127". Chapter 25.7 handles exactly that.

9. Proving the Command Reproduces the Run

cmd.sh claims to reproduce the run. That is a testable claim, so test it: run every saved command again and compare its output with the captured log, byte for byte.

#!/usr/bin/perl
# replay.pl -- launch the plan, then run every saved cmd.sh again and compare
# its output with the log the regression captured, byte for byte.
use strict;
use warnings;

system("$^X launch.pl > /dev/null") == 0 or die "launch.pl failed\n";
for my $dir (sort glob "runs/*") {
    my %st = do { open my $s, "<", "$dir/status" or die; map { /^(\w+)=(\d+)$/ } <$s> };
    if ($st{exit} == 127) { print "$dir: skipped, no simulation ran\n"; next }
    my $again    = `sh $dir/cmd.sh 2>&1`;
    my $captured = do { local $/; open my $l, "<", "$dir/sim.log" or die; <$l> };
    printf "%s: %s\n", $dir, $again eq $captured ? "identical" : "DIFFERENT";
}

runs/bogus_s1: identical
runs/corner_s1387083561: identical
runs/rand_s2: identical
runs/rand_s3: skipped, no simulation ran
runs/rand_s7: identical
runs/smoke_s1733883798: identical

All five runs that simulated anything reproduced byte for byte, including rand_s7 with its quoted arguments and rand_s2 with its failure. The sixth is skipped, and the script says so instead of quietly leaving it out: its "output" was the launcher's own error message, which sh would phrase differently, so comparing them would test nothing.

Byte-identical replay works here because these logs contain nothing that changes between runs. Real simulator logs usually contain dates, host names, run times and process ids. For those, compare the parts that matter — the verdict, the first error, the seed — or normalise the log first (Chapter 18.3 strips that kind of noise). Chapter 25.9 builds the full reproducibility record on top of cmd.sh.

10. What This Launcher Still Does Not Do

11. Exercises

1. A fourth special character. Add the argument +home=$HOME to the list in string_launch.pl, and replace bin/simv in the string with /bin/echo so you can see exactly which arguments arrive. Predict the output first. Then pass the same argument through launch.pl's list form (again with /bin/echo as the program) and compare.

2. Prove shell_quote correct. Write a test that takes a list of awkward words — a space, a single quote, a double quote, a backslash, $HOME, a backquoted command, *, an embedded newline, the empty string — quotes each one, passes it through sh -c 'printf "%s|" "$@"' sh WORD, and checks that exactly the original word comes back. (When this chapter's version was tested this way, all of those came back intact.) Then add a word your own test lists contain that you think is risky, and run the test again.

3. Refuse, or move aside? Change launch so that instead of refusing an existing directory it renames it to <id>.prev first. Is that safer or more dangerous? What happens on the third run?

4. Status file as evidence. Add the start time, end time and the host name to the status file. Which of those must never be used in a byte-for-byte comparison, and why?

5. Your launcher. Look at how runs are launched in a flow you use. Is there a shell between the runner and the simulator? Find the one argument in your own test list that would change meaning if it went through a shell unquoted.

12. What To Remember

• Every run leaves three files: cmd.sh, sim.log, status. A log without the command cannot be reproduced; a command without the log cannot be checked.
• Measured: the one-line string launch sent a failing simulation's output to a stray file called b, left the log holding INJECTED, and exited 0.
• Never build a command line as one string. Use a list, and redirect in a child before exec, so no shell reads the arguments.
• Through a shell, "could not start" becomes 127 and a signal becomes 128 + N. Measured: a KILLed simulator was exit 137, signal 0 through sh, and signal 9 without it.
• Capture both streams into one fresh log. vvp wrote everything on standard output here; the launcher's own errors go to standard error.
• Open the log with >, never >>, and refuse a run directory that already exists. Measured: an appended log turned a launch that never simulated into a PASS.
• Copy $? on the next line. Measured: one later backtick command turned exit 1 into exit 0.
• Write cmd.sh with every word shell-quoted, before the run starts — and prove it reproduces the run.

Chapter 25.5 sends runs to a compute farm instead of starting them locally. The launch then happens on another machine, the only thing the runner gets back is a job id, and keeping track of which id belongs to which run directory becomes the whole problem.