環境

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で良いデバッグライフを！