サービスの状態とログの確認
サービスの失敗から再起動までを、PIDと二種類の時計で照合します。
説明
サービス管理の状態、プロセスの存在、機能が使えた記録は、それぞれ確認している内容が違います。過去の障害を調べる際には、PIDの再利用、ログのローテーション、時計の補正にも注意が必要です。
設定不足で終了したサービスと、修正後に再起動したサービスの記録をつなぎます。前世代ログも含めて順序を並べ、壁時計が後戻りした区間と別起動の記録を分け、現在の状態と動作記録を照合します。
1サービスの失敗状態
service-before.txtはsystemctl showの必要項目を保存した教材記録です。
cat service-before.txtサービスの状態と終了値ユニットは読み込まれていますがfailedで、MainPIDは0です。ExecMainCode=1はCLD_EXITED、ExecMainStatus=1は主プロセスの終了コード1に対応します。サービス定義の読込み成功と、実行成功は別です。
2PIDだけで現在のプロセスを結び付けない
現在のプロセス一覧と、失敗時の前世代ログを読みます。ログ列は起動ID、単調時計µs、表示時刻、ユニット、PID、メッセージの順です。
cat processes.csv現在の実行; cat events-previous.csv失敗時の記録失敗時のPID7000はlab-apiでしたが、現在の同じ番号はother-workerです。PIDは再利用されるため、現在の一覧だけで過去ログの主体を置き換えません。開始時刻、ユニット、起動IDも使います。
3前世代と現在のログをつなぐ
同じ起動IDの前世代ログと現在ログを合わせ、単調時計の値で並べます。
cat events-previous.csv events-current.csv保存先をまたいで読む | sort -t, -k2,2n > combined.csv同じ起動内の時系列; cat combined.csvつながった記録起動、設定ファイル不足、終了、再起動、待受開始、時刻変更、要求受付という順です。ローテーション後のファイルだけを読むと、失敗の原因が抜ける場合があります。
4サービスだけに絞る
lab-api.serviceの行だけを取り出します。
awk -F, '$4=="lab-api.service" {print $2,$5,$6}'ユニットで絞り時刻・PID・内容を表示 combined.csv結合済みの記録PID7000の失敗とPID7020の再起動後の処理を、同じユニットの経過として確認できます。設定不足の記録は失敗直前にあり、終了コードだけより具体的な調査手掛かりになります。
5システム時刻が過去へ戻った場合
待受開始と要求受付の表示時刻を取り出し、単調時計の差も計算します。
awk -F, '$6=="listening" {start=$2; wall=$3} $6=="request accepted" {printf "wall=%s -> %s elapsed=%.1f sec\n",wall,$3,($2-start)/1000000}'二種類の時刻で比較 combined.csv時刻補正を含む記録表示時刻は10:02:00から09:57:02へ戻っていますが、経過は1.8秒です。壁時計は時刻補正等で変更されるため、同一起動内の順序や時間差には単調時計の記録が役立ちます。単調時計も通常は起動をまたいで比較できません。
6再起動後の同じ単調時計値
別のOS起動のログにも1000000という単調時計値があることを確認します。
cat events-other-boot.csv別の起動の記録; head -n 1 events-previous.csv元の起動の同じ値boot-Aとboot-Bの1000000は別の基準です。systemd journalでは_BOOT_IDと__MONOTONIC_TIMESTAMPを組み合わせて扱います。教材のboot-A/Bは識別しやすくしたラベルで、実際の起動IDは128ビットの値です。
7現在の稼働状態と利用できた記録
再起動後のサービス状態を読み、要求受付の記録と合わせます。
cat service-after.txt現在のサービス状態; awk -F, '$6=="request accepted" {print $4,$5,$6}' combined.csv同じ実行の動作記録現在はactive/runningでMainPID7020です。さらに同じPIDが要求を受け付けた記録があります。ただし受け付けたことだけで全要求への応答成功までは分かりません。サービス管理上の状態と、利用者が必要とする機能の確認を合わせます。
まとめ
ユニットの読込み、実行状態、終了コード、機能の動作は別々に確認します。
PIDだけで過去と現在を結び付けず、開始時点や起動IDも使います。
同一起動内の経過には単調時計を使い、別起動では基準の違いを考慮します。
操作履歴と解説を振り返れます。
Bash / Linuxの記録
cat service-before.txtId=lab-api.service LoadState=loaded ActiveState=failed SubState=failed MainPID=0 ExecMainCode=1 ExecMainStatus=1 Result=exit-code
cat processes.csv; cat events-previous.csvPID,START,COMMAND 7000,10:01:00,other-worker 7020,10:02:00,lab-api boot-A,1000000,10:00:00,lab-api.service,7000,starting boot-A,1200000,10:00:00,lab-api.service,7000,config missing boot-A,1300000,10:00:00,lab-api.service,7000,exited status=1
cat events-previous.csv events-current.csv | sort -t, -k2,2n > combined.csv; cat combined.csvboot-A,1000000,10:00:00,lab-api.service,7000,starting boot-A,1200000,10:00:00,lab-api.service,7000,config missing boot-A,1300000,10:00:00,lab-api.service,7000,exited status=1 boot-A,121000000,10:02:00,lab-api.service,7020,starting boot-A,121200000,10:02:00,lab-api.service,7020,listening boot-A,122000000,09:57:01,clock.service,90,clock stepped backward boot-A,123000000,09:57:02,lab-api.service,7020,request accepted
awk -F, '$4=="lab-api.service" {print $2,$5,$6}' combined.csv1000000 7000 starting 1200000 7000 config missing 1300000 7000 exited status=1 121000000 7020 starting 121200000 7020 listening 123000000 7020 request accepted
awk -F, '$6=="listening" {start=$2; wall=$3} $6=="request accepted" {printf "wall=%s -> %s elapsed=%.1f sec\n",wall,$3,($2-start)/1000000}' combined.csvwall=10:02:00 -> 09:57:02 elapsed=1.8 sec
cat events-other-boot.csv; head -n 1 events-previous.csvboot-B,1000000,11:00:00,lab-api.service,7020,starting boot-A,1000000,10:00:00,lab-api.service,7000,starting
cat service-after.txt; awk -F, '$6=="request accepted" {print $4,$5,$6}' combined.csvId=lab-api.service LoadState=loaded ActiveState=active SubState=running MainPID=7020 ExecMainCode=0 ExecMainStatus=0 Result=success lab-api.service 7020 request accepted
演習完了