Doma2 でログ出力を制御する

4日目担当の [null](https://qiita.com/YujiSoftware/items/2dc002977e730a3293fd#%E3%81%BE%E3%81%A8%E3%82%81) です。

デフォルトだと、 INFO レベルでいっぱいログが出るので、そのへんを制御する。

# 環境
**Java**

`openjdk 11.0.1 2018-10-16`

**Doma2**

`2.19.3`

**doma-spring-boot**

`1.1.1`

**Spring Boot**

`2.1.1`

# ソース（一部）
```gradle:build.gradle
buildscript {
	ext {
		springBootVersion = '2.1.1.RELEASE'
	}
	repositories {
		mavenCentral()
	}
	dependencies {
		classpath("org.springframework.boot:spring-boot-gradle-plugin:${springBootVersion}")
	}
}

apply plugin: 'java'
apply plugin: 'org.springframework.boot'
apply plugin: 'io.spring.dependency-management'

sourceCompatibility = 11
targetCompatibility = 11

compileJava.options.encoding = "UTF-8"

repositories {
	mavenCentral()
}

dependencies {
	implementation('org.springframework.boot:spring-boot-starter-jdbc')
	implementation('org.seasar.doma.boot:doma-spring-boot-starter:1.1.1') {
		exclude group: 'org.seasar.doma', module: 'doma'
	}
	implementation('org.seasar.doma:doma:2.19.3')
	runtimeOnly('com.h2database:h2')
}

processResources.destinationDir = compileJava.destinationDir
compileJava.dependsOn processResources
```

```java:TestTable.java
package sample.springboot.doma2;

import org.seasar.doma.Entity;
import org.seasar.doma.GeneratedValue;
import org.seasar.doma.GenerationType;
import org.seasar.doma.Id;
import org.seasar.doma.Table;

@Table(name = "TEST_TABLE")
@Entity
public class TestTable {
    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    public Long id;
    public String name;

    @Override
    public String toString() {
        return "TestTable{" +
                "id=" + id +
                ", name='" + name + '\'' +
                '}';
    }
}
```

```java:TestTableDao.java
package sample.springboot.doma2;

import org.seasar.doma.Dao;
import org.seasar.doma.Insert;
import org.seasar.doma.Select;
import org.seasar.doma.boot.ConfigAutowireable;

import java.util.List;

@Dao
@ConfigAutowireable
public interface TestTableDao {
    
    @Select
    List<TestTable> findAll();
    
    @Insert
    int insert(TestTable testTable);
}
```

```java:Doma2Application.java
package sample.springboot.doma2;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ConfigurableApplicationContext;

@SpringBootApplication
public class Doma2Application {

	public static void main(String[] args) {
		try (ConfigurableApplicationContext context = SpringApplication.run(Doma2Application.class, args)) {
			TestTableDao dao = context.getBean(TestTableDao.class);

			System.out.println(dao.findAll());

			TestTable foo = new TestTable();
			foo.name = "foo";
			dao.insert(foo);

			TestTable bar = new TestTable();
			bar.name = "bar";
			dao.insert(bar);

			System.out.println(dao.findAll());
		}
	}
}
```

# 実行結果
```
2018-12-03 22:32:25.979  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2220] ENTER  : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[findAll]
2018-12-03 22:32:26.038  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[META-INF/sample/springboot/doma2/TestTableDao/findAll.sql],
SELECT *
  FROM TEST_TABLE
2018-12-03 22:32:26.049  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2221] EXIT   : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[findAll]
[]
2018-12-03 22:32:26.049  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2220] ENTER  : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[insert]
2018-12-03 22:32:26.068  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[null],
insert into TEST_TABLE (id, name) values (null, 'foo')
2018-12-03 22:32:26.071  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2221] EXIT   : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[insert]
2018-12-03 22:32:26.072  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2220] ENTER  : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[insert]
2018-12-03 22:32:26.072  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[null],
insert into TEST_TABLE (id, name) values (null, 'bar')
2018-12-03 22:32:26.072  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2221] EXIT   : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[insert]
2018-12-03 22:32:26.072  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2220] ENTER  : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[findAll]
2018-12-03 22:32:26.073  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[META-INF/sample/springboot/doma2/TestTableDao/findAll.sql],
SELECT *
  FROM TEST_TABLE
2018-12-03 22:32:26.075  INFO 24784 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2221] EXIT   : クラス=[sample.springboot.doma2.TestTableDaoImpl], メソッド=[findAll]
[TestTable{id=1, name='foo'}, TestTable{id=2, name='bar'}]
```

デフォルトだと、 Doma2 に関するログが INFO レベルで大量に出力されている。
このまま本番で動かすのはアレなので、 DEBUG レベルに出力したりいろいろ制御する。

# Doma2 のログ出力の仕組み
![doma2.jpg](https://qiita-image-store.s3.amazonaws.com/0/28302/f8c2f306-b835-8c0f-8250-1029b3e9c5fd.jpeg)

- Doma2 のログ出力は、 `JdbcLogger` インターフェースを介して行われている
- 実装クラスとして、デフォルトで `java.util.logging.Logger` を使用する `UtilLoggingJdbcLogger` が用意されている
    - Spring Boot を利用している場合、 `java.util.logging.Logger` を使用していても最終的には SLF4J からログが出力されるようになっています
    - そのへんは [jul-to-slf4jのしくみ - Qiita](https://qiita.com/kochoru/items/f4318654b188369830e3) とかを参照ください

```java:AbstractJdbcLogger.java
package org.seasar.doma.jdbc;

...

public abstract class AbstractJdbcLogger<LEVEL> implements JdbcLogger {

    /** デフォルトのログレベル */
    protected LEVEL defaultLevel;

    protected AbstractJdbcLogger(LEVEL level) {
        if (level == null) {
            throw new DomaNullPointerException("level");
        }
        this.defaultLevel = level;
    }

    @Override
    public void logDaoMethodEntering(String callerClassName,
            String callerMethodName, Object... args) {
        logDaoMethodEntering(callerClassName, callerMethodName, args,
                defaultLevel, () -> Message.DOMA2220.getMessage( // ★インスタンスフィールドのログレベルを渡してる
                        callerClassName, callerMethodName));
    }

    protected void logDaoMethodEntering(String callerClassName,
            String callerMethodName, Object args[], LEVEL level,
            Supplier<String> messageSupplier) {
        log(level, callerClassName, callerMethodName, null, messageSupplier);
    }

...
```

- 例えば、 `logDaoMethodEntering()` は Dao のメソッドが開始されたときのログを出力する
- このメソッドは、 `protected` な `logDaoMethodEntering()` を呼んでいて、引数のログレベル（`LEVEL`）に、インスタンスフィールドのデフォルトのログレベル（`defaultLevel`）を渡している
- `AbstractJdbcLogger` には、他にも Dao が実行されるときのロギングメソッドが多数定義されているが、どれも構造は同じ
- つまり、デフォルトは `AbstractJdbcLogger` の `defaultLevel` に設定されているログレベルでログが出力されることになる
- そして、問題のデフォルトのログレベルが設定されている場所は `UtilLoggingJdbcLogger` の中

```java:UtilLoggingJdbcLogger.java
package org.seasar.doma.jdbc;

...

public class UtilLoggingJdbcLogger extends AbstractJdbcLogger<Level> {

    /** このインスタンスで使用するロガーです。 */
    protected final Logger logger;

    ...
    public UtilLoggingJdbcLogger() {
        this(Level.INFO); // ★デフォルトコンストラクタで生成されると INFO レベルになる
    }

    ...
    public UtilLoggingJdbcLogger(Level level) {
        this(level, Logger.getLogger(UtilLoggingJdbcLogger.class.getName()));
    }

    ...
```

- `UtilLoggingJdbcLogger` をデフォルトコンストラクタで生成した場合、ログレベルは INFO になる
- Doma2 の設定で明示的に `JdbcLogger` のインスタンスを指定していない場合、 `UtilLoggingJdbcLogger` はデフォルトコンストラクタで生成されるので、結果としてログ出力レベルは全て INFO になる

# デフォルトのログ出力レベルを変更する
[doma-spring-boot](https://github.com/domaframework/doma-spring-boot) を利用している場合、 Doma2 の設定は `DomaConfigBuilder` を利用して行えるようになっている。

```java:Doma2Application.java
package sample.springboot.doma2;

import org.seasar.doma.boot.autoconfigure.DomaConfigBuilder;
import org.seasar.doma.jdbc.JdbcLogger;
import org.seasar.doma.jdbc.UtilLoggingJdbcLogger;
...
import org.springframework.context.annotation.Bean;

import java.util.logging.Level;

@SpringBootApplication
public class Doma2Application {

	public static void main(String[] args) {
		try (ConfigurableApplicationContext context = SpringApplication.run(Doma2Application.class, args)) {
			...
		}
	}
	
	@Bean
	public JdbcLogger jdbcLogger() {
		return new UtilLoggingJdbcLogger(Level.FINE); // ★ ログレベルを FINE にして生成
	}

	@Bean
	public DomaConfigBuilder domaConfigBuilder() {
		DomaConfigBuilder builder = new DomaConfigBuilder();
		builder.jdbcLogger(jdbcLogger()); // ★ jdbcLogger を設定
		return builder;
	}
}
```

```text:実行結果
[]
[TestTable{id=1, name='foo'}, TestTable{id=2, name='bar'}]
```

- `UtilLoggingJdbcLogger` のコンストラクタ引数でログレベルを `FINE` にして生成し、 `DomaConfigBuilder` の `jdbcLogger()` にセットしている
- これでログの出力レベルが `FINE` （SLF4J などにおける DEBUG レベル）になるので、ログが出力されなくなった
    - `java.util.logging.Logger` のログレベルと SLF4J のログレベルの対応は、 `SLF4JBridgeHandler` の [Javadoc](https://www.slf4j.org/api/org/slf4j/bridge/SLF4JBridgeHandler.html) を参照

# メソッドごとにログ出力レベルを変更する
「SQL の出力だけは INFO レベルで出したい」みたいに、特定のログだけはデフォルトのログレベルとは異なるレベルで出力したい場合は、たぶん次のようにする。

```java:MyJdbcLogger.java
package sample.springboot.doma2;

import org.seasar.doma.jdbc.Sql;
import org.seasar.doma.jdbc.UtilLoggingJdbcLogger;

import java.util.function.Supplier;
import java.util.logging.Level;

// ★UtilLoggingJdbcLogger を継承して自作のロガーを作成
public class MyJdbcLogger extends UtilLoggingJdbcLogger {
    
    public MyJdbcLogger() {
        super(Level.FINE); // ★デフォルトのログレベルは FINE
    }

    // ★SQL を出力するロギングメソッドをオーバーライド
    @Override
    protected void logSql(String callerClassName, String callerMethodName, Sql<?> sql, Level level, Supplier<String> messageSupplier) {
        // ★引数の level (デフォルトログレベル) を無視して、強制的に INFO に差し替え
        super.logSql(callerClassName, callerMethodName, sql, Level.INFO, messageSupplier);
    }
}
```

```java:Doma2Application.java
package sample.springboot.doma2;

...

@SpringBootApplication
public class Doma2Application {

	public static void main(String[] args) {
		try (ConfigurableApplicationContext context = SpringApplication.run(Doma2Application.class, args)) {
			...
		}
	}
	
	@Bean
	public JdbcLogger jdbcLogger() {
		return new MyJdbcLogger(); // ★自作のロガーを使用
	}

	@Bean
	public DomaConfigBuilder domaConfigBuilder() {
		DomaConfigBuilder builder = new DomaConfigBuilder();
		builder.jdbcLogger(jdbcLogger());
		return builder;
	}
}
```

```text:実行結果
2018-12-03 23:09:34.627  INFO 18180 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[META-INF/sample/springboot/doma2/TestTableDao/findAll.sql],
SELECT *
  FROM TEST_TABLE
[]
2018-12-03 23:09:34.656  INFO 18180 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[null],
insert into TEST_TABLE (id, name) values (null, 'foo')
2018-12-03 23:09:34.660  INFO 18180 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[null],
insert into TEST_TABLE (id, name) values (null, 'bar')
2018-12-03 23:09:34.661  INFO 18180 --- [           main] o.s.doma.jdbc.UtilLoggingJdbcLogger      : [DOMA2076] SQLログ : SQLファイル=[META-INF/sample/springboot/doma2/TestTableDao/findAll.sql],
SELECT *
  FROM TEST_TABLE
[TestTable{id=1, name='foo'}, TestTable{id=2, name='bar'}]
```

- `UtilLoggingJdbcLogger` を継承して自作のロガーを作る
- そして、ログレベルを変更したいロギングメソッド（`protected` の方）をオーバーライドして、ログレベルを変更したいレベルに差し替えている
- これで、差し替えたロギングメソッドだけが、異なるログレベルで出力されるようになる

# 参考
- [Java - 【doma2】【SpringBoot】SQLログの非出力設定の方法がわかりません。｜teratail](https://teratail.com/questions/58674)
- [ログ出力ライブラリへのアダプタ | 設定 — Doma 2.0 ドキュメント](https://doma.readthedocs.io/ja/stable/config/#id7)

-----

<del>以上、明日の Java アドベントカレンダー、担当は null さんです。<br></del>
<del>誰か！書いて！！！！</del>

明日の担当は [@orekyuu](https://twitter.com/orekyuu) さんです。