Messages, Logging and Which Stream They Belong On

Part I · Module 20 · Chapter 20.7 · Messages, Logging and Which Stream They Belong On

Module 12 established that a process has two output channels. This chapter is the rule for deciding which one each line of your script belongs on, and the measurement of what happens when you get it wrong.

1. The Rule

Standard output is for the answer. Standard error is for everything else.

"Everything else" is broader than it sounds: progress, warnings, errors, the name of the scratch directory, "processing 14 of 400", and the usage message. All of it is diagnostics.

2. What the Split Buys, Measured

#!/usr/bin/env bash
# s.sh
printf 'RESULT: 42\n'                  # stdout — the answer
printf 'note: working\n' >&2           # stderr — the diagnostic

At a terminal, both appear and you cannot tell them apart:

$ ./s.sh
RESULT: 42
note: working

That is the point at which people conclude the distinction does not matter. It matters as soon as anything other than a terminal is on the other end.

Captured — only the answer arrives:

$ v=$(./s.sh)
note: working
$ echo "v=[$v]"
v=[RESULT: 42]

The note went to the terminal while the script was running, and $v is exactly the answer. The caller gets a clean value and the human gets the progress.

Piped — only the answer flows:

$ ./s.sh 2>/dev/null | cat
RESULT: 42

And the diagnostics can be read on their own:

$ ./s.sh 2>&1 >/dev/null
note: working

