ログにエラー発生箇所情報が出力できない。

Question

ログの出力テストを行っているのですが、エラーの発生箇所情報がうまく出力できません。

[テスト内容]
1.Registration.javaの定数フィールド「PROPERTY_FILE」に存在しないプロパティファイル名を設定。
2.Htmlページからサーブレットにリクエストを送信。
3.プロパティファイルが存在しないため、NullPointerExceptionが発生する。
4.出力されたログを確認する。

ログの出力自体は問題なくできたのですが、エラー発生箇所の情報が期待通りになりません。
ログの出力内容は以下の通りです。

2017-05-04 10:42:47.426 WARN  [プロパティファイル未存在],取得ファイル名=url2.properties
 registration.servlet.RegistrationServlet.init(RegistrationServlet.java:46) 

()の部分の情報がログを出力している箇所(logger.warn(XXX)の行番号)が出力されました。やりたいことは(Registration.java:「エラー発生箇所であるprop.load(inStream)の行番号」)を出力させたいです。
このエラー発生箇所の情報はどのように設定するのか調べてみたのですが有力な情報が見つかりませんでした。ログ出力設定にお詳しい方がいましたらご回答をいただけないでしょうか。

原因がありそうな箇所のソースコード、設定内容を以下に共有いたします。

package registration.servlet;

import java.io.IOException;
import java.io.InputStream;
import java.io.PrintWriter;
import java.util.Properties;
import java.util.logging.Logger;

import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.apache.logging.log4j.LogManager;

import registration.controller.RegistrationController;
import util.exception.UnexpectedProcessingException;

public class RegistrationServlet extends HttpServlet {
	private static final long serialVersionUID = 1L;
	static org.apache.logging.log4j.Logger logger = LogManager.getLogger(Logger.class.getName());
	final static String COMMON_URL = "CommonUrl";
	final static String PROPERTY_FILE = "url2.properties";
	final Properties prop = new Properties();

	public void init() throws ServletException{

		InputStream inStream = null;
		try {
			inStream = RegistrationServlet.class.getClassLoader().getResourceAsStream(PROPERTY_FILE);
			prop.load(inStream);
		} catch (IOException e) {
			throw new UnexpectedProcessingException("プロパティ読み込み中にエラーが発生", e);
		} catch (NullPointerException e) {
			logger.warn("[プロパティファイル未存在],取得ファイル名={}", PROPERTY_FILE);
			throw new UnexpectedProcessingException("予期せぬエラーが発生しました。", e);
		} finally {
			try {
				if (inStream != null) {
					inStream.close();
				}
			} catch (IOException e) {
				System.out.println("予期せぬエラーが発生しました。");
				e.printStackTrace();
			}
		}
	}

	protected void doGet(HttpServletRequest request, HttpServletResponse response)
			throws ServletException, IOException {

		// パラメータを取得する
		String process_code = request.getParameter("process_name");

		// コントローラを呼び出す
		RegistrationController rc = new RegistrationController();
		rc.invoke(process_code);
	}

	protected void doPost(HttpServletRequest request, HttpServletResponse response)
			throws ServletException, IOException {

	}
}

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>

<configuration status="OFF">

<Properties>
	<Property name="error_daily_log">logs/app_error_%d{yyyy-MM-dd HH:mm:ss.SSS}</Property>
</Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{DEFAULT} | [%t] | %-5level | %c{36} | %msg%n"/>
        </Console>
        <File name="File" fileName="logs/normal_app.log">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} | [%t] | %-5level | %c{36} | %msg%n"/>
        </File>
        	<RollingFile name="RollingFile" fileName="logs/app.log" filePattern="logs/app_%date{yyyyMMddHHmmss}.log">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %msg%n %C.%M(%F:%L)"/>
            <Policies>
                <TimeBasedTriggeringPolicy />
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="trace">
            <AppenderRef ref="File" />
            <AppenderRef ref="RollingFile" />
        </Root>
        <Logger name="registration.servlet" level="debug" additivity="false">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="RollingFile" />
        </Logger>
    </Loggers>
</configuration>

Answer 1

ログのWARNの行の下が例外発生の文字列ということでしょうか。
これは最終的に発した例外の情報を示しているようなので、NullPointerExceptionによるものではなく、
自分で投げたUnexpectedProcessingExceptionの例外情報となります。
なので、この行番号は実はthrow new UnexpectedProcessingException("予期せぬエラーが発生しました。", e);の行です。

catchの引数のようになっているeはException系クラス型のインスタンスであり、
その中にはスタックトレースという情報が含まれています。
このスタックトレース情報は、ThrowableクラスのgetStackTrace()メソッドで取得できます。
後は、この中から自クラス内の実行ポイント、もしくは実行したinitメソッドを含む実行ポイントを探し出せばいいのだと思います。
こんな風に…(未検証)

} catch (NullPointerException e) {
    StackTraceElement[] elements = e.getStackTrace();
    String name = this.getClass().getName();
    for (StackTraceElement ste : elements) {
        if (ste.getClassName().equals(name)){
            String log = ste.toString();  //この文字列を出力すればいい
        }
    }
    logger.warn("[プロパティファイル未存在],取得ファイル名={}", PROPERTY_FILE);
    throw new UnexpectedProcessingException("予期せぬエラーが発生しました。", e);
}

Comments

[Linkey]

ログ出力の参考にさせていただきます。ありがとうございます。

Answer 2

prop.load(inStream) で発生した例外はアプリケーション内で catch してしまっているので、ハンドルされていない例外はその下の throw new UnexpectedProcessingException() となり、その行がスタックトレースとして出力されているだけで、ログ出力とは直接関係ないと思います。

ロガーは、ログに何かを出力する以上のことは何もしないので、例外が発生した行番号をログに出したいなら、logger.warn("[プロパティファイル未存在],取得ファイル名={}", PROPERTY_FILE); の所で、自力でスタックトレースを見て、行番号を出力に追加してください。

スタックトレースに単純に出力されればいいだけなら、UnexpectedProcessingException でラップするのを止めて、catch した NullPointerException をそのまま throw してもいけるかもしれません(できないかも)。