ログ&トレース|PS4 / set -x / syslog

運用と安全設計

この記事の狙い

Bash スクリプトの観測可能性を高めるために、ログ(stderr・syslog)とトレース(set -x)を安全・低摩擦で運用する流儀を示します。
PS4 でのトレース行フォーマット、BASH_XTRACEFD による出力分離、logger による syslog 連携、秘密情報のマスキングをコピペ可の形でまとめます。

前提と対象

  • Bash 4+(BASH_XTRACEFD は 4.1+)
  • set -Eeuo pipefail 前提
  • Linux(logger 経由で syslog/journald に出す前提)

TL;DR(最小実装・コピペ可)

#!/usr/bin/env bash
set -Eeuo pipefail

# ==== ログ(stderr) + syslog 併用 ====
: "${APP_NAME:=myapp}"
log(){ printf '%s %s\n' "$(date +'%Y-%m-%dT%H:%M:%S%z')" "$*" >&2; }
log_sys(){ command -v logger >/dev/null && logger -t "$APP_NAME[$$]" -p user.info -- "$*"; }
log_info(){ log "INFO  $*"; log_sys "INFO  $*"; }
log_warn(){ log "WARN  $*"; log_sys "WARN  $*"; }
log_err(){  log "ERROR $*"; log_sys "ERROR $*"; }

# ==== トレース(-x)を専用ファイルへ、PS4 で整形 ====
enable_trace(){
  local file="${1:-/tmp/${APP_NAME}.trace}"
  exec {__xfd}>"$file"
  export BASH_XTRACEFD=$__xfd
  # 軽量版(遅延少):ファイル名:行:関数名 を付与
  export PS4='+ [$$] [${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]}] '
  set -x
}
disable_trace(){
  set +x
  [[ -n ${BASH_XTRACEFD-} ]] && eval "exec ${BASH_XTRACEFD}>&-"
  unset BASH_XTRACEFD
}

# ==== 使い方 ====
log_info "start"
# 秘密の直前は必ずトレースOFFに
enable_trace "/tmp/${APP_NAME}.trace"
# ... 重めの処理 ...
disable_trace
log_info "done"

設計の要点(原則)

  • stdout=結果、stderr=ログを徹底(パイプ下流を汚さない)
  • ログ出力は 1 箇所に集約(関数 log_* を経由)
  • set -x常用しない。必要な範囲でオン/オフし、専用 FD に分離BASH_XTRACEFD
  • PS4PID / 位置情報(ファイル:行:関数) を付け、後解析を容易に
  • 秘密値はトレース禁止区間を設けて回避(set +x)し、ログ側ではマスクする

ログ設計(stderr と syslog)

最小ログ API(stderr 基本・syslog 併用)

: "${APP_NAME:=myapp}" : "${APP_LOG_LEVEL:=info}"  # env で制御

__should(){ # info|warn|error
  local lvl="$1" want="$APP_LOG_LEVEL"
  [[ "$want" == error && "$lvl" != error ]] && return 1
  [[ "$want" == warn  && "$lvl" == info  ]] && return 1
  return 0
}

_log_emit(){ # level msg...
  __should "$1" || return 0
  local ts; ts="$(date +'%Y-%m-%dT%H:%M:%S%z')"
  printf '%s %-5s %s\n' "$ts" "$1" "${*:2}" >&2
  command -v logger >/dev/null && logger -t "$APP_NAME[$$]" -p "user.$1" -- "${*:2}" || :
}
log_info(){ _log_emit info  "$@"; }
log_warn(){ _log_emit warn  "$@"; }
log_err(){  _log_emit err   "$@"; }
  • レベル制御は環境変数で。CI/本番で切替しやすい
  • logger -t TAG -p FACILITY.LEVEL -- "message" で syslog へ(journald 環境でも journalctl -t TAG で追える)

機密値のマスク

mask_secret(){ sed -E 's/(token|password)=\S+/\1=****/g'; }
log_info "$(printf 'calling API token=%s' "$API_TOKEN" | mask_secret)"

トレース設計(set -x / PS4)

BASH_XTRACEFD による出力分離

set -x の既定出力は stderr。アプリのログと混ざると可読性が落ちます。
BASH_XTRACEFD にファイル記述子を指定すると、トレースだけ別ファイルに出せます。

exec {XFD}>"/tmp/my.trace"
export BASH_XTRACEFD=$XFD
set -x
# ... トレースしたい区間 ...
set +x
exec {XFD}>&-

PS4 で位置情報を付ける