(That ordering is Chapter 12.3's: 2>&1 first points stderr at wherever stdout currently goes — the terminal — and >/dev/null then moves stdout only. Reverse them and you discard both.)

Four different consumers, each getting what it needs, from one script that made one decision per line.

3. What Getting It Wrong Costs

Chapter 18.4 §4 measured this for functions; it is the same at script scale and worth seeing again, because it is the concrete cost:

$ bad()  { echo "LOG: working";      printf '%s\n' RESULT; }
$ v=$(bad);  printf 'v=[%s]\n' "$v"
v=[LOG: working
RESULT]

$ good() { echo "LOG: working" >&2;  printf '%s\n' RESULT; }
$ v=$(good); printf 'v=[%s]\n' "$v"
LOG: working
v=[RESULT]

The log line is inside the value. $v is two lines, the first of which is diagnostic text, and every later use of $v is wrong. Nothing errored, and the failure surfaces somewhere else entirely — a comparison that never matches, a filename with a newline in it, an arithmetic expansion that chokes.

Three consequences that follow:

Your script cannot be used in a pipeline. ./myscript | awk '{print $2}' now has to skip your progress lines, which means the consumer needs to know your logging format. That is a coupling you did not intend to create.

It cannot be captured. Any caller writing v=$(./myscript) gets contaminated data, and the contamination varies with how far the script got — so the bug is intermittent.

And its log cannot be separated. ./myscript > out.txt 2> err.txt is the thing an operator wants when a nightly run fails. If everything is on stdout, out.txt is a mix and err.txt is empty.

4. What "The Answer" Means

The rule is easy to state and occasionally hard to apply, because some scripts have no answer.

A script that computes something has an obvious answer — a count, a path, a list, a verdict. That goes on stdout, one record per line, nothing else:

# newest-log.sh — prints one path
printf '%s\n' "$newest"

A script that does something has no answer, and its stdout should be empty or near-empty:

# deploy.sh — stdout says almost nothing; progress is diagnostics
note "copying $count files"
note "restarting service"
printf 'deployed %s\n' "$version"       # one line, the summary

The distinction to hold on to: if a human reading it is the only possible consumer, it is a diagnostic. "copying 14 of 400" is for a person watching; "deployed v1.4" is a fact a caller might capture. Progress bars, spinners and counters are always diagnostics, which is also why they are safe to suppress.

A script that is a filter reads stdin and writes stdout, and its diagnostics must go to stderr or it breaks the pipeline it was written for. This is the case where the rule is not negotiable.

5. A Minimal Logging Vocabulary

Four functions cover almost everything, and shell scripts that grow more than this usually should not have:

note() { printf '%s: %s\n' "${0##*/}" "$*" >&2; }
warn() { printf '%s: warning: %s\n' "${0##*/}" "$*" >&2; }
die()  { printf '%s: %s\n' "${0##*/}" "$*" >&2; exit 1; }
dbg()  { [ "${VERBOSE:-0}" -eq 1 ] || return 0
         printf '%s: debug: %s\n' "${0##*/}" "$*" >&2; }

$ note "scratch: /tmp/x"
myscript: scratch: /tmp/x
$ warn "no testlist; using the default"
myscript: warning: no testlist; using the default
$ VERBOSE=1 dbg "filelist has 42 entries"
myscript: debug: filelist has 42 entries
$ dbg "this one is suppressed"
$

Four properties are worth noticing:

Every line is prefixed with the script's name. In a nightly log that interleaves five tools, an unprefixed cannot read file is unattributable. ${0##*/} is Chapter 8.3's basename, and it costs nothing.

warn and die say which they are. A grep for warning: across a week of logs is a useful thing to be able to do.

dbg is off unless asked. A VERBOSE environment variable rather than a flag, so it can be turned on for one run of a script you do not want to edit — VERBOSE=1 ./nightly.sh.

And die exits. Chapter 18.3's rule: the name is the contract, and it is the only one of the four that does not return.

6. Redirecting a Whole Script

For an unattended run you often want everything on disk and nothing on the terminal. Three ways, in increasing precision.

At the call site, which needs no change to the script:

$ ./nightly.sh > nightly.out 2> nightly.err
$ ./nightly.sh > nightly.log 2>&1              # both interleaved in order

Inside the script, with exec:

exec 2> "$logdir/run.err"            # all later stderr goes to the file
exec 1> "$logdir/run.out"            # and all later stdout

exec with only a redirection and no command changes the current shell's file descriptors — Chapter 12.2's redirection applied to the shell itself rather than to one command. Everything after that line is redirected, including the output of commands the script runs.

And keeping a handle on the terminal, which is what you want for a progress line that must stay visible:

exec 3>&2                            # 3 is now the original stderr
exec 2> "$logdir/run.err"            # 2 goes to the log
status() { printf '%s\n' "$*" >&3; } # still reaches the terminal

Chapter 12.3's descriptor duplication. 3>&2 makes descriptor 3 a copy of the current stderr before stderr is moved, so >&3 writes to where stderr used to go.

And tee when you want both at once — Chapter 12.6:

./nightly.sh 2>&1 | tee nightly.log

With the Chapter 20.2 §5 caveat: that is a pipeline, so under set -o pipefail in the calling shell the status is the worse of the two, and $? is tee's rather than the script's. ${PIPESTATUS[0]} has the script's.

7. A Complete Script

A filter — the case where the rule cannot be bent — that also reports progress:

#!/usr/bin/env bash
# summarise-logs.sh — read log paths on stdin, write one summary line each
# usage: find . -name '*.log' | summarise-logs.sh [-v]
#
# stdout: one "VERDICT<TAB>path" record per input line
# stderr: progress, warnings, errors
#
# exit: 0 all passed · 1 at least one did not · 2 unusable invocation

set -o errexit
set -o nounset
set -o pipefail

note() { printf '%s: %s\n' "${0##*/}" "$*" >&2; }
warn() { printf '%s: warning: %s\n' "${0##*/}" "$*" >&2; }
die()  { printf '%s: %s\n' "${0##*/}" "$*" >&2; exit 2; }
dbg()  { [ "${VERBOSE:-0}" -eq 1 ] || return 0
         printf '%s: debug: %s\n' "${0##*/}" "$*" >&2; }

case ${1:-} in
  -v) VERBOSE=1; shift ;;
  '') ;;
  *)  die "usage: ${0##*/} [-v]  (log paths on stdin)" ;;
