Add tip about quarkus.log.level on quarkus.hibernate-orm.log.bind-parameters property

[felipewind]

Description

On the hibernate-orm guide, add the following tip to the quarkus.hibernate-orm.log.bind-parameters property:

• You must change the quarkus.log.min-level to TRACE after changing this property to true.

As I've explained in this topic, when we only set the quarkus.hibernate-orm.log.bind-parameters to TRUE the following error occurs:

WARN  [io.qua.run.log.LoggingSetupRecorder] (Quarkus Main Thread) Log level TRACE for category 'org.hibernate.type.descriptor.sql.BasicBinder' set below minimum logging level DEBUG, promoting it to DEBUG

Until Quarkus version 1.10.5.Final this wasn't necessary.

But, if you think this is too obvious please forgive me and just close this issue.

Thanks!

[quarkus-bot]

/cc @Sanne, @gsmet, @yrodiere

[Sanne]

We could improve the warning message with a suggestion / pointers about how to really change the logging level.

You think that would make this simpler?

Re-labeling the issue as it's not really Hibernate related. cc/ @galderz

[felipewind]

We could improve the warning message with a suggestion / pointers about how to really change the logging level.

You think that would make this simpler?

Ra-labeling the issue as it's not really Hibernate related. cc/ @galderz

Yes, I think this would make it simpler. Good idea!

[gsmet]

@Sanne AFAICS, this one is build time, couldn't we adjust automatically the log level for this category? Producing a LogCategoryBuildItem would work I think.

Let me try that this afternoon, I'll get back to you.

[gsmet]

We would also need something similar to LogCategoryBuildItem for the min level but it doesn't sound like undoable.

[Sanne]

@gsmet I'm not sure I understand your proposal - you'd want the ORM specific property to override the system logger's configuration? Sounds like a bit confusing

[galderz]

Was away for a few weeks and this slip. Do you still need my help with this? Yeah, the message you explain what propertie(s) that can be passed in to workaround the issue.

[kucharzyk]

I was just going to report that quarkus.hibernate-orm.log.bind-parameters is not working.

After digging in quarkus issues I've realized I need to configure logger like this:

quarkus.log.category."org.hibernate.type.descriptor.sql".min-level=TRACE

It need to be documented at least unless there is an option to change log level automatically after setting this property.

[galderz]

@kucharzyk What about you send a PR to improve the guide?

[kenyee]

does this work for unit tests? I do this and it doesn't seem print the params with Quarkus 2.7.5.Final or 2.8.0.CR1:

%test.quarkus.hibernate-orm.log.sql=true
%test.quarkus.log.category."org.hibernate.type.descriptor.sql".min-level=TRACE
%test.quarkus.hibernate-orm.log.bind-parameters=true

Also tried adding it to %dev w/o luck

[felipewind]

does this work for unit tests? I do this and it doesn't seem print the params with Quarkus 2.7.5.Final or 2.8.0.CR1:

%test.quarkus.hibernate-orm.log.sql=true
%test.quarkus.log.category."org.hibernate.type.descriptor.sql".min-level=TRACE
%test.quarkus.hibernate-orm.log.bind-parameters=true

Also tried adding it to %dev w/o luck

Have you tried to add %test.quarkus.log.min-level=TRACE ?

[felipewind]

Post on StackOverflow about this:

https://stackoverflow.com/questions/67305893/quarkus-hibernate-orm-log-bind-parameters-dont-work

[siudeks]

%test.quarkus.log.min-level=TRACE

It does not work either

Do you need some code to reproduce the bug, or is it qualified as proven and just waiting for prioritization / PR?

[felipewind]

%test.quarkus.log.min-level=TRACE

It does not work either

Do you need some code to reproduce the bug, or is it qualified as proven and just waiting for prioritization / PR?

What version of Quarkus are you using?

Just to clarify, some parameters are build time, so you can't change them on deploy:

• They have a picture of a padlock
• 

Here you can read all parameters from Quarkus:

• https://quarkus.io/guides/all-config

quarkus.log.min-level

• Build time parameter
• 

quarkus.hibernate-orm.log.bind-parameters

• Also a build time parameter

quarkus.hibernate-orm.log.sql

• A parameter that you can change on your deploy.

Test with 2.9.1.Final version

I run just now one application with the 2.9.1Final version using these parameters and I was able to see all the SQL logs, that are the SQL instruction and the SQL binding variables:

quarkus.log.min-level=TRACE
quarkus.hibernate-orm.log.bind-parameters=true
quarkus.hibernate-orm.log.sql=true

[siudeks]

@felipewind Thanks for quick response, let me clarify with reproduction

source: https://github.com/siudeks/tech-spikes/tree/master/bugrepro_sql_binding_parameters

Reproduction steps:

1. mvn install
2. Check produced logs
   Expected:

   Hibernate: 
    insert 
    into
        Client
        (name, id) 
    values
        ('my name', 1)
   

   Actual

   Hibernate: 
    insert 
    into
        Client
        (name, id) 
    values
        (?, ?)
   

[felipewind]

@felipewind Thanks for quick response, let me clarify with reproduction

source: https://github.com/siudeks/tech-spikes/tree/master/bugrepro_sql_binding_parameters

Reproduction steps:

1. mvn install

2. Check produced logs
   Expected:

   Hibernate: 
    insert 
    into
        Client
        (name, id) 
    values
        ('my name', 1)
   

   Actual

   Hibernate: 
    insert 
    into
        Client
        (name, id) 
    values
        (?, ?)
   

Actually, it works a bit different. You don't see ('my name', 1), you see (?,?) and after the (? ? ) you should view two new lines with something like

binding parameter [1] as [VARCHAR] - ["my name"]
binding parameter [2] as [INTEGER] - [1]

Every parameter that you have in your SQL will appear sequentially (1, 2, 3...) after your SQL.

You must count the SQL parameters to realize what binding parameter [n] is.

[felipewind]

I created this application how you can enable the Hibernate ORM log binding parameters:

• https://github.com/felipewind/quarkus-hibernate-log-bind-parameters

Shortly, you add this to your application.properties:

# dev mode - mvn quarkus:dev
%dev.quarkus.log.min-level=TRACE
%dev.quarkus.hibernate-orm.log.bind-parameters=true
%dev.quarkus.hibernate-orm.log.sql=true

# test mode - mvn quarkus:test
%test.quarkus.log.min-level=TRACE
%test.quarkus.hibernate-orm.log.bind-parameters=true
%test.quarkus.hibernate-orm.log.sql=true

And you will see something like this:

Hibernate: 
    select
        fruit0_.id as id1_0_0_,
        fruit0_.name as name2_0_0_ 
    from
        known_fruits fruit0_ 
    where
        fruit0_.id=?

2022-05-29 19:13:41,584 TRACE [org.hib.typ.des.sql.BasicBinder] (executor-thread-0) binding parameter [1] as [INTEGER] - [1]

[siudeks]

@felipewind is working as a charm, thanks for educating me

'missing' parameters are in logs, but below - exactly as you pointed

[yrodiere]

@Sanne AFAICS, this one is build time, couldn't we adjust automatically the log level for this category? Producing a LogCategoryBuildItem would work I think.

So, that's already the case since January 2020.

We would also need something similar to LogCategoryBuildItem for the min level but it doesn't sound like undoable.

I'll have a look.