Full stacktrace logged for services that cannot be loaded

[papegaaij]

Search first

• I searched and no similar issues were found

Description

The change in #5300 causes a full stacktrace to be logged when a service cannot be loaded. In our case HibernateSpringBeanDatabase cannot be loaded, because we do not include spring. This is fine, and expected. I'm ok with a single log line at INFO, and a full stacktrace at FINE (as it was before #5300), but now we get quite some log spam and no way to disable it (other than fully disabling all logging on this class).

I don't see why #5300 was needed in the first place. The logging was already in place. The only thing needed to get the full stacktrace was to simply enable the fine log level. Now the trace is logged twice.

Steps To Reproduce

Start liquibase without spring on the classpath.

Expected/Desired Behavior

StandardServiceLocator should not log full stacktraces under normal circumstances.

Liquibase Version

4.25.1

Database Vendor & Version

No response

Liquibase Integration

no spring

Liquibase Extensions

No response

OS and/or Infrastructure Type/Provider

No response

Additional Context

No response

Are you willing to submit a PR?

• I'm willing to submit a PR (Thank you!)

[tati-qalified]

Hi @papegaaij, could you provide some more information about your project's environment?
Are you using Maven, Gradle, or something else?
Are you using the Liquibase plugin or just the dependency?

Thanks,
Tatiana

[papegaaij]

@tati-qalified We are using maven and just the dependency. Liquibase runs from within our application at startup. The problem with the change in #5300 is that the logging is duplicated. The same, full error is logged twice. Not being able to load a certain service that depends on an optional dependency does not warrant logging a full stacktrace. Many of our developers got confused by this stacktrace in the logging and thought that the application failed to deploy.

[tati-qalified]

@papegaaij I see what you mean. We'll work on improving the log message so that it's informative but not overpowering.
Thanks!
Tatiana

[StevenMassaro]

The change in #5300 was necessary because the exceptions in the service loader are thrown before logging is configured, thus, there is no way to change the log level prior to the service loader being called.

I am not opposed to a more appropriate solution, but I personally don't know of one that doesn't involve a large refactoring of the log service to not use the service loader (which would also break other features).

Perhaps we could break away from our existing pattern of using the LiquibaseConfiguration classes to load configuration properties, and add in an environment variable or system property to this class that allows customization of logging at this point? This type of change is necessary, because the LiquibaseConfiguration classes themselves use the service loader mechanism.

[StevenMassaro]

Just to clarify on your point here:

I'm ok with a single log line at INFO, and a full stacktrace at FINE (as it was before #5300), but now we get quite some log spam and no way to disable it (other than fully disabling all logging on this class).

I agree that the original behavior is ideal, but since the logging isn't set up at this point, the log message logged at level FINE will never actually get logged, regardless of what you set your log level to.

[papegaaij]

@StevenMassaro this may hold for your setup, but it does not for us. Our logging is provided by the WildFly configuration and is correctly setup at startup, way before Liquibase is started.

IMHO it is not a very good idea to rely on a service for logging and use this service from the service loader that is supposed to load that very service. Why not simply rely on a logging facade, like SLF4J, and not try to put yet another facade around this?

[StevenMassaro]

@papegaaij Thanks for the quick response.

Liquibase supports numerous different types of setups, and the logging facade that currently exists supports the default (and most common) configuration of Liquibase well. It also follows the pattern of service discovery that Liquibase uses heavily, and was mainly introduced due to Liquibase's desire not to depend on third party libraries when possible.

Our team has discussed replacing our logging facade with something like slf4j. I cannot guarantee that this will happen, and if it does happen, we don't have a real timeline for it.

The setup that you have with wildfly is certainly not one of the more common setups. It sounds to me like this is a bug on the hibernate extension, which should not be causing this exception to occur when Spring is not on the classpath. I believe this can be fixed by moving the references to Spring classes out of this class, so that the service loader can instantiate it despite Spring not being on the classpath.

I am going to close this issue so that we can track this issue in the hibernate extension repo: liquibase/liquibase-hibernate#659. Could you include a copy of your logs in that newly created ticket?

[StevenMassaro]

Reopened this issue, when the hibernate issue is fixed, then we can close this one.

[filipelautert]

Thanks @StevenMassaro ! @papegaaij we can follow up this on hibernate extension, I'll ask @kevin-atx to prioritize this one.

[papegaaij]

I do have a request for this ticket still. If the loglevel is not going to be changed, can the category be changed on which the full stracktrace is logged? A simple solution would be to create an inner class and log on that class instead. This would allow us to silence that category, without loosing the informative message.

[filipelautert]

I talked to Steve and we agree that this is fine, no problems with that . Thanks for the workaround idea @papegaaij !

[filipelautert]

@papegaaij do you think https://github.com/liquibase/liquibase/pull/5667/files would be enough? Or did I got your request wrong?

[papegaaij]

Yes, that looks great. That should make it possible to silence warnings for that specific category. Thanks for the fix!