Logback debugging property is ignored unless a logback file is present

[philwebb]

See #16851 for background. If you start an app that has no logback.xml file then the-Dlogback.debug=true system property is totally ignored.

This is probably because we programmatically configure logback.

[wilkinsona]

I have a fix for this that adds an OnConsoleStatusListener when logback.debug is true, mimicking what Joran does for XML-based configuration.

A lot of the output that's usually produced by logback.debug=true is generated by Joran as it parses the XML. With our programmatic configuration that is all lost as the statuses are not added. With an app that's only logging to the console, we get the following output:

12:42:10,647 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.apache.catalina.startup.DigesterFactory] onto the JUL framework
12:42:10,648 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.apache.catalina.util.LifecycleBase] onto the JUL framework
12:42:10,649 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.coyote.http11.Http11NioProtocol] onto the JUL framework
12:42:10,649 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.sshd.common.util.SecurityUtils] onto the JUL framework
12:42:10,649 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.tomcat.util.net.NioSelectorPool] onto the JUL framework
12:42:10,649 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.eclipse.jetty.util.component.AbstractLifeCycle] onto the JUL framework
12:42:10,649 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.hibernate.validator.internal.util.Version] onto the JUL framework
12:42:10,665 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating INFO level on Logger[ROOT] onto the JUL framework

With a log file configured, we get the following:

12:42:41,406 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.apache.catalina.startup.DigesterFactory] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.apache.catalina.util.LifecycleBase] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.coyote.http11.Http11NioProtocol] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.sshd.common.util.SecurityUtils] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.apache.tomcat.util.net.NioSelectorPool] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating ERROR level on Logger[org.eclipse.jetty.util.component.AbstractLifeCycle] onto the JUL framework
12:42:41,407 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating WARN level on Logger[org.hibernate.validator.internal.util.Version] onto the JUL framework
12:42:41,426 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1860250540 - Archive files will be limited to [10 MB] each.
12:42:41,427 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1860250540 - Will use gz compression
12:42:41,428 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1860250540 - Will use the pattern /var/folders/jj/5zwjflp915gg3gyqdkgqwnf40000gn/T/junit4946647983568456273/junit820045986623551609/logback-test.log.%d{yyyy-MM-dd}.%i for the active file
12:42:41,429 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@8e0379d - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/folders/jj/5zwjflp915gg3gyqdkgqwnf40000gn/T/junit4946647983568456273/junit820045986623551609/logback-test.log.%d{yyyy-MM-dd}.%i.gz'.
12:42:41,430 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@8e0379d - Roll-over at midnight.
12:42:41,431 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@8e0379d - Setting initial period to Wed May 29 12:42:41 BST 2019
12:42:41,433 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /var/folders/jj/5zwjflp915gg3gyqdkgqwnf40000gn/T/junit4946647983568456273/junit820045986623551609/logback-test.log
12:42:41,433 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/var/folders/jj/5zwjflp915gg3gyqdkgqwnf40000gn/T/junit4946647983568456273/junit820045986623551609/logback-test.log]
12:42:41,434 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@58a90037 - Propagating INFO level on Logger[ROOT] onto the JUL framework

@philwebb is this sufficient for what you had in mind for this issue? We could update LogbackConfigurator to add statuses in the same way that the various actions triggered by Joran do, but perhaps that's what you had envisaged as being done in #16851?

[philwebb]

@wilkinsona I think it would be good if we could get the action information as part of this one. For #16851 I was thinking about some higher level output that was less verbose in general.