SpringFrameworkのログ出力

2025.01.27

ログ出力方法

いくつか選択肢があるが、ここではlogbackというライブラリを使用する。

JavaでLoggerを作成し、クラスパスを設定すると、logback設定ファイル (logback-spring.xml)の、対応するLoggerの設定が使用される。

ログ出力実装

参考：SpringBoot_ログ

LogBackによるログ出力で編集するファイルは以下の4つです。

■src\main/resources/
┗logback-spring.xml  // LogBackのメイン設定
┗logback/appender/app.xml  // アベンダー※。ファイル名は任意。複数作成可能。
┗application.env.yml  // 環境変数。使わなくても良いが、ここに記載したプロパティを上記xmlから呼び出すことができる。
■Sample.java (ログ出力を行いたいjavaファイル)

※アベンダー：ログ出力設定の単位。ログを出力するファイルバスやライフサイクル、ログレベルなどを設定する。アペンダーを複数作成すれば、その分異なるログ出力設定を定義できる。

各ファイルについて、以下で説明していきます。

logback-spring.xml

LogBackのメイン設定。


<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <!-- プロパティ-->
  <springProperty name="filePath" source="log.file.path" /> …①
  <springProperty name="fileMaxHistory" source="log.file.max.history" />
  <property name="fileExtension" value=".log" /> …②
  <property name="fileRotateExtension" value=".log.gz" />
  <property name="formatConsole" value="%d [%-5p] [%c {5}.%M] %m [%t] %n" />
  <!-- アペンダー -->
  <include resource="logback/appender/app.xml" /> …③
  <include resource="logback/appender/console.xml" />
  <!-- ロガー -->
  <logger name="app" additivity="false"> …④
    <appender-ref ref="APP" />
  </logger>
  <logger name="com.Sample" additivity="false">
    <appender-ref ref="CONSOLE" />
  </logger>
  <!-- デフォルトのロガー -->
  <root level="INFO"> …⑤
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

以下、解説。

①springProperty

<springProperty name="filePath" source="log.file.path" />

source属性にapplication.env.ymlのプロパティを指定して使用できる。取得した値は、本xml と、アベンダーxml内で、nameに指定した変数名で呼び出すことができる。

②property

<property name="fileExtension" value="log" />

valueで指定した値を、本xmlと、アベンダーxml内で呼び出すことができる。

③include

<include resource="logback/appender/console.xml" />

アベンダーxmlをインポートしている。

④loggerとappender-ref

<logger name="app" additivity="false">
  <appender-ref ref="APP" />
</logger>

・<logger>部分

name属性に指定した値を使用して、javaからロガーを呼び出せるようになる（後述）。additivity属性をfalseに設定することで、 親loggerからのログも受け継がれないようにしている。

・<appender-ref>部分

appender-refを使用して、include済みのアベンダーを指定できる。ref属性には、アベンダーxmlファイル内で定義されているNAME属性を指定する。

⑤root

<root level="INFO">

javaからロガーが呼び出されたが、getLogger(“loggerName”) で指定されたロガー名の設定が見つからなかった場合の、デフォルトのロガー設定。

app.xml

アペンダー。ロガーの出力設定を定義する。

Logbackには、ただコンソール出力した場合と、ログを保存してローテーションしたい場合などの用途の違いに応じて、あらかじめ複数のクラスが用意されている。

アペンダーでは、まずこのベースとなるクラスを指定し、そこからさらに必要な機能をカスタムする。

<?xml version="1.0" encoding="UTF-8"?>
<included>
  <!-- コンソール出力用設定 -->
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> …ベースとなるクラス
    <encoder>
      <charset>UTF-8</charset>
      <pattern>${formatConsole}</pattern> // ${}によって、logback-spring.xmlで指定した変数を呼び出している
    </encoder>
  </appender>
</included>

