| ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■ 2009年06月28日 Java総合講座 - 初心者から達人へのパスポート vol.159 セルゲイ・ランダウ バックナンバー： http://www.flsi.co.jp/Java_text/ ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■ [このメールマガジンは、画面を最大化して見てください。] ======================================================== ◆ ０１．SOAPのアプリケーション(Webサービス) ======================================================== さて、デバッグのための情報のログ出力として、最低限やっておくことは ・各メソッドを呼び出したときの引数の値 ・呼び出されたメソッドの結果（戻り値） ・ファイルやデータベースなど外部への入出力を行っている場合は、その 出力するデータ値と入力するデータ値 をその発生時点でログ出力することです。（Loggerのdebug()メソッドを使う。） これは定石的なログ出力であり、これらのデータがログに出力されていれば、 あとは大抵の場合は、各メソッドのロジックをソース・コードで調べれば、 不具合の原因箇所を絞り込んでいくことができます。 しかし、ロジックが複雑過ぎるなど、これだけではソース・コードの追跡が 困難な場合は、さらに適所で細かいログ出力を行わせます。 （なお、デバッグを効率的に行うためには、サーバーのプログラムを Eclipseで実行することによって、デバッガーを起動するという方法も ありますが、このやり方については後ほど説明いたします。） 本来、定石的にはすべてのメソッドに上記のログ出力をやらせるのですが、 今回は、話を簡単に済ませるために、不具合箇所がどのように追跡されるか を紹介するために必要な、最小限のデバッグ情報だけを書き出させて説明する ことにします。 前回の最後のHotelClientの実行結果から、プログラムのどこに不具合がある のか、大雑把な推定はできます。 つまり、予約されているはずの部屋が予約されていないかのように検索結果 が返ってくるのは、HotelSoapBindingImplのfindRooms()メソッドの中で 予約済みの部屋のデータを検索結果から除外している箇所の付近に不具合が あると推定できます。 それは、 for (int i = 0; i < numOfNights; i++) { if (roomDbManager.isBooked(roomNum, stayDate)) { roomInfoVector.remove(roomIndex); break; } stayDate.add(Calendar.DAY_OF_MONTH, 1); } という箇所です。 ここでは、RoomDbManagerのisBooked()メソッドを呼び出していますから、 このメソッドの引数の値と戻り値をログに書き出すだけでも、不具合箇所の 追跡が可能でしょう。 というわけで、RoomDbManagerのソース・コードを下記のように書き換えて みて下さい。 -------------------------------------------------------- package jp.co.flsi.lecture.webservice.hotel.db; import java.sql.Date; import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; import java.sql.Statement; import java.util.Calendar; import java.util.GregorianCalendar; import java.util.Vector; import org.apache.log4j.Logger; import jp.co.flsi.lecture.webservice.hotel.RoomInfo; public class RoomDbManager extends DbManager { private static final String selectAllSql = "SELECT * FROM ROOMINFO"; private static final String selectCapaSql = "SELECT * FROM ROOMINFO WHERE CAPACITY > ?"; private static final String selectCapaAndMinRateSql = "SELECT * FROM ROOMINFO WHERE CAPACITY > ? AND RATE > ?"; private static final String selectCapaAndRateSql = "SELECT * FROM ROOMINFO WHERE CAPACITY > ? AND RATE > ? AND RATE < ?"; private static final String selectRoomnumAndDateSql = "SELECT * FROM ROOMBOOK WHERE ROOMNUM = ? AND DATE = ?"; private static Logger logger = Logger.getLogger(RoomDbManager.class); public boolean isBooked(int roomNum, GregorianCalendar stayDate) throws HotelDbException { logger.info("Start ..............."); boolean booked = false; logger.debug("checked room: " + roomNum); logger.debug("checked date: " + stayDate.get(Calendar.YEAR) + "/" + stayDate.get(Calendar.MONTH) + "/" + stayDate.get(Calendar.DAY_OF_MONTH)); try { PreparedStatement selectPs = null; ResultSet rs; selectPs = conn.prepareStatement(selectRoomnumAndDateSql); selectPs.setInt(1, roomNum); selectPs.setDate(2, new Date(stayDate.getTimeInMillis())); rs = selectPs.executeQuery(); while (rs.next()) { booked = true; } selectPs.close(); } catch (SQLException e) { logger.error(e, e); throw new HotelDbException("Error: isBooked() failed!", e); } catch (Throwable e) { logger.error(e, e); } finally { logger.info("End ..............."); } return booked; } public Vector<RoomInfo> getAllData() throws HotelDbException { Vector<RoomInfo> roomInfoList = new Vector<RoomInfo>(); logger.info("Start ..............."); try { Statement selectSql = conn.createStatement(); ResultSet rs = selectSql.executeQuery(selectAllSql); while (rs.next()) { RoomInfo roomInfo = new RoomInfo(); roomInfo.setRoomNum(rs.getInt("ROOMNUM")); logger.info("ROOMNUM = " + rs.getInt("ROOMNUM")); roomInfo.setCapacity(rs.getInt("CAPACITY")); roomInfo.setRatePerNight(rs.getInt("RATE")); roomInfo.setRoomType(rs.getString("TYPE")); if ("Y".equals(rs.getString("WEB"))) { roomInfo.setWebBrowsable(true); } else { roomInfo.setWebBrowsable(false); } roomInfoList.add(roomInfo); } selectSql.close(); } catch (SQLException e) { logger.error(e, e); throw new HotelDbException("Error: getAllData() failed!", e); } catch (Throwable e) { logger.error(e, e); } finally { logger.info("End ..............."); } return roomInfoList; } public Vector<RoomInfo> getData(int capacity, int minRate, int maxRate) throws HotelDbException { Vector<RoomInfo> roomInfoList = new Vector<RoomInfo>(); logger.info("Start ..............."); try { PreparedStatement selectPs = null; ResultSet rs; if (maxRate > -1) { selectPs = conn.prepareStatement(selectCapaAndRateSql); selectPs.setInt(1, capacity); selectPs.setInt(2, minRate); selectPs.setInt(3, maxRate); } else if (minRate > -1) { selectPs = conn.prepareStatement(selectCapaAndMinRateSql); selectPs.setInt(1, capacity); selectPs.setInt(2, minRate); } else { selectPs = conn.prepareStatement(selectCapaSql); selectPs.setInt(1, capacity); } rs = selectPs.executeQuery(); while (rs.next()) { RoomInfo roomInfo = new RoomInfo(); roomInfo.setRoomNum(rs.getInt("ROOMNUM")); logger.info("ROOMNUM = " + rs.getInt("ROOMNUM")); roomInfo.setCapacity(rs.getInt("CAPACITY")); roomInfo.setRatePerNight(rs.getInt("RATE")); roomInfo.setRoomType(rs.getString("TYPE")); if ("Y".equals(rs.getString("WEB"))) { roomInfo.setWebBrowsable(true); } else { roomInfo.setWebBrowsable(false); } roomInfoList.add(roomInfo); } selectPs.close(); } catch (SQLException e) { logger.error(e, e); throw new HotelDbException("Error: getData() failed!", e); } catch (Throwable e) { logger.error(e, e); } finally { logger.info("End ..............."); } return roomInfoList; } } -------------------------------------------------------- どこを変更したのか、わかりますね？ isBooked()メソッドの引数の値をログに書き出すように、 logger.debug("checked room: " + roomNum); logger.debug("checked date: " + stayDate.get(Calendar.YEAR) + "/" + stayDate.get(Calendar.MONTH) + "/" + stayDate.get(Calendar.DAY_OF_MONTH)); の2行を追加したことと、戻り値をログに書き出すように logger.debug("return value: " + booked); という行を追加したことだけです。 なお、上記のログ出力では、日付（GregorianCalendar型）のデータを出力するために 特殊な処理を行っていますが、このように引数や戻り値が複雑な構造を持つ型の場合は、 その中のデータをログに書き出させるための処理が面倒ですね。 これをすべてのメソッドに渡って統一した形式で簡単に実装できる方法がありますので 後ほど説明いたします。 変更が終わりましたら、例によってAntでデプロイしておきましょう。 さて、これからテストするにあたって、上記のログを出力するためには、 デバッグのレベルでログ出力するようにlog4j.propertiesファイルを変更しますが、 すべてのクラスでデバッグのレベルのログ出力をさせてしまうとログが多量に出て しまって大変ですから、デバッグのレベルの対象を特定のクラスだけを絞り込むんで 出力する方法を下に示します。 （log4j.propertiesファイルは C:\Tomcat6.0\webapps\axis\WEB-INF\classes の中にあるのでしたね。） -------------------------------------------------------- log4j.rootLogger=INFO, A1 log4j.appender.A1=org.apache.log4j.ConsoleAppender log4j.appender.A1.layout=org.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern=*%-5p [%d] %c.%M: %m%n # The following log is only for jp.co.flsi.lecture.webservice.hotel.db package. log4j.logger.jp.co.flsi.lecture.webservice.hotel.db=DEBUG, B1 log4j.appender.B1=org.apache.log4j.FileAppender log4j.appender.B1.file=logs/debugout.log log4j.appender.B1.layout=org.apache.log4j.PatternLayout log4j.appender.B1.layout.ConversionPattern=*%-5p [%d] %c.%M: %m%n -------------------------------------------------------- このうち log4j.logger.jp.co.flsi.lecture.webservice.hotel.db=DEBUG, B1 という行は、jp.co.flsi.lecture.webservice.hotel.dbのLoggerオブジェクトの ログ・レベルをDEBUGにし、それに対してB1という名前のAppenderオブジェクトを 設定することを意味します。 こうすれば、jp.co.flsi.lecture.webservice.hotel.dbパッケージの中のすべて のクラスのDEBUG以上のログ（debug()、info()、warn()、error()、fatal()のメ ソッド呼び出しで出力されるログ）が対象になります。 なお、RoomDbManagerクラスだけを対象に指定したい場合は、 log4j.logger.jp.co.flsi.lecture.webservice.hotel.db.RoomDbManager=DEBUG, B1 と指定すればいいのですが、log4j.logger.の右側には、jpやjp.coやjp.co.flsi、 あるいは・・・（中略）・・・、jp.co.flsi.lecture.webservice.hotelのように、 もっと上の階層の名前を指定することもでき、そうすれば、もっと多くのクラスが 対象になります。 （なお、これらの名前は、ソース・コード内にRoomDbManager.classによって、つまり private static Logger logger = Logger.getLogger(RoomDbManager.class); という行によって指定されたLoggerオブジェクトの名前の一部または全部です。 この行によって、（パッケージ名を含む）クラス名をLoggerオブジェクトの名前 にしているのです。） そして、今回は、 log4j.appender.B1.file=logs/debugout.log というように指定しておきましたので、このDEBUGレベルのログ出力のファイル名は、 debugout.logになります。 なお、rootLogger（階層構造の根元(root)のLoggerオブジェクト）のほうは、 log4j.appender.A1=org.apache.log4j.ConsoleAppender という指定によって、Tomcatの標準出力に戻しておきました。 これで、jp.co.flsi.lecture.webservice.hotel.dbパッケージの（DEBUG以上の）ログ はdebugout.logに出力され、他のログは stdout_YYYYMMDD.log (ここでYYYYMMDDは年月日を表す数字) に出力されるというように、２つのファイルに分類されて出力されることになります。 では、log4j.propertiesファイルを上記のように変更したら、Tomcatを再起動して テストしてみましょう。 HotelClientを実行すると、前回と同じく ============================================== Room number : 307 Room capacity : 3 Rate per night : 30000 Room type : SUITE Web browsable : true ============================================== という検索結果が出ますね。 では、ログ（debugout.log）のほうを見てみましょう。 日付の引数の値がなんだか変ですね。 *DEBUG [2009-06-28 23:01:03,187] jp.co.flsi.lecture.webservice.hotel.db.RoomDbManager.isBooked: checked date: 2009/10/30 から始まっているのはいいけれど、3泊の指定のはずなのに、日付はどんどん増える 一方で、最後は *DEBUG [2009-06-28 23:01:03,437] jp.co.flsi.lecture.webservice.hotel.db.RoomDbManager.isBooked: checked date: 2009/11/20 というように2009/11/20で終わっている。 これは、isBooked()メソッドに渡す日付の引数の値が狂っていることを意味します。 そこで、HotelSoapBindingImplのfindRooms()メソッドの中で予約済みの部屋のデータ を検索結果から除外している箇所の日付の処理部分をよく見てみると、 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 (roomDbManager.isBooked(roomNum, stayDate)) { roomInfoVector.remove(roomIndex); break; } stayDate.add(Calendar.DAY_OF_MONTH, 1); } } となっていて、単純にstayDateに日にちを1日ずつ加算（add()メソッドの実行）して いるばかりで、roomIndexが変わったら（つまり、部屋が変わったら）stayDateを 最初の日付（ここでは2009年10月30日）にリセットするということを行っていない ことに気づきます。 単純にstayDateのリセットを行うのを忘れていたのが不具合の原因だということが わかりますね。そこで、上の部分を for (int roomIndex = roomInfoSize - 1; roomIndex > -1; roomIndex--) { RoomInfo roomInfo = roomInfoVector.get(roomIndex); stayDate.setTime(dateFormat.parse(startDate)); // 宿泊日の初日にリセット int roomNum = roomInfo.getRoomNum(); for (int i = 0; i < numOfNights; i++) { if (roomDbManager.isBooked(roomNum, stayDate)) { roomInfoVector.remove(roomIndex); break; } stayDate.add(Calendar.DAY_OF_MONTH, 1); } } のように変更してみましょう。念のために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.HotelDbException; import jp.co.flsi.lecture.webservice.hotel.db.RoomDbManager; 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; RoomDbManager roomDbManager = new RoomDbManager(); 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)); if (stayDate.get(Calendar.YEAR) != Integer.parseInt(startDate.substring(0, 4)) || (stayDate.get(Calendar.MONTH) + 1) != Integer.parseInt(startDate.substring(4, 6)) || stayDate.get(Calendar.DAY_OF_MONTH) != Integer.parseInt(startDate.substring(6))) { logger.info("Invalid parameter: startDate(= " + startDate + ") is not correct: impossible date"); throw new RemoteException("Invalid parameter: startDate(= " + startDate + ") is not correct: impossible date"); } 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."); } roomDbManager.connect(); roomInfoVector = roomDbManager.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); stayDate.setTime(dateFormat.parse(startDate)); // 宿泊日の初日にリセット int roomNum = roomInfo.getRoomNum(); for (int i = 0; i < numOfNights; i++) { if (roomDbManager.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 e; } catch (Throwable e) { logger.error(e, e); } finally { try { roomDbManager.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 ..............."); BookingDbManager bookingDbManager = new BookingDbManager(); 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)); if (startStayDate.get(Calendar.YEAR) != Integer.parseInt(startDate.substring(0, 4)) || (startStayDate.get(Calendar.MONTH) + 1) != Integer.parseInt(startDate.substring(4, 6)) || startStayDate.get(Calendar.DAY_OF_MONTH) != Integer.parseInt(startDate.substring(6))) { logger.info("Invalid parameter: startDate(= " + startDate + ") is not correct: impossible date"); throw new RemoteException("Invalid parameter: startDate(= " + startDate + ") is not correct: impossible date"); } 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."); } bookingDbManager.connect(); bookingDbManager.insertData(roomReserve.getRoomNum(), roomReserve.getName(), roomReserve.getAddress(), roomReserve.getTelNo(), startStayDate, numOfNights, numOfLodgers); } catch (HotelDbException e) { logger.error(e, e); return false; } catch (ParseException e) { logger.info(e); throw new RemoteException("ParseException occured (startDate format not correct)", e); } catch (RemoteException e) { logger.info(e); throw e; } catch (Throwable e) { logger.error(e, e); return false; } finally { try { bookingDbManager.disconnect(); } catch (Exception e) { logger.info("Disconnect failed or there is no connection."); } logger.info("End ..............."); } return true; } } -------------------------------------------------------- 修正が終わったら、再度Antでデプロイした後、HotelClientを実行して再度テスト してみましょう。 今度はうまくいきますね。つまり、検索結果には307号室はリストされませんね。 ログを見てみても、日付が変だったのは直っていますね。 これで一件落着です。 （次回に続く） では、今日はここまでにします。 ┏━━━━━━━━━━━━━━━━━━━━━━━━━━━┓ ★ホームページ： 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. 不許無断複製 |