Fix Module Debug Logging #370
Conversation
Sonatype Lift is retiringSonatype Lift will be retiring on Sep 12, 2023, with its analysis stopping on Aug 12, 2023. We understand that this news may come as a disappointment, and Sonatype is committed to helping you transition off it seamlessly. If you’d like to retain your data, please export your issues from the web console. |
|
I think it's better if we keep using MessageFormat though since it usually reads a little bit better: Instead of this diff: - log.log(INFO, "Wired beans in {0}ms", (System.currentTimeMillis() - start));
+ log.log(INFO, String.format("Wired beans in %sms", System.currentTimeMillis() - start));we can have this: - log.log(INFO, "Wired beans in {0}ms", (System.currentTimeMillis() - start));
+ log.log(INFO, MessageFormat.format("Wired beans in {0}ms", System.currentTimeMillis() - start));Though, we could also commit to the swanky new adapter and make it use Actually, that "swanky new adapter" seems to be really similar to https://github.com/avaje/slf4j-jdk-platform-logging/, except there is a EDIT - after a little bit of research I now know
EDIT 2 - It is lines 144-145 in // The JDK uses a different formatting convention. We must invoke it now.
- message = String.format(message, params);
+ message = MessageFormat.format(message, params);I'll send this their way momentarily. EDIT 3 - qos-ch/slf4j#351 (comment) |
|
Yeah, this was logged as https://jira.qos.ch/browse/SLF4J-545 which is a duplicate of https://jira.qos.ch/browse/SLF4J-529 and has the related PR of qos-ch/slf4j#273 which is as yet not merged - yikes. |
|
So to be clear, there is a bug in SLF4J here and the logging message changes here are not ideal. There is an alternative "fix" provided by the fact that avaje libs do NOT use System.Logger directly but instead obtain the System.Logger via private static final System.Logger log = AppLog.getLogger("io.avaje.inject");See https://github.com/avaje/avaje-applog Now the original reason for using AppLog.getLogger() and not using System.getLogger() directly was due to AWS Lambda runtime not actually honouring the service loading of a System.Logger implementation. So I added this 1 extra level of indirection to allow controlling the System.Logger implementation for the AWS Lambda runtime but also it felt like a good idea to have this. This means we can alternatively use TLDR: The alternative (until the SL4J bug fix is merged) is to add |
Personally, I find it inconvenient that I have to add a whole dependency just for debugging purposes. Are you sure we can't just format it ourselves using MessageFormat? |
|
I guess it is best we don't merge this as they will eventually fix the issue. <!--
TODO - Revert to this dependency once the MessageFormat changes are accepted.
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-jdk-platform-logging</artifactId>
<version>${slf4j.version}</version>
<scope>runtime</scope>
</dependency>
-->
<dependency>
<groupId>com.github.Mechite.slf4j</groupId>
<artifactId>slf4j-jdk-platform-logging</artifactId>
<version>patch-1-SNAPSHOT</version>
<scope>runtime</scope>
</dependency>This dependency will work as expected: |
The PR was raised in 2021, so I'm doubting hard. |
I guess given this then, while it's controversial, I think it's a better idea to just format things ourselves anyway since at the end of the day even if the whole codebase ended up littered with MessageFormat.format calls, this is the most resilient way to do it (the logging will continue to work on every single version of the slf4j adapter). |
As I see it, its the "thin end of the wedge" in that ALL the avaje libraries and ALL the ebean libraries all use AppLog SystemLogger and they hence ALL expect the correct message format to "work". For me, it isn't just these few log messages in avaje-inject that will not work as expected.
Nice. If we want that in maven central via io.avaje we can do that.
Yeah. Probably need to ask why it hasn't been merged yet. |
Figuring out this issue actually shed light on why config wasn't logging correctly either (I had thought it was something on my end). Indeed, the message format doesn't work anywhere where slf4j bridges |
public class FormattedLogger implements System.Logger {
private final System.Logger delegate;
public FormattedLogger(System.Logger delegate) {
this.delegate = delegate;
}
(...) // other methods excluded for brevity, they would forward to delegate
@Override
public void log(Level level, ResourceBundle bundle, String format, Object... params) {
delegate.log(level, bundle, MessageFormat.format(String.format(format, params), params), params);
}
}What you can do is simply make a wrapping logger that formats things automagically. This implementation does
|
As I see it, it formats too early - before the check if it needs to log at all is performed. That might be ok for a lot of cases but not ideal for any "hot conditional debugging" type cases as I see it. |
But ... that could be accounted for I think by just adding an IF block - hmm, interesting thought ... |
|
I guess this is more of an SLF4J problem |
|
Refer to #373. |
It seems that even when I add that swanky new adapter from slf4j:
the debug log looks like this instead of showing the loaded modules:
22:20:44.627 [main] DEBUG io.avaje.inject - building with modules {0}Also adds logging for the detected modules from the generator.