esac

[ -t 0 ] && die "expects log paths on stdin — try: find . -name '*.log' | ${0##*/}"

seen=0
bad=0
skipped=0

while IFS= read -r f || [ -n "$f" ]; do
  [ -n "$f" ] || continue
  seen=$(( seen + 1 ))

  if ! [ -f "$f" ]; then
    warn "no such file: $f"
    skipped=$(( skipped + 1 ))
    continue
  fi
  if ! [ -r "$f" ]; then
    warn "not readable: $f"
    skipped=$(( skipped + 1 ))
    continue
  fi

  dbg "reading $f"

  if   ! [ -s "$f" ];                  then verdict=EMPTY
  elif grep -q 'UVM_FATAL' "$f";       then verdict=FATAL
  elif grep -q 'UVM_ERROR' "$f";       then verdict=ERRORS
  elif ! grep -q 'TEST PASSED' "$f";   then verdict=NO-VERDICT
  else                                      verdict=PASS
  fi

  # THE ANSWER — the only thing on stdout
  printf '%s\t%s\n' "$verdict" "$f"

  [ "$verdict" = PASS ] || bad=$(( bad + 1 ))
done

note "$seen log(s), $bad not passing, $skipped skipped"
[ "$bad" -eq 0 ]

$ mkdir logs
$ printf 'UVM_ERROR : x\n'           > logs/a.log
$ printf 'running\nTEST PASSED\n'    > logs/b.log
$ : >                                  logs/c.log

$ find logs -name '*.log' | ./summarise-logs.sh
PASS	logs/b.log
EMPTY	logs/c.log
ERRORS	logs/a.log
summarise-logs.sh: 3 log(s), 2 not passing, 0 skipped
$ echo "${PIPESTATUS[1]}"
1

Now the thing the split was for — it works as a pipeline stage, and the diagnostics stay out of the data:

$ find logs -name '*.log' | ./summarise-logs.sh | sort | column -t -s$'\t'
summarise-logs.sh: 3 log(s), 2 not passing, 0 skipped
EMPTY   logs/c.log
ERRORS  logs/a.log
PASS    logs/b.log

(find does not sort, which is why the records are in filesystem order until sort gets them.) The summary appeared on the terminal while sort was buffering, because it went to stderr and never entered the pipe. Had note written to stdout, sort would have sorted it into the middle of the data and column would have tried to lay it out as a record.

And the data can be captured cleanly:

$ out=$(find logs -name '*.log' | ./summarise-logs.sh)
summarise-logs.sh: 3 log(s), 2 not passing, 0 skipped
$ printf '%s\n' "$out" | wc -l
       3

Three lines in the variable, exactly the three records, with the summary on the terminal rather than in the value.

$ find logs -name '*.log' | VERBOSE=1 ./summarise-logs.sh > /dev/null
summarise-logs.sh: debug: reading logs/b.log
summarise-logs.sh: debug: reading logs/c.log
summarise-logs.sh: debug: reading logs/a.log
summarise-logs.sh: 3 log(s), 2 not passing, 0 skipped

$ printf 'logs/a.log\nlogs/missing.log\n' | ./summarise-logs.sh
ERRORS	logs/a.log
summarise-logs.sh: warning: no such file: logs/missing.log
summarise-logs.sh: 2 log(s), 1 not passing, 1 skipped
$ echo $?
1

$ ./summarise-logs.sh --bogus
summarise-logs.sh: usage: summarise-logs.sh [-v]  (log paths on stdin)
$ echo $?
2

Six decisions:

Exactly one printf writes to stdout, and it writes one tab-separated record. Everything else in the script — six note/warn/dbg calls and two dies — goes to stderr, by construction rather than by discipline.

The header comment documents both channels separately. A caller needs to know what stdout's format is; an operator needs to know diagnostics are on stderr. Saying so is cheaper than making them find out.

