bpftraceで深夜にプロセスをkillした犯人を特定する

2023/05/11

インフラのいわほり（egmc）です。

eBPFを利用したプロダクトとしてはCiliumなどがcloud nativeな文脈として盛り上がっていますが、一方でBCC Toolsやbpftaceは、システム内部のかゆいところに手が届くソリューションとして身近な課題解決にカジュアルに役立つツールとして提供されています。

これらのツールは実際に便利ではあるものの現実世界での事例をそれほど見かけないというのもあり、「こんな感じで役に立った」という事例をカジュアルに紹介していくのもコミュニティにとって有用ではないか、ということで今回はOSのバージョンアップに関連して発生した問題の調査にbpftraceが役立ったというお話をご紹介したいと思います。

環境

  • Ubuntu 20.04.6 LTS
  • bpftrace v0.9.4

発生した事象

GREEのクラウド環境で利用しているシステムのアラートの配送を行うワーカー（Yusura）はRubyで実装されており、Shoryukenを利用しているのですが、こちらのワーカーの動作環境をUbuntu 18.04 Bionicから20.04 Focalに移行したところ、深夜0時に全ワーカープロセスがダウンするという事象が発生しました。

yusura-down-image

幸いこちらの環境はキューの滞留具合に応じてオートスケールを行う設定となっており、新規に起動したインスタンスが処理を継続したため、アラートは鳴ったものの大きな影響はなくサービス自体は継続されていました。

一次対応としてはBionicへの切り戻しを実施し、staging相当の検証環境で改めて原因調査を行うこととしました。

ログの調査

ワーカーのログ、syslogなどを確認したところ、事象発生前後でlogrotateが行われていました。
当該ワーカーもローテーション処理を行っており、かつログファイルを掴み直すためにpostrotateで再起動処理を行っているので状況としてはこの処理があやしそうです。

ワーカーは2015年頃から使われており実装もやや古く、デーモン管理は素朴なstart/stop用の以下のようなシェルスクリプトで実装されていました。

  • startスクリプト
    • EC2のタグ情報などをもとに実行環境を判定して環境変数を設定する
    • S3から追加の設定ファイルをダウンロードして配置する
    • Shoryukenの-dオプションによりプロセスをデーモナイズして起動、pidファイルを生成する
  • stopスクリプト
    • pidファイルをチェックし、対象プロセスに対してSIGUSR1（Shoryukenでのsoft stop相当）を送る
      • 一定時間経過しプロセスがまだ起動している場合はSIGTERMを送る
    • pidファイルを削除する

本来ワーカーは再起動などを期待してデーモン管理をsystemdやsupervisordなどに任せるのが良いのですが、既存の前処理がやや面倒なのとワーカーに問題があって突然死する、みたいなケースもあまりなかったのでそのまま使われて続けてきたスクリプトですね。

ワーカーのログ上を確認するとpostrotateでこのstop/startスクリプトが実行され、正常にSIGUSR1を受け取ってのプロセス停止、起動していることが確認できましたが、起動した直後にSIGTERMを受けてプロセスが停止されていました。

しかしlogrotateを -fオプションつきで手動で実行してみてもpostrotateによる再起動は正常に実施され、SIGTERMはどこからも飛んでこず、ワーカーは動作しています。

stopスクリプトでもSIGTERMは扱っていますが、ログに記録されているSIGTERMは起動後に受け取っているので、やはりどこか別のプロセスから送出されたものと考えられます。

logrotateまわりの処理を疑いつつも確証を得るため、SIGTERMの送出元を特定することにしました。

bpftraceによる調査

Shoryukenではシグナルをtrapで処理していますが、送出元に関する情報をここで取得することはできません。

そこでbpftraceでカーネルのsyscallに設定されたtracepointにフックしてシグナルの情報を取得します。

これを行ってくれるそのものずばりなbpftraceツール（killsnoop.bt）が既に存在するのでこれをそのまま使います（BCC Toolsの一部として同じくkillsnoopが提供されていますが、こちらはfocalのパッケージで提供されているBCCのバージョンが古く残念ながらそのままでは動きません）。

