正常に動作しないスクリプトやプログラムに標準出力処理（echoやSystem.out.print()など）を追加して、デバッグした経験は誰にでもあるのではないでしょうか。標準出力処理の追加は、簡単なプログラムの動作検証から制限などによりデバッガーを使用できない環境での調査まで、いろいろな場面で活用されていると思います。
しかし、1行の標準出力処理の追加でもプログラムの動作を致命的に変える可能性はあります。
過去に、echoが原因でバッチが停止した問題の対策のために、JavaのプログラムにSystem.out.println(･･･);の1行を追加した結果、アプリケーションが応答を返せなくなったことがありました。その時の記憶を、サンプルプログラムを交えながら説明したいと思います。
年次バッチが停止した！
10年ほど前のある日、あるシステムの保守を担当していた私のもとに「年次バッチが停止してしまったので、急いで調査して欲しい」という旨のメールが入りました。本文をさらに読んでみると、バッチファイルのecho命令の行でプログラムが停止しているとのこと。
最初に聞いたときは、報告者の勘違いを疑ったのですが、確かに次のような4行連続するechoを含むバッチファイル(サンプルはこちら)があり、
・・・(省略)・・・
echo %date% %time% ==================================================>> logs/result.log
echo %date% %time% [Step4] >> logs/result.log
echo %date% %time% Pre-Import Processing >> logs/result.log
echo %date% %time% >> logs/result.log
・・・(省略)・・・
それが出力したログ(result.log)を見ると、2行分のechoのメッセージしか表示されていませんでした。
・・・(省略)・・・
2007/09/28 12:04:44.72 ==================================================
2007/09/28 12:04:44.72 [Step4]
(これ以降ログが出力されていない)
「そんなことはあり得ない」と思ったのですが、念のため簡単なテスト環境を構築して、バッチファイルを実行してみることにしました。結果は予想した通り。事象は再現せず、正常に処理が完了しました。外部からバッチプロセスを強制終了した以外に思いつく原因はありませんでした。
その後、報告者と電話で連絡ができるようになったため、詳細をヒアリングしてみると、このバッチはJavaのプログラムから呼び出されるとのこと。
報告者から入手したJavaのプログラムは、以下のようなmain()メソッドを含み、バッチファイルをjava.lang.ProcessBuilderで起動するものでした(サンプルはこちら)。
import java.io.*;
import org.springframework.core.io.*;
public class BatchImpl implements BatchInterface {
public static void main(String[] args) {
System.out.println("Result: " + new BatchImpl().executeBatch());
}
public int executeBatch() {
try {
Resource resource = new ClassPathResource("annual.bat");
File batFile = resource.getFile();
ProcessBuilder pb = new ProcessBuilder(batFile.getAbsolutePath());
Process process = pb.start();
return 0;
} catch (IOException e) {
e.printStackTrace();
}
return -1;
}
}
| ※この話の論点とは関係のない例外処理などは省いて、ソースコードは実際のもの（当時のもの）より大幅に簡略化しています。 |
さっそく、Javaのプログラムを実際に実行してみると、意外なことに事象が再現したのです。確かに「[Step4]」のメッセージの後の「Pre-Import Processing」というメッセージが表示されませんでした。
では、echoを取り除いてみたら、動作するのでしょうか。試してみたところ、確かに問題なく動作します。どうも、echoが一定数以上あると、事象が発生するようです。
調べる
事象が再現できることを確認したので、調査開始です。ネット上でいろいろと調べたところ、可能性が高いと考えられる一つの原因が見つかりました。それは、Javaのプログラムが起動したプロセス（java.lang.Process）の出力ストリームを読み出していないと、内部で保持している出力バッファが一杯になって処理が停止してしまうというものです。
そこで、Process.getInputStream()で出力ストリームを読み出して、System.out.println()で標準出力に出力するようなコードを1行追加してみました。
public int executeBatch() {
// ・・・(省略)・・・
Process process = pb.start();
System.out.println(IOUtils.toString(process.getInputStream())); // この1行を追加
return 0;
// ・・・(省略)・・・
}
すると、バッチは停止することなく、正常に動作するようになりました。バッチの標準出力処理(echo)が沢山あることが直接的な原因となった問題が、Javaの標準出力処理(System.out.println())を追加したことで対策できたことになります。
※少し補足すると、System.out.println()で標準出力に出力しなくても、ログに出力してもいいですし、さらに付け加えると、戻り値を無視してしまいますが、IOUtils.toString(process.getInputStream());だけを追加すればいいことになります。
出力バッファが一杯になる問題に関しては、このページが分かりやすくまとまっていると思います。 |
原因が分かったので、どのように対策するかを検討する必要がありますが、それはこの件で会議をしている「偉い人」たちに任せて、帰宅することにしました。「これで、この問題は解決した」、そう思ったんですが...
年次バッチの応答が返らない！
翌日出社してみると、今度は昨日直したはずの「年次バッチの応答が返らなくなった」という報告が。
修正の仕方が違うのでは？と思ったのですが、自分が想定したものと違いはありませんでした。
そして、もう一つの新しい事実が分かりました。それは、昨日対策したJavaのプログラムと年次バッチは、以下のようにRMI経由で別ホストのWebアプリケーションから呼び出される、ということです。
| ※RMI(Java Remote Method Invocation):ネットワークを通じてJavaのプログラム同士が通信を行ない、異なるコンピューター上にあるオブジェクト（リモートオブジェクト）のメソッドを呼び出すための技術。 |
Webアプリケーションにはこのバッチを呼び出す次のような画面があり、「バッチ実行」ボタンをクリックすると、RMIを使用してリモートのバッチを非同期で実行します。そして、Webアプリケーションは、バッチの完了を待たずに「バッチを実行しました」というメッセージをユーザーに表示します。
その後、Webアプリケーションから定期的な完了確認のリクエストが送信され、数時間後にバッチが完了すると、RMIサーバーが完了の応答を返し、「バッチが完了しました」というメッセージが出力されます。
しかし、今回の修正により、「バッチ実行」ボタンをクリックした直後に「バッチを実行しました」というメッセージが出力されず、応答が返らなくなってしまったということです。
（つまり、ブラウザでこのように応答待ちになった）
この新しい事実とともに昨日行った修正内容を考えると、原因が分かるまでにそれほど時間は必要ありませんでした。
System.out.println(･･･);の1行を追加する前はJavaのプログラム（＝RMIサーバーから呼び出されるJavaモジュール）がすぐに応答を返していたのに対して、追加後はバッチの完了を待ってからJavaのプログラムが応答を返すようになっていたのです。なぜかというと、Javaのプログラムが、バッチの標準出力を随時読む込むことにより、バッチと同期をとって実行するようになったためです。
今度こそ問題の無い対策を
では、どうすればいいのか？
バッチファイルのechoの出力量が多いことが要因となっているので、echoを減らすというのも暫定案としては考えられます。至急で対応すべき問題なので、これも1つの正しい選択肢といえますが、ログが出力されないのはあまりいいこととは言えません。加えて、デグレードを考慮した最小限の修正で、可能であれば今後のことも考慮した対策をしておきたいところです（デバッグなどの目的で、誰かがechoを追加してしまうかもしれないので）。
何かいい方法は...とよくよく考えてみると、結論は簡単なことでした。バッチファイルの先頭に以下の1行を追加する、ということです。
つまり、バッチが標準出力に出力しないようにすればよかったわけです。
バッチファイルをコマンドプロンプトで実行してみると分かりますが、実行後にコマンドプロンプトに表示される情報（＝標準出力）は以下のように、実行されたコマンドだけになります。
C:\batch>mkdir logs
C:\batch>echo 2007/09/28 12:04:44.72 ==================================================>> logs/result.log
C:\batch>echo 2007/09/28 12:04:44.73 [Start] >> logs/result.log
C:\batch>echo 2007/09/28 12:04:44.74 >> logs/result.log
C:\batch>echo 2007/09/28 12:04:44.75 Initialize >>logs/result.log
・・・（以下略）・・・
バッチが出力したい情報は全てリダイレクトでログファイルに出力されるようにしてあり（>> logs/result.log）、標準出力は必要の無い情報だったわけです。
※@echo offの動作については、このページの解説が分かりやすいと思います。 |
ということで、バッチファイルの先頭に@echo offを追加し、問題が無いことを検証して、ひとまず対策は完了となりました。
| ※上で提示したJavaのプログラムの実装に、見直しの余地が無いというわけではありません。 |
修正箇所の全ての呼び出し元を調査する作業が抜けていたという反省点はありますが、至急な対応が求められるバグ修正は難しいなぁと思った出来事でした。そして、標準出力が問題となった事象の対策に標準出力を使用し、そこにもまた別の問題があったというレアな体験でした。
最後に
「標準出力処理のように一見、悪影響が無いように見える1行のコードでも、プログラムの動作を致命的に変える可能性はある」ということは、頭の片隅に置いておいた方がいいかもしれません。
[補足] 実際に試す
サンプルプログラムをつくったので、興味のある方は試してみて下さい。10年ほど前の記憶をもとにSpring Bootベースでつくりました。アプリケーションサーバーとRMIサーバーは同じホストにあり、localhostで通信するようなつくりになっています。
動作確認用なので、Webアプリケーションがバッチの完了を検知する処理は実装していません。また、DBアクセスなどのバッチ処理は書かず、一定時間スリープすることで擬似的にバッチの動作を再現しています。
参考資料
