ログの最近のブログ記事

前回はDJUnitを使った単体試験を紹介しましたが、今回はWEBアプリケーションでよく使われるStrutsのアクションクラスのテストを楽に行うライブラリを紹介いたします。
StrutsTestCaseを利用することによってアクション単位にテストすることが可能でブラウザを開かなくても試験ができます。今まではアクションの試験は実際にブラウザを動かす必要があったため面倒なものでした。さらに画面から入力される情報をプログラム上で作成するので未入力でボタンを押したなどのバリデートのテストも同時行えます。

StrutsTestCase for JUnit
http://sourceforge.net/project/showfiles.php?group_id=39190

cactus(今回はStrutsTestCaseの中にあるjarを使いますので落とさなくても良いです)
http://jakarta.apache.org/cactus/downloads.html

【環境・バージョン情報】
OS：WindowsXP SP3
Eclipse:3.3.2
JDK：JDK1.5.0
StrutsTestCase：strutstest214-1.2_2.4.zip
Tomcat：6.0.16
struts:1.2
 

すでにhttp://localhost:8080/sampleでログイン処理後(セッションにユーザID格納)、一覧ページを開くような処理が実装されているとします。

StrutsTestCase for JUnitのページからダウンロードしたstrutstest214-1.2_2.4.zipのexamples\test.warに入っているjarの中身を利用します。

【新たに追加したLIB】
aspectjrt-1.2.1.jar
cactus-13-1.7.jar
commons-collections.jar
commons-httpclient-2.0.jar
junit-4.0.jar
strutstest-2.1.4.jar

WEB.xmlに記述を追加します。

【WEB.xmlの追加】
    <!-- Cactus Servlet Redirector configuration -->
    <servlet>
        <servlet-name>ServletRedirector</servlet-name>
        <servlet-class>org.apache.cactus.server.ServletTestRedirector</servlet-class>
    </servlet>

    <!-- Cactus Servlet Redirector URL mapping -->
    <servlet-mapping>
        <servlet-name>ServletRedirector</servlet-name>
        <url-pattern>/ServletRedirector</url-pattern>
    </servlet-mapping>

以下のように記述したcactus.propertiesをsrc直下に置きコンパイルすればclassesにコピーされます。

【cactus.propertiesの中身】
cactus.contextURL = http://localhost:8080/sample
cactus.servletRedirectorName = ServletRedirector
cactus.enableLogging=true
 

そこで以下のようなテストプログラムを作成して、Tomcatプラグインを起動しつつ、JUnitで実行してみると

と無事にJUnitが完了できました。

setUpメソッドにログイン処理を書くことができることによって、ログインした状態で各ページのテストを実行することが可能です。これはわざわざブラウザでログインしないでテストできるので、シナリオを作ってテストするようなツールで実行するより早くテストが実行できるかもしれません。

最終的にはJSPも含めたブラウザからのテストをしないといけないのですが、アクションのテスト結果も出せなどと言われた場合や、余裕があるプロジェクトでは利用する価値はあるのではないでしょうか。

「犯人はこの何にいる！！」

マガジンで連載していた、金田一少年の事件簿で、金田一君が6話ぐらいかけて犯人を見つけていましたが、被害者が死ぬ前に、ダイイングメッセージで犯人の名前を残してくれたら、一話かからず事件が解決するでしょう。

プログラミングでも同じ事が言えます。
プログラムが死んだ時(プログラムが死ぬという事はありえてはいけないのですが、今回は比喩でつかいます。)、ダイイングメッセージに値するログを残さなかった場合、犯人(バグ)を見つけるのに大変な苦労がかかります。
プログラムが死ぬ前に最後の力を振り絞って、ログを残してくれれば、調査するのに何日も徹夜せず済むかもしれませんしれません。
プライベートな時間を仕事に削られずにすんだかもしれません。
それが原因で彼女とも別れずに。。。

。。。それほどログは重要なものです。
ということで前置きが長かったですが、今回はログについて書きたいと思います。

私は現地で作業をする機会が多く、その時に他人が作ったプログラムの問題を改修、調査する事があります。まず問題が起きた時にはログを確認するのですが、大半のログは見ただけでは、何が原因で問題が発生したのか解りません。

例えば、「○○処理で異常が発生しました処理を終了します。」と結果だけログに出力してあり、何が原因で問題が発生したかが出力されていない場合や、問題が発生したソースの行数が出力されていているだけで、ソースを解析しないと原因が解らない等、結果調査に時間が掛かってしまいます。

それではどうすれば良いか？
私は、ログを出力する際に下記の事を心がけるようにしています。

１、引数の値をログに出力する

問題が起きる原因として、関数に渡す引数に原因がある事が多いと感じています。
引数がNULLだったり、空文字だったりと原因は多様にありますが、問題が発生した時にログに引数の値が出力しているだけで、原因を調査する時間が格段に短縮されます。
一番良いのは、どの引数が何が原因で問題が発生しているのかがログに出力されていれば一発で調査終了です。当り前のような事で、とて重要な事です。

また、ログを出力するにあたって関数の作り方も私なりのポイントがあるのですが、それはまたの機会に。。。

２、関数の開始、終了をログに出力する

関数の始めと、終りに「○○関数処理を開始します。」「○○関数処理を正常終了します。」とログに出力するようにします。
ここで、重要なのは正常終了した時もログに出力しているという事です。
そうする事によって、問題が発生した事自体ログに出力されていなくても「正常終了」のログがなかった場合、そこで問題が発生した事が解りますし、どこまで処理を行っているかが解りパッチ対応が比較的簡単にできます。
注意しないといけない点として、for文なので1000回呼び出される関数に上記ログを仕込んでしまうと、1000回出力されてしまうので、そういった場合はfor文の前と終了した時に「開始」、「終了」ログを仕込む等の考慮が必要です。　　

３、問題が起きた時に目印となるものをログに出力する

私は、lessコマンドを使いログをリアルタイムで見て、実際にプログラムが動いている事を実感するのが趣味なのですが、ログの出力が頻繁に起きていると問題が発生しても気づかない事があります。
そこで問題が発生した時に「***************異常発生***************」などの様な、目立つ印を出力しておくと、リアルタイムで見ていても解りやすいです。
また問題を検索する時のキーワードにも使えます。

４、ログの見やすさ

ログをただ単に出力するだけではダメです。
問題が発生した時に調査するのは人の目なわけですから、見やすさも重要です。
多くのシステムでは、一定の処理を繰り返し行う事で成りったっているいると思いますが、その一定の処理が終わった後に空行を入れるだけで、ログが見やすくなります。

たまに、見やすさが考慮されていないログがあり、見ているだけで酔うことがあります。。。

ログをたくさん出力すると、SEの方達は処理速度が落ちないか、ログファイルがサーバのディスク容量を食い尽くさないかと心配しがちですが、最近のサーバのスペックならばログを出力したぐらいで体感的に処理が遅くなる事もありませんし、ディスク容量も、ログを一定期間保持した後に削除する仕組みがあれば問題ありません。
問題なのは、ログに出力する情報を少なくする事により問題を改修する時間が掛かってしまうことです。

と、偉そうな事を書いていますが、プログラマーになりたての頃、問題が多発した事があり、その時に学んだ事なんですがね。。。