12.2. Bashデバグテクニック

ルールセットの書かれたスクリプトをデバグする際に bash でできることはあまり多くはない。バグを見つける段でまず越えなければならない課題は、どの行で問題が発生するのかを知ることだ。これには、 bash-x フラグを使うか、単純に echo ステートメントを挿入して問題の発生する箇所を見つけるという、ふたつの方法がある。理想的には、 echo ステートメントを利用して、コード中へ一定間隔で以下のような echo 命令を入れることになるだろう:

  ...
  echo "Debugging message 1."
  ...
  echo "Debugging message 2."
  ...
      

僕はよく、 grep したりスクリプトファイルを検索したりして該当するメッセージを見つけられる程度に、固有の文字列を含む、甚だ意味のないメッセージを使う。今、エラーメッセージは "Debugging message 1." の後で現れ、 "Debugging message 2." より前だったとすれば、問題のある行はそれらふたつのデバグメッセージの間のどこかにあると分かる。ご存じのように、 bash には、途中のコマンドにエラーがあっても最後まで全てのコマンドを実行し続けるという、悪いとは言わないまでもかなりヘンテコな設計思想がある。 netfilter で使うと、これが元で非常に面白い問題に遭遇することがある。上記のように単純に echo ステートメントでエラーを見つけるという方法は、非常に単純でありながら、極めて有効な手段となる。それによってトラブルをコードの 1 行にまで絞り込み、問題の正体を知ることができるからだ。

エラーを探る第二の方法は、前にも述べたように bash-x オプションを与える方法だ。もちろんこれには少々の問題がある。特に、スクリプトが長く、コンソールバッファが足りない場合だ。 -x オプションの意味するところは非常に単純で、スクリプトコードの各行を、シェルの標準出力 (standard output) (通常はコンソール) へ逐一エコーさせる。やるべきことは、スクリプトの最初の行:

#!/bin/bash
      

を下記のように書き換えること。

#!/bin/bash -x
      

やってみれば分かると思うが、元の行数がそれほど多くないとしても大量のデータが出力される。コマンドの一行一行が変数の値などとともに全て現れるわけで、各コードが何をやっているのかまでいちいち読み取ろうとする必要はない。簡単に言うと、各行が実行と当時にスクリーンにも出力されるのだ。そこでありがたいのが、 bash が出力している行には頭に + 記号が付くという点。おかげで、何の目印もない大量の羅列を読むよりは幾分か、エラーや警告メッセージが識別しやすくなる。

-x オプションは、もう少し複雑なルールセットを書く時にありがちな幾つかのトラブルをデバグするのにも、非常に役に立つ。第一に挙げられるのが、 for, if, while といった基本的 (だとあなたが思いこんでいる) ループの中で実際に行われていることがつぶさに分かることだ。例えば、下の例を見てみよう。

  #!/bin/bash 
  iptables="/sbin/iptables"
  $iptables -N output_int_iface
  cat /etc/configs/machines | while read host; do
    $iptables -N output-$host
    $iptables -A output_int_iface -p tcp -d $host -j output-$host

    cat /etc/configs/${host}/ports | while read row2; do
      $iptables -A output-$host -p tcp --dport $row2 -d $host -j ACCEPT
    done
  done
      

ごく単純なルールセットに見えるが、何度試してもエラーになってしまう。単純に echo を使ったデバグ方法を試した結果、上記のコードからは以下のエラーメッセージが出ることが分かっている。

work3:~# ./test.sh
Bad argument `output-'
Try `iptables -h' or 'iptables --help' for more information.
cat: /etc/configs//ports: No such file or directory
      

そこで、 bash-x オプションをオンにして出力を眺めてみる。そのアウトプットが下記だが、ご覧のようにかなり奇妙なことが起こっている。幾つかのコマンドで変数 $host$row2ヌル (空文字) に置き換えられているのだ。よく見ると、問題が発生しているのはコード繰り返しの最終回だけだということが分かる。プログラミング上の間違いか、データにおかしなところがあるかのいずれかだと考えられる。この場合はデータ側の単純な問題であり、データファイルの最後に余分な改行がひとつ紛れ込んでいることが原因だ。そのため、ループの最後で本来起こるべきでない余分な繰り返しが起こっていたわけだ。ファイル末尾の改行を削除すれば問題はあっさりと解決だ。あまりエレガントな解決策とはいえないかもしれないが、個人レベルならそれで充分。もちろん、変数 $host$row2 にデータが含まれているかどうかを検証するコードを加えるという手もある。

