Learn › Bash Redirection and File Descriptors › Logging without lying

Chapter 11. Logging without hiding failures

Logging without hiding failures. Try the examples, inspect their output, and explain the result. Practice feedback does not award XP or mastery.

Define a useful logging contract

A report command feeds JSON to another program. Someone adds a reassuring progress message to stdout, and the JSON reader fails. Later, a logging disk fills while the report still appears on screen. Visible output alone no longer tells you whether the operation succeeded.

Treat stdout as the command's promised data interface. Put diagnostics on stderr. A sink is a destination accepting output, such as a file or another process. If a required sink fails, the operation needs to report that failure even when another sink works.

Use Bash 5.2 or later and GNU tee in a private directory. The disk-full probe requires Linux. The buffering instrument uses Python 3.9 or later. These commands use tiny disposable files and do not change a real logging service.

In your managed Bash practice terminal

Run camp-redirection 11 to enter this chapter's private directory. While this lab machine is running, the same command returns to it after reconnecting; camp-redirection 11 --fresh creates a new one without deleting earlier files. Run the code blocks there and use cd to leave.

Separate data from explanation

This function emits one JSON record and one diagnostic. JSON is structured text data; here {"rows":2} says the rows field has the number 2. The caller decides where to send each stream, then inspects the files with labels. Those labels belong to the inspection, not the JSON file.

Predict which file receives the JSON and which receives the warning. After running, read both files and decide whether either has bytes from the wrong channel.

report() {
  printf '{"rows":2}\n'
  printf 'warning: optional row skipped\n' >&2
}
report > report.json 2> diagnostics.log
printf 'data: '
cat report.json
printf 'diagnostic: '
cat diagnostics.log

Expected output

data: {"rows":2}
diagnostic: warning: optional row skipped

Process	Descriptor	Destination during the call
Report function	1	Open report.json output
Report function	2	Separately opened diagnostics.log output
Later inspection commands	1	Caller's original stdout

Merging with 2>&1 can be appropriate for a human-readable combined log. Do not merge diagnostic prose into a machine-readable interface that promises JSON.

Copy and append deliberately

tee copies stdin to stdout and its named files. It normally overwrites existing named files. Its -a option appends instead.

Compare visible.txt with activity.log: stdout contains current, while tee -a keeps earlier and appends current.

printf 'earlier\n' > activity.log
printf 'current\n' | tee -a activity.log > visible.txt
printf 'forwarded: '
cat visible.txt
printf 'log:\n'
cat activity.log

Expected output

forwarded: current
log:
earlier
current

Appending preserves prior bytes but is not a complete concurrency or rotation design. The next chapters examine competing writers and safe file replacement. First, establish whether every required destination actually accepted the output.

Detect a sink that cannot write

Linux /dev/full opens successfully but rejects writes as out of space. It lets us test a write failure without filling a disk. GNU tee --output-error=warn diagnoses output errors, continues with usable outputs, and returns failure if any output failed.

Check producer status 0, tee status 1, and the nonempty diagnostic; the successful producer does not erase the sink failure.

printf 'row\n' | LC_ALL=C tee --output-error=warn /dev/full > /dev/null 2> sink-error.log
stages=("${PIPESTATUS[@]}")
printf 'producer=%s tee=%s\n' "${stages[0]}" "${stages[1]}"
if test -s sink-error.log; then printf 'diagnostic captured\n'; fi

Expected output

producer=0 tee=1
diagnostic captured

Read sink-error.log for the actual error during practice. Its wording can differ across utility versions. The exact evidence here is a successful producer, a failed tee, and a nonempty diagnostic. A downstream successful command would otherwise hide that failure under the default pipeline status rule.

Distinguish write order from source order

Programs may buffer output in memory before writing it. A merged destination records writes as they arrive, not necessarily the order of print statements in source code. This Python instrument explicitly flushes stderr while stdout remains buffered in a redirected file.

python3 -E -c 'import sys; sys.stdout.write("report\n"); sys.stderr.write("warning\n"); sys.stderr.flush()' > buffered.log 2>&1
cat buffered.log

The file contains warning followed by report. This is runtime buffering, not reversed redirect processing. Changing a program's flush behavior can change that order. Concurrent processes add scheduling variation too, so do not infer a total event chronology merely from line order in a combined log.

Give debug traces their own descriptor

Bash set -x prints commands after expansion. That can help diagnose a wrapper, but it can also expose expanded arguments, including secrets. Use nonsecret practice values and a dedicated trace destination.

(
  exec {trace}> trace.log
  BASH_XTRACEFD=$trace
  PS4='+ '
  set -x
  printf '{"rows":1}\n'
  set +x
  unset BASH_XTRACEFD
) > traced.json 2> traced-errors.log
cat traced.json
if grep -q 'printf' trace.log && test ! -s traced-errors.log; then
  printf 'trace separated\n'
fi

The inspection prints the JSON record and trace separated. Unsetting BASH_XTRACEFD closes the descriptor Bash used for tracing. Do not set it to descriptor 2 and then unset it, because that would close stderr. The subshell contains these diagnostic settings.

Preserve the producer's failure

Try a final repair before reading the solution. A producer emits a partial JSON record, explains its failure on stderr, and returns 9. Keep the candidate for inspection, append a completion status to its log, publish no stdout data, and preserve status 9.

(
  produce() { printf '{"rows":1}\n'; printf 'source incomplete\n' >&2; return 9; }
  produce > candidate.json 2> run.log
  result=$?
  printf 'producer status=%s\n' "$result" >> run.log
  if (( result == 0 )); then
    cat candidate.json
  else
    printf 'rejected: producer status %s\n' "$result" >&2
  fi
  exit "$result"
)

The worked result has empty stdout, stderr rejected: producer status 9, and status 9. Parentheses keep this deliberate exit inside a child shell environment. Appending the log entry cannot replace the saved producer result. A production wrapper must also handle failure to append a required log; the earlier sink check provides that separate obligation.

Ready to practice

Make the producer succeed, then make a required log destination fail. State which outputs are allowed and which status wins in each case. Verify the bytes, destination failures, and returned status together. Successful logging must describe the operation accurately, including when the logging itself fails.

Return to Chapters 7 and 8 now that the failing stage has changed from producer to logging sink. Before rereading the worked tee result, predict the producer and tee statuses for /dev/full, capture both immediately, and state whether your report is acceptable when its required log write fails. Inspect sink-error.log to justify the decision. Record any hint or worked answer you needed; a successful producer alone does not settle the policy.

References: GNU tee behavior, Bash trace descriptor.

Practice Chapter 11. Logging without hiding failures in a real Linux terminal at The Linux Camp. Progress is verified automatically as you type commands on the machine.