Exception logged although it's wrapped and thrown to the caller

[bratkartoffel]

Hi,

as our users are pretty picky about stacktraces in the logfile, we found the following code in hikari:

HikariCP/src/main/java/com/zaxxer/hikari/pool/HikariPool.java

Line 593 in c993ef0

logger.error("{} - Exception during pool initialization.", poolName, t);

The exception during startup is logged there, then packed into another exception and thrown to the caller. Can you please remove the logging statement there and leave the logging of this exception to the caller?

Thanks,
Simon

[quaff]

Your request may break compatibility, and what's your real intent?

[bratkartoffel]

I think it's not good to log exceptions and errors twice or more often. An error should be logged only once, and only where it is handled. In the case of a library (as HikariCP) this is usually the calling application.

In this case, the exception is logged and packed into an PoolInitializationException (an unchecked exception) and is thrown this callstack: throwPoolInitializationException() -> checkFailFast() -> HikariPool() -> caller

I think it's not good that it's an unchecked exception, but that would indeed be a breaking change. We have to catch and handle it nevertheless. Thus I think logging it within the library is redundant.

Thanks,
Simon

[quaff]

See #1660

[jamey-clari]

Your request may break compatibility, and what's your real intent?

How does this break compatibility - no API or application behavior is changed?

Okay, I see it now, it's the request that PoolInitializationException perhaps not be unchecked. Honestly, I don't understand the choice of using an unchecked exception here but I think it would be reasonable to divorce the issue of the redundant logging from the conversion of the exception to checked. I'm finding the former more problematic than the latter which our application can handle just fine.

[jamey-clari]

I think it's not good to log exceptions and errors twice or more often. An error should be logged only once, and only where it is handled. In the case of a library (as HikariCP) this is usually the calling application.

In this case, the exception is logged and packed into an PoolInitializationException (an unchecked exception) and is thrown this callstack: throwPoolInitializationException() -> checkFailFast() -> HikariPool() -> caller

I think it's not good that it's an unchecked exception, but that would indeed be a breaking change. We have to catch and handle it nevertheless. Thus I think logging it within the library is redundant.

Thanks,
Simon

+1 on this - mostly. I came here to file something very close to this issue. It is generally undesirable for libraries to log exceptions and re-throw. If it is a condition that warrants logging as determined by the caller then it results in redundant logs. If it isn't then it creates log clutter and possible confusion where non needed exist. The notion that suppressing the logging by dialing the log level up to FATAL is a poor one as it means that the potentially desirable informational logging provided at DEBUG, INFO, or WARN levels is now omitted. We may wish to view these for debugging purposes without the clutter of this exception being logged.

Here is why I care:

Our application will sometimes fault-in DB creation. In particular we have a DB resolution mechanism that, particularly in a testing environment, may read a connection pool descriptor and attempt to connect. Upon failure with a code that indicates the DB doesn't exist, it will create and initialize the DB and then retry creation of the pool. In our normal production environment this is a scenario that rarely, if ever, exists and we handle the exception accordingly. For testing this results in literally 10s of MB of additional logging that is both superfluous and misleading when our full test suite is executed. While we don't want to see this exception logged (we catch and handle it), we don't want to mute info level logging of Hikari because it aids in debugging and checking of our dynamic creation and tear-down of connection pools (of which our application maintains hundreds).

In short, the redundant logging is annoyingly noisy and unnecessary. Let's not get hung up on changing the throws signature of the HikariPool constructor and let that be the reason for continuing to log and then throw. It would be totally reasonable to remove the embedded error logging in HikariPool.throwPoolInitializationException while leaving the throwing of the unchecked PoolInitializationException as-is. The only information that I can see that we are losing in doing that is the poolName which was never really available to the application anyway as it was simply logged and this could easily be added to the PoolInitializationException with no impact to method signatures. If there is an important reason to consider throwing a checked exception than I'd ask that you please file a separate issue for that so that the issue of redundant logging can be resolved.

Thanks for your consideration!

[jamey-clari]

Just a ping to see if anyone else is on-board with moving this forward as a non-breaking change? This would entail no change to method signature but would eliminate the, IMO superfluous, internal logging in addition to throwing the PoolInitializationException?

[jamey-clari]

Is anyone considering this at all? The fix would be trivial and incredibly low risk. Is this really not worth a moment's consideration? Thanks!

[dhait]

+1 !
I also came here ready to file this and found your issue. I want to catch this exception and log it myself, not use the logging already built into throwPoolInitializationException().
The only workaround here it to turn off error logging in hikari which is a bit drastic.

[jamey-clari]

Still hoping this and #1660 will be picked up and simply merged as this is a trivial improvement that follows standard library exception handling practice. Pretty please!