Bash - Log all commands and exit codes in a script

Question

I have a long (~2,000 lines) script that I'm trying to log for future debugging. Right now I have:

function log_with_time()
{
    while read a; do
        echo `date +'%H:%M:%S.%4N '` " $a" >> $LOGFILE
    done
}

exec 7> >(log_with_time)
BASH_XTRACEFD=7
PS4=' exit($?)ln:$LINENO: '
set -x
echo "helloWorld 1"

which gives me very nice logging for any and all commands that are run:

15:18:03.6359  exit(0)ln:28: echo 'helloWorld 1'

The issue that I'm running into is that xtrace seems to be asynchronous. With longer scripts, the log times fall behind the actual time the commands are called, and the exit code doesn't match the logged command.

There has to be a better way to do this but I'd be happy if I could just synchronize xtrace.

...

tldr: How can I generally log the time, command and exit code for all commands in a script?

...

(First time posting, feedback appreciated)

UPDATE:

exec {BASH_XTRACEFD}>>$LOGFILE
PS4=' time:$(date +%H:%M:%S.%4N) ln:$LINENO: '
set -x
fail()
{
    echo "fail" >> $LOGFILE
    return 1
}
trap 'echo exit:$? >> $LOGFILE' DEBUG
fail

solves all of my synchronization issues. exit codes and timestamps are working beautifully. My only issue now is one of formatting: the trap itself is getting reported by xtrace.

  time:18:30:07.6080 ln:27: fail
  time:18:30:07.6089 ln:12: echo fail
fail
  time:18:30:07.6126 ln:13: return 1
   time:18:30:07.6134 ln:28: echo exit:1
exit:1

I've tried setting +x in the trap but then set +x gets logged. If I could find a way to omit one line from xtrace, this log would be perfect.

What's async is your process substitution. Anything in >(...) is on the other side of a FIFO, running in its own process. The actual write to BASH_XTRACEFD is itself fully synchronous. — Charles Duffy
– Charles Duffy, Commented Mar 27, 2018 at 20:37
Anyhow, you don't need it -- you can set a PS4 that inserts the date itself. — Charles Duffy
– Charles Duffy, Commented Mar 27, 2018 at 20:38
...btw, as a stylistic note -- function funcname() { is a mix of POSIX sh and ancient-ksh declaration conventions (the former is just funcname() {, the second is function funcname {), and compatible with neither. It's best practice to pick one or the other -- I strongly suggest the POSIX form, as bash's ksh-esque function declaration syntax doesn't actually have the same semantics that format had in ksh (where it made variables defined in functions local-by-default). — Charles Duffy
– Charles Duffy, Commented Mar 27, 2018 at 20:40
...the other thing you could do, by the way, is just direct everything else through that same process substitution. What makes things effectively async is that some contents go straight to the TTY (or otherwise your preexisting output destination), and others go through the process substitution; if everything goes through the same pipeline, it's synchronous again. — Charles Duffy
– Charles Duffy, Commented Mar 27, 2018 at 20:45
...as another aside, modern bash has printf %(%H:%M:%S)T -1 to emit the current time without all the overhead of forking off a subshell and then using an exec-family syscall to replace that subshell with a copy of /usr/bin/date (not to mention setting up a pair of FIFOs to read that subshell's output, &c). — Charles Duffy
– Charles Duffy, Commented Mar 27, 2018 at 20:47

Charles Duffy · Accepted Answer · 2018-03-27 20:59:14Z

2

The async behavior is coming from the process substitution -- anything in >(...) is running in its own subshell on the other end of a FIFO. Since it's a separate process, it's inherently unsynchronized.

You don't need log_with_time here at all, though, and so you don't need BASH_XTRACEFD redirecting to a process substitution in the first place. Consider:

# aside: $(date ...) has a *huge* amount of performance overhead here. Personally, I'd
#        advise against using it, unless you really need all that precision; $SECONDS will
#        be orders-of-magnitude cheaper.
PS4=' prior-exit:$? time:$(date +%H:%M:%S.%4N) ln:$LINENO: '

...thereafter:

$ true
 prior-exit:0 time:16:01:17.2509 ln:28: true
$ false
 prior-exit:0 time:16:01:18.4242 ln:29: false
$ false
 prior-exit:1 time:16:01:19.2963 ln:30: false
$ true
 prior-exit:1 time:16:01:20.2159 ln:31: true
$ true
 prior-exit:0 time:16:01:20.8650 ln:32: true

edited Mar 27, 2018 at 20:59

answered Mar 27, 2018 at 20:42

Charles Duffy

299k43 gold badges441 silver badges497 bronze badges

Sign up to request clarification or add additional context in comments.

3 Comments

Ptolemy Over a year ago

After failed formatting attempts in my comment, I've updated my answer to reflect my latest attempt. (Thanks by the way for all of your help so far)

Ptolemy Over a year ago

aside from not aligning properly in some instances, prior-exit isn't really acceptable in terms of readability

Charles Duffy Over a year ago

prior-exit is what your original code did too -- I'm just providing a more accurate label.

Ptolemy · Accepted Answer · 2018-03-28 19:16:51Z

Per conversation with Charles Duffy in the comments to whom all credit is given:

Process substitution >(...) is asynchronous, allowing the log writing to fall behind and out of sync with the xtrace. Instead use:

exec {BASH_XTRACEFD}>>$LOGFILE
PS4=' time:$(date +%H:%M:%S.%4N) ln:$LINENO: '

for synchronously logging the time and line.

Furthermore, xtrace is triggered before running the command, making it a bad candidate for capturing exit codes. Instead use:

trap 'echo exit:$? >> $LOGFILE' DEBUG

to log the exit codes of each command since trap triggers on command completion. Note that this won't report on every step in a function call like xtrace will. (could use some help with the phrasing here)

No solution yet for omitting the trap from xtrace, but it's good enough:

LOGFILE="SomeFile.log"

exec {BASH_XTRACEFD}>>$LOGFILE
PS4=' time:$(date +%H:%M:%S.%4N) ln:$LINENO: '
set -x

fail() # test function that returns 1
{
    echo "fail" >> $LOGFILE
    return 1
}
 success() # test function that returns 0
{
    echo "success" >> $LOGFILE
    return 0
}

trap 'echo $? >> $LOGFILE' DEBUG

fail
success

echo "complete"

yields:

  time:14:10:22.2686 ln:21: trap 'echo $? >> $LOGFILE' DEBUG
   time:14:10:22.2693 ln:23: echo 0
0
  time:14:10:22.2736 ln:23: fail
  time:14:10:22.2741 ln:12: echo fail
fail
  time:14:10:22.2775 ln:13: return 1
   time:14:10:22.2782 ln:24: echo 1
1
  time:14:10:22.2830 ln:24: success
  time:14:10:22.2836 ln:17: echo success
success
  time:14:10:22.2873 ln:18: return 0
   time:14:10:22.2881 ln:26: echo 0
0
  time:14:10:22.2912 ln:26: echo complete

Collectives™ on Stack Overflow

Bash - Log all commands and exit codes in a script

2 Answers 2

3 Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

2 Answers 2

3 Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related