チャットbotお試し用アプリ開発_24日目_ログ出力機能実装（SLF4J＋Logback）

目次

・本日の成果・考え
・最後に

本日の成果

前回リンクテストの計画をしましたが、テストパターンを検討する中で、「処理の途中でエラー落ちはしないが、処理としては正しくない」パターンを把握する必要がでてきました。

上記をキャッチするためにログ出力機能が必要みたいなので先にそちらから実装することにしました。

というよりも、アプリとして必要なのだから先に実装しておけという話ではなりますね笑

とはいえ、ログの実装は業務では担当したことがありませんので、
「Java ログ出力」でググった結果
以下の記事を参考にして今回の機能実装を進めたいと思います。

今回採用したSLF4Jは、JDK標準で実装されているJULと違い、ログを出力する仕組み自体を抽象化（ファサード）したもので、自身ではログを出力しないみたいです。

そのため、実際の出力方式はLogbackやLog4j2などで変更可能みたいです。

上記2つのうちLogbackを採用することにしました。
理由としては、以下の検証記事を参考にした限り、既存コードへの影響が少なく実装できるみたいです。

jarのダウンロード

以下の公式サイトよりダウンロードしました。

サイトのバージョン一覧を確認すると、以下のバージョンが安定稼働しているとデカデカと教えてくれます。

slf4j-api　：2.0.17
logback-classic　：1.5.18
logback-core　：1.5.18

Maven構成の場合、logback-classicをビルド構成に追加すると、logback-coreも自動で使えるみたいですが、jarファイルを直接配置する時は明示的に配置しないとダメみたいです。
※Mavenでのpom.xmlの記載は、SLF4Jのマニュアルのページ下の方に記載されていましたので、ご参考ください。

では、早速jarをダウンロードして、ビルドパスに追加します。

ログルールの設定（logback.xml）

以下のルールを基準としています。

1. ログローテーション
   　* ファイルサイズは最大5MB
   　* 保管期間は30日
   　* 当日のログは常に同名（app.log or error.log）
   　* ローテーション時にファイル名を変更し、ファイル生成日（YYYYmmDD）とする。
2. 出力先：Javaプロジェクトのクラスパス/log*

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds" debug="false">
  <!-- 
    scan="true" : 設定ファイルの自動リロードを有効化。
    scanPeriod="30 seconds" : 30秒ごとに変更をチェック。
    ※ 開発時はログレベルやパターン調整に便利。
    ※ 本番環境では不要（OFF推奨：scan="false"）。
  -->

  <!-- 変数 -->
  <property name="LOG_DIR" value="log"/>
  <property name="APP_NAME" value="app"/>

  <!-- Console（開発時はON。本番ではOFFを推奨） -->
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{ISO8601} %-5level [%thread] %logger - %msg %X{requestId}%n</pattern>
    </encoder>
  </appender>

  <!-- メイン出力：最新は固定名、日毎＋サイズでローテ（YYYYMMDD） -->
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/${APP_NAME}.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${LOG_DIR}/bk/${APP_NAME}.%d{yyyyMMdd}.%i.log</fileNamePattern>
      <maxFileSize>5MB</maxFileSize>
      <maxHistory>30</maxHistory>
      <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%d{ISO8601} %-5level [%thread] %logger - %msg %X{requestId}%n</pattern>
    </encoder>
  </appender>

  <!-- ERROR専用：最新は固定名、日毎ローテ（YYYYMMDD） -->
  <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/error.log</file>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>ERROR</level></filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${LOG_DIR}/bk_error/error.%d{yyyyMMdd}.%i.log</fileNamePattern>
      <maxFileSize>5MB</maxFileSize>
      <maxHistory>30</maxHistory>
      <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%d{ISO8601} %-5level [%thread] %logger - %msg %X{requestId}%n</pattern>
    </encoder>
  </appender>

  <!-- パッケージ別（雛形。必要時に level/appender-ref を追記）
       API通信詳細ログは不要：処理内容はチャットBot側で確認可能。 -->
  <logger name="app.windowView"/>
  <logger name="app.windowView.api"/>
  <logger name="app.windowView.window"/>

  <!-- ルート：INFO以上を Console + File + Error へ -->
  <root level="INFO">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
    <appender-ref ref="ERROR_FILE"/>
  </root>
</configuration>

では、適当にウィンドウ表示ができたらログを出すようにして、ログの出力ができるかチェックしたいと思います。
※JavaFXのウィンドウ初期化処理に組み込みました。