export PS4='+ [$$] [${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]}] '
  • $$(PID)、${BASH_SOURCE##*/}(ファイル名)、${LINENO}${FUNCNAME[0]}
  • 日時も付けたい場合は次(ただし遅くなる。大量トレースには不向き)
export PS4='+ [$(date +%H:%M:%S)] [$$] [${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]}] '

部分的にオン/オフ(秘密の前後で切替)

set +x     # ここから秘密処理は追跡しない
# use $API_TOKEN ...
set -x

パイプラインのトレース

set -o pipefail と併用し、失敗点をトレースで迅速特定。

set -o pipefail
set -x
grep -E '^[0-9]+$' file | awk '{s+=$1} END{print s}'
set +x

運用レシピ

1) すべての標準出力をログとファイルに二重化

exec {LOGFD}> >(tee -a "/var/log/${APP_NAME}.log" >&2)
log(){ printf '%s %s\n' "$(date +'%F %T')" "$*" >&$LOGFD; }

2) 関数単位でトレース

trace_fn(){ set -x; "$@"; local st=$?; set +x; return "$st"; }
trace_fn deploy_to prod

3) エラー時だけトレースダンプ

trap 'st=$?; set +x; [[ -f $TRACE ]] && log_err "see $TRACE"; exit "$st"' EXIT
TRACE="/tmp/${APP_NAME}.trace"
enable_trace "$TRACE"   # 成功なら最後に消す運用でも可

失敗しやすい点(アンチパターン)

  • set -x を常時ON:大量出力で機密漏洩・性能劣化
    → 区間限定、BASH_XTRACEFD で分離
  • トレースを stderr に流す:アプリの stderr ログと混線
    BASH_XTRACEFD を使う
  • ログを stdout に出す:下流のデータ処理が壊れる
    → ログは stderr、結果は stdout
  • 秘密値をそのままログ/トレース
    → 秘密の直前で set +x、ログはマスキング

“コピペ可”テストブロック(最小)

#!/usr/bin/env bash
set -Eeuo pipefail
TMP="$(mktemp -d)"; trap 'rm -rf "$TMP"' EXIT

APP_NAME=testapp
# 1) stderr にレベル付きで出るか
out="$("$BASH" -lc '
  set -Eeuo pipefail
  APP_NAME=testapp
  log(){ printf "%s %-5s %s\n" "2025-01-01T00:00:00+0000" "$1" "$2" >&2; }
  log info "hello"
' 2>&1 >/dev/null)"
grep -q 'INFO  hello' <<<"$out" || { echo "log-stderr NG"; exit 1; }

# 2) set -x を別ファイルへ分離できるか
trace="$TMP/x.trace"
"$BASH" -lc "
  exec {XFD}>\"$trace\"; export BASH_XTRACEFD=\$XFD
  export PS4='+ [\$\$] [\${BASH_SOURCE##*/}:\${LINENO}:\${FUNCNAME[0]}] '
  set -x; echo ok >/dev/null; set +x; exec {XFD}>&-
"
grep -q '\[.*\] \[.*sh:' "$trace" || { echo "xtrace NG"; exit 1; }

echo "PASS"

セキュリティと安全設計

  • 秘密(トークン・パスワード・クッキー)はトレース禁止区間を徹底し、ログではマスク
  • syslog 送信に失敗しても本処理を止めないlogger || :
  • ログファイルには適切な権限(例: umask 077、ローテーション設定)

パフォーマンスの勘所(短く)

  • set -x1 行ごとに I/Oが発生。広範囲 ON は避ける
  • PS4$(date ...) を入れると毎行サブプロセスで重い。PID/位置情報だけの軽量版を常用
  • syslog 送信を大量に行う場合はバッチ化またはレベル制御で間引く

参考リンク

Bash玄

はじめまして!Bash玄です。

エンジニアとしてシステム運用に携わる中で、手作業の多さに限界を感じ、Bashスクリプトを活用して業務を効率化したのがきっかけで、この道に入りました。「手作業は負け」「スクリプトはシンプルに」をモットーに、誰でも実践できるBashスクリプトの書き方を発信しています。

このサイトでは、Bashの基礎から実践的なスクリプト作成まで、初心者でもわかりやすく解説しています。少しでも「Bashって便利だな」と思ってもらえたら嬉しいです!

# 好きなこと
- シンプルなコードを書くこと
- コマンドラインを快適にカスタマイズすること
- 自動化で時間を生み出すこと

# このサイトを読んでほしい人
- Bashに興味があるけど、何から始めればいいかわからない人
- 定型業務を自動化したい人
- 効率よくターミナルを使いこなしたい人

Bashの世界に一歩踏み出して、一緒に「Bash道」を極めていきましょう!

Bash玄をフォローする