work3:~# ./test.sh
+ iptables=/sbin/iptables
+ /sbin/iptables -N output_int_iface
+ cat /etc/configs/machines
+ read host
+ /sbin/iptables -N output-sto-as-101
+ /sbin/iptables -A output_int_iface -p tcp -d sto-as-101 -j output-sto-as-101
+ cat /etc/configs/sto-as-101/ports
+ read row2
+ /sbin/iptables -A output-sto-as-101 -p tcp --dport 21 -d sto-as-101 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-101 -p tcp --dport 22 -d sto-as-101 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-101 -p tcp --dport 23 -d sto-as-101 -j ACCEPT
+ read row2
+ read host
+ /sbin/iptables -N output-sto-as-102
+ /sbin/iptables -A output_int_iface -p tcp -d sto-as-102 -j output-sto-as-102
+ cat /etc/configs/sto-as-102/ports
+ read row2
+ /sbin/iptables -A output-sto-as-102 -p tcp --dport 21 -d sto-as-102 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-102 -p tcp --dport 22 -d sto-as-102 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-102 -p tcp --dport 23 -d sto-as-102 -j ACCEPT
+ read row2
+ read host
+ /sbin/iptables -N output-sto-as-103
+ /sbin/iptables -A output_int_iface -p tcp -d sto-as-103 -j output-sto-as-103
+ cat /etc/configs/sto-as-103/ports
+ read row2
+ /sbin/iptables -A output-sto-as-103 -p tcp --dport 21 -d sto-as-103 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-103 -p tcp --dport 22 -d sto-as-103 -j ACCEPT
+ read row2
+ /sbin/iptables -A output-sto-as-103 -p tcp --dport 23 -d sto-as-103 -j ACCEPT
+ read row2
+ read host
+ /sbin/iptables -N output-
+ /sbin/iptables -A output_int_iface -p tcp -d -j output-
Bad argument `output-'
Try `iptables -h' or 'iptables --help' for more information.
+ cat /etc/configs//ports
cat: /etc/configs//ports: No such file or directory
+ read row2
+ read host
      

最後に挙げるのは、 -x オプションが、完璧ではないにしろ手助けとなるタイプのトラブルだ。それは、ファイヤーウォールスクリプトを SSH 経由で実行していて、スクリプトの実効途中でコンソールがハングしたまま戻らず、再度 SSH で接続することもできなくなるという問題だ。そうしたケースの 99.9% は、スクリプト内部に何箇所か問題があるのが原因と思われる。 -x オプションを有効にすれば、少なくとも、スクリプトがどの行で無応答になるかというところまでは突き止められる。ただし、残念ながら例外もある。例えば、スクリプトが、受信トラフィックをブロックするような何らかのルールを作り上げるものだったとしよう。しかし、 sshtelnet サーバは送出トラフィックの初めに echo を送信するので、その時点で netfilter はコネクションを記憶することができる。そのため、コネクションステータスを司るようなルールがブロックルール構築よりも前にある場合には、受け取り方向のトラフィックはなんとか通してもらえるのだ。

ご覧いただいたように、結局のところ、書き上げたルールセットを完璧にデバグするのはかなり込み入った作業だ。とはいえ、やってできないことではない。 SSH を通じてファイヤーウォールを遠隔で設定しなければならない場合に、出来損ないのルールセットをロードすれば、ファイヤーウォールが無応答になってしまったりするケースがあることも分かったはずだ。そんな場合に時間を浪費しないための奥の手がある。無駄な時間を節約してくれる素晴らしい手段となるのは cron だ。仮に、50km 離れた場所にあるファイヤーウォールに取り組んでいるとしよう。ルールを幾つか足したり、削除したり、削除して新しいルールセットに差し替えたりする。と、ファイヤーウォールが無応答に。もう何も届かない。付けるものを付けておかないと、物理的にファイヤーウォールのある所まで馳せ参じ、現地で直接直すしかなくなってしまう!