シェルスクリプトのデバッグ

シェルスクリプトをデバッグするには

プログラムにバグはつきものであり、それはシェルスクリプトも例外ではない。bash にはシェルスクリプトのデバッグに非常に有効なオプションが用意されているので、「Syntax Error」で実行できない場合や、変数にどんな値が設定されているのか確認したい場合は、それらオプションを指定した上で実行することで、簡単にデバッグを行うことができる。

「-x」オプションを使用する

-x オプションは、シェルスクリプト内で実際に実行されたコマンドを表示するオプションである。変数が使用されている場合は、その変数の値が展開された状態で表示される。

bash -x デバッグするシェルスクリプト

→ bash に -x オプションを指定し、引数にデバッグするシェルスクリプトを指定する。

-x オプションでシェルスクリプトを実行すると、echo コマンドなどの出力に加えて、スクリプト内で実際に実行されたコマンドラインが出力される。この出力により、変数に設定されている値などを確認することができる。

また、この場合は bash を使用しているが、Bシェルで実行される場合は sh を、Kシェルで実行される場合は ksh をそれぞれ使用する。

変数に値を設定するのみのシェルスクリプト (debug_test.sh) を作成して、-x オプションでの実行結果を見てみる。

#!/bin/bash

var1=`date +%M`
var2=`ls -1 | wc -l`

if [ $var1 -ge 30 ]; then
  var3="BIG"
else
  var3="SMALL"
fi

exit 0

このシェルスクリプト debug_test.sh の -x オプション付き実行結果は、以下のとおりとなる。

$ ./debug_test.sh
$
#↑通常通りに実行すると、何も出力されずに終了する。

$ bash -x ./debug_test.sh
++ date +%M
+ var1=46
++ ls -1
++ wc -l
+ var2=26
+ '[' 46 -ge 30 ']'
+ var3=BIG
+ exit 0
$
#↑「-x」オプション付きだと、実際に実行されたコマンドと変数に設定された値を確認できる。

行頭に + が付いているコマンドがシェルスクリプト内で実行されたコマンド、++は `` (バッククォート) 内で実行されたコマンドとなっている。

通常の実行では変数に設定される値を確認できないが、-x オプションを使用すると実際に実行されたコマンドが出力される。これを見ることで実行時に変数に設定された値を確認することができる。

実行時に -x オプションを指定する以外にも、シェルスクリプト内に直接オプションを記述することでも同様の効果を得ることができる。

実際にシェルスクリプト (debug_test2.sh) 内で -x オプションを指定してみる。

#!/bin/bash -x
# ↑ここで「-x」オプションを指定する。

var1=`date +%M`
var2=`ls -1 | wc -l`

if [ $var1 -ge 30 ]; then
  var3="BIG"
else
  var3="SMALL"
fi

exit 0

このシェルスクリプト debug_test2.sh の実行結果は、以下のとおりとなる。

#↓シェルスクリプト内に直接「-x」オプションを指定すると、実行時に「-x」オプションを指定する必要はない。
$ ./debug_test2.sh
++ date +%M
+ var1=47
++ ls -1
++ wc -l
+ var2=26
+ '[' 47 -ge 30 ']'
+ var3=BIG
+ exit 0
$

実行時に -x オプション指定はしていないが、指定した場合と同じ出力が得られている。

「-v」オプションを使用する

-v オプションは、シェルスクリプト内でこれから実行されるコマンドを表示する。変数が使用されている場合は -x オプションとは異なり、変数名がそのまま表示される。

bash -v デバッグするシェルスクリプト

→ 使用するシェルに -v オプションを指定し、引数にデバッグするシェルスクリプトを指定する。

使用方法に関して -x オプションと同様になる。-v オプションは、スクリプト内に記述されているコマンドが出力されるだけなので、-x オプションと共に使用されることが多い。

$ cat debug_test.sh
#!/bin/bash

var1=`date +%M`
var2=`ls -1 | wc -l`

if [ $var1 -ge 30 ]; then
var3="BIG"
else
var3="SMALL"
fi

exit 0
#↑シェルスクリプトの内容を確認。

$ bash -v ./debug_test.sh
#!/bin/bash

var1=`date +%M`
date +%M
var2=`ls -1 | wc -l`
ls -1 | wc -l

if [ $var1 -ge 30 ]; then
var3="BIG"
else
var3="SMALL"
fi

exit 0
$
#↑実行されるコマンドが出力されている。

$ bash -vx ./debug_test.sh
#!/bin/bash

var1=`date +%M`
date +%M
++ date +%M
+ var1=51
var2=`ls -1 | wc -l`
ls -1 | wc -l
++ ls -1
++ wc -l
+ var2=26

if [ $var1 -ge 30 ]; then
var3="BIG"
else
var3="SMALL"
fi
+ '[' 51 -ge 30 ']'
+ var3=BIG

exit 0
+ exit 0
#↑「-x」オプションと併用することも可能。

ヌルコマンドを応用したデバッグ

