(第5回) log4jdbc-log4j2でSQLログの出力設定【H2, Spring Boot2】

H2入門の第5回です。Spring Bootでlog4jdbc-log4j2を使ってSQLログ出力の設定を説明しています。Spring Bootを学習している初心者・入門者の方は、参考にしてください。

今回の目的

最終更新日:2021/5/19

前回は、Spring BootでSpring Data JPAによって実行されるSQLログの出力設定をしました。
(第4回) Spring Bootで実行されるSQLのログ出力の設定【Spring Boot2】

ただ前回のSQLログは、SQLログの条件文は「where id=?」とプレースホルダーになっていて、"?"に入る値は別の行で出力される書式でした。

Hibernate: delete from diary where id=?
〜
binding parameter [1] as [INTEGER] - [2]
また、初期データ作成のために作ったdata.sqlファイルにあるSQLの実行ログも出力されていません。

ですので、今回はまた別の方法のlog4jdbc-log4j2を使って、SQLログの出力を設定してみます。

動作環境

◾️動作環境やバージョン情報です。
OS:macOS Catalina(バージョン10.15.5)
開発環境:Eclipse(Pleiades All in One、4.16(2020-06)、Java Full Edition版)、(*2020/8/28時点の最新安定版です)
Spring Boot:バージョン2.3.3
Java:11
データベース:H2

今回作成するファイル

今回作成するファイルを先に書いておきます。
Spring Boot、log4jdbc-log4j2でSQLログ出力

今回新規に作成するファイルは「log4jdbc.log4j2.properties」1つで、編集するファイルは「pom.xml」「application.properties」の2つです。

Log4jdbc-log4j2でSQLロギングの設定

Log4jdbc-log4j2 は、SQLロギングのためのJDBCプロキシードライバーです。
Log4jdbc-log4j2を使用する事で、JDBCドライバ経由のSQLログを出力できます。SQLログの他にJDBC呼び出しやSQLの実行時間などのオプション情報も出力できます。

以前は、log4jdbc(log4jdbc-remix)というSQLロギングのJDBCプロキシードライバーがありましたが、log4jdbcはかなり昔(2013/11)に開発は終了していて、log4jdbc-remixのページを見ても、log4jdbc-remixではなくLog4jdbc-log4j2を使用する事を推奨しています。

という事で、Log4jdbc-log4j2を使用してSQLログ出力の設定をしてみます。

まず、log4jdbc-log4j2ライブラリを読み込むために、pom.xmlに<dependency>タグを追加します。

<dependency>
  <groupId>org.bgee.log4jdbc-log4j2</groupId>
  <artifactId>log4jdbc-log4j2-jdbc4.1</artifactId>
  <version>1.16</version>
</dependency>

次に、使用するドライバクラスと接続するJDBC URLを変更するため、application.propertiesの2項目を編集します。

spring.datasource.driverClassName=net.sf.log4jdbc.sql.jdbcapi.DriverSpy
spring.datasource.url=jdbc:log4jdbc:h2:mem:hogedb
spring.datasource.urlの"h2"はH2データベースを使用、"mem"はインメモリでH2を使用、"hogedb"はデータベース名を意味しています。

ちなみに上のapplication.propertiesの設定をして、pom.xmlにlog4jdbc-log4j2-jdbc4.1を読み込む設定をしないと、アプリ起動時に下のエラーが出ます。
「Caused by: java.lang.IllegalStateException: Cannot load driver class: net.sf.log4jdbc.sql.jdbcapi.DriverSpy」

次に、src/main/resourcesディレクトリ下にlog4jdbc.log4j2.propertiesファイルを作成して、1行コードを書きます。

log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator

これでLog4jdbc-log4j2を使用してSQLログを出力することができます。
ただこのままだと、SQL以外のJDBC関連の膨大なログが出力されるので、JDBC関連のどのログを出力するか、出力するログレベルはどうするかなどの設定を、またapplication.propertiesでします。

今回は実行するSQLログだけを出力するように、application.propertiesに追記します。

logging.level.jdbc.sqlonly=info
logging.level.jdbc.resultsettable=off
logging.level.jdbc.connection=off
logging.level.jdbc.sqltiming=off
logging.level.jdbc.audit=off
logging.level.jdbc.resultset=off

logging.level.jdbc.sqlonlyだけログレベルinfoで出力して、あとのログ情報はoffにしています。
それぞれの項目の意味についてです。

logging.level.jdbc.sqlonly 実行するSQLログを出力。info,debug,traceで出力してくれる。
logging.level.jdbc.resultsettable select SQLのレコード取得結果をテーブル形式で出力。
logging.level.jdbc.connection JDBCコネクション(オープン・クローズ)ログを出力。
logging.level.jdbc.sqltiming 各SQLの実行時間を出力。処理に時間がかかる場合、どのSQLで時間がかかっているかがわかる。info,debug,traceで出力してくれる。
logging.level.jdbc.audit ResultSet(SQL取得結果)以外の全てのJDBC呼び出しログを出力。このログを出力すると膨大になるので、通常はoffにしてJDBC周りのトラブルシューティング時はdebug,infoにすべき。
logging.level.jdbc.resultset ResultSet(SQL取得結果)ログを出力。SQL取得結果レコードを1フィールドずつ出力するので、これもログが膨大になる。

