| ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■ 2009年05月17日 Java総合講座 - 初心者から達人へのパスポート vol.153 セルゲイ・ランダウ バックナンバー： http://www.flsi.co.jp/Java_text/ ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■ [このメールマガジンは、画面を最大化して見てください。] ======================================================== ◆ ０１．SOAPのアプリケーション(Webサービス) ======================================================== さて、どんな例外も逃さず記録して、例外がどこで発生しているか 分かるように、ログを取るためにはどうすればよいでしょうか？ すべての例外を捕捉すればいいのだから、catchブロックの並びの最後に catch (Exception e) { logger.error(e); } というcatchブロックを追加すればいいでしょうか。 実は、これでも不十分です。 これだと、ログには *ERROR [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.HotelSoapBindingImpl.findRooms: java.lang.NullPointerException （ただし、YYYY MM DD HH MM SS SSSの部分は実際は数字） のようにNullPointerExceptionの記録は書かれますが、これだけではどこで例外が 発生したのかさっぱり分かりません。 ではどうすればいいかと言うと、 catch (Exception e) { logger.error(e, e); } のように、error()メソッドに第二引数も指定します。このように第二引数を指定する と、例外eのスタック・トレース（stack trace）がログに書き出されることになります。 スタック・トレースというのは、その例外の発生箇所をメソッドの呼び出し（入れ子に なったメソッド呼び出し）ごとに書き並べていったもの（あとで実際のトレースの例を 提示します）ですので、これを見れば例外の発生原因を調べられます。 （基本的には、これまで logger.error(e); と書いてきた行は、すべて logger.error(e, e); に書き換えるべきです。） なお一般には、Exception以外にも投げられる(Throwable)ものがある（Errorなど）ため、 さらに catch (Throwable e) { logger.error(e, e); } という指定にします。ExceptionもThrowableのサブクラスですので、Throwableを catchしておけばExceptionも捕捉できます。 ただし、このとき注意しないといけないことは、このcatchブロックでは、なんでも 捕捉してしまいますから、本来は外に投げ出さなければならないRemoteExceptionまで 捕捉してしまうということです。 このため、 catch (RemoteException e) { logger.info(e); throw new RemoteException(e.getMessage()); } catch (Throwable e) { logger.error(e, e); } のように、Throwableを捕捉する前にRemoteExceptionを捕捉して再度throwし直すという ことを行っておきます。 では、これらを反映して、HotelSoapBindingImplのソース・コードを下記のように 修正しましょう。 -------------------------------------------------------- /** * HotelSoapBindingImpl.java * * このファイルはWSDLから自動生成されました / [en]-(This file was auto-generated from WSDL) * Apache Axis 1.4 Apr 22, 2006 (06:55:48 PDT) WSDL2Java生成器によって / [en]-(by the Apache Axis 1.4 Apr 22, 2006 (06:55:48 PDT) WSDL2Java emitter.) */ package jp.co.flsi.lecture.webservice.hotel; import java.rmi.RemoteException; import java.text.ParseException; import java.text.SimpleDateFormat; import java.util.Calendar; import java.util.GregorianCalendar; import java.util.Vector; import jp.co.flsi.lecture.webservice.hotel.db.BookingDbManager; import jp.co.flsi.lecture.webservice.hotel.db.DbManager; import jp.co.flsi.lecture.webservice.hotel.db.HotelDbException; import jp.co.flsi.lecture.webservice.hotel.db.RoomBookDbManager; import jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager; import org.apache.log4j.Logger; public class HotelSoapBindingImpl implements Hotel{ private static Logger logger = Logger.getLogger(HotelSoapBindingImpl.class); public RoomInfo[] findRooms(StayInfoInput stayInfo) throws RemoteException { logger.info("Start ..............."); Vector<RoomInfo> roomInfoVector = null; try { String startDate = stayInfo.getStartDate(); if (startDate.length() != 8) { logger.info("Invalid parameter: startDate(= " + startDate + ") format not correct: must be 8 letters"); throw new RemoteException("Invalid parameter: startDate(= " + startDate + ") is invalid: must be 8 letters"); } SimpleDateFormat dateFormat = new SimpleDateFormat("yyyyMMdd"); GregorianCalendar stayDate = new GregorianCalendar(); stayDate.setTime(dateFormat.parse(startDate)); int numOfNights = stayInfo.getNumOfNights(); int numOfLodgers = stayInfo.getNumOfLodgers(); if (numOfNights < 1 || numOfLodgers < 1) { logger.info("Invalid parameter: numOfNights (" + numOfNights + ") or numOfLodgers (" + numOfLodgers + ") is invalid."); throw new RemoteException("Invalid parameter: numOfNights (" + numOfNights + ") or numOfLodgers (" + numOfLodgers + ") is invalid."); } DbManager.connect(); roomInfoVector = RoomInfoDbManager.getData(numOfLodgers, stayInfo.getMinRatePerNight(), stayInfo.getMaxRatePerNight()); int roomInfoSize = roomInfoVector.size(); if (roomInfoSize > 0) { for (int roomIndex = roomInfoSize - 1; roomIndex > -1; roomIndex--) { RoomInfo roomInfo = roomInfoVector.get(roomIndex); int roomNum = roomInfo.getRoomNum(); for (int i = 0; i < numOfNights; i++) { if (RoomBookDbManager.isBooked(roomNum, stayDate)) { roomInfoVector.remove(roomIndex); break; } stayDate.add(Calendar.DAY_OF_MONTH, 1); } } } } catch (HotelDbException e) { logger.error(e, e); } catch (ParseException e) { logger.info(e); throw new RemoteException("ParseException occured (startDate format not correct)", e); } catch (RemoteException e) { logger.info(e); throw new RemoteException(e.getMessage()); } catch (Throwable e) { logger.error(e, e); } finally { try { DbManager.disconnect(); } catch (Exception e) { logger.info("Disconnect failed or there is no connection."); } logger.info("End ..............."); } return roomInfoVector.toArray(new RoomInfo[roomInfoVector.size()]); } public boolean reserveRoom(RoomReserveInfo roomReserve) throws RemoteException { logger.info("Start ..............."); try { String startDate = roomReserve.getStartDate(); if (startDate.length() != 8) { logger.info("Invalid parameter: startDate(= " + startDate + ") format not correct: must be 8 letters"); throw new RemoteException("Invalid parameter: startDate(= " + startDate + ") is invalid: must be 8 letters"); } SimpleDateFormat dateFormat = new SimpleDateFormat("yyyyMMdd"); GregorianCalendar startStayDate = new GregorianCalendar(); startStayDate.setTime(dateFormat.parse(startDate)); int numOfNights = roomReserve.getNumOfNights(); int numOfLodgers = roomReserve.getNumOfLodgers(); if (numOfNights < 1 || numOfLodgers < 1) { logger.info("Invalid parameter: numOfNights (" + numOfNights + ") or numOfLodgers (" + numOfLodgers + ") is invalid."); throw new RemoteException("Invalid parameter: numOfNights (" + numOfNights + ") or numOfLodgers (" + numOfLodgers + ") is invalid."); } DbManager.connect(); BookingDbManager.insertData(roomReserve.getRoomNum(), roomReserve.getName(), roomReserve.getAddress(), roomReserve.getTelNo(), startStayDate, numOfNights, numOfLodgers); } catch (HotelDbException e) { logger.error(e, e); } catch (ParseException e) { logger.info(e); throw new RemoteException("ParseException occured (startDate format not correct)", e); } catch (RemoteException e) { logger.info(e); throw new RemoteException(e.getMessage()); } catch (Throwable e) { logger.error(e, e); } finally { try { DbManager.disconnect(); } catch (Exception e) { logger.info("Disconnect failed or there is no connection."); } logger.info("End ..............."); } return true; } } -------------------------------------------------------- なお、HotelSoapBindingImpl以外のクラス（jp.co.flsi.lecture.webservice.hotelパッ ケージの他のクラス、およびjp.co.flsi.lecture.webservice.hotel.dbパッケージの クラス）についても同様のcatchブロックの追加／修正をすべきですが、これは読者の課題 とし、ここでは説明を省略いたします。 ソース・コードの修正が終わったら、保管した後、前回と同じくAntでデプロイを 行っておきましょう。 ここで、ログを見やすくするために、log4j.propertiesファイルを以前の -------------------------------------------------------- log4j.rootLogger=INFO, A1 log4j.appender.A1=org.apache.log4j.FileAppender log4j.appender.A1.file=logs/stdout.log log4j.appender.A1.layout=org.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern=*%-5p [%d] %c.%M: %m%n -------------------------------------------------------- という内容に書き換えておきましょう。 （log4j.propertiesファイルの所在場所を忘れた人は C:\Tomcat6.0\webapps\axis\WEB-INF\classes の中を見てください。） では、Tomcatをいったん停止してから、ログ・ファイル（stdout.log）を削除 しておきましょう。（古いログが残っていると紛らわしいので消しておくのです。） （ログ・ファイルの所在地は C:\Tomcat6.0\logs でしたね。） 続いて、Tomcatを再度起動し直してください。 そして、HotelClientを実行してみて下さい。 ログ・ファイル（stdout.log）を見てみると、 -------------------------------------------------------- *ERROR [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.HotelSoapBindingImpl.findRooms: java.lang.NullPointerException java.lang.NullPointerException at jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager.getData(RoomInfoDbManager.java:60) at jp.co.flsi.lecture.webservice.hotel.HotelSoapBindingImpl.findRooms(HotelSoapBindingImpl.java:54) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java:397) at org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.java:186) at org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:323) at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32) at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118) at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83) at org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:454) at org.apache.axis.server.AxisServer.invoke(AxisServer.java:281) at org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:699) at javax.servlet.http.HttpServlet.service(HttpServlet.java:710) at org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.java:327) at javax.servlet.http.HttpServlet.service(HttpServlet.java:803) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:263) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:584) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Unknown Source) -------------------------------------------------------- というような箇所がありますね。このうち2行目（java.lang.NullPointerExceptionの行） 以降がスタック・トレースです。 これを上から順に見ていくと、まず、NullPointerExceptionが発生しているのは、 RoomInfoDbManagerのgetData()メソッドの中で、RoomInfoDbManager.javaの60行目で あることが分かります。 そして、このgetData()メソッドはHotelSoapBindingImplのfindRooms()メソッドの中で、 HotelSoapBindingImpl.javaの54行目で呼び出されていることがわかります。 それから、さらに下に見ていくと、さらにそれを呼び出しているのがどのクラスのどの メソッドで・・・ということが分かりますが、ここらへんになると自分が作ったクラス ではないので、無視しましょう。 というわけで、まずHotelSoapBindingImpl.javaの54行目を見てみましょう。 roomInfoVector = RoomInfoDbManager.getData(numOfLodgers, stayInfo.getMinRatePerNight(), stayInfo.getMaxRatePerNight()); という行になっていますね。確かにRoomInfoDbManagerのgetData()メソッドを呼び出して います。 次にRoomInfoDbManager.javaの60行目を見てみましょう。 selectPs = conn.prepareStatement(selectCapaAndRateSql); という行になっていますが、ここでNullPointerExceptionが発生しているわけです。 NullPointerExceptionというのは、変数の値がnullになっているために問題が生じて いることを意味する例外です。 つまり、変数にちゃんとした値が設定されていないために問題が起こっているのです。 いったいどの変数でしょうか？ selectCapaAndRateSqlはちゃんと設定されていますね。（selectCapaAndRateSqlに カーソルを入れてF3キーを押してみる）これは問題ないです。 connはどうでしょうか？connはDbManagerの中で定義されていますね。 connにはconnect()メソッドを実行したときにConnectionオブジェクトが設定される ようにしたはずですが、この設定がちゃんと行われていない可能性があります。 と思ってよくみると、connect()メソッドの中(20行目)では、 if (conn != null) { ・ ・ conn = ds.getConnection(); ・ ・ } というように、connがnullでない場合に設定を行っています。なんと、これでは、 あべこべじゃないですか！！！（実はわざとこうしておいたのだが。） このままでは、connがnullの場合には何も設定されず、nullのままになって しまいます。 本当は、connがnullの場合（つまり、まだConnectionオブジェクトが設定されていな い場合）にConnectionオブジェクトを設定しなければいけません。 というわけで、DbManager.javaの20行目の if (conn != null) { の行を if (conn == null) { に書き換えてください。 書き換えが終わったら、保管して、再度Antでデプロイを行っておきましょう。 では、HotelClientを再度、実行してみて下さい。 今度は例外は発生せず、正常に結果が返ってきますね。 というわけで、やはり先ほどの if (conn != null) { の箇所が原因でNullPointerExceptionが発生していたのですね。 connがnullのままだと、 selectPs = conn.prepareStatement(selectCapaAndRateSql); を実行しようとしても、connがオブジェクトではなくnullであるからprepareStatement() メソッドは実行できず、NullPointerExceptionが通知されたのです。 これでめでたしめでたし！・・・と思うのは、まだ早いです。 では、続いてHotelClientをもう一度、実行してみて下さい。 今度は、またエラーになってしまいますね。 さっきは、うまくいったのに、もう一度実行すると今度はエラー・・・ なぜだかわかりますか？ ログを見てください。うまくいったときには、 *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.HotelSoapBindingImpl.findRooms: Start ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.DbManager.connect: Start ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.DbManager.connect: Connection has been gotten. *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.DbManager.connect: End ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager.getData: Start ............... というような記録になっていた部分が、今度エラーになったときには、 *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.HotelSoapBindingImpl.findRooms: Start ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.DbManager.connect: Start ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.DbManager.connect: End ............... *INFO [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager.getData: Start ............... *ERROR [YYYY-MM-DD HH:MM:SS,SSS] jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager.getData: java.sql.SQLException: Connection is closed. というような記録になっています。 つまり、うまくいったときにはDbManagerのconnect()メソッドの中で「Connection has been gotten.」 というメッセージをログに書き出していたのに、今度エラーになったときには、この メッセージは書き出されず、「Connection is closed.」というSQLExceptionが通知されて いることがわかります。 これについては、 Caused by: java.sql.SQLException: Connection is closed. at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.checkOpen(PoolingDataSource.java:175) at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:301) at jp.co.flsi.lecture.webservice.hotel.db.RoomInfoDbManager.getData(RoomInfoDbManager.java:60) という記録があることから、RoomInfoDbManager.javaの60行目、つまり selectPs = conn.prepareStatement(selectCapaAndRateSql); というコードを実行しようとしたときにエラーが発生したことがわかります。 この時点でconn（Connectionオブジェクト）がクローズされている状態だったという ことです。 このconnがクローズされている状態だったということと、DbManagerのconnect()メソッド の中で「Connection has been gotten.」というメッセージがログに書き出されなかった こと、それから、HotelClientの一回目の実行ではうまくいくのに、二回目以降の実行で エラーになることを頭に入れて、DbManagerのソース・コードをよく見ると、原因が わかりますね。 （次回に続く） では、今日はここまでにします。 ┏━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ★ホームページ： http://www.flsi.co.jp/Java_text/ ★このメールマガジンは 「まぐまぐ（http://www.mag2.com）」 を利用して発行しています。 ★バックナンバーは http://www.flsi.co.jp/Java_text/ にあります。 ★このメールマガジンの登録／解除は下記Webページでできます。 http://www.mag2.com/m/0000193915.html ★このメールマガジンへの質問は下記Webページにて受け付けて います。わからない所がありましたら、どしどしと質問をお寄 せください。 http://www.flsi.co.jp/Java_text/ ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ Copyright (C) 2009 Future Lifestyle Inc. 不許無断複製 |