Hibernate 6 で slf4j-simple を使って binding parameters を表示する

Hibernate 6 で slf4j-simple で binding parameters を表示しようとした場合、2つの罠があります。抜け出し方を解説します。

罠1: slf4j-simple の設定が読まれない

simplelogger.properties を配置しても読んでくれないので悩んでいたのですが、以下の Q&A を見て解決することができました。

なぜかシステム プロパティを設定しなくても SLF4J が読み込まれるのは Logback が使われるときだけというコードになっているため、システム プロパティの org.jboss.logging.provider に slf4j を設定する必要があるそうです。コマンドラインで

java -Dorg.jboss.logging.provider=slf4j

のようにしても良いですが、メイン クラス冒頭に以下の static イニシャライザーを加えてしまうのが、IDE から実行する場合にはお手軽かと思います。

    static {
        System.setProperty("org.jboss.logging.provider", "slf4j");
    }

Hibernate のチュートリアルの場合、TestCase を拡張している EntityManagerIllustrationTest などのクラスがメイン クラス相当になりますが、この場合は setUp() への追加で大丈夫です。

	protected void setUp() throws Exception {
        System.setProperty("org.jboss.logging.provider", "slf4j");

罠2: binding parameters を表示するログ カテゴリーが変更されている

Hibernate 6 から binding parameters を表示するログ カテゴリーが log4j.logger.org.hibernate.type.descriptor.sql から以下の2つに変更になったようです。

• org.hibernate.orm.jdbc.bind - INSERT 時のパラメーター
• org.hibernate.orm.jdbc.extract - SELECT などで返ってきた値

なお、公式の文書 27.2. Logging によれば log4j.logger.org.hibernate.type.descriptor.jdbc を設定することになっているのですが、これは機能しませんでした。

したがって、罠1を回避した上で SimpleLogger の JavaDoc に従って simplelogger.properties を以下のように設定すると、binding parameter を表示することができます。

simplelogger.properties

org.slf4j.simpleLogger.log.org.hibernate.orm.jdbc.bind=trace
org.slf4j.simpleLogger.log.org.hibernate.orm.jdbc.extract=trace

persistence.xml で以下のように show_sql と format_sql を指定してある場合、

            <property name="hibernate.show_sql" value="true" />
            <property name="hibernate.format_sql" value="true" />

以下のように、binding parameters や抽出された値がログに出力されます。

Hibernate: 
    insert 
    into
        EVENTS
[main] DEBUG org.hibernate.orm.jdbc.bind - binding parameter [1] as [TIMESTAMP] - [2022-04-25 00:26:19.433]
        (EVENT_DATE, title, id) 
    values
        (?, ?, ?)
[main] DEBUG org.hibernate.orm.jdbc.bind - binding parameter [2] as [VARCHAR] - [A follow up event]
[main] DEBUG org.hibernate.orm.jdbc.bind - binding parameter [3] as [BIGINT] - [2]
[main] WARN org.hibernate.orm.deprecation - HHH90000021: Encountered deprecated setting [javax.persistence.lock.timeout], use [jakarta.persistence.lock.timeout] instead
Hibernate: 
    select
        e1_0.id,
        e1_0.EVENT_DATE,
        e1_0.title 
    from
        EVENTS e1_0
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([1] : [BIGINT]) - [1]
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([2] : [TIMESTAMP]) - [2022-04-25 00:26:19.377]
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([3] : [VARCHAR]) - [Our very first event!]
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([1] : [BIGINT]) - [2]
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([2] : [TIMESTAMP]) - [2022-04-25 00:26:19.433]
[main] DEBUG org.hibernate.orm.jdbc.extract - extracted value ([3] : [VARCHAR]) - [A follow up event]