環境
ruby 2.5
GNU gdb (Debian 7.12-6)
Kubernetes 1.10
gdbを使うモチベーション
この記事をご覧の皆さんも普段からデバッグすることは多いと思います。そして、大抵の場合p 変数で済みます。ですが、たまに必殺pが使えない状況があります。
例1) 謎のプロセスいるんですけど？（怒）
Finding a Ruby bug with GDB（超面白いです。）という記事では、「たまにPumaの古いプロセスが見える」というバグレポートを元にGDBでデバッグしているが、古い(何週間というレベル)ので例外やログを終えず、そもそも欲しいものが適切に記録されているかも怪しい。ただ、デバッグすべきプロセスは目の前にいるのである。
例２) なんか知らんけど止まっているですけど？（怒）
よく分からんが、ごく稀に停止する。ただ、普段は意図した通りに動く。とりあえずはps xHopid,lwp,wchan,commandとか打って、停止している原因に迫ることは一応できるが、これだけの情報では原因を特定することはかなり難しい。ただ、デバッグすべきプロセスは目の前にいるのである。
デバッガを使おう
上のような状況（IDEが使えない環境）でデバッグするなら、デバッガの出番だ。デバッガはかなり色んなことができる。例えば、今動いているプロセスのとあるスレッドのコールスタックを見ることができる。コールスタックを見る以外にも、動的にrubyのコードを実行できたりする。さらに、面白い使い方としてファイルディスクリプタを変更することもできる。つまり、稼働中のプロセスのログが/dev/nullに流していたが、それを変更することも可能。それについてはこの記事によくまとまっている。ただし、デバッガをアタッチするとプロセスは停止するので、その点は気をつけなければいけない。
準備編) gdbをdocker環境で使えるようにする
とりあえず準備しますが、興味ない人は読み飛ばして下さい。docker環境でgdbを使えるようにするにはちょっと骨が折れます。何も考えずやると、ptrace: Operation not permitted.とか言われます。
コンテナを1体立ち上げて、gdbを実行する
これは簡単。
docker pull ubuntu
とかして、
docker run -it --cap-add=SYS_PTRACE --security-opt="seccomp=unconfined" --name hoge ubuntu /bin/bash
とかすれば、コンテナ内でgdbを実行できる。Linuxでは権限をいくつかのグループに分割していて、そのグループはcapabilityと呼ばれ、各capabilityは特定の操作や動作を行う権限を得ることができる。詳しくはマニュアルを見て欲しい。そして、上のdockerコマンドではcapabilityに、SYS_PTRACEを追加している。これはgdbが使っているシステムコールであるptraceを許可するものである。セキュリティの問題で、コンテナの中はかなり権限的に制限されているので、権限を付与してやらないといけない。
Kubernetes
僕がgdbを実際に使った状況では、Kubernetesにより構成される環境でした。この記事を参考にしたのですが、Deployment specに次のように書くと大丈夫です。
spec:
restartPolicy: Always
containers:
- name: hoge
image: hoge_image:0.0.0.0
securityContext:
capabilities:
add:
- SYS_PTRACE
command:
- hoge
docker-compose
これには敗北しました。docker-compose.ymlに次のように書けばいけそうなのですが、いけません。
services:
fuga:
(略)
cap_add:
- SYS_PTRACE
security_opt:
- seccomp:unconfined
このissueは僕と同じことをして、「できないんですけど？」と言っているのですが、だいたい次のような回答をもらっています（ただし、使っているシステムコールはstraceです）。
services:
foo:
command: strace /bin/ls
build: .
cap_add:
- SYS_PTRACE
security_opt:
- seccomp:unconfined
うーん、commandでやるのって違うよなぁ。やりたいときにやりたいよね。
Let's debug
さて、それでは実際にやってみます。k8sで稼働しているpodに入って、その中のとあるスレッドのコールスタックを見てみます。kubectl get podsを実行してみます。
NAME READY STATUS RESTARTS AGE
batch-aaaaaaaaaa 0/1 Completed 0 1m
daemon-bbbbbbbbbb 1/1 Running 0 5s
server-cccccccccc 1/1 Running 0 1d
次に、daemon-bbbbbbbbbbの中に入ります。kubectl exec -it daemon-bbbbbbbbbb bashを実行して、daemonpodの中に入ります。ps xopid,commandを実行すると、
PID COMMAND
1 /usr/local/bundle/bin/rake daemon
1 /usr/local/bundle/bin/rake daemon
1 /usr/local/bundle/bin/rake daemon
1 /usr/local/bundle/bin/rake daemon
1 /usr/local/bundle/bin/rake daemon
1 /usr/local/bundle/bin/rake daemon
(略)
1078 bash
8902 ps xHopid,command
このdaemonプロセスはマルチスレッドなプロセスなので同じPIDの行がたくさん出力されます。gdbをアタッチするプロセスのPIDは1であることが分かりました。アタッチする前に確認しなければならないことが1つあります。gdbをアタッチしてコマンドを実行するわけですが、その結果はgdbプロセスの標準出力ではなく、対象プロセスの標準エラーに出力されます。なので、PIDが1のプロセスの標準エラーの向き先がどうなっているのかを確認したいです。
そこで、ls -la /proc/1/fd/を実行してみます。
total 0
dr-x------ 2 tomita_kazuya tomita_kazuya 0 Dec 9 08:57 .
dr-xr-xr-x 9 tomita_kazuya tomita_kazuya 0 Dec 9 08:57 ..
lr-x------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 08:57 0 -> pipe:[31993418]
l-wx------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 08:57 1 -> pipe:[31993420]
lrwx------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 09:01 10 -> socket:[32011592]
lrwx------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 08:57 11 -> socket:[31992811]
lrwx------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 09:01 12 -> socket:[32279584]
l-wx------ 1 tomita_kazuya tomita_kazuya 64 Dec 9 08:57 2 -> pipe:[31993420]
(略)
標準エラーの向き先は標準出力と同様(pipe:[31993420])みたいですね。よって、kubectl logsコマンドでgdbのコマンドの結果を確認できることが分かりました。ただ、この場合はkubectl logsで確認できますが、どこに向いてるかよく分からないケースもあると思います。その時は、/tmp/hogeみたいなファイルに書き出したり、向き先を標準出力にしたりするといいと思います。
いよいよアタッチします。
コンソールでgdb /usr/local/bundle/bin/ 1と打つと、gdbを実行することができ、入力待ちになります。その状態でinfo threadsと打ちます。
(gdb) info threads
Id Target Id Frame
* 1 Thread 0x7f61238a4700 (LWP 1) "bundle" 0x00007f6122f5a508 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
2 Thread 0x7f61238b3700 (LWP 7) "ruby-timer-thr" 0x00007f612254d67d in poll () from /lib/x86_64-linux-gnu/libc.so.6
3 Thread 0x7f611a49a700 (LWP 8) "connection_poo*" 0x00007f6122f5a508 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
4 Thread 0x7f6115bf1700 (LWP 9) "hoge.rb:1*" 0x00007f6122f5a15f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
5 Thread 0x7f6115af0700 (LWP 10) "hoge.rb:1*" 0x00007f6122f5a15f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(略)
こんな感じの出力がでます。1つ目はbundleのスレッド、2つ目はタイマースレッド、3つ目はActiveRecordのReaperスレッドだと思われます。4つめ以降が僕が起動しているスレッド達です。
(gdb) thread 4
[Switching to thread 4 (Thread 0x7f6115bf1700 (LWP 9))]
#0 0x00007f6122f5a15f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
スレッドを切り替え、最後にコールスタックを出力します。
(gdb) call rb_print_backtrace
$1 = {void (void)} 0x7f6123398d00 <rb_print_backtrace>
これで、kubectl logsコマンドでスレッド4のコールスタックを確認できます。
課題) その他のコマンドが実行できない
rb_eval_stringを始めとしたそのほかのコマンドがほとんど実行できませんでした。
次のエラーメッセージが出ます。
Couldn't write extended state status: Bad address.
この英文で検索すると、この香ばしいバグレポートのページが出てきます。
I was now able to test my hypothesis that this is/was a bug in Linux
that has been fixed since.
とのことなので、OSがアップグレードされれば改善されそうです。
まとめ
GDBで良いデバッグライフを！