Info log about registered Agroal Pool interceptors

[Postremus]

Describe the bug

I added an agroal pool interceptor to my project, to help me debug some high vendor_agroal_max_used_count metrics.

During this I noticed an additional log line informing about the registered Listener on quarkus startup. Maybe it can be removed?

See log output below - first line after quarkus banner.

Expected behavior

No additional log line when using quarkus supported features.

Actual behavior

__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2022-10-25 07:24:20,520 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Pool interceptors: [org.acme.LoggingAgroalPoolInterceptor_ClientProxy@15dc662c (priority 0)]
2022-10-25 07:24:20,660 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) acq
2022-10-25 07:24:20,668 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) ret
2022-10-25 07:24:20,835 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) acq
2022-10-25 07:24:20,841 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2022-10-25 07:24:20,842 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "myentity" does not exist, skipping
2022-10-25 07:24:20,844 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2022-10-25 07:24:20,845 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) sequence "hibernate_sequence" does not exist, skipping
2022-10-25 07:24:20,846 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) ret
2022-10-25 07:24:20,848 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) acq
2022-10-25 07:24:20,853 INFO  [org.acm.LoggingAgroalPoolInterceptor] (JPA Startup Thread: <default>) ret
2022-10-25 07:24:20,862 INFO  [io.quarkus] (Quarkus Main Thread) pool-interceptor-log 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.13.3.Final) started in 5.665s.
2022-10-25 07:24:20,864 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2022-10-25 07:24:20,865 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, hibernate-orm, jdbc-postgresql, narayana-jta, smallrye-context-propagation]

How to Reproduce?

Reproducer: pool-interceptor-log.zip

1. mvn quarkus:dev
2. The additional log line appears directly after the banner

Output of uname -a or ver

Microsoft Windows [Version 10.0.19044.2130]

Output of java -version

openjdk 19 2022-09-20 OpenJDK Runtime Environment Temurin-19+36 (build 19+36) OpenJDK 64-Bit Server VM Temurin-19+36 (build 19+36, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.13.3.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537) Maven home: C:\eclipse\tools\java\maven Java version: 19, vendor: Eclipse Adoptium, runtime: C:\eclipse\tools\java\19 Default locale: de_DE, platform encoding: UTF-8 OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

No response

[quarkus-bot[bot]]

/cc @Sanne, @barreiro, @yrodiere

[geoand]

Looking at the code it does seem that Agroal intentionally uses INFO for this case, but I agree that it's probably better to have it DEBUG.

@barreiro WDYT?

[gsmet]

@yrodiere WDYT? My inclination would also be to make it debug.

[yrodiere]

@yrodiere WDYT? My inclination would also be to make it debug.

Sure, makes sense to me. Preferably in Agroal, but from what I can see we can also override the level in Quarkus if need be (with io.quarkus.deployment.logging.LogCleanupFilterBuildItem#LogCleanupFilterBuildItem(java.lang.String, java.util.logging.Level, java.util.List<java.lang.String>)).

[geoand]

Yeah we can do that, but if we can do it in Agroal, it would be best.

[geoand]

Since this is super simple to do, I just went ahead and opened https://github.com/agroal/agroal/pull/58. Let's see what the outcome is.

[barreiro]

I decided against incorporating this change.

The log level can always be changed with quarkus.log.category."io.agroal.pool".level=WARN

Anyway, thanks for the report.

[gsmet]

@yrodiere I think we need to override this in Quarkus because I don't think @barreiro 's decision is satisfying for us.

[yrodiere]

@yrodiere I think we need to override this in Quarkus because I don't think @barreiro 's decision is satisfying for us.

Ok.

I couldn't find the reason behind that decision, btw, I'd be curious to know...

[Sanne]

I decided against incorporating this change.

The log level can always be changed with quarkus.log.category."io.agroal.pool".level=WARN

Anyway, thanks for the report.

@barreiro In Quarkus we're striving for absolutely zero logging messages - unless there's something the user really needs to know. And this should be the out-of-the-box experience, so needing the users to reconfigure their logging isn't an approach we can take; if you really need this logged by Agroal at INFO it would be nice to:

1. explain why here so we can refer to the reasons in the future, should this come up again
2. patch the Quarkus extension for Agroal to reconfigure your logging levels automatically - and please be careful in not silencing other things which are actually important to report.

[barreiro]

@Sanne, @yrodiere, @gsmet I will reply privately.