Separate execution traces from error output exactly, and filter by PS4 only when it is literal

cronic

@@ -6,14 +6,14 @@
 # In brief:
 #   Cronic is a small shim shell script for wrapping cron jobs so that cron
 #   only sends email when an error has occurred. Cronic defines an error as
-#   any non-trace error output or a non-zero result code. Cronic filters
-#   Bash execution traces (or anything matching PS4) from the error output,
-#   so jobs can be run with execution tracing to aid forensic
-#   debugging. Apart from its options, Cronic simply executes its
-#   arguments.
+#   any non-trace error output or a non-zero result code. Cronic separates
+#   execution traces from the error output, so jobs can be run with execution
+#   tracing to aid forensic debugging. Apart from its options, Cronic simply
+#   executes its arguments.
 # Extended by Michael Ernst to add the --expected-status, --permit-stderr, and
 # --duplicate-stderr options, which may be given in any order.
-# The options are documented in function `cronic_help`; run `cronic --help`.
+# The options and the treatment of execution traces are documented in function
+# `cronic_help`; run `cronic --help`.
 
 # Exit if a command exits with a non-zero status, and treat unset variables
 # as an error.
@@ -44,6 +44,12 @@ cronic_help() {
   echo "                       is less likely to be overlooked"
   echo "  --                   end the options, so that COMMAND may start with \"-\""
   echo "  -h, --help           print this message"
+  echo "Execution traces (from \"set -x\") are not treated as error output."
+  echo "Bash 4.1 or later writes them to a separate file, via BASH_XTRACEFD; they"
+  echo "appear in the report under \"TRACE OUTPUT\".  Other shells write them to"
+  echo "stderr, from which lines that start with PS4 are removed.  That removal"
+  echo "is skipped if PS4 contains \"\$\", a backquote, a backslash, or a newline,"
+  echo "because such a PS4 can expand differently on each line."
   exit 0
 }
 
@@ -117,6 +123,7 @@ cronic_out=$cronic_tmpdir/out
 cronic_err=$cronic_tmpdir/err
 cronic_reduced_err=$cronic_tmpdir/err.reduced
 cronic_trace=$cronic_tmpdir/trace
+cronic_xtrace=$cronic_tmpdir/xtrace
 
 # Remove the temporary files however this script terminates, including when it
 # is interrupted before it reaches the end.  When cronic_debug is true, the
@@ -140,6 +147,17 @@ trap 'cronic_cleanup; trap - HUP EXIT; kill -s HUP $$' HUP
 trap 'cronic_cleanup; trap - INT EXIT; kill -s INT $$' INT
 trap 'cronic_cleanup; trap - TERM EXIT; kill -s TERM $$' TERM
 
+# A bash command writes its execution trace to the file descriptor named by
+# BASH_XTRACEFD, rather than to stderr, so the trace is separated from the
+# error output exactly, whatever PS4 is.  The descriptor is allocated by bash
+# (as 10 or higher), so that it does not collide with a descriptor, such as 3,
+# that the wrapped command uses for its own purposes.  Bash before 4.1 supports
+# neither BASH_XTRACEFD nor descriptor allocation.
+if ((BASH_VERSINFO[0] > 4 || (BASH_VERSINFO[0] == 4 && BASH_VERSINFO[1] >= 1))); then
+  exec {cronic_xtrace_fd}> "$cronic_xtrace"
+  export BASH_XTRACEFD=$cronic_xtrace_fd
+fi
+
 set +e
 # `command` because the wrapped command runs in this shell, where a function of
 # this script, such as `cronic_usage`, would otherwise run in place of a
@@ -148,8 +166,38 @@ command -- "$@" > "$cronic_out" 2> "$cronic_trace"
 cronic_result=$?
 set -e
 