特に以下に関してはログの要件として非常に良く使用されるため、押さえておく。

  • rollingPolicy：ログのライフサイクル（どのくらいの期間・量がたまったら別ファイルに切り出すか）
  • file：ログファイルの出力パスを設定する
  • encoderとpattern：ログの出力形式を設定する（日付 ファイル名 ステータス リクエストレスポンス）
  • filter：SpringFilterを使用して、リクエストレスポンスなど通信条件でさらに分岐させたい場合

参考

application.env.yml

環境変数。Lobback専用のファイルではないが、ファイルの保存場所などの指定はこのファイルで管理することが多い。

logback-spring.xmlの<property>で指定すれば、

log:
  file:
    path: /opt/tomcat/apache-tomcat/logs
    name:
      app: appName-app
      req: appName-req
    max:
      history: 45

logback-spring.xml上で、以下のように指定して呼び出すことができる。

<springProperty name="filePath" source="log.file.path" />

Sample.java

ここまでで設定は完了。

ここではSample.javaとしているが、任意のクラスでロガーを呼び出して使用できる。

ログ出力をしたい処理の中で、以下のように実装する。

@Service
public class Sample {
	// 冒頭でロガーを定義する
	private static final Logger LOGGER = LoggerFactory.getLogger(app);	// …①

	public void sampleFnc() {
		// ログを出力したい箇所でLOGGERを使用する
		LOGGER.debug("errorが起きました");
	}
}

①でgetLoggerしたロガー名（app）を、logback-spring.xmlで設定したloggerのnameから検索し、以下のように同じ名前のloggerが見つかればその設定が適用される。

<logger name="app">

見つからない場合は、<root>の設定が適用される。

ロガーのテスト方法

ロガーのUTを作成する場合、検証するサービスのロガーをモックする必要があり、なかなかハードな実装となる。

検証メソッドで、s1f4jを使用していても、テストコードでは以下のように、logbackのパッケージで検証する点に注意する

  • import ch.qos.logback.classic.Logger;
  • import ch.qos.logback.classic.spi. LoggingEvent;
  • import ch.qos.logback.core.Appender;
@Mock
private Appender mockAppender; // Appenderのモック
@Captor
private Argument Captor captorLoggingEvent; // ログイベント監視用オブジェクト
@Test
void test() {
  final Logger logger = (Logger) LoggerFactory.getLogger(sarvice.class);
  logger.addAppender (mockAppender); // mockしたAppenderを設定
  service.methodName(); // 検証メソッド実行
  verify(mockAppender).doAppend(captorLoggingEvent.capture()); // ログイベントをキャプチャ（監視）
  assertEquals(captorLoggingEvent.getValue().getLevel().toString(), "WARN"); // ログ情報を色々取得して検証できる
  // ログが複数出力される可能性がある場合は、 captorLogging Event.getAllValue() を使用する
}

NGパターン

java.lang.reflect.Fieldを使用して、検証メソッドのLoggerを取得、mockしたLoggerで上書きして検証する方法も考えられる。

Loggerはprivateメソッドで定義されているため、 setAccessible(true)とするのだが、この設定をしても、参照と実行は許可されるが、上書きは許可されないためNGとなる。

Logger mockLogger = mock (Logger.class);
Field field = service.getClass().getDeclared Field("LOGGER"); // 検証メソッドからLoggerを取得
field.setAccessible(true);
field.set(null, mockLogger); // エラー：Can not set static final org.slf4j.Logger field ※上書きふ化
service.methodName();
verify(mockLogger).debug("期待するログテキスト");

異なるログレベルのテスト

以下のようなコードがある。

■SampleService.java
if (LOGGER.isDebugEnabled()) {
  LOGGER.debug("sampleLog");
}

このメソッドを検証するには、ログレベルがINFO時と、DEBUG時の2つの挙動について確認する必要がある。

■SampleServiceTest.java
private static final Logger logger = (Logger) LoggerFactory.getLogger(SampleService.class);

@BeforeEach
public void before() {
  logger.setLevel(Level.DEBUG); // デフォルトのログレベル
}

