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

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

今回の目的

最終更新日:2022/11/27

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

今回作成するファイル

今回作成するファイルを先に書いておきます。
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.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
"spring.datasource.driver-class-name"は、"spring.datasource.driverClassName"でも問題ないです。
"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値です)

あと、今回はlog4jdbc-log4j2でSQLログ出力をするので、前回ページでapplication.propertiesファイルに指定したプロパティ"spring.jpa.show-sql"、"logging.level.org.hibernate.type.descriptor.sql.BasicBinder"は削除しても構いません。ついでにSQL整形の"spring.jpa.properties.hibernate.format_sql"プロパティも削除します。

#この3つはここではもう使用しないのでコメントアウトしておく。削除してもOK。
#spring.jpa.show-sql=true
#logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace
#spring.jpa.properties.hibernate.format_sql=true
"spring.jpa.show-sql"、"logging.level.org.hibernate.type.descriptor.sql.BasicBinder"プロパティを残しておくと、Hibernate(Spring Data JPA機能)のSQLログも出力されるので、削除しないと同じSQLログが2回出力されてしまうためです。

Spring Boot 本をAmazonで探す [広告]

アプリの実行と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('今日は晴れ。コメント1', 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('こめんと3', 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 
〜
ログを見ると、Diaryエンティティからdiaryテーブルが作成するcreate tableログがありますし、data.sqlにある初期データ作成のinsertクエリのログもあります。
また、プレースホルダー無しのselect,deleteのSQLログもしっかり出力されています。これでやりたい事ができました。

あと例えば、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  |今日は晴れ。コメント1 |2022-11-26 19:20:11.0 |
|2  |comment 2   |2022-11-26 19:20:11.0 |
|3  |こめんと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】トップに戻る

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

Spring Bootの記事

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