-cronic_pattern="^${PS4:0:1}\\+${PS4:1}"
-if grep -q "$cronic_pattern" "$cronic_trace"; then
+# Unsetting BASH_XTRACEFD also closes its file descriptor.
+unset BASH_XTRACEFD
+
+# Prints a basic regular expression that matches its argument literally.
+# The argument must not contain a backslash.
+cronic_bre_quote() {
+  printf '%s\n' "$1" | LC_ALL=C sed 's/[*.[^]/\\&/g'
+}
+
+# Prints a basic regular expression that matches the trace lines, for PS4, that
+# a shell other than bash 4.1 or later writes to stderr.  Such a line starts
+# with PS4 after expansion, with PS4's first character repeated once per level
+# of nesting.  If PS4 contains a `$`, backquote, or backslash, then its
+# expansion can differ from line to line, so nothing is printed:  any pattern
+# for such a PS4 could also match, and hide, a real error.  Nothing is printed
+# if PS4 contains a newline, either, because `grep` would treat each line of
+# the pattern as a separate pattern.
+cronic_trace_pattern() {
+  case ${PS4-} in
+    '' | *[\$\`\\]* | *$'\n'*) return ;;
+  esac
+  # In the C locale, a character is a byte.  The first character is a UTF-8
+  # lead byte and its continuation bytes, or else a single byte, so that a
+  # multibyte character is repeated as a whole, whatever the locale.
+  local LC_ALL=C
+  [[ $PS4 =~ ^([$'\xc0'-$'\xff'][$'\x80'-$'\xbf']*|.) ]]
+  local first=${BASH_REMATCH[0]}
+  printf '^\\(%s\\)\\+%s\n' "$(cronic_bre_quote "$first")" "$(cronic_bre_quote "${PS4#"$first"}")"
+}
+
+cronic_pattern=$(cronic_trace_pattern)
+if [ -n "$cronic_pattern" ] && grep -q "$cronic_pattern" "$cronic_trace"; then
   # `|| true` because `grep -v` exits with status 1 when it selects no lines,
   # which happens whenever stderr consists only of trace lines.  Without it,
   # `set -e` would abort the script here, before it produces its report,
@@ -200,6 +248,11 @@ if [ $cronic_result -ne "$cronic_expected" ] || { [ $cronic_permitstderr -eq 0 ]
     echo "TRACE-ERROR OUTPUT:"
     cat "$cronic_trace"
   fi
+  if [ -s "$cronic_xtrace" ]; then
+    echo
+    echo "TRACE OUTPUT:"
+    cat "$cronic_xtrace"
+  fi
   if [ $cronic_duplicate_stderr -eq 1 ]; then
     echo
     echo "ERROR OUTPUT:"

tests/cronic-test/cronic-test.sh

@@ -70,6 +70,23 @@ exit "$1"
 EOF
 chmod +x "$work/make-noise-and-stderr"
 
+# A command that writes, to stderr, lines that start with `+` but are not trace
+# lines.
+cat > "$work/plus-stderr" << 'EOF'
+#!/bin/sh
+echo "+++ b/file" 1>&2
+echo "++ conflict" 1>&2
+EOF
+chmod +x "$work/plus-stderr"
+
+# A command that writes each of its arguments, as a line, to stderr.  It stands
+# for a shell other than bash, which writes its trace lines to stderr.
+cat > "$work/stderr-lines" << 'EOF'
+#!/bin/sh
+printf '%s\n' "$@" 1>&2
+EOF
+chmod +x "$work/stderr-lines"
+
 # temp_files: prints `cronic`'s temporary files, in a canonical order.
 temp_files() {
   find "$TMPDIR" -mindepth 1 -maxdepth 1 2> /dev/null | sort
@@ -282,4 +299,79 @@ check "caller's exported variables" 0 silent "$work/check-variables" $exported_n
 # shellcheck disable=SC2086  # each name is a separate argument.
 unset $exported_names
 
+# Bash writes its trace lines to a separate file, so they are not error
+# output, whatever PS4 is.
+export PS4
+# shellcheck disable=SC2016 # The expansion is for the traced command to do.
+PS4='+${LINENO}: '
+check "bash, PS4 with expansions, trace-only stderr" 0 silent \
+  "$work/trace-only" 0
+check "bash, PS4 with expansions, trace in the report" 3 \
+  "report:echo 'the standard output'$" "$work/trace-only" 3
+check "bash, PS4 with expansions, trace lines and real stderr" 0 \
+  "report:^a real error$" "$work/trace-and-stderr" 0
+PS4='+\D{%H}: '
+check "bash, PS4 with an escape, trace-only stderr" 0 silent \
+  "$work/trace-only" 0
+PS4='[trace] '
+check "bash, PS4 with metacharacters, trace-only stderr" 0 silent \
+  "$work/trace-only" 0
+
+# The tests below concern trace lines that a shell other than bash writes to
+# stderr; they are recognized by PS4.  Bash running as root does not import
+# PS4 from the environment, so `cronic` would see the default PS4, and these
+# tests are skipped.
+if [ "$(id -u)" -eq 0 ]; then
+  echo "SKIP: tests of PS4 in stderr, because bash ignores PS4 when run as root"
+  unset PS4
+  exit "$status"
+fi
+
+# Trace lines are recognized when PS4 contains regular-expression
+# metacharacters or quotes, and the metacharacters do not match other lines.
+PS4='[trace] '
+check "PS4 with metacharacters, trace-only stderr" 0 silent \
+  "$work/stderr-lines" "[trace] echo hi" "[[trace] echo nested"
+check "PS4 with metacharacters, trace lines and real stderr" 0 \
+  "report:^a real error$" \
+  "$work/stderr-lines" "[trace] echo hi" "a real error"
+PS4='+.* '
+check "PS4 with metacharacters, error line that they would match" 0 \
+  "report:^+++ b/file$" "$work/stderr-lines" "+++ b/file"
+PS4="+\"it's\" "
+check "PS4 with quotes, trace-only stderr" 0 silent \
+  "$work/stderr-lines" "+\"it's\" echo hi" "++\"it's\" echo nested"
+# A multibyte first character is repeated as a whole, even in the C locale.
+PS4='→ '
+LC_ALL=C
+export LC_ALL
+check "PS4 with a multibyte first character, trace-only stderr" 0 silent \
+  "$work/stderr-lines" "→ echo hi" "→→ echo nested"
+unset LC_ALL
+# When PS4 contains an expansion, an escape, or a newline, no line is treated
+# as a trace line, so trace lines are reported, and so is an error line that
+# resembles one.
+# shellcheck disable=SC2016 # The expansion is for the traced command to do.
+PS4='+${LINENO}: '
+check "PS4 with expansions, trace-only stderr" 0 \
+  "report:^+3: echo hi$" "$work/stderr-lines" "+3: echo hi"
+check "PS4 with expansions, error line that starts with +" 0 \
+  "report:^+++ b/file$" "$work/stderr-lines" "+++ b/file"
+# shellcheck disable=SC2016 # The expansion is for the traced command to do.
+PS4='+${BASH_SOURCE}:${LINENO}: '
+check "PS4 with several expansions, error line that resembles a trace line" 0 \
+  "report:^+++ conflict: in file.c$" "$work/stderr-lines" "+++ conflict: in file.c"
+PS4='+\D{%H}: '
+check "PS4 with an escape, trace-only stderr" 0 \
+  "report:^+12: echo hi$" "$work/stderr-lines" "+12: echo hi"
+# shellcheck disable=SC2016 # The expansion is for the traced command to do.
+PS4='+$LINENO'
+check "PS4 ending with an expansion, error line that starts with +" 0 \
+  "report:^+ error happened$" "$work/stderr-lines" "+ error happened"
+PS4='a
+b '
+check "PS4 with a newline, error line that contains its second line" 0 \
+  "report:^error: bad b input$" "$work/stderr-lines" "error: bad b input"
+unset PS4
+
 exit "$status"