[ -t 0 ] catches being run with no input. Chapter 16.4 §6's terminal test: if stdin is a terminal, nobody piped anything in and the script would otherwise sit waiting for the user to type log paths. The message says what to try instead.

A tab separator, not a space. logs/my report.log contains a space, so a space-separated record could not be parsed — Chapter 19.1's lesson applied to output rather than input. A tab survives cut -f2 and column -t -s$'\t'.

${PIPESTATUS[1]} is how the caller reads the status, because the script is the second stage. $? would be sort's. Chapter 12.8, and the reason the usage comment names it.

VERBOSE=1 as an environment variable as well as -v. So it can be turned on for one invocation of a script inside a pipeline someone else wrote, without editing anything.

Practice

1. Write s.sh with one line on each stream. Run it four ways: plain, captured with $( ), piped with 2>/dev/null, and with 2>&1 >/dev/null. Record what each shows.
2. Reverse the order to >/dev/null 2>&1 in the fourth case. What do you see, and which chapter explains the ordering?
3. Write bad() logging to stdout and good() logging to stderr, both printing a result. Capture each and print the value in brackets. Then explain why putting >&2 inside note protects forty call sites at once.
4. Take a script of your own whose progress goes to stdout and pipe it into sort. Describe exactly what goes wrong.
5. Write the four-function vocabulary. Confirm dbg is silent by default and visible under VERBOSE=1.
6. Add ${0##*/} to each message. Then run two different scripts into the same log file and explain why the prefix is not optional.
7. Use exec 2> err.log at the top of a script and confirm that a command's stderr several lines later also lands in the file.
8. Use exec 3>&2 before redirecting stderr, and write a progress line to >&3. Confirm it reaches the terminal while everything else goes to the file.
9. Run summarise-logs.sh into sort | column -t -s$'\t'. Then change note to write to stdout and run it again. What does column do with the summary line?
10. Change summarise-logs.sh's output separator from a tab to a space and feed it a path containing a space. Show that the record can no longer be parsed with cut.
11. Run summarise-logs.sh with no stdin at a real terminal and confirm the [ -t 0 ] message. Then explain why [ -t 1 ] could not be demonstrated in this chapter.

Check Your Understanding

1. What belongs on stdout, and what belongs on stderr?
2. v=$(./script) and the script's progress lines end up in $v. What went wrong?
3. Name three things a script cannot be used for if it logs to stdout.
4. Why does >&2 belong inside the note function rather than at each call?
5. What is the difference between 2>&1 >/dev/null and >/dev/null 2>&1?
6. Why prefix every message with the script's name?
7. A script is the second stage of a pipeline. How does the caller read its status?

8. Remember

• Stdout is for the answer; stderr is for everything else. Progress, warnings, errors, usage, scratch paths — all diagnostics.
• The split is not stylistic. It decides whether the script can be piped, captured, or logged to two files.
• A log line on stdout ends up inside a caller's variable, intermittently, and surfaces as a bug somewhere else.
• Put >&2 inside note/warn/die, so every call site is right by construction.
• If a human reading it is the only possible consumer, it is a diagnostic. Progress counters always are.
• A filter has no choice: diagnostics on stderr or the pipeline breaks.
• Four functions are enough — note, warn, die, and a dbg gated on an environment variable.
• Prefix every message with ${0##*/}. An unattributable line in a shared log is useless.
• exec 2> file redirects the rest of the script; exec 3>&2 first keeps a handle on the terminal.
• 2>&1 >/dev/null shows only stderr; >/dev/null 2>&1 shows nothing. Order matters.
• Use a tab, not a space, between output fields — a path can contain a space.
• A script inside a pipeline is read with PIPESTATUS, not $?.

Chapter 20.8 closes Part I with the question none of the other chapters can answer: not "did it fail" but what did it actually do — line by line, with every variable already expanded.

• Every flow script repeats these same few functions. Chapter 35.1 factors them into one sourced library with a written contract, and measures what breaks when two copies drift apart.