WindowView.java

	@Override
	public void start(Stage stage) throws Exception {

		//呼び出しメソッドlaunchの引数受け取り(1,title 2,windWidth 3,windHeight)全てStrin型
		List<String> laParams = getParameters().getRaw();

		//引数の中身が存在しない場合エラー
		if (laParams.size() == 0) {
			throw new IllegalStateException("引数に必要な項目がありません。");
		}
		String title = laParams.get(0);
		int width, height;

		//整数に格納
		try {
			width = Integer.parseInt(laParams.get(1));
			height = Integer.parseInt(laParams.get(2));

		} catch (NumberFormatException e) {
			//整数以外例外
			throw new IllegalStateException("幅または高さが整数ではありません。:" + e.getMessage());
		}
		//ウィンドウ表示HTMLのURL取得
		URL url = getClass().getResource(ChATWINDOW_PATH);

		//WebEngineの初期化ロードのチェック。ロードが完了してから、ロジッククラスのブリッジセット処理を呼び出す。
		webView.getEngine().getLoadWorker().stateProperty().addListener((obs, oldState, newState) -> {
			if (newState == Worker.State.SUCCEEDED) {
				//ロジッククラスからコールバック用のオブジェクトがセットされているかチェック。
				if (staticCallback != null) {
					//セットされていれば、ロジッククラスにWindoViewオブジェクトを渡してブリッジセットメソッド起動。
					staticCallback.onWindowSet(this);
				} else {
					throw new IllegalStateException("BridgeCallbackがセットされていません。");
				}
			}
		});

		if (url == null) {
			throw new IllegalStateException("HTMLファイルが見つかりません" + ChATWINDOW_PATH);
		} else {
			webView.getEngine().load(url.toExternalForm());

			//ウィンドウ表示
			Scene scene = new Scene(webView, width, height);
			stage.setTitle(title);
			stage.setScene(scene);
			stage.show();
			logger.info("ウィンドウ起動");
		}
	}
}

さて、実行してみましたが、コンソールには出る！
しかし、ファイルが出力されない。

では、調査開始。

アプリ起動のVM引数でロガーの設定を出力させる。

以下をVM引数に追加

-Dlogback.debug=true -Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener

実行時のコンソール結果

11:11:33,562 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.5.18
11:11:33,576 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - No custom configurators were discovered as a service.
11:11:33,576 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
11:11:33,577 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
11:11:33,578 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
11:11:33,579 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
11:11:33,582 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 2 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
11:11:33,582 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
11:11:33,582 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
11:11:33,582 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
11:11:33,583 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
11:11:33,583 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
11:11:33,583 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Trying to configure with ch.qos.logback.classic.BasicConfigurator
11:11:33,584 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - Constructed configurator of type class ch.qos.logback.classic.BasicConfigurator
11:11:33,584 |-INFO in ch.qos.logback.classic.BasicConfigurator@17ed40e0 - Setting up default configuration.
11:11:33,588 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - BEWARE: Writing to the console can be very slow. Avoid logging to the 
11:11:33,588 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - console in production environments, especially in high volume systems.
11:11:33,588 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - See also https://logback.qos.ch/codes.html#slowConsole
11:11:33,588 |-INFO in ch.qos.logback.classic.util.ContextInitializer@5f5a92bb - ch.qos.logback.classic.BasicConfigurator.configure() call lasted 5 milliseconds. ExecutionStatus=NEUTRAL
11:11:34.736 [JavaFX Application Thread] INFO app.windowView.window.WindowView -- ウィンドウ起動

ログに以下が出ていますね。
Could NOT find resource [logback-test.xml]
設定ファイル読み込めてません笑。

では、フォルダを正しくしてみます。

再度実行

ログファイルが正しく出力できました！
では、以下の処理に実装しました。

・ウィンドウ表示
・API通信イベント発火および終了
・API通信処理の開始および終了

一応ローテーションの確認。

次の日にログを出力したタイミングでローテーションが実行できています！

最後に

本当に今更ですが、ログの実装を行いました。
LTに向けて急遽の実装となったので出力内容とかも精査できていませんが、一旦これで進めたいと思います。

今回の実装に伴い、元々用意していたログクラスが全て不要となりました笑。
まぁ、出力形式などをもっとカスタマイズしたい際は必要かもですが、今の実力で無理する機能ではないのかなと思いました。

また、各処理にログを実装する際に発見した点がありまして、
API通信実行するstreamingMsg（OkHttp）処理内で、もともとエラーが発生したら上位にスローしていたのですが、この処理が別スレッド扱いみたいでした。
そのため、上位（Controller）に伝播しないため、エラーが発生しても揉み消されてしまうみたいです。
つまり、API通信中のエラーを発見できない可能性があるみたいです。
次回か、どこかで検証した上で対応したいと思います。😢

以上、ここまでお付き合いありがとうございます。