ヌルコマンド : と -x オプションを組み合わせることで、処理にほぼ影響を与えずにデバッグメッセージを表示することができる (影響は後述するが、直後の終了ステータスのみ)。

具体的には、以下のスクリプト (debug_null.sh) のようにする。

#!/bin/bash

# 文字列の先頭は半角文字にしないと...
: "文字化けします."

: "[DEBUG] デバッグメッセージです."

if true; then
  : "[DEBUG] true のルートに入りました."
fi

var=`expr 26 + 31`
: "[DEBUG] var=$var"

echo "26+31=$var"

: "[DEBUG] 処理を終了します."

exit 0

-x オプションを使用することで、処理内容が視覚化されるため、ヌルコマンドの引数として指定したデバッグメッセージが出力されるようになる。

ヌルコマンドは引数の有無に関わらず、一切の処理を行わずに終了するコマンドであるため、結果的に処理に影響を与えずにデバッグメッセージを出力できるということになる。

ただし、一切の処理を行わないとはいえ、直後の終了ステータスはヌルコマンドの終了ステータス (常に0) となるため、その点のみは注意してほしい。

また、デバッグメッセージに2バイト文字を含む場合は、先頭を半角文字にしないと文字化けするので注意すること。上記スクリプトでは、文字化けを避けるため、デバッグメッセージの先頭に [DEBUG] を付加している。

-x オプション付きでの実行結果は、以下のとおりとなる。

$ bash -x ./debug_null.sh
+ : $'\346\226\207\345\255\227\345\214\226\343\201\221\343\201\227\343\201\276\343\201\231.'
#↑先頭が2バイト文字なので文字化けしている
+ : '[DEBUG] デバッグメッセージです.'
+ true
+ : '[DEBUG] true のルートに入りました.'
++ expr 26 + 31
+ var=57
+ : '[DEBUG] var=57'
+ echo 26+31=57
26+31=57
+ : '[DEBUG] 処理を終了します.'
+ exit 0

-x オプションなしでの実行結果は以下のとおり。

$ ./debug_null.sh
26+31=57

ヌルコマンドに指定したメッセージは、当然出力されることはない。

シェルスクリプトを部分的にデバッグする

シェルスクリプトの先頭に -x オプションを指定することでシェルスクリプト全体をデバッグすることが可能であるが、この -x オプションの指定を部分的に適用することも可能である。

# デバッグを開始する
set -x

# デバッグを終了する
set +x

→ set コマンドに対して -x オプションを指定する。

set コマンドに対して -x オプションを指定することで、bash -x でシェルスクリプトを実行したときと同じ状態になる。これを解除したいときは、set コマンドに +x を指定する。

この -x オプションの部分指定を行うシェルスクリプト (debug_test3.sh) を作成してみる。

#!/bin/bash

# デバッグ開始
set -x

var1=`date +%M`

# デバッグ終了
set +x

var2=`ls -1 | wc -l`
var3="DEBUG TEST"

exit 0

このシェルスクリプト debug_test3.sh の実行結果は、以下のとおりとなる。

$ ./debug_test3.sh
++ date +%M
+ var1=56
+ set +x
$

シェルスクリプト内で指定した set -x から set +x までの処理内容が出力されていることが確認できる。

参考サイト

デバッグ用関数を自作する

-x オプション以外にも、処理の途中でデバッグのために echo コマンドで変数の内容を出力し、デバッグが終わったらその echo コマンド部分を削除する、といったデバッグ方法を実践している人も多いだろう。

ただ、この方法だとデバッグ前と後でソースを修正する必要があるため、デバッグ文が増えるにつれてコーディングが非効率になりがちだ。

ある程度大きな規模のシェルスクリプトを作成するときは、デバッグログを出力するデバッグ用関数を用意し、デバッグモードで実行された場合のみ、この関数でデバッグログを出力するようにするとよい。

以下は、筆者が普段使用している自作のデバッグ用関数。

