0

Our app has 3rd party code that uses JUL to log. Our app has the jul-to-slf4j.jar on the classpath. I see the SLF4JBridgeHandler.install() method gets called (several times) as for whatever reason spring cleans up logging config a few times on based on certain ApplicationEvents. I created an event listener on ApplicationStartedEvent to again make sure the handler is installed as late as possible. I verify by checking the SLF4JBridgeHandler.isInstalled() method. Yet the 3rd party logs keep flowing to standard out. If i breakpoint the 3rd party logging class in IntelliJ and call SLF4JBridgeHandler.isInstalled() it returns false. If I then execute the below code the logs get picked up by slf4j and everyone is happy.

SLF4JBridgeHandler.install();
LogManager.getLogManager().getLogger("com.3rdparty").setUseParentHandlers(false);

Why does SLF4J keep getting uninstalled? How do I keep it installed? Are the 3rd party loggers getting created before we install slf4j and then not getting updated by the install() call?

zawarudo
  • 1,907
  • 2
  • 10
  • 20
futevolei
  • 180
  • 2
  • 14

1 Answers1

0

Why does SLF4J keep getting uninstalled?

Most common reason is there is code calling LogManager.reset(). You can find the source by using a security manager.

If you user a logging.properties file then just add the bridge as a handler. That way reset is actually installing the bridge handler.

handlers= java.util.logging.ConsoleHandler, org.slf4j.bridge.SLF4JBridgeHandler

The only downside is that the bridge handler has to be visible to the system classloader. A very hacky trick you can try is to subclass SLF4JBridgeHandler and override equals to return false. LogManager.reset won't be able to remove this handler.

Logger.getLogger("").addHandler(new SLF4JBridgeHandler() {
    public boolean equals(Object o) { return false;}
});

Are the 3rd party loggers getting created before we install slf4j and then not getting updated by the install() call?

You'll have to do some work to find out that answer. Use JConsole Mbeans or the system out debugging to walk the logger tree while debugging your application. The security manager tracing is your best bet for finding the exact stacktrace for who is responsible for removing the handler.

Can there be two root loggers somehow?

That can't happen under the standard LogManager. Tomcat has an implementation that is sensitive to the context classloader. That LogManager may return different instances of the same logger name based on context class loader. The only other way the handlers can be removed without going through the security manager is if the root logger was garbage collected. You could try to hold a strong reference to the root logger but that really shouldn't be needed. You should print the identity hash code of the root logger when the handler was known to be added and the identity hash code of the root logger after the handler was dropped. If the values are different the logger was garbage collected.

jmehrens
  • 10,580
  • 1
  • 38
  • 47
  • Yes, I am purposefully creating the "com.3rdparty" logger in order to handle all the child logs and prevent them from trickling up to the root logger. However, even when I create this as a private static final logger in a bean that lives the life of the app the useParentHandler property gets modified from false to true at some point in time. And also the bridge handler gets removed. – futevolei Jun 08 '22 at 18:20
  • @futevolei LogManager.reset is probably being invoked in the code. You can track down the caller [with a security manager](https://stackoverflow.com/questions/44882648/logging-not-showing/44888306#44888306). Most cases are initialization order is not what you expected. – jmehrens Jun 08 '22 at 21:09
  • i implemented the code and there are no further calls to checkPermission() after we call Slf4jBridgeHandler.install() and yet somehow the root logger doesnt have it attached when 3rd party code starts printing. Can there be two rootloggers somehow? – futevolei Jun 09 '22 at 18:54
  • @futevolei Are you installing the SecurityManager using the system property argument on the command line or from code? If you install it from code that is too late to capture everything. – jmehrens Jun 09 '22 at 22:13
  • I was doing it in code. What do you mean its too late that way? Isnt my main concern what is causing the handler to be removed after we call install()? Also, I have tried to add slf4j to the .handlers property in the logging.properties file but it throws class not found error on start up. – futevolei Jun 10 '22 at 15:02
  • @futevolei Did you verify that install() attached the handler to the root logger by enumerating the handlers? The only way handlers can be removed and not be seen by the security manager is: 1. There were never added (due to failure), 2, Remove happened before the security manager was installed, 3. The logger was garbage collected. 4. You are using a config file and the root logger never saw a log message. Handlers are lazy loaded for root logger from config. Need to start ruling these out to figure out what is truly happening. – jmehrens Jun 10 '22 at 16:57
  • After calling SLF4JBridgeHandler.install(), i call LogManager.getLogManager().getLogger("") and i notice the slf4j handler is installed but the async file handler is removed. That should be configured in the logging.properties file we have which is the seemingly standard tomcat file. – futevolei Jun 10 '22 at 19:05
  • Tomcat has its own LogManager implementation where the configuration and loggers are dependent on the context classloader. In this case you might be seeing different loggers for the same name when the caller classloader is different. – jmehrens Jun 10 '22 at 21:12
  • Sorry, im totally lost, can you explain to a dummy what the cause could be? – futevolei Jun 13 '22 at 16:42
  • I think you are going to have to attach some of the debugging output to your question so I can continue to troubleshoot. This would be output of the security manager tracing and output of DebugLogging::printLogging. There is just not enough details to explain what you are seeing. – jmehrens Jun 21 '22 at 14:21