From 5ef28ebe1ee3dd34095319b7f630a04f4f494f9c Mon Sep 17 00:00:00 2001 From: Koichi Murase Date: Tue, 5 Jul 2022 17:37:23 +0900 Subject: [PATCH] history: work around broken timestamps in HISTFILE --- docs/ChangeLog.md | 1 + memo/D1831.bashrc | 13 ++++ memo/D1831.history | 10 +++ note.txt | 111 ++++++++++++++++++++++++++++-- src/history.sh | 165 ++++++++++++++++++++++++++++++++++++--------- 5 files changed, 262 insertions(+), 38 deletions(-) create mode 100644 memo/D1831.bashrc create mode 100644 memo/D1831.history diff --git a/docs/ChangeLog.md b/docs/ChangeLog.md index 595bec87..3e2014ef 100644 --- a/docs/ChangeLog.md +++ b/docs/ChangeLog.md @@ -359,6 +359,7 @@ - util: work around old `vte` not supporting `DECSCUSR` yet setting `TERM=xterm` (reported by dongxi8) `#D1785` 70277d0 - progcomp: work around the cobra V2 description hack (reported by SuperSandro2000) `#D1803` 71d0736 - complete: work around blocking `_scp_remote_files` and `_dnf` (reported by iantra) `#D1807` a4a779e 46f5c13 +- history: work around broken timestamps in `HISTFILE` `#D1831` XXXXXXX ## Internal changes and fixes diff --git a/memo/D1831.bashrc b/memo/D1831.bashrc new file mode 100644 index 00000000..6e76ba6f --- /dev/null +++ b/memo/D1831.bashrc @@ -0,0 +1,13 @@ +# bashrc -*- mode: sh; mode: sh-bash -*- + +if [[ ! -f out/ble.sh ]]; then + echo 'memo/D1831.bashrc: out/ble.sh not found.' >&2 + return 2 +fi + +cp -f memo/D1831.history{,.tmp} +HISTFILE=$PWD/memo/D1831.history.tmp +HISTFILESIZE= +HISTSIZE= +HISTTIMEFORMAT=%s +source out/ble.sh --norc -o vbell_duration=5000 diff --git a/memo/D1831.history b/memo/D1831.history new file mode 100644 index 00000000..ce4a48b4 --- /dev/null +++ b/memo/D1831.history @@ -0,0 +1,10 @@ +#1656625044 +echo 1 +#1656625044 +echo 2 +#1647948811646449694 +echo a +#1656625044 +echo b +#1656625044 +echo c diff --git a/note.txt b/note.txt index 0e276906..49b6ecf9 100644 --- a/note.txt +++ b/note.txt @@ -1823,13 +1823,17 @@ bash_tips 2022-07-04 - * ext: trueline と組み合わせた時に問題が起こるとのこと。 - https://github.com/lecramyajiv/Emptydeeds/commit/b57e8354cc350d71c655d93c32112427ec8addda#diff-0a1c1083789380c5f4b4aaebd19b6a4b2431ae808f8b456cf865825cfb93b9dfR2527 + * [保留] debug_xtrace を bash-4.0 以下でも対応する? - * bash: history timestamp に問題がある時に history の初期化が正しくない + debug_xtrace が bash-3.2 で動いていない。と思ったらそもそも BASH_XTRACEFD + は bash-4.1 以降の機能だったのだ。bash-4.0 以下では 2 を redirect する事に + よって実現する? と思ったが 2 は ble.sh が出力するのに使っている気がする。特 + に ble/util/buffer.flush で使っている。更に他にも様々なエラーメッセージが 2 + に出力されるのではないか。という事を考えると 2 を xtrace に使うのは余り良い + ことではない様な気がする。取り敢えず保留という事にする。 - bash がエラーメッセージを出力する (bash-5.0+) または segfault する - (bash-4.4-)。現状ではエラーメッセージがそのまま履歴に混入してしまっている。 + * ext: trueline と組み合わせた時に問題が起こるとのこと。 + https://github.com/lecramyajiv/Emptydeeds/commit/b57e8354cc350d71c655d93c32112427ec8addda#diff-0a1c1083789380c5f4b4aaebd19b6a4b2431ae808f8b456cf865825cfb93b9dfR2527 2022-06-28 @@ -6451,6 +6455,103 @@ bash_tips 2022-07-05 + * bash: history timestamp に問題がある時に history の初期化が正しくない [#D1831] + https://github.com/akinomyoga/ble.sh/issues/202 + + bash がエラーメッセージを出力する (bash-5.0+) または segfault する + (bash-4.4-)。現状ではエラーメッセージがそのまま履歴に混入してしまっている。 + うーん。stderr も読み取ってしまっているのかと思ったが実際に試してみるとエラー + メッセージが stdout に出力されている。 + + % これは後で bash に提出する。 + % + % * reject: bug-bash: HISTTIMEFORMAT=%s history でエラーメッセージが stdout + % に混入するエラーメッセージは stderr に出力するべきなのではないか。 + % + % と思ったがこの文字列はエラーメッセージとしてではなく履歴時刻の文字列の代 + % わりに埋め込まれているという事が判明した。という事はやはり history の出力 + % の中にメッセージを埋め込むべきという事なのかもしれない。 + + 取り敢えず問題のエラーメッセージは正規表現によるパターンで除去する事にする。 + + * fixed: 更に履歴を書き込む時にも問題になっている。これも修正した。 + + * done: 履歴読み込み時に invalid timestamp を検出したらそれを vbell で報告 + する様にする。 + + これで bash-5.0+ 以降でエラーメッセージが履歴に紛れ込むのは修正した。一方で + bash-4.4 以下で segfault してしまうのに対する対策は難しいのではないか。一応 + 終了ステータスを確認する事で segfault した事は検出できるが、もし検出したと + してどの様に対処するのが良いか。例えば、HISTTIMEFORMAT なしで改めて履歴を読 + み直す事にする? 履歴行の境をどの様に判定するべきだろうか。或いは、エラーを + 検出した時に vbell に表示してしまって、history の状態は壊れた状態でも仕方が + ないという事にする? それが良い気がする。 + + * 実際にエラーになった時に問題の行を指摘したい。 + + どの様な形式の時にエラーになるのか調べようとしたがよく分からない。先ず、 + そもそも数字でない場合には timestamp 行として認識されない。数字の後にごみ + が入っていてもそれらは単に無視される。得に巨大な数が指定された時に於いて + 問題が生じる様である。問題が起こる最小の整数を探索すると + 67768036191644399 であった。これは16進数で見ても特に特別な数ではない + (0xf0c2ab7c542aef)。検索してみたらどうもやはり時刻関係で特別な数字の様で + はある。 + + > https://mevius.5ch.net/test/read.cgi/unix/1590454119/ + > + > 115名無しさん＠お腹いっぱい。2020/06/01(月) 17:52:40.57 + > macos での限界 + > $ date -r 67768036191644399 + > 2147485547年 12月31日 水曜日 23時59分59秒 JST + > $ date -r 67768036191644400 + > date: localtime: Value too large to be stored in data type + + 実際手許の date で試してみても同様である。 + + $ date --date=@67768036191644399 + $ date --date=@67768036191644400 + + これは一体何が決めているのだろうか。と思ったらどうも 2147485547 年という + のは1900 + 0x7FFFFFFF らしい。つまり localtime で時刻構造体に変換する時に + 代入できないという状態になるという事だ。 + + https://www.wdic.org/w/TECH/21%E5%84%844748%E4%B8%875548%E5%B9%B4%E5%95%8F%E9%A1%8C + + 67768036191644399 で検索して日本語のページが幾つかしか出てこないのは + upper bound が TZ に依存するからである。 + + さて、TZ に依存するのだとすればこの数値を threshold に選ぶ事はできない。 + それに正規表現で判定できなければ問題の行の検出に於いて不都合である。更に、 + この上限の値は time.h の実装にも依存するのではないだろうか。 + + 更に bash-3.2 以下では無限ループになる。関係ない無限ループかもしれないと思っ + たが実際に履歴の timestamp に問題がある時にのみ無限ループになる。何処で無限 + ループになっているか確認する。 + + →実際に ble.sh なしで試して見た所、単に history を実行しただけで無限ループ + になって固まってしまう。これに対する対策は難しい気がする。。builtin history + を呼び出すあらゆる操作で問題が起こる可能性があるという事になるのであるから。 + + * done: bash-3.2: history の読み出しに使っている部分だけ conditoinal-sync で呼び出す。 + + conditional-sync で timeout を設定してみたがやはり 100% になってしまう。 + という事は関係ない別の history -n 等でも全て無限ループになっているという + 事か。と思ったが手許で実行している限りは特に無限ループにはならない。 + + →と思ったら分かった。.get-min で history | head -1 を呼び出している。こ + の history で無限ループになっている。 + + ? ok: 実際に conditional-sync で呼び出してみたところ timeout よりも断然早く + 中断する。何かと思ったら conditional-sync 経由で呼び出した時には無限ルー + プにならずに 300ms 程度でちゃんと終了する様である。何故だろうか。 + + もしかすると conditional-sync を使わなくても subshell ならばちゃんと終了 + する可能性? と思ったが、元より問題になる箇所では subshell を使っていた。 + なので、bg で動かした時にだけ無限ループにならないという事だろうか。だとし + たらやはり conditoinal-sync 経由で呼び出して置くのが楽である。 + + 取り敢えず bash-3.2 でも固まらなくなった。OK + * edit: プロンプト評価時に LINENO は一時的に現在の行番号に設定するべき [#D1830] →これは DEBUG を PREEXEC に使っている設定でも重要になる。 diff --git a/src/history.sh b/src/history.sh index 5be8abc4..fe03ca12 100644 --- a/src/history.sh +++ b/src/history.sh @@ -42,10 +42,91 @@ function ble/builtin/history/is-empty { # わりに history 1 の出力を確認する実装に変更する事にした。 ! ble/util/assign.has-output 'history 1' } -function ble/builtin/history/.get-min { - ble/util/assign-words min 'builtin history | head -1' - min=${min/'*'} -} + +## @fn ble/builtin/history/.check-timestamp-sigsegv status +## #D1831: Bash 4.4 以下では履歴ファイル (HISTFILE) に不正な timestamp +## (0x7FFFFFFF+1900年より後を指す巨大な unix time) が含まれていると segfault +## する。実際に SIGSEGV で終了した時に履歴ファイルを確認して問題の行番号を出 +## 力する。 +if ((_ble_bash>=50000)); then + function ble/builtin/history/.check-timestamp-sigsegv { :; } +else + function ble/builtin/history/.check-timestamp-sigsegv { + local stat=$1 + ((stat)) || return 0 + + local ret=11 + ble/builtin/trap/.get-sig-index SIGSEGV + ((stat==128+ret)) || return 0 + + local msg="bash: SIGSEGV: suspicious timestamp in HISTFILE" + + local histfile=${HISTFILE:-$HOME/.bash_history} + if [[ -s $histfile ]]; then + msg="$msg='${HISTFILE:-~/.bash_history}'" + local rex_broken_timestamp='^#[0-9]\{12\}' + ble/util/assign line 'ble/bin/grep -an "$rex_broken_timestamp" "$histfile"' + ble/string#split line : "$line" + [[ $line =~ ^[0-9]+$ ]] && msg="$msg (line $line)" + fi + + if [[ ${_ble_edit_io_fname2-} ]]; then + ble/util/print $'\n'"$msg" >> "$_ble_edit_io_fname2" + else + ble/util/print "$msg" >&2 + fi + } +fi + +## @fn ble/builtin/history/.dump args... +## #D1831: timestamp に不正な値が含まれていた時のメッセージを検出する為、一時 +## 的に LC_MESSAGES を設定して builtin history を呼び出します。更にこの状況で、 +## bash-3.2 以下で無限ループになる問題を回避する為に、bash-3.2 以下では +## conditional-sync 経由で呼び出します。 +if ((_ble_bash<40000)); then + # Note (#D1831): bash-3.2 以下では不正な timestamp が history に含まれている + # と無限ループになるので timeout=3000 で強制終了する。然し、実際に確認して + # みると、conditional-sync 経由で呼び出した時には無限ループにならずに + # timeout する前に SIGSEGV になる様である + function ble/builtin/history/.dump.proc { + local LC_ALL= LC_MESSAGES=C 2>/dev/null + builtin history "${args[@]}" + ble/util/unlocal LC_ALL LC_MESSAGES 2>/dev/null + } + function ble/builtin/history/.dump { + local -a args; args=("$@") + ble/util/conditional-sync \ + ble/builtin/history/.dump.proc \ + true 100 progressive-weight:timeout=3000:SIGKILL + local ext=$? + if ((ext==142)); then + printf 'ble.sh: timeout: builtin history %s' "$*" >/dev/tty + local ret=11 + ble/builtin/trap/.get-sig-index SIGSEGV + ((ext=128+ret)) + fi + ble/builtin/history/.check-timestamp-sigsegv "$ext" + return "$ext" + } +else + function ble/builtin/history/.dump { + local LC_ALL= LC_MESSAGES=C 2>/dev/null + builtin history "$@" + ble/util/unlocal LC_ALL LC_MESSAGES 2>/dev/null + } +fi + +if ((_ble_bash<40000)); then + function ble/builtin/history/.get-min { + ble/util/assign-words min 'ble/builtin/history/.dump | head -1' + min=${min/'*'} + } +else + function ble/builtin/history/.get-min { + ble/util/assign-words min 'builtin history | head -1' + min=${min/'*'} + } +fi function ble/builtin/history/.get-max { ble/util/assign-words max 'builtin history 1' max=${max/'*'} @@ -123,11 +204,12 @@ if ((_ble_bash>=40000)); then local IFS=$_ble_term_IFS __ble_tmp; __ble_tmp=('\'{2,3}{0..7}{0..7}) builtin eval "local _ble_util_writearray_rawbytes=\$'${__ble_tmp[*]}'" fi - local -x __ble_rawbytes=$_ble_util_writearray_rawbytes + local -x __ble_rawbytes=$_ble_util_writearray_rawbytes # used by _ble_bin_awk_libES + local -x fname_stderr=${_ble_edit_io_fname2:-} local apos=\' # 482ms for 37002 entries - builtin history $arg_count | ble/bin/awk -v apos="$apos" -v arg_offset="$arg_offset" -v _ble_bash="$_ble_bash" ' + ble/builtin/history/.dump ${arg_count:+"$arg_count"} | ble/bin/awk -v apos="$apos" -v arg_offset="$arg_offset" -v _ble_bash="$_ble_bash" ' '"$_ble_bin_awk_libES"' BEGIN { @@ -139,6 +221,9 @@ if ((_ble_bash>=40000)); then if (!opt_null && !opt_source) printf("") > INDEX_FILE; # create file + fname_stderr = ENVIRON["fname_stderr"]; + fname_stderr_count = 0; + n = 0; hindex = arg_offset; } @@ -147,22 +232,22 @@ if ((_ble_bash>=40000)); then if (n < 1) return; if (opt_null) { - if (t ~ /^eval -- \$'$apos'([^'$apos'\\]|\\.)*'$apos'$/) + if (t ~ /^eval -- \$'"$apos"'([^'"$apos"'\\]|\\.)*'"$apos"'$/) t = es_unescape(substr(t, 11, length(t) - 11)); printf("%s%c", t, 0); } else if (opt_source) { - if (t ~ /^eval -- \$'$apos'([^'$apos'\\]|\\.)*'$apos'$/) + if (t ~ /^eval -- \$'"$apos"'([^'"$apos"'\\]|\\.)*'"$apos"'$/) t = es_unescape(substr(t, 11, length(t) - 11)); - gsub(/'$apos'/, "'$apos'\\'$apos$apos'", t); + gsub(/'"$apos"'/, "'"$apos"'\\'"$apos$apos"'", t); print "_ble_history[" hindex "]=" apos t apos; } else { if (n == 1) { - if (t ~ /^eval -- \$'$apos'([^'$apos'\\]|\\.)*'$apos'$/) + if (t ~ /^eval -- \$'"$apos"'([^'"$apos"'\\]|\\.)*'"$apos"'$/) print hindex > INDEX_FILE; } else { - gsub(/['$apos'\\]/, "\\\\&", t); + gsub(/['"$apos"'\\]/, "\\\\&", t); gsub(/\n/, "\\n", t); print hindex > INDEX_FILE; t = "eval -- $" apos t apos; @@ -175,14 +260,28 @@ if ((_ble_bash>=40000)); then t = ""; } + function check_invalid_timestamp(line) { + if (line ~ /^ *[0-9]+\*? +.+: invalid timestamp/ && fname_stderr != "") { + sub(/^ *0*/, "bash: history !", line); + sub(/: invalid timestamp.*$/, ": invalid timestamp", line); + if (fname_stderr_count++ == 0) + print "" >> fname_stderr; + print line >> fname_stderr; + } + } + { - if (sub(/^ *[0-9]+\*? +(__ble_ext__|\?\?)/, "", $0)) + # Note: In Bash 5.0+, the error message of "invalid timestamp" + # goes into "stdout" instead of "stderr". + check_invalid_timestamp($0); + if (sub(/^ *[0-9]+\*? +(__ble_ext__|\?\?|.+: invalid timestamp)/, "", $0)) flush_line(); t = ++n == 1 ? $0 : t "\n" $0; } END { flush_line(); } ' >| "$history_tmpfile.part" + ble/builtin/history/.check-timestamp-sigsegv "${PIPESTATUS[0]}" ble/bin/mv -f "$history_tmpfile.part" "$history_tmpfile" } @@ -335,35 +434,35 @@ else # 285ms for 16437 entries local apos="'" - builtin history $arg_count | ble/bin/awk -v apos="'" ' + ble/builtin/history/.dump ${arg_count:+"$arg_count"} | ble/bin/awk -v apos="'" ' BEGIN { n = ""; } #% # 何故かタイムスタンプがコマンドとして読み込まれてしまう /^ *[0-9]+\*? +(__ble_ext__|\?\?)#[0-9]/ { next; } #% # ※rcfile として読み込むと HISTTIMEFORMAT が ?? に化ける。 - /^ *[0-9]+\*? +(__ble_ext__|\?\?)/ { + /^ *[0-9]+\*? +(__ble_ext__|\?\?|.+: invalid timestamp)/ { if (n != "") { n = ""; print " " apos t apos; } n = $1; t = ""; - sub(/^ *[0-9]+\*? +(__ble_ext__|\?\?)/, "", $0); + sub(/^ *[0-9]+\*? +(__ble_ext__|\?\?|.+: invalid timestamp)/, "", $0); } { line = $0; - if (line ~ /^eval -- \$'$apos'([^'$apos'\\]|\\.)*'$apos'$/) + if (line ~ /^eval -- \$'"$apos"'([^'"$apos"'\\]|\\.)*'"$apos"'$/) line = apos substr(line, 9) apos; else gsub(apos, apos "\\" apos apos, line); - # 対策 #D1239: bash-3.2 以前では ^A, ^? が ^A^A, ^A^? に化ける - gsub(/\001/, "'$apos'${_ble_term_SOH}'$apos'", line); - gsub(/\177/, "'$apos'${_ble_term_DEL}'$apos'", line); +#% # 対策 #D1239: bash-3.2 以前では ^A, ^? が ^A^A, ^A^? に化ける + gsub(/\001/, "'"$apos"'${_ble_term_SOH}'"$apos"'", line); + gsub(/\177/, "'"$apos"'${_ble_term_DEL}'"$apos"'", line); - # 対策 #D1270: MSYS2 で ^M を代入すると消える - gsub(/\015/, "'$apos'${_ble_term_CR}'$apos'", line); +#% # 対策 #D1270: MSYS2 で ^M を代入すると消える + gsub(/\015/, "'"$apos"'${_ble_term_CR}'"$apos"'", line); t = t != "" ? t "\n" line : line; } @@ -503,7 +602,7 @@ if ((_ble_bash>=30100)); then } else { for (i = 0; i < command_count; i++) { c = command_text[i]; - gsub(/'$apos'/, Q, c); + gsub(/'"$apos"'/, Q, c); print "builtin history -s -- " q c q > filename_source; } } @@ -521,14 +620,14 @@ if ((_ble_bash>=30100)); then } function is_escaped_command(cmd) { - return cmd ~ /^eval -- \$'$apos'([^'$apos'\\]|\\[\\'$apos'nt])*'$apos'$/; + return cmd ~ /^eval -- \$'"$apos"'([^'"$apos"'\\]|\\[\\'"$apos"'nt])*'"$apos"'$/; } function unescape_command(cmd) { cmd = substr(cmd, 11, length(cmd) - 11); gsub(/\\\\/, "\\q", cmd); gsub(/\\n/, "\n", cmd); gsub(/\\t/, "\t", cmd); - gsub(/\\'$apos'/, "'$apos'", cmd); + gsub(/\\'"$apos"'/, "'"$apos"'", cmd); gsub(/\\q/, "\\", cmd); return cmd; } @@ -547,7 +646,7 @@ if ((_ble_bash>=30100)); then if (_ble_bash >= 40040) { register_command(cmd); } else { - gsub(/'$apos'/, Q, cmd); + gsub(/'"$apos"'/, Q, cmd); write_complex(q cmd q); } } @@ -588,7 +687,7 @@ if ((_ble_bash>=30100)); then { if (is_resolve) { save_timestamp($0); - if (sub(/^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?)/, "", $0)) + if (sub(/^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?|.+: invalid timestamp)/, "", $0)) flush_entry(); entry_text = ++entry_nline == 1 ? $0 : entry_text "\n" $0; } else { @@ -623,7 +722,7 @@ if ((_ble_bash>=30100)); then local HISTTIMEFORMAT=__ble_time_%s__ local -x TMPBASE=$_ble_base_run/$$.history.mlfix local multiline_count=0 modification_count=0 - builtin eval -- "$(builtin history | ble/history:bash/resolve-multiline/.awk resolve 2>/dev/null)" + builtin eval -- "$(ble/builtin/history/.dump | ble/history:bash/resolve-multiline/.awk resolve 2>/dev/null)" if ((modification_count)); then ble/bin/mv -f "$TMPBASE.part" "$TMPBASE.sh" else @@ -968,10 +1067,10 @@ function ble/builtin/history/.write { if ((delta>0)); then local HISTTIMEFORMAT=__ble_time_%s__ if [[ :$opts: == *:append:* ]]; then - builtin history "$delta" >> "$histapp" + ble/builtin/history/.dump "$delta" >> "$histapp" ((_ble_builtin_history_histapp_count+=delta)) else - builtin history "$delta" >| "$histapp" + ble/builtin/history/.dump "$delta" >| "$histapp" _ble_builtin_history_histapp_count=$delta fi fi @@ -995,10 +1094,10 @@ function ble/builtin/history/.write { if (!mode) return; mode = 0; if (text ~ /\n/) { - gsub(/['$apos'\\]/, "\\\\&", text); + gsub(/['"$apos"'\\]/, "\\\\&", text); gsub(/\n/, "\\n", text); gsub(/\t/, "\\t", text); - text = "eval -- $'$apos'" text "'$apos'" + text = "eval -- $'"$apos"'" text "'"$apos"'" } if (timestamp != "") @@ -1013,7 +1112,7 @@ function ble/builtin/history/.write { return "#" line; } - /^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?)?/ { + /^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?|.+: invalid timestamp)?/ { flush_line(); mode = 1; @@ -1021,7 +1120,7 @@ function ble/builtin/history/.write { if (flag_timestamp) timestamp = extract_timestamp($0); - sub(/^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?)?/, "", $0); + sub(/^ *[0-9]+\*? +(__ble_time_[0-9]+__|\?\?|.+: invalid timestamp)?/, "", $0); } { text = text != "" ? text "\n" $0 : $0; } END { flush_line(); }