DEBUG_LOG()
{
  [ ! -f "$_DEBUG_LOGFILE_" -a $# -ne 0 ] && return 1
  if [ ! -f "$_DEBUG_LOGFILE_" -a $# -eq 0 ]; then
    cat <&0
    return 1
  fi

  if [ $# -eq 0 ]; then
    {
      echo "--- `date '+%Y/%m/%d %H:%M:%S'` --------------------------------"
      cat <&0
      printf "\n\n"
    # ロギング用に付加したものは削除しておく
    } | tee -a $_DEBUG_LOGFILE_ | sed -e '1d' | head -n -2
  else
    {
      echo "--- `date '+%Y/%m/%d %H:%M:%S'` --------------------------------"
      printf "$*\n\n"
    } >>$_DEBUG_LOGFILE_
  fi

  return 0
}

この関数はデバッグモードのときのみ機能し、非デバッグモードのときは処理が動く前に return で戻る仕組みになっている。

デバッグモード・非デバッグモードの判定には、デバッグ用ログファイルの存在自体をフラグとして利用している。

デバッグ用ログファイルが存在する場合はデバッグモードで動作し、
デバッグ用ログファイルが存在しない場合は非デバッグモードで動作する。

つまり、スクリプトをデバッグモードで動作させたいときは、あらかじめ touch コマンドなどでデバッグ用ログファイルを作成しておけばよい。デバッグモードを解除したいときは、デバッグ用ログファイルを削除するかリネームする。

デバッグモードでコールされた場合、引数に指定された文字列をデバッグ用ログファイルに追記する。引数が存在しなかった場合は、標準入力から渡された文字列を同様にデバッグ用ログファイルに追記する。

パイプ処理の途中の値を確認したい場合は、確認したい箇所にこの関数を引数なしで記述する。もちろん関数はパイプ処理に影響を与えないよう、標準入力から渡された文字列をそのまま次のコマンドに引き渡すようになっている。

デバッグ用ログファイルのファイル名は、関数コール前に事前に変数 _DEBUG_LOGFILE_ に設定しておく。一つ注意しなくてはならないのは、「debug.log」など簡単すぎる名前にすると、他のユーザに同名のファイルを作成される可能性が出てくる。そうなるとシェルスクリプトが意図せずデバッグモードで動作してしまう危険性があるので、これを避けるために、デバッグ用ログファイル名はできるだけユニークな名前にすること。

関数外でデバッグ用ログファイルを設定するのは、関数の再利用がしやすいようにするためである。この方法だとどんなファイル名でも、関数に修正を加えることなく設定を行うことができる。

余談だが、以前はデバッグ用のコマンドラインオプションを用意して、それをデバッグフラグとしていたのだが ( ./debug.sh -d など)、この方式だとメイン処理で使用したいオプションと被ったり、引数チェックが複雑になったりと、デメリットばかりが大きかった。デバッグ用ログファイルの存在自体をデバッグフラグとする方式だと、そのようなデメリットは一切なく、簡単にデバッグモードで実行することができる。

このデバッグ用関数を使用したシェルスクリプト (debug_function.sh) を作成してみる。

#!/bin/bash

DEBUG_LOG()
{
  [ ! -f "$_DEBUG_LOGFILE_" -a $# -ne 0 ] && return 1
  if [ ! -f "$_DEBUG_LOGFILE_" -a $# -eq 0 ]; then
    cat <&0
    return 1
  fi

  if [ $# -eq 0 ]; then
    {
      echo "--- `date '+%Y/%m/%d %H:%M:%S'` --------------------------------"
      cat <&0
      printf "\n\n"
    # ロギング用に付加したものは削除しておく
    } | tee -a $_DEBUG_LOGFILE_ | sed -e '1d' | head -n -2
  else
    {
      echo "--- `date '+%Y/%m/%d %H:%M:%S'` --------------------------------"
      printf "$*\n\n"
    } >>$_DEBUG_LOGFILE_
  fi

  return 0
}

# デバッグ用ログファイルの設定
readonly _DEBUG_LOGFILE_="./_TEST_DEBUG_.log"

DEBUG_LOG "$LINENO: デバッグを開始します。"

DEBUG_LOG "コマンド実行結果も出力できます。\n`cal`"

# パイプ処理の途中にも組み込み可能
cal | grep 15 | DEBUG_LOG | awk '{print $3}'

DEBUG_LOG "$LINENO: デバッグを終了します。"

exit 0

シェルスクリプト中で使用している変数 LINENO は、使用した場所の行番号が自動的に設定される特殊変数である。デバッグ作業には非常に有効な変数なので、ぜひ覚えておいてほしい。

このシェルスクリプト debug_function.sh の実行結果は、以下のとおりとなる。

$ ls ./_TEST_DEBUG_.log
/bin/ls: ./_TEST_DEBUG_.log: そのようなファイルやディレクトリはありません
#↑デバッグ用ログファイルが存在しないので、非デバッグモードで動作するはず。

$ ./debug_function.sh
12
#↑正常に結果が出力されている。

$ ls ./_TEST_DEBUG_.log
/bin/ls: ./_TEST_DEBUG_.log: そのようなファイルやディレクトリはありません
#↑デバッグ用ログファイルには出力されいてない。

$ touch ./_TEST_DEBUG_.log
#↑今度はデバッグ用ログファイルを作成し、デバッグモードで動作させる。

$ ./debug_function.sh
12
#↑デバッグモードでも実行結果は変わらない。

#↓デバッグ用ログファイルにはログが出力されている。
$ cat ./_TEST_DEBUG_.log
--- 2007/06/05 23:00:19 --------------------------------
33: デバッグを開始します。

--- 2007/06/05 23:00:19 --------------------------------
コマンド実行結果も出力できます。
      6月 2007
日 月 火 水 木 金 土
                1  2
 3  4  5  6  7  8  9
10 11 12 13 14 15 16
17 18 19 20 21 22 23
24 25 26 27 28 29 30

--- 2007/06/05 23:00:19 --------------------------------
10 11 12 13 14 15 16

#↑これがパイプ処理の途中の値になる。

--- 2007/06/05 23:00:19 --------------------------------
40: デバッグを終了します。