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

今回の目的

Tweet

前回は、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]

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

動作環境

◾️動作環境やバージョン情報です。
OS：macOS Big Sur（バージョン11.7.1）
開発環境：Eclipse（Pleiades All in One、4.16(2020-06)、Java Full Edition版）
Spring Boot：バージョン2.7.6
Java：11
データベース：H2

今回作成するファイル

今回作成するファイルを先に書いておきます。

今回新規に作成するファイルは「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の２項目を編集します。
■編集前

spring.datasource.driver-class-name=org.h2.Driver
spring.datasource.url=jdbc:h2:mem:hogedb

spring.datasource.driver-class-name=net.sf.log4jdbc.sql.jdbcapi.DriverSpy
spring.datasource.url=jdbc:log4jdbc:h2:mem: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ファイルを作成して、１行コードを書きます。

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にしています。
それぞれの項目の意味についてです。

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

#この３つはここではもう使用しないのでコメントアウトしておく。削除してもOK。
#spring.jpa.show-sql=true
#logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace
#spring.jpa.properties.hibernate.format_sql=true

(広告)Spring BootのKindleや本をアマゾンで探す！本でSpring Bootプログラミング開発を体系的に勉強する！

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

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

〜
2022-11-26 19:16:12.923  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : drop table if exists diary CASCADE 
2022-11-26 19:16:12.928  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : create table diary (id integer generated by default as identity, comment varchar(255), create_datetime
timestamp not null, primary key (id)) 
〜
2022-11-26 19:16:13.545  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('今日は晴れ。コメント１', LOCALTIME()) 
2022-11-26 19:16:13.551  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('comment 2', LOCALTIME()) 
2022-11-26 19:16:13.552  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : INSERT INTO diary(comment, create_datetime) VALUES('こめんと３', LOCALTIME()) 
〜
2022-11-26 19:16:13.658  INFO 39287 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 3.706 seconds (JVM running for 4.717)
2022-11-26 19:16:13.785  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_, diary0_.comment as comment2_0_, diary0_.create_datetime as create_d3_0_ 
from diary diary0_ 
2022-11-26 19:16:13.825  INFO 39287 --- [  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 
2022-11-26 19:16:13.829  INFO 39287 --- [  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 
2022-11-26 19:16:13.865  INFO 39287 --- [  restartedMain] jdbc.sqlonly                             : delete from diary where id=2 
〜

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

logging.level.jdbc.resultsettable=info

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

2022-11-26 19:20:10.949  INFO 39522 --- [  restartedMain] jdbc.sqlonly                             : select diary0_.id as id1_0_, diary0_.comment as comment2_0_, diary0_.create_datetime as create_d3_0_ 
from diary diary0_ 

2022-11-26 19:20:10.968  INFO 39522 --- [  restartedMain] jdbc.resultsettable                      : 
|---|------------|----------------------|
|id |comment     |create_datetime       |
|---|------------|----------------------|
|1  |今日は晴れ。コメント１ |2022-11-26 19:20:11.0 |
|2  |comment 2   |2022-11-26 19:20:11.0 |
|3  |こめんと３       |2022-11-26 19:20:11.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】トップに戻る

Spring Bootの記事

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

参考サイト

Log4jdbc-log4j2
log4jdbc-log4j2 Google Code
Spring Boot アプリケーションプロパティ一覧、application.properties