スタックトレースの読み方

僕もスタックトレースの読み方についてちょっと書いてみる。
例はOracle Technology Network for Java Developers | Oracle Technology Network | Oracleを使う。

  1:class MyClass {
  2:     public static void main (String  args) {
  3:         crunch(null);
  4:     }
  5:     static void crunch(int a) {
  6:         mash(a);
  7:     }
  8:     static void mash(int[] b) {
  9:         System.out.println(b[0]);
 10:     }
 11: }

これを実行すると以下のようになる

Exception in thread "main" java.lang.NullPointerException
	at MyClass.mash(MyClass.java:9)
	at MyClass.crunch(MyClass.java:6)
	at MyClass.main(MyClass.java:3)

まず発生した例外クラス(NullPointerException)が表示され、その下のatにて下から順に呼ばれたメソッドが表示されます。数字は行番号で次に呼び出すメソッドの場所を表しています。
この例ではMyClass.mainメソッド内の3行目でcrunchメソッドを呼び出しており、crunchメソッド内の6行目でmashメソッドを呼び出しています。
そして一番上のatの場所(9行目)が例外が発生した箇所です。

次に例外がラップされるケースを見てみましょう。

  1:public class Junk {
  2:     public static void main(String args[]) {
  3:         try {
  4:             a();
  5:         } catch(HighLevelException e) {
  6:             e.printStackTrace();
  7:         }
  8:     }
  9:     static void a() throws HighLevelException {
 10:         try {
 11:             b();
 12:         } catch(MidLevelException e) {
 13:             throw new HighLevelException(e);
 14:         }
 15:     }
 16:     static void b() throws MidLevelException {
 17:         c();
 18:     }   
 19:     static void c() throws MidLevelException {
 20:         try {
 21:             d();
 22:         } catch(LowLevelException e) {
 23:             throw new MidLevelException(e);
 24:         }
 25:     }
 26:     static void d() throws LowLevelException {
 27:        e();
 28:     }
 29:     static void e() throws LowLevelException {
 30:         throw new LowLevelException();
 31:     }
 32: }
 33:
 34: class HighLevelException extends Exception {
 35:     HighLevelException(Throwable cause) { super(cause); }
 36: }
 37:
 38: class MidLevelException extends Exception {
 39:     MidLevelException(Throwable cause)  { super(cause); }
 40: }
 41: 
 42: class LowLevelException extends Exception {
 43: }

上記を実行すると書きのようになります。

HighLevelException: MidLevelException: LowLevelException
	at Junk.a(Junk.java:13)
	at Junk.main(Junk.java:4)
Caused by: MidLevelException: LowLevelException
	at Junk.c(Junk.java:23)
	at Junk.b(Junk.java:17)
	at Junk.a(Junk.java:11)
	... 1 more
Caused by: LowLevelException
	at Junk.e(Junk.java:30)
	at Junk.d(Junk.java:27)
	at Junk.c(Junk.java:21)
	... 3 more

ラップされるたびにCaused by〜となっていきます。見方としては一番下のCaused by〜のうちアプリに関係している一番上のatの部分に注目すればいいんじゃないでしょうか。
この例では30行目でLowLevelExceptionが発生し、23行目でLowLevelExceptionはMidLevelExceptionにラップされ、13行目でMidLevelExceptionはHighLevelExceptionにラップされています。

