Logger should use SLF4J

[vic-ma]

@andrewazores

So the way I understand it...normally a project would use some logging library directly, and if they switched to slf4j, then they would use that interface directly, with slf4j then calling some underlying logger. But we are using our own logger right now, so if we wanted to switch to slf4j, then we could just change the method implementations of our logger to be calls to slf4j, and so that way our logger becomes a wrapper, and the interface of our logger is still the same, so no changes are needed in container-jfr?

Which underlying logger out of LOGBACK-CLASSIC, LOG4J, and JAVA.UTIL.LOGGING should I choose for the dependency?

[andrewazores]

Yea, that's what I had in mind here - keep our core Logger, but just have that as a simple wrapper around the SLF4J logger. Maybe in the future we refactor to eliminate our Logger since SLF4J is already a good abstraction.

I think java.util.Logging (JUL) is fine for us, for now. In the future we should also make it so that this is easy for the user to configure so that if they have their own logging requirements and want to integrate ContainerJFR into that, they just have to build an image on top of ours, then add a JAR to the classpath and set an env var or something.

[vic-ma]

Since SLF4J does its own automatic checks for if a log should be printed or not based on if its level is high enough, should I just remove everything related to levels from our logger implementation? Since setting the SLF4J logger's level is more of a runtime thing done by the user that depends on the underlying library, right?

[andrewazores]

Yea I think it would be very redundant to both keep our own levels implementation and stack that on top of the underlying SLF4J levels.

[vic-ma]

In ContainerJfrCore.initialize(), what is the line LogManager.getLogManager().reset() for? If I comment this line out, I am able to get SLF4J working, but if it's there, none of the logging commands print anything. I guess because the method "sets the level to null" for the underlying JUL logger? Is there a way I can work around this?

[andrewazores]

I don't remember the precise reason it was required (added in commit c7552fe93f623c52212bfe0db4084311fe6b45c8 - over a year ago), but it must have had something to do with log setup being performed by some JMC class we rely upon within -core, probably indirectly. There are a bunch of JMC utility classes that do weird and ugly stuff with grabbing logger instances from static members of UI classes, so that reset probably came out of my work trying to untangle that mess and just setting the logger to null to work around it.

If removing the line doesn't break anything and allows your SLF4J stuff to work then it's probably fine. Just run through a regular check with ContainerJFR's smoketest.sh and your modified -core in use and be sure nothing is broken.

[vic-ma]

Hmm yeah it looks like getting rid of that line causes a bunch of weird error logs when starting a recording. It looks like functionally everything still works, but the logs get really messed up. And I tested this on upstream cjfr and cjfr-core, with just the line removed, to make sure it wasn't just a problem with my SLF4J changes.

[INFO] Max concurrent WebSocket connections: 2
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
Oct 07, 2020 5:18:31 PM org.openjdk.jmc.rjmx.services.jfr.internal.EventTypeMetadataV2 optionInfoFrom
WARNING: Inferred content type 'jdk.jfr.Period' for option Period
Oct 07, 2020 5:18:31 PM org.openjdk.jmc.flightrecorder.configuration.internal.CommonConstraints forContentTypeV2
WARNING: Unparsable infinity, expected 1234.0 s
org.openjdk.jmc.common.unit.QuantityConversionException$Quantity: Unparsable infinity, expected 1234.0 s
...

Oct 07, 2020 5:18:31 PM org.openjdk.jmc.rjmx.services.jfr.internal.EventTypeMetadataV2 optionInfoFrom
WARNING: Inferred content type 'jdk.jfr.Period' for option Period
Oct 07, 2020 5:18:31 PM org.openjdk.jmc.rjmx.services.jfr.internal.EventTypeMetadataV2 optionInfoFrom
WARNING: Inferred content type 'jdk.jfr.Period' for option Period
Oct 07, 2020 5:18:31 PM org.openjdk.jmc.rjmx.services.jfr.internal.EventTypeMetadataV2 optionInfoFrom
WARNING: Inferred content type 'jdk.jfr.Period' for option Period
Oct 07, 2020 5:18:31 PM org.openjdk.jmc.rjmx.services.jfr.internal.EventTypeMetadataV2 optionInfoFrom
WARNING: Inferred content type 'jdk.jfr.Period' for option Period
...

(repeats a couple of times)

So should I just use one of the other underlying loggers for SLF4J then?

[andrewazores]

Might it be possible to continue using JUL but disable the loggers for org.openjdk.jmc.*, or (re)set them to a very low level?

https://stackoverflow.com/questions/4972954/how-to-disable-loggers-of-a-class-or-of-whole-package https://stackoverflow.com/questions/24322573/log4j-can-i-enable-disable-logging-from-a-class-at-runtime https://stackoverflow.com/questions/23996762/disable-log-output-from-libraries

I wouldn't want to do this if we had to manually maintain a list of specific packages to allow/deny logging, but if any of this works in a hierarchical fashion or allows wildcarding, then I think this would be a fair solution.

[vic-ma]

Since the methods of our logger are now just simple calls to the SLF4J logger, and that logger is private, is there a way I can still write unit tests / are any needed? Logger.java for reference.

We have a dependency in container-jfr right now for slf4j-simple, which is causing SLF4J to complain about multiple bindings. I couldn't figure how exactly it gets used, other than that I see the setting of SLF4J properties in IntegrationTestUtils. So is it just a dependency because some tool we use for running integration tests uses SLF4J for logging, so we're setting the binding for that? And in that case we could probably just change it to use JUL as well to avoid the conflict?

[andrewazores]

Since the methods of our logger are now just simple calls to the SLF4J logger, and that logger is private, is there a way I can still write unit tests / are any needed? Logger.java for reference.

I don't think tests are really needed (or even helpful) for such a simple wrapper.

We have a dependency in container-jfr right now for slf4j-simple, which is causing SLF4J to complain about multiple bindings. I couldn't figure how exactly it gets used, other than that I see the setting of SLF4J properties in IntegrationTestUtils. So is it just a dependency because some tool we use for running integration tests uses SLF4J for logging, so we're setting the binding for that? And in that case we could probably just change it to use JUL as well to avoid the conflict?

Some other dependency of ours - vertx probably - uses slf4j and so I had added the -simple binding for it. I would expect that the binding can be swapped out with no issue, but I haven't tried that out.