Slf4j does not log correct class

[re-thc]

Describe the bug
When using slf4j-tinylog the correct class is not logged

To Reproduce
Steps to reproduce the behavior:

1. Use tinylog, tinylog-api and slf4j-tinylog
2. Run an application that uses slf4j e.g. Flyway
3. It runs and logs incorrectly, e.g.

2021-01-01 15:33:23 [io-executor-thread-1] org.flywaydb.core.internal.logging.slf4j.Slf4jLog.info()
INFO: Flyway Community Edition 7.3.1 by Redgate
2021-01-01 15:33:23 [io-executor-thread-1] org.flywaydb.core.internal.logging.slf4j.Slf4jLog.info()
INFO: Database: jdbc:postgresql://127.0.0.1:6432/test (PostgreSQL 13.1)
2021-01-01 15:33:23 [io-executor-thread-1] org.flywaydb.core.internal.logging.slf4j.Slf4jLog.info()
INFO: Current version of schema "public": 1.1

Where these entries belong to different classes, e.g. the first is run from a class called VersionPrinter.

Environment
tinylog version: 2.2.1
Java version: 15

[pmwmedia]

The cause for this issue is that flyway's Slf4jLog class is a wrapper around SLF4J's real logger class. So, tinylog has no chance to detect the real caller class. Which caller method does Logback or Log4j output?

[re-thc]

Is there a workaround for this? Noticed quite a few "popular" third party libraries doing similar. Hazelcast is another example that has a "wrapper". Slf4j keeps a log name - is that usable for this?

Flyway routes to slf4j as a priority. Will try to create an isolated test case and get back to you.

[pmwmedia]

SLF4J is just a logging API. For me, it is interesting what method other logging back-ends like Logback and Log4j output. Could you test it and paste the output here?

[pmwmedia]

After some research, I came to the conclusion that flyway has to use the LocationAwareLogger functionality for their custom Slf4jLog wrapper class. Otherwise no logging back-end would have any chance to detect the real caller method.

[re-thc]

Below is what I get from Logback:

14:09:33.329 [io-executor-thread-1] INFO io.micronaut.flyway.AbstractFlywayMigration - Running migrations for database with qualifier [default]
14:09:33.331 [io-executor-thread-1] INFO org.flywaydb.core.internal.license.VersionPrinter - Flyway Community Edition 7.3.1 by Redgate
14:09:33.366 [io-executor-thread-1] INFO org.flywaydb.core.internal.database.base.DatabaseType - Database: jdbc:postgresql://127.0.0.1:6432/test (PostgreSQL 13.1)
14:09:33.410 [io-executor-thread-1] INFO org.flywaydb.core.internal.command.DbValidate - Successfully validated 2 migrations (execution time 00:00.019s)
14:09:33.423 [io-executor-thread-1] INFO org.flywaydb.core.internal.command.DbMigrate - Current version of schema "public": 1.1
14:09:33.424 [io-executor-thread-1] INFO org.flywaydb.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.

[pmwmedia]

Could you add also the caller method? I assume either me or you will be surprised ;-)

[re-thc]

Is this what you're looking for? This is with logback.

Pattern is: %d{HH:mm:ss.SSS} [%thread] %-5level %class{36}.%M %L - %msg%n

03:30:28.377 [io-executor-thread-1] INFO i.m.flyway.AbstractFlywayMigration.runFlyway 88 - Running migrations for database with qualifier [default]
03:30:28.380 [io-executor-thread-1] INFO o.f.c.i.logging.slf4j.Slf4jLog.info 49 - Flyway Community Edition 7.3.1 by Redgate
03:30:28.416 [io-executor-thread-1] INFO o.f.c.i.logging.slf4j.Slf4jLog.info 49 - Database: jdbc:postgresql://127.0.0.1:6432/test(PostgreSQL 13.1)
03:30:28.459 [io-executor-thread-1] INFO o.f.c.i.logging.slf4j.Slf4jLog.info 49 - Successfully validated 2 migrations (execution time 00:00.018s)
03:30:28.473 [io-executor-thread-1] INFO o.f.c.i.logging.slf4j.Slf4jLog.info 49 - Current version of schema "public": 1.1
03:30:28.475 [io-executor-thread-1] INFO o.f.c.i.logging.slf4j.Slf4jLog.info 49 - Schema "public" is up to date. No migration necessary.

[pmwmedia]

So, Logback has the same issue.

Flyway could fix the issue for all logging framework by using the LocationAwareLogger API for their Slf4jLog wrapper class.

I found a good and working Slf4jLoggerwrapper class template here:
dubbo-common/src/main/java/com/alibaba/dubbo/common/logger/slf4j/Slf4jLogger.java

[re-thc]

It's able to log it correctly with default logback settings though (as per earlier comment). Is it a configuration issue. What pattern on tinylog would match the original logback output that shows the right classes?

[pmwmedia]

In your default Logback configuration, you use the logger category, neither the caller class name nor caller method. For such logger wrappers, SLF4J has introduced the LocationAwareLogger API.

However, Flyway does not use the correct API for forwarding log entries. If they don't use the LocationAwareLogger API, there is no chance for any logging framework to output the correct caller class and method. The logger category would work nevertheless, but tinylog does not support logger categories by design.

[re-thc]

Sure, will contact Flyway and anyone else. Thanks

[pmwmedia]

Please let me know if I can support you for creating an issue or a pull request there.

[github-actions]

This closed issue has been locked automatically. However, please feel free to file a new issue.