もっとリアルっぽい例としてバッチもどきを見てみます。DBはHSQLDB1.8.0.10です。DBExceptionは自作の例外クラスです。finallyでcloseしてないとかprintStackTraceじゃなくてロガーだろっていうのはおいときますｗ

  1:import java.sql.Connection;
  2:import java.sql.DriverManager;
  3:import java.sql.ResultSet;
  4:import java.sql.SQLException;
  5:import java.sql.Statement;
  6:
  7:import org.hsqldb.lib.java.JavaSystem;
  8:
  9:public class SampleMain {
 10:	private static final String DB_URL = "jdbc:hsqldb:mem:.";
 11:
 12:	public static void main(String[] arguments) {
 13:		try {
 14:			process();
 15:		} catch (Throwable e) {
 16:			e.printStackTrace();
 17:		}
 18:	}
 19:
 20:	private static void process() {
 21:		try {
 22:			Class.forName("org.hsqldb.jdbcDriver");
 23:			Connection connection = DriverManager.getConnection(DB_URL);
 24://			JavaSystem.setLogToSystem(true);//エラーコードを取る場合はコメントアウトをはずす
 25:			createTable(connection);
 26:			insertTable(connection);
 27:			selectTable(connection);
 28:			updateTable(connection);
 29:			selectTable(connection);
 30:			dropTable(connection);
 31:			connection.close();
 32:		} catch (SQLException e) {
 33:			throw new DBException(e);
 34:		} catch (ClassNotFoundException e) {
 35:			throw new RuntimeException(e);
 36:		}
 37:	}
 38:
 39:	private static void createTable(Connection connection) throws SQLException {
 40:		Statement statement = connection.createStatement();
 41:		statement
 42:				.execute("CREATE TABLE Person (id INTEGER PRIMARY KEY, name VARCHAR(16), age INTEGER)");
 43:		statement.close();
 44:	}
 45:
 46:	private static void insertTable(Connection connection) throws SQLException {
 47:		Statement statement = connection.createStatement();
 48:		statement.execute("INSERT INTO Person VALUES(1, 'hoge', 30)");
 49:		statement.execute("INSERT INTO Person VALUES(1, 'hoge', 30)");//ここで一意制約エラーを起こす
 50:		statement.close();
 51:	}
 52:
 53:	private static void updateTable(Connection connection) throws SQLException {
 54:		Statement statement = connection.createStatement();
 55:		statement.execute("UPDATE Person SET age=20");
 56:		statement.close();
 57:	}
 58:
 59:	private static void selectTable(Connection connection) throws SQLException {
 60:		Statement statement = connection.createStatement();
 61:		statement.execute("SELECT * FROM Person");
 62:		ResultSet resultSet = statement.getResultSet();
 63:		while (resultSet.next()) {
 64:			System.out.println(resultSet.getInt("id"));
 65:			System.out.println(resultSet.getString("name"));
 66:			System.out.println(resultSet.getInt("age"));
 67:		}
 68:		statement.close();
 69:	}
 70:
 71:	private static void dropTable(Connection connection) throws SQLException {
 72:		Statement statement = connection.createStatement();
 73:		statement.execute("DROP TABLE Person");
 74:		statement.close();
 75:	}
 76:
 77:}

上記を実行すると以下のようになります。

DBException: java.sql.SQLException: Violation of unique constraint SYS_PK_47: duplicate value(s) for column(s) ID
	at SampleMain.process(SampleMain.java:33)
	at SampleMain.main(SampleMain.java:14)
Caused by: java.sql.SQLException: Violation of unique constraint SYS_PK_47: duplicate value(s) for column(s) ID
	at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
	at org.hsqldb.jdbc.jdbcStatement.fetchResult(Unknown Source)
	at org.hsqldb.jdbc.jdbcStatement.execute(Unknown Source)
	at SampleMain.insertTable(SampleMain.java:49)
	at SampleMain.process(SampleMain.java:26)
	... 1 more

SQLExceptionがDBExceptionにラップされていますね。
一番下のCaused by〜のうちアプリに関係している一番上のat部分はSampleMain.javaの49行目なのでここの呼び出しで例外が発生していることがわかります。たまにCaused by〜の部分を除いて例外の上のほうだけログとして送ってくる人がいるようですが、それだけだとわからないので全部送りましょう。

ちなみにUnknown SourceとなっているのはHSQLDBをコンパイルする際にオプションでdebugをオフにしているためです。
build.xmlの

をonにすれば行番号もでます。

また33行目の

throw new DBException(e);

を

throw new DBException();

として実行すると、以下のようになってどこがおかしいのかさっぱりわかりません。例外のもみ消しはやめましょう。

DBException
	at SampleMain.process(SampleMain.java:33)
	at SampleMain.main(SampleMain.java:14)

おまけ

