Expect ログファイルとデバッグ

スクリプトを用意して実行させるなら、後で見返すためのログファイルが必要になってくると思います。

ここでは、 Expect のログファイルの作り方とデバックの仕方について解説してみたいと思います。

log_file

Expect は、標準入出力で動作しますので、 command > file というような リダイレクトが使えません。

では、 標準入出力をファイルに出力してくれる tee ならどうかと試してみると、上手く Expect スクリプトの実行状況をファイルに記録することが出来ました。

ただ、 Expect にはスクリプトに組み込む ログファイルを記録するいくつかの方法が用意されているようですので、 ご紹介したいと思います。

１つめは、 tee と同じ働きをする、 log_file -noappend です。　以下がその例となります。

  1   #!/usr/bin/expect
  2   spawn $env(SHELL)
  3   log_file -noappent shell_session.log
  4   interact

上の例のように -noappend とオプションを付けることによって、 shell_session.log というファイルにログが上書きされます。 -noappend を付けずに log_file shell_session.log とすると、すでに shell_session.log があった場合、最後の行に書き足されていくログファイルとなります。 なぜ、既存のファイルに追記していくのがオプションいらずで、書き換えるほうにオプションが必要になるのでしょうかね。

実は Expect スクリプトの中にログファイルを出力するコマンドを組み込むことが出来ると、次の例のようにログの出力を途中で止めることが出来るようになります。 これは、 tee コマンドでは出来ませんし、 -noappend という、オプションがある理由のようです。

  1   #!/usr/bin/expect
  2   set send_slow {1 .05}
  3   spawn $env(SHELL)
  4   log_file -noappent shell_session_a.log
  5   expect "$ "
  6   send -s -- "ls -a\r"
  7   expect "$ "
  8   log_file
  9   interact "~I" return
 10   log_file shell_session_a.log
 11   send -s -- "\r"
 12   expect "$ "
 13   send -s -- "ls -a\r"
 14   expect "$ "

上の例では、 interact の中でやった事がログに残らないようになっています。

8行目の 何も引数を持たない log_file はログの出力をしないこと意味します。

9行目の interact は Expect スクリプトに代わって 人が作業する コマンド です。 Expect に戻るには、 ~I をタイプすると、 return と書かれているように、 人の作業を抜けて Expect スクリプトに戻ります。 この ~I というキー入力が、偶然に他の必要な作業のタイプイングと重なることがないよう、気を付けてください。

10行目の -noappend のない log_file は、 shell_session_a.log の最後の行からログを書き加えていくので、 結果 interact で人が作業したところのログが残らないようになります。

ログファイルを more で表示させると以下のようになります。 interact 中に touch hoge をやったのですがログには残っていません。

  $ more shell_session_a.log
  $ ls -a
  . .. shell_session_a.log
  $
  $ ls -a
  . .. hoge shell_session_a.log
  $

exp_internal

デバッグについて Expect の場合は パターンマッチが意図している通り出来ているかが大事になりますので、 Expect がパターンマッチをどのようにやれているかを出力してくれるコマンド exp_internal というものがあります。

exp_internal 1 でデバッグ出力 ON で exp_internal 0 でデバッグ出力 OFF になります。

よくやる失敗例として、 ftp のパスワードを訊いてくるプロンプトを expect コマンドでパターンマッチさせるときに、 "Password: " としてしまいがちですが、 実際のプロンプトには スペースがないので、パターンマッチしません。 同じ ftp のログインプロンプト "(ftp.server.jp:accountA): " にはスペースがあるのに なぜパスワードプロンプトにはスペースがないのでしょうかね。

下の例は あえて パスワードプロントを 誤って expect "Password: " として デバッグをしてみたものです。

  1   #!/usr/bin/expect
  2   set send_slow {1 .05}
  3   spawn ftp ftp.server.jp
  4   exp_internal 1
  5   expect "(ftp.server.jp:accountA): "
  6   send -s -- "accountB\r"
  7   expect "Password: "
  8   send -s -- "passwordB\r"

これを実行してみると、標準出力は以下のようになりました。

spawn ftp ftp.server.jp

expect: does "" (spawn_id exp4) match glob pattern "(ftp.server.jp:accountA): "? no
Connected to ftp.server.jp.

expect: does "Connected to ftp.server.jp.\r\n" (spawn_id exp4) match glob pattern "(ftp.server.jp:accountA): "? no
.... omitted ....
Name (ftp.server.jp:accountA):
expect: does "Connected to ftp.server.jp.\r\n .... \r\nName (ftp.server.jp:accountA): "? yes
expect: set expect_out(0,string) "(ftp.server.jp:accountA): "
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "Connected to xianzhi.sakura.ne.jp.\r\n .... \r\nName (xianzhi.sakura.ne.jp:kena): "
send: sending "accountB\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "Password: "? no
accountB

expect: does "accountB\r\n" (spawn_id exp4) match glob pattern "Password: "? no
331 Password required for accountB
Password:
expect: does "accountB\r\n331 Password required for accountB\r\nPassword:" (spawn_id exp4) match glob pattern "Password: "? no
expect: timed out
....

expect: does の後に " " 囲まれた部分と、expect文のパターンマッチしているか? というチェックを標準出力に文字列が出力される度に行っているのが分かりますでしょうか。

なんとなく、分かるような、、、でも、標準出力じゃ難しいと思います。

そこで、このデバッグ出力をファイルに出力したい場合は、 exp_internal -f debug.log 1 のように -f オプションで ファイルを指定してください。 また、ファイル出力をやめるときは。 exp_internal 0 でやめることが出来ます。

なお、デバッグ出力にある spawn_id については、マルチプロセスで説明したいと思います。