Spring Boot解説第10回(開発環境編：ログの設定について～logback)

こんにちは！
情創 技術開発局
腹筋を30回やったら3日間筋肉痛になった@TEBASAKIです。
日頃から意識して運動しないとダメですね。

今回は第9回に引き続き、ログについて解説していきます。

# logbackについて
第9回でもlogbackについて触れましたが、設定ファイルについてもう少し掘り下げていきます。
## 設定ファイル名の変更(logback.xmlからlogback-spring.xmlへ）
Spring Boot1.3.0M2からlogbackの設定ファイル名に、
「-spring」サフィックスを付けることが推奨されるようになりました。
[リリースノート](https://github.com/spring-projects/spring-boot/wiki/Spring-Boot-1.3-Release-Notes "Spring Boot 1.3.0 Release Notes")には以下のように記載されています。
>In order to prevent double initialization Spring specific log configuration files can now be used. It’s recommended (although not required) that you rename any default log configuration files to use a -spring suffix. For example logback.xml would change to logback-spring.xml.

二重の初期化を避けることがファイル名変更の理由のようです。
これに従い、logbackの設定ファイルはlogback-spring.xmlとします。

## logbackの内部状態メッセージ表示
logback-spring.xmlの解析中に警告やエラーが発生したとき、
内部状態を表すメッセージがコンソールに表示されます。
警告やエラーが発生しなくてもメッセージを表示したい場合、
configurationタブのdebug属性にtrueを設定します。

``` xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration debug="true">
    ...
</configuration>
```

これにより、logbackの内部状態を常に表示することができます。
debag属性の記述がない場合やfalseが設定されている場合は、デフォルトの設定になり、
警告やエラーがない限りは表示されなくなります。

## デフォルト設定の読み込み
Spring Bootはlogbackのデフォルト設定を提供しています。
以下のincludeタグをlogback-spring.xmlに追加することで、
デフォルト設定を読み込むことができます。

``` xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration>
	<!-- デフォルト設定読み込み -->
	<include　resource="org/springframework/boot/logging/logback/base.xml" />
    ...
</configuration>
```
プロジェクト独自の設定は、この下に追加して記述します。

## Springのプロファイルごとの設定
Spring Boot1.3.0M2からsprigProfileタグが使用可能になりました。
これにより、後述するロガーのログレベルや出力先のパスなどを、プロファイルごとに設定できます。

第7回でapplication.propertiesを開発、本番それぞれの環境用に分けて設定しましたが、
それと同様にlogbackの設定も分けることができます。

``` xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration>
    ...
	<!--設定開発用 -->
	<springProfile name="dev">
		...
	</springProfile>

	<!--設定本番用 -->
	<springProfile name="prd">
		...
	</springProfile>
    ...
</configuration>
```

ここでの「dev」および「prd」は第7回で解説した通り、
開発環境および本番環境にそれぞれ対応しており、
プロファイル名に使用している文字列と統一させる必要があります。

## アペンダー
アペンダーとは実際にログを出力するコンポーネントであり、
ログの出力先やフォーマットを指定することができます。
アペンダーはappenderタグを使って定義します。
以下の例では、コンソール出力、WEBアプリケーション、バッチアプリケーション
(以下コンソール、WEB、バッチと省略します)の3つのアペンダーを定義しています。

``` xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration>
    ...
	<!--出力ルール～コンソール～ -->
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<target>System.out</target>
		<encoder>
			<pattern>出力内容</pattern>
		</encoder>
	</appender>

	<!--出力ルール～WEB～ -->
	<appender name="FILE_WEB" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>ログファイル名</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>自動生成ファイル名パターン</fileNamePattern>
			<maxHistory>ログファイルの寿命</maxHistory>
		</rollingPolicy>
		<encoder>
			<charset>UTF-8</charset>
			<pattern>出力内容</pattern>
		</encoder>
	</appender>

	<!--出力ルール～バッチ～ -->
	<appender name="FILE_BATCH" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>ログファイル名</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>自動生成ファイル名パターン</fileNamePattern>
			<maxHistory>ログファイルの寿命</maxHistory>
		</rollingPolicy>
		<encoder>
			<charset>UTF-8</charset>
			<pattern>出力内容</pattern>
		</encoder>
	</appender>
    ...
</configuration>
```

コンソール出力はtargetタグで指定されたターゲットにログを出力します。
WEBおよびバッチでは、ログをファイル出力するようにしています。
さらに、ログファイルの出力先の切替や、ファイルの寿命などを設定しています。

アペンダーやアペンダー内のrollingPolicyやencoderなどの詳細については、
以下のサイトを参照してください。

- [第4章 アペンダー](http://logback.qos.ch/manual/appenders_ja.html "第4章 アペンダー")

## ロガーおよびrootロガー
ロガーはloggerタグ、rootロガーはrootタグでそれぞれ定義します。

```xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration>
    ...
	<!--ロガー1 -->
	<logger name="demo.logger1" level="INFO">
		<appender-ref ref="STDOUT" />
	</logger>

	<!--ロガー2 -->
	<logger name="demo.logger1.logger2" level="WARN">
	</logger>

	<!--rootロガー -->
	<root level="DEBUG">
		<appender-ref ref="STDOUT" />
		<appender-ref ref="FILE_WEB" />
	</root>
    ...
</configuration>
```

すべてのロガーはrootロガーを最上位とした親子関係となっており、
子は親のログレベルおよびアペンダーを継承します。
設定を記述していないロガーは、デフォルトでrootロガーと同じログレベル、アペンダーを持ちます。

上記の例では、ロガー1はロガー2の親であり、
ロガー2はロガー1と同じアペンダーを持ちますが、ログレベルは異なります。

ロガーの名前はFQCN(完全修飾クラス名)を設定するのが一般的です。
理由はパッケージ階層とロガーの設定を一致させるためです。

※アペンダーの設定は上書きではなく、**継承したものに追加**されます。
上記の例では、ロガー1はSTDOUTアペンダーを2回呼ぶことになるので、
コンソールに同じ内容を2回出力します。

## ログレベル
ログレベルはログの重要度を表します。
重要度の高い順に、下記の種類があります。

1. error
2. warn
3. info
4. debug
5. trace

ロガーは自身に設定されているログレベルより高いレベルのログを出力対象とします。

例えばログレベルが「info」のロガーの場合、
「error」,「warn」,「info」のレベルを持つログは出力されますが、
「debug」,「trace」は出力されません。

# データベース接続テスト
それでは、第9,10回と続いたログの設定について、
実際にデータベースへ接続してログがどのように出力されるか確認してみましょう。

## データテーブル
今回はあくまでログがどのように出力されるかの確認なので、
使用するテーブルは以下のような簡単なものにします。
テーブル名は「demo」です。

| id | name |
|:--:|:----:|
| 1  | aaa  |
| 2  | bbb  |
| 3  | ccc  |

## 設定ファイル
application.propertiesとlog4jdbc.log4j2.propertiesについては、
第9回で解説したものを使用します。
そちらを参照してください。

また、build.gradleにはdependenciesに以下の記述を追加します。

```groovy:build.gradle
dependencies {
    compile("org.springframework.boot:spring-boot-starter-jdbc:${springBootVersion}")
    compile("org.postgresql:postgresql:9.4-1206-jdbc41")
    ...
}
```

## logback-spring.xmlの例
今回使用するlogback-spring.xmlは以下の通りです。

```xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<configuration>
	<include resource="org/springframework/boot/logging/logback/base.xml" />

	<property name="logname" value="demo" />

	<!--ログレベル設定開発用 -->
	<springProfile name="dev">
		<property name="logpath" value="D:/log/demo/" />
		<!--ログレベル -->
		<property name="LOG_LEVEL" value="INFO" />
		<property name="BATCH_LOG_LEVEL" value="INFO" />
		<!--log4jdbc-log4j2 -->
		<logger name="jdbc.sqltiming" level="INFO" />
		<logger name="jdbc.resultsettable" level="INFO" />
		<logger name="jdbc.connection" level="WARN" />
	</springProfile>

	<!--ログレベル設定本番用 -->
	<springProfile name="prd">
		<property name="logpath" value="D:/log/demo/" />
		<!--ログレベル -->
		<property name="LOG_LEVEL" value="INFO" />
		<property name="BATCH_LOG_LEVEL" value="INFO" />
		<!--log4jdbc-log4j2 -->
		<logger name="jdbc.sqltiming" level="INFO" />
		<logger name="jdbc.resultsettable" level="INFO" />
		<logger name="jdbc.connection" level="WARN" />
	</springProfile>

	<!--共通log4jdbc-log4j2 -->
	<logger name="jdbc" level="OFF" />
	<logger name="jdbc.sqlonly" level="OFF" />
	<logger name="jdbc.resultset" level="OFF" />
	<logger name="jdbc.audit" level="OFF" />

	<!--出力ルール～コンソール～ -->
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<target>System.out</target>
		<encoder>
			<!--出力内容 -->
			<pattern>%d{yyyy/MM/dd HH:mm:ss} %-5level %msg%n</pattern>
		</encoder>
	</appender>

	<!--出力ルール～WEB～ -->
	<!--場合によってはファイルサイズごとのRollに変更する -->
	<appender name="FILE_WEB"
		class="ch.qos.logback.core.rolling.RollingFileAppender">
		<!--日ごとにログファイル作成 -->
		<file>${logpath}${logname}.log</file>
		<!--日ごとにログファイル作成 -->
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<!--日付けが変わったら年月フォルダ内にzipファイル作成 -->
			<fileNamePattern>${logpath}%d{yyyyMM,aux}/${logname}-%d{yyyy-MM-dd}.log.zip</fileNamePattern>
			<!--180日後に破棄 -->
			<maxHistory>180</maxHistory>
		</rollingPolicy>

		<encoder>
			<charset>UTF-8</charset>
			<!--出力内容 -->
			<pattern>%d{yyyy/MM/dd HH:mm:ss}\t%-5level\t%msg%n</pattern>
		</encoder>
	</appender>

	<!--出力ルール～バッチ～ -->
	<appender name="FILE_BATCH"
		class="ch.qos.logback.core.rolling.RollingFileAppender">
		<!--日ごとにログファイル作成 -->
		<file>${logpath}${logname}batch.log</file>
		<!--日ごとにログファイル作成 -->
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<!--日付けが変わったら年月フォルダ内にzipファイル作成 -->
			<fileNamePattern>${logpath}%d{yyyyMM,aux}/${logname}batch-%d{yyyy-MM-dd}.log.zip</fileNamePattern>
			<!--180日後に破棄 -->
			<maxHistory>180</maxHistory>
		</rollingPolicy>

		<encoder>
			<charset>UTF-8</charset>
			<!--出力内容 -->
			<pattern>%d{yyyy/MM/dd HH:mm:ss}\t%-5level\t%msg%n</pattern>
		</encoder>
	</appender>

	<!--バッチログレベルと使用出力ルール -->
	<logger name="jp.co.johso.demo.batch" level="${BATCH_LOG_LEVEL}">
		<appender-ref ref="STDOUT" />
		<appender-ref ref="FILE_BATCH" />
	</logger>


	<!--rootログレベルと使用出力ルール -->
	<root level="${LOG_LEVEL}">
		<appender-ref ref="STDOUT" />
		<appender-ref ref="FILE_WEB" />
	</root>

</configuration>
```

今回のデータベース接続では、rootロガーに設定されている2つのアペンダーが使用されるので、
コンソール出力とファイル出力が行われます。

## コントローラーの作成
/src/main/java/com/qiita/demo/web/controller/に
動作確認用のコントローラー、LogbackDemoController.javaを作成します。

```java:LogbackDemoController.java
package com.qiita.demo.web.controller;

import java.util.List;
import java.util.Map;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.jdbc.core.JdbcTemplate;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.ResponseBody;

@Controller
public class LogbackDemoController
{
	@Autowired
	private JdbcTemplate jdbc;

    @RequestMapping("/demo")
    @ResponseBody
    public String home() {

    	List<Map<String, Object>> list = jdbc.queryForList("SELECT * FROM demo");

        return "";
    }
}
```

select文で全要素を取得するSQLを実行するだけのコントローラーです。

## 動作確認
それでは動作を確認してみましょう。
プロジェクトを右クリック→Gradle→すべてリフレッシュした後、
右クリック→Gradle→タスク・クイック・ランチャーからbootRunで実行します。

実行が成功したら、「 http://localhost:8080/demo 」にアクセスします。
ページには何も表示されませんが、eclipseのコンソールには以下のようなログが出力されます。

```text:コンソール出力
2016-05-20 13:53:14.894  INFO 6468 --- [nio-8080-exec-1] jdbc.sqltiming                           : SELECT * FROM demo 
 {executed in 23 msec}
2016/05/20 13:53:14 INFO  SELECT * FROM demo 
 {executed in 23 msec}
2016-05-20 13:53:14.911  INFO 6468 --- [nio-8080-exec-1] jdbc.resultsettable                      : 
|---|-----|
|id |name |
|---|-----|
|1  |aaa  |
|2  |bbb  |
|3  |ccc  |
|---|-----|

2016/05/20 13:53:14 INFO  
|---|-----|
|id |name |
|---|-----|
|1  |aaa  |
|2  |bbb  |
|3  |ccc  |
|---|-----|

```

続いてログファイルを確認してみます。
ログファイルの出力先は、logback-spring.xmlに設定した通り、
「D:/log/demo/」です。
![image](https://qiita-image-store.s3.amazonaws.com/0/116031/14274d67-5d1c-90fd-95a3-ceb928f58c59.png)



このようにログファイルが出力されていることが確認できます。

また、今回の設定においてログファイルは日付が変化した際にzipフォルダに圧縮され、
180日経過したものは自動で削除されます。

端末の時刻をずらしてこの動作も確認します。
まずは日付を1日進めて実行してみます。
実行後ページにアクセスし、ログファイル出力先のフォルダを確認すると、
以下のようになりました。
![image](https://qiita-image-store.s3.amazonaws.com/0/116031/d5953a22-6532-f614-a109-1cf543327490.png)

![image](https://qiita-image-store.s3.amazonaws.com/0/116031/1c059088-d276-f281-3dd9-53243d2fe8eb.png)

![image](https://qiita-image-store.s3.amazonaws.com/0/116031/e6b06a72-762a-8d1a-f865-dca170b61516.png)


日付変更前のログファイルがzipに圧縮されていることがわかります。

続いて、日付を6か月進めて実行すると、以下のようになりました。
![image](https://qiita-image-store.s3.amazonaws.com/0/116031/76d1bd16-c374-1875-b06d-7368242483ce.png)

![image](https://qiita-image-store.s3.amazonaws.com/0/116031/2103ae99-ec7b-c04e-98f0-35cd89a9630a.png)


180日経過したログファイルが削除されていることがわかります。

このようにlogbackを用いることで、ログの管理が非常に楽になります。

今回はここまでです。
それではみなさん、アリーヴェデルチ！

# 参考URL

- [Logback 使い方メモ](http://qiita.com/opengl-8080/items/49719f2d35171f017aa9)
- [Spring Bootのログ設定を変更する](http://qiita.com/tag1216/items/b898b8fb58920bf335b2)
- [Spring Boot 1.3.0のlogback extensionsについて](http://qiita.com/rubytomato@github/items/fbcc103f0d286040ed88)