また、設定できるログレベルは、debug,error,fatal,info,off,trace,warnの7つです。
(*ちなみにこの7つは、org.springframework.boot.logging.LogLevelにあるENUM値です)

アプリの実行とSQLログの確認

それでは実際にアプリを実行して、コンソールビューでSQLのログを確認します。

〜
2020-10-15 04:15:05.042  INFO 31390 --- [         task-1] jdbc.sqlonly                             : drop table if exists diary CASCADE 

2020-10-15 04:15:05.046  INFO 31390 --- [         task-1] jdbc.sqlonly                             : create table diary (id integer generated by default as identity, comment varchar(255), create_datetime 
timestamp not null, primary key (id)) 

2020-10-15 04:15:05.057  INFO 31390 --- [         task-1] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2020-10-15 04:15:05.063  INFO 31390 --- [         task-1] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2020-10-15 04:15:05.191  INFO 31390 --- [  restartedMain] DeferredRepositoryInitializationListener : Spring Data repositories initialized!
2020-10-15 04:15:05.194  INFO 31390 --- [         task-2] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('今日は晴れ。コメント1', LOCALTIME()) 

2020-10-15 04:15:05.201  INFO 31390 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 2.671 seconds (JVM running for 3.365)
2020-10-15 04:15:05.201  INFO 31390 --- [         task-2] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('comment 2', LOCALTIME()) 

2020-10-15 04:15:05.202  INFO 31390 --- [         task-2] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('こめんと3', LOCALTIME()) 

2020-10-15 04:15:05.304  INFO 31390 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_, diary0_.comment as comment2_0_, diary0_.create_datetime as create_d3_0_ 
from diary diary0_ 

2020-10-15 04:15:05.326  INFO 31390 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_0_, diary0_.comment as comment2_0_0_, diary0_.create_datetime as 
create_d3_0_0_ from diary diary0_ where diary0_.id=1 

2020-10-15 04:15:05.330  INFO 31390 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_0_, diary0_.comment as comment2_0_0_, diary0_.create_datetime as 
create_d3_0_0_ from diary diary0_ where diary0_.id=2 

2020-10-15 04:15:05.343  INFO 31390 --- [  restartedMain] jdbc.sqlonly                             : delete from diary where id=2 
ログを見ると、Diaryエンティティからdiaryテーブルが作成するcreate tableログがありますし、data.sqlにある初期データ作成のinsertクエリのログもあります。
また、プレースホルダー無しのselect,deleteのSQLログもしっかり出力されています。これでやりたい事ができました。

あと例えば、select SQLの結果もログで出したい場合の設定です。

logging.level.jdbc.resultsettable=info

これでアプリを実行した場合、select SQLで取得したレコードのログも出力されます。

2020-10-15 04:34:20.755  INFO 32402 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_, diary0_.comment as comment2_0_, diary0_.create_datetime as create_d3_0_ 
from diary diary0_ 

2020-10-15 04:34:20.762  INFO 32402 --- [  restartedMain] jdbc.resultsettable                      : 
|---|------------|----------------------|
|id |comment     |create_datetime       |
|---|------------|----------------------|
|1  |今日は晴れ。コメント1 |2020-10-15 04:34:21.0 |
|2  |comment 2   |2020-10-15 04:34:21.0 |
|3  |こめんと3       |2020-10-15 04:34:21.0 |
|---|------------|----------------------|

最後に、次回

以上簡単でしたが、Spring Bootアプリでlog4jdbc-log4j2を使ってSQLログの出力設定を説明しました。
これで開発するプログラマにとって、バグや問題解決の助けになると思います。

次回は、log4jdbc-log4j2を使用するためにJDBCドライバやJDBCの接続するURLも変更したので、再度H2 Consoleの接続を確認してみます。

(第6回) H2の管理ツールH2 Console、Log4jdbc-log4j2用のドライバDriverSpy使用時【H2, Spring Boot2】
H2データベース入門【Spring Boot】トップに戻る

[広告] Kindle Unlimitedなら対象の本が定額で読み放題
対象本には、プログラミングなどのIT関連本、マンガ、雑誌、ビジネス書などがたくさんあります!

Spring Bootの記事

Spring Boot2で日記投稿ウェブアプリ開発入門トップページ
Spring Boot2.3,2.4でシンプルな日記投稿ウェブアプリの開発しながら、入門者・初心者にもわかりやすいように説明しています。DBを使用して、新規投稿、編集、削除、一覧表示という基本的なCRUD機能を備えたアプリです。