log4jの設定ファイルとログの関係

log4jの設定ファイル(log4j.xml)

今回の講習で使ったlog4jの設定ファイルlog4j.xmlファイルは以下になります。

            
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration>
<Configuration status="OFF">
	<Properties>
		<Property name="ptn">
    %n %d{yyyy-MM-dd HH:mm:ss.SSS} p=%p C=%C M=%M %n m=%m
    </Property>
	</Properties>
	<Appenders>
		<Console name="console" target="SYSTEM_OUT">
			<PatternLayout pattern="${ptn}" />
		</Console>
		<RollingFile name="file" fileName="log/log4j2.log"
			filePattern="log/%d{yyyyMM}/log4j2_%d{yyyyMMdd}_%i.log">
			<PatternLayout pattern="${ptn}" />
			<Policies>
				<OnStartupTriggeringPolicy />
				<SizeBasedTriggeringPolicy size="2 MB" />
				<TimeBasedTriggeringPolicy />
			</Policies>
			<DefaultRolloverStrategy max="10" />
		</RollingFile>
	</Appenders>
	<Loggers>
		<Root level="all">
			<AppenderRef ref="console" />
			<AppenderRef ref="file" />
		</Root>
	</Loggers>
</Configuration>
          

この設定ファイルで、
開発環境なら、Eclipseディレクトリ/log/log4j2.logに保存されます。
Tomcatなら、tomcatディレクトリ/log/log4j2.logに保存されます。

ログ出力のソース

サーブレット中のログ出力部分のソースは、以下になります。

            
    //ログの準備
    Logger logger = LogManager.getLogger(LoginServlet.class);
    //ログの書き込み
    logger.info("@login,");
    logger.info(
    ((HttpServletRequest)request).getRequestURI()+","
    +((HttpServletResponse)response).getStatus()+","
    +"user_id:" + userBean.getUser_id() +","
    +"status:" + userBean.getStatus()+","
    +"user_name:" + userBean.getUser_name() +","
    +"role:" + userBean.getRole()
    );
          

Loggerクラスを使ってログの準備をして、logger.infoを使って任意の変数を出力します。

ログ出力結果と質問

上記log4j.xmlの設定ファイルとソースで動かしたところ、
以下の質問がきました。

質問
講習のログパートのアウトプットとして、以下のログが作成されました。
（もちろん行頭のカッコ数字は、手で追加で入れた記述です）

(1) 2020-08-30 02:04:28.905 p=INFO C=controller.LoginServlet M=doGet
(2) m=@login,
(3) 2020-08-30 02:04:28.936 p=INFO C=controller.LoginServlet M=doGet
(4) m=/login/LoginServlet,200,user_id:001,status:0,user_name:小林,role:member
(5) 2020-08-30 02:04:30.590 p=INFO C=controller.LogoutServlet M=doGet
(6) m=@logout,
(7) 2020-08-30 02:04:30.591 p=INFO C=controller.LogoutServlet M=doGet
(8) m=/login/LogoutServlet,200,user_id:001,status:0,user_name:小林,role:member

よく分からないのが、(1)と(5)の行です。
ソースでは @login, @logout の後に詳細をログ出力する命令文が書かれているので、
(1)と(2)
(5)と(6)
の出力が逆転しているように見えます。これはなぜでしょうか？

ログ出力の回答

以下が回答になります。

回答
(1)と(5)は、ログ出力命令文の前に、
デフォルトみたいな感じで出すように設定されています。

その設定はlog4j.xml にあって、<Property name="ptn">の部分です。

ここで、まず、デフォルトみたいなものを出して、
改行して、メッセージ(ログ出力命令)を出すように設定しています。