Derby 10.4.1.3だと以下のような感じ。Class.forNameしなくていいみたいね。

  1:import java.sql.Connection;
  2:import java.sql.DriverManager;
  3:import java.sql.ResultSet;
  4:import java.sql.SQLException;
  5:import java.sql.Statement;
  6:
  7:
  8:public class SampleMainDerby {
  9:	private static final String DB_URL = "jdbc:derby:SampleDB;create=true";
 10:
 11:	public static void main(String[] arguments) {
 12:		try {
 13:			process();
 14:		} catch (Throwable e) {
 15:			e.printStackTrace();
 16:		}
 17:	}
 18:
 19:	private static void process() {
 20:		try {
 21:			Connection connection = DriverManager.getConnection(DB_URL);
 22:			createTable(connection);
 23:			insertTable(connection);
 24:			selectTable(connection);
 25:			updateTable(connection);
 26:			selectTable(connection);
 27:			dropTable(connection);
 28:			connection.close();
 29:		} catch (SQLException e) {
 30:			throw new DBException(e);
 31:		}
 32:	}
 33:
 34:	private static void createTable(Connection connection) throws SQLException {
 35:		Statement statement = connection.createStatement();
 36:		statement
 37:				.execute("CREATE TABLE Person (id INTEGER PRIMARY KEY, name VARCHAR(16), age INTEGER)");
 38:		statement.close();
 39:	}
 40:
 41:	private static void insertTable(Connection connection) throws SQLException {
 42:		Statement statement = connection.createStatement();
 43:		statement.execute("INSERT INTO Person VALUES(1, 'hoge', 30)");
 44:		statement.execute("INSERT INTO Person VALUES(1, 'hoge', 30)");//ここで一意制約エラーを起こす
 45:		statement.close();
 46:	}
 47:
 48:	private static void updateTable(Connection connection) throws SQLException {
 49:		Statement statement = connection.createStatement();
 50:		statement.execute("UPDATE Person SET age=20");
 51:		statement.close();
 52:	}
 53:
 54:	private static void selectTable(Connection connection) throws SQLException {
 55:		Statement statement = connection.createStatement();
 56:		statement.execute("SELECT * FROM Person");
 57:		ResultSet resultSet = statement.getResultSet();
 58:		while (resultSet.next()) {
 59:			System.out.println(resultSet.getInt("id"));
 60:			System.out.println(resultSet.getString("name"));
 61:			System.out.println(resultSet.getInt("age"));
 62:		}
 63:		statement.close();
 64:	}
 65:
 66:	private static void dropTable(Connection connection) throws SQLException {
 67:		Statement statement = connection.createStatement();
 68:		statement.execute("DROP TABLE Person");
 69:		statement.close();
 70:	}
 71:
 72:}

実行結果です。44行目の呼び出しで例外が発生してますね。

DBException: java.sql.SQLIntegrityConstraintViolationException: このステートメントは、ユニークまたは主キー制約、または 'PERSON' 上で定義された 'SQL090301223159860' によって識別されるユニーク索引において重複キー値の原因となる可能性があったため、打ち切られました。
	at SampleMainDerby.process(SampleMainDerby.java:30)
	at SampleMainDerby.main(SampleMainDerby.java:13)
Caused by: java.sql.SQLIntegrityConstraintViolationException: このステートメントは、ユニークまたは主キー制約、または 'PERSON' 上で定義された 'SQL090301223159860' によって識別されるユニーク索引において重複キー値の原因となる可能性があったため、打ち切られました。
	at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:81)
	at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:201)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:391)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346)
	at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2125)
	at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81)
	at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1325)
	at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625)
	at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
	at SampleMainDerby.insertTable(SampleMainDerby.java:44)
	at SampleMainDerby.process(SampleMainDerby.java:23)
	... 1 more
Caused by: java.sql.SQLException: このステートメントは、ユニークまたは主キー制約、または 'PERSON' 上で定義された 'SQL090301223159860' によって識別されるユニーク索引において重複キー値の原因となる可能性があったため、打ち切られました。
	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
	at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:119)
	at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70)
	... 11 more
Caused by: ERROR 23505: このステートメントは、ユニークまたは主キー制約、または 'PERSON' 上で定義された 'SQL090301223159860' によって識別されるユニーク索引において重複キー値の原因となる可能性があったため、打ち切られました。
	at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:303)
	at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:465)
	at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383)
	at org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589)
	at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268)
	at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453)
	at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1011)
	at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:487)
	at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:372)
	at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)
	... 5 more