title: Bash - Log all commands and exit codes in a script
body: <p>I have a long (~2,000 lines) script that I'm trying to log for future debugging. Right now I have:</p>
  
  <pre><code>function log_with_time()
  {
      while read a; do
          echo `date +'%H:%M:%S.%4N '` " $a" &gt;&gt; $LOGFILE
      done
  }
  
  exec 7&gt; &gt;(log_with_time)
  BASH_XTRACEFD=7
  PS4=' exit($?)ln:$LINENO: '
  set -x
  echo "helloWorld 1"
  </code></pre>
  
  <p>which gives me very nice logging for any and all commands that are run:</p>
  
  <pre><code>15:18:03.6359  exit(0)ln:28: echo 'helloWorld 1'
  </code></pre>
  
  <p>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.</p>
  
  <p>There has to be a better way to do this but I'd be happy if I could just synchronize xtrace.</p>
  
  <p>...</p>
  
  <p><strong>tldr:</strong> How can I generally log the time, command and exit code for all commands in a script?</p>
  
  <p>...</p>
  
  <p>(First time posting, feedback appreciated)</p>
  
  <p><strong>UPDATE:</strong></p>
  
  <pre><code>exec {BASH_XTRACEFD}&gt;&gt;$LOGFILE
  PS4=' time:$(date +%H:%M:%S.%4N) ln:$LINENO: '
  set -x
  fail()
  {
      echo "fail" &gt;&gt; $LOGFILE
      return 1
  }
  trap 'echo exit:$? &gt;&gt; $LOGFILE' DEBUG
  fail
  </code></pre>
  
  <p>solves all of my synchronization issues. exit codes and timestamps are working beautifully. My <strong>only issue now</strong> is one of formatting: the trap itself is getting reported by xtrace.</p>
  
  <pre><code>  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
  </code></pre>
  
  <p>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.</p>