今回は時間が深夜0時直後ということがわかっているので、

のようなスクリプトをcronで23:59から一定時間実行してログに記録するようにしました。

結果以下のようなログ群が取得できました。

killsnoop.btのログ

logrotate.serviceのログ

ワーカー（Yusura）のログ

最初のkillコマンドによるSIGUSR1がlogrotateのpostrotateスクリプトから実行されたもので、その後起動したワーカーのプロセス（466335）に対してsystemdからSIGTERMが送出されてシャットダウンしていることがわかりました。

おや、使ってないはずのsystemdですね・・。

ということでsystemdのサービスまわりを改めて確認したところ、logrotateサービスがbionicではcronで動作していたものがfocalではsystemd.timerに切り替わっており、そのために今回の事象に繋がった、ということがわかりました。

原因はlogrotateがsystemdで動作することによる挙動の変化

focalのlogrotateサービスはType=oneshotのsystemd.serviceとして動作しています。

このサービスがsystemd.timerのOnCalendar=dailyという定義によってcron.daily相当のルールとして起動するようになっています。

Type=oneshotのサービスは実行が完了するとKillModeの指定に従って実行中のプロセスにkillシグナルを送出します。

logrotate.serviceユニットには　KillModeの指定はないためデフォルトのcontrol-group（unitのcgroupに所属するすべてのプロセスを対象とするモード）で動作しています。

これにより以下のような流れで今回の事象が発生していました

  • logrotateサービスがtimerにより起動される
  • logrotateのpostrotateスクリプトによりワーカー（Yusura）が再起動される
    • ワーカーはこの時点でRubyのProcess.daemonによりデーモナイズが行われ、logrotateのプロセスグループから分離される
  • logrotate処理が終了し、unitのcgroupに所属するプロセスに対してSIGTERMが送出されることによりワーカーが停止する
    • ワーカーはプロセスグループからは分離できているもののcgroupはそのままなので、systemdから停止シグナルを送る対象として認識される

bionicまでではlogrotateはcronから起動されるため、logrotate実行後のワーカープロセスもcgroupとしてはcron.serviceユニットのものに属しており、cronが生き続けている限り起動し続けることが出来ていました。

しかしfocalではlogrotate自身がsystemd.timerで起動させられるようになったため上記のような流れでlogrotate終了後に、ワーカーのプロセスにもSIGTERMが送出され、結果すべてのワーカーがlogrotateの時間で停止する、という事象が発生することとなりました。

原因を踏まえての対応

原因がわかりましたので、長く使われてきたワーカーのstop/startスクリプトを廃止し、systemdでデーモン管理する方式に変更することで対応しました。

起動スクリプトをそのまま流用して、systemd.serviceをtype=forkingで定義するのがもっとも手数の少ない対応になりそうでしたが、せっかく手を入れる機会でもあるので今回は以下の対応を行うことでtype=simpleのサービスとして既存のスクリプトと同様の処理を行うことができました。

  • 環境変数の設定 ->  デプロイ処理の過程でenvファイルを動的に生成しEnvironmentFileで指定
  • 追加の設定ファイルダウンロード -> ExecStartPreで実施
  • Stop時にSIGUSR1を送り一定時間経過後に生きていたらkillする -> KillSignal=SIGUSR1としTimeoutStopSecを指定

現代のsystemd.seriveはunitファイル一つで細かい挙動を指定できるので便利ですね。

この対応によりワーカープロセスはsystemd管理となり、logrotate処理後も問題なく処理を継続出来るようになりましたので、focalへの移行も完了することが出来ました。

まとめ

  • 意図せぬプロセスの停止原因となったSIGTERMの送出元を調べるためにbpftraceを利用しました
  • Ubuntuでシステムの挙動調査にeBPFを利用したい場合bpftraceが便利です
  • 現代のプロセスデーモン化は素朴なプロセス分離だけでは不十分なのでsystemdなどにまかせていきましょう