@Test
void sampleTest() {
  service.methodName(); // ログレベルはDebugで実行される
}

@Test
void sampleInfoTest() {
  logger.setLevel(Level.INFO);
  service.methodName(); // ログレベルはInfoで実行される
}

Appendix

変数の埋め込み

ロガーで変数を使用する場合は、 第一引数 (メッセージ) 内で{}を使用し、 第2引数以降で、{}に対応する変数を指定する。

同様に{}を複数使用する場合は第3引数以降で指定する。

LOGGER.info("Err_name:{}_id:{}", person.name, person.id};
// 1つ目の{}にperson.nameが入り、2つ目の{}にperson.idが入る

プロファイルによるロガーの分岐

サーバーで指定しているプロファイルによって、本番環境 (prod) と、開発環境 (dev) の挙動を切り分けるケース。

dev環境は複数存在することもあるので、例えばprodとそれ以外で分けたい場合は以下のように記述する。

<logger name="app" additivity="false">
  <springProfile name="prod">
    <appender-ref ref= "APP" />
  </springProfile>
  <springProfile name="!prod">
    <appender-ref ref= "CONSOLE" />
  </springProfile>
</logger>

nameは以下のようにorやandも使用できる。

<springProfile name="dev | dev2">
<springProfile name="!dev & !dev2">

ロガーのname属性をクラス名と一致させる

■Sapmle.java

private static final Logger LOGGER = LoggerFactory.getLogger (Sample.class);

■logback-spring.xml

<logger name="[プロジェクトルート ] . Sample" additivity="false">
  <appender-ref ref= "CONSOLE" />
</logger>

アーキ部品など、特定のクラスでのみ使用するロガーを定義する場合に、logback-spring.xmlのloggerのname を、使用するクラス名と一致させる方法。

Sample.javaからロガーを呼び出す際、getLogger (Sample.java) とすると、getLogger の中の Sapmle.java の部分は以下に読み替えられる。

[プロジェクトルート].Sample

自身のクラスを指定する記述でロガーが呼び出せることになり、わざわざロガーに任意の名前を付ける必要が無くなる。

プロジェクトルートのバスがわからない場合は、eclipse などのIDE上でSample.java ファイルを開く。

public class Sample() {
  // 省略
}

上記のSampleの記述にカーソルを合わせれば、プロジェクトルート込みのファイルバスがポップアップするので参考にすれば良い。

インシデント

401レスポンスの中身がログ出力できない

外部APIとの通信で、 401が返却された際に、レスポンスをログ出力しようとしたらエラー。

cannot retry due to server authentication, in streaming mode

レスポンスボディをログ出力するためには、以下のようにストリームとして読み込んで文字列に変換することが多いが、ストリーミングは一度しか読み込みを許可しない。（バッファリーダーと書いてあるが。HttpClientの仕様に引っ張られる？）

String reponseBody =
  new BufferedReader(new InputStreamReader(response.getBody(), StandardCharsets.UTF_8));

一方でHTTPクライアントは401レスポンスを受け取ると、認証をリトライしようとするが、ストリームはすでに読まれてしまっているため、再試行できないとのエラー。

この再試行の仕組みから、401の時のみこのエラーが発生する。

以下のようにHttpComponentsClientHttpRequestFactoryをrestTemplateのFactoryに指定してあげるだけでエラーは解消する。

HttpComponentsClientHttpRequestFactory requestFactory =
  new HttpComponentsClientHttpRequestFactory();
this.restTemplate.setRequestFactory(requestFactory);  // 401レスポンスをハンドリングできるようにする

これは、restTemplateのデフォルトのHttpClientであるHttpURLConnection は、ストリーミング（一度しか読み込めない）であるのに対し、HttpComponents ClientHttpRequestFactoryのHttpClientであるApacheHttpClientはストリームをバッファしている※ので、ストリームを読み直すことができるようになるため。

※バッファする：再利用できるようにメモリに保存する

 

コメント

タイトルとURLをコピーしました