Bash - 记录脚本中的所有命令和退出码

Question

我有一份长达约2000行的脚本，我想记录下来以备将来调试。目前我的记录方式如下：

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"

这为所有运行的命令提供了非常好的日志记录：

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

我遇到的问题是xtrace似乎是异步的。在较长的脚本中，日志时间落后于实际调用命令的时间，并且退出代码与记录的命令不匹配。

肯定有更好的方法来解决这个问题，但如果我能同步xtrace就会很高兴。

...

简而言之：如何记录脚本中所有命令的时间、命令和退出代码？

...

（第一次发布，请提供反馈）

更新：

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

解决了我所有的同步问题。退出代码和时间戳都很好地工作。我现在唯一的问题是格式：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

我尝试在trap中设置+x，但是set +x被记录了。如果我能找到一种方法从xtrace中省略一行，这个日志就完美了。

- Ptolemy

---

异步的是您的进程替换。任何在 >(...) 中的内容都在一个FIFO的另一侧运行，运行在它自己的进程中。对 BASH_XTRACEFD 的实际写入本身是完全同步的。 - Charles Duffy

无论如何，你不需要它 - 你可以设置一个 PS4 自动插入日期。 - Charles Duffy

顺便说一下，作为一种风格上的注意事项——function funcname() {是POSIX sh和古老的ksh声明约定的混合体（前者只是funcname() {，后者是function funcname {），并且与两者都不兼容。最好的做法是选择其中之一——我强烈建议选择POSIX形式，因为bash的ksh-esque函数声明语法实际上没有在ksh中具有相同的语义（在ksh中，它使得在函数中定义的变量默认为本地变量）。 - Charles Duffy

顺便提一下，你可以将所有其他内容直接通过同一个进程替换来处理。使事情有效异步的是某些内容直接传输到TTY（或者其他预先存在的输出目标），而其他内容则通过进程替换进行传输；如果所有内容都通过相同的管道进行传输，则它又变成同步了。 - Charles Duffy

另外一件事，现代的Bash有printf %(%H:%M:%S)T -1命令，可以在不产生子shell并使用exec系统调用替换该子shell为/usr/bin/date副本（更不用说设置一对FIFO来读取该子shell的输出等操作）的情况下发出当前时间。 - Charles Duffy

Answer 1

异步行为来自进程替换 - 位于 >(...) 中的任何内容都在其自己的子shell中运行，位于FIFO的另一端。由于它是一个单独的进程，因此本质上是不同步的。

这里根本不需要使用 log_with_time，因此也不需要将 BASH_XTRACEFD 重定向到进程替换中。考虑：

# 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: '

接下来：

$ 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

- Charles Duffy

---

在我的评论中尝试格式化失败后，我已更新我的答案以反映我的最新尝试。（顺便说一句，感谢迄今为止所有的帮助） - Ptolemy

除了某些情况下不能正确对齐外，从可读性的角度来看，prior-exit并不是很可接受。 - Ptolemy

“prior-exit” 是你原始代码所做的事情，我只是提供了一个更准确的标签。 - Charles Duffy

Answer 2

根据评论区中Charles Duffy的建议：

进程替换 >(...) 是异步的，可能导致日志写入滞后并与xtrace不同步。 建议使用以下方法：

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

用于同步记录时间和行号。

此外，xtrace 在运行命令之前触发，因此不适合捕获退出代码。请改用：

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

为了记录每个命令的退出代码，因为陷阱会在命令完成时触发。请注意，这不会像xtrace一样报告函数调用中的每个步骤。(这里的措辞可能需要一些帮助)

目前还没有省略xtrace中陷阱的解决方案，但已经足够好了：

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"

产出：

  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

- Ptolemy