Tomcat logging confusion

Question

I have a fresh installaion of tomcat.

To improove the logging I edit the conf/logging.properties.

Step 1

I change the Line

java.util.logging.ConsoleHandler.level = FINE

to

java.util.logging.ConsoleHandler.level = FINER

Step 2

And append the line

org.apache.catalina.level = FINER

Step 3

Then I start the server and if I fail to authenticate to http://localhost:8080/manager/ with username MyUsername and MyPassword I see this output:

FINE [http-bio-443-exec-2] org.apache.catalina.authenticator.AuthenticatorBase.invoke Security checking request GET /manager/html
FINE [http-bio-443-exec-2] org.apache.catalina.loader.WebappClassLoaderBase.loadClass loadClass(org.apache.catalina.manager.HTMLManagerServlet, false)
FINE [http-bio-443-exec-2] org.apache.catalina.loader.WebappClassLoaderBase.loadClass   Delegating to parent classloader1 java.net.URLClassLoader@1218025c
FINE [http-bio-443-exec-2] org.apache.catalina.loader.WebappClassLoaderBase.loadClass   Loading class from parent
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[Status interface]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[JMX Proxy interface]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[Text Manager interface (for scripts)]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[HTML Manager interface (for humans)]' against GET /html --> true
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[Status interface]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[JMX Proxy interface]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[Text Manager interface (for scripts)]' against GET /html --> false
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.findSecurityConstraints   Checking constraint 'SecurityConstraint[HTML Manager interface (for humans)]' against GET /html --> true
FINE [http-bio-443-exec-2] org.apache.catalina.authenticator.AuthenticatorBase.invoke  Calling hasUserDataPermission()
FINE [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.hasUserDataPermission   User data constraint has no restrictions
FINE [http-bio-443-exec-2] org.apache.catalina.authenticator.AuthenticatorBase.invoke  Calling authenticate()
FINER [http-bio-443-exec-2] org.apache.catalina.realm.RealmBase.authenticate Username MyUsername NOT successfully authenticated
FINE [http-bio-443-exec-2] org.apache.catalina.authenticator.AuthenticatorBase.invoke  Failed authenticate() test
FINE [http-bio-443-exec-2] org.apache.catalina.core.StandardHostValve.custom Processing ErrorPage[errorCode=401, location=/WEB-INF/jsp/401.jsp]
FINER [http-bio-443-exec-2] org.apache.catalina.core.StandardWrapper.allocate   Returning non-STM instance
FINE [http-bio-443-exec-2] org.apache.catalina.core.ApplicationDispatcher.doForward  Disabling the response for futher output
FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.session.ManagerBase.processExpires Start expire sessions StandardManager at 1525428004090 sessioncount 0
FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.session.ManagerBase.processExpires End expire sessions StandardManager processingTime 4 expired sessions: 0

Question

Now I modify Step 2 and add the package realm to the definition. Now the Step 2 adds this line instead:

org.apache.catalina.realm.level = FINER

Why do the FINER-Loggings disappear? I mean, org.apache.catalina.realm is more specific, right?

Answer 1

If I'm understanding correctly you end up with a logging properties that looks like:

java.util.logging.ConsoleHandler.level = FINER
org.apache.catalina.realm.level = FINER

The Java Logging Overview section 1.1 states:

Applications make logging calls on Logger objects. Loggers are organized in a hierarchical namespace and child Loggers may inherit some logging properties from their parents in the namespace.

When reading the logger names the parent loggers are to the left of the dots. Therefore, org.apache.catalina is the parent of org.apache.catalina.realm and org.apache.catalina.core.

The executing code code has to demand a logger in order for it to exist. Simply adding lines in the properties file doesn't create loggers. If it did they would just be garbage collected anyway. This means that say you have a logger tree A <- B <- C. You want to set the level for B and therefor all of B children so you add A.B.level line in the properties file. However, at run-time the loggers that are demanded are A and C

So what you have to work with is "" <- A <- A.B.C when you are expecting "" <- A <- A.B <- A.B.C

Putting that all together, I think at runtime your loggers look like:

"" <- org.apache.catalina <- org.apache.catalina.realm.RealmBase and no Tomcat code has created an actual logger named org.apache.catalina.realm.

You can verify by connecting JConsole to runnting JVM and checking the MBean tab and listing the logger names. On Tomcat this won't work because the loggers returned depend on the calling classloader.

To work around this you can use the config option to demand and hold the logger in memory. You just have to install this on the custom code on the system class path.

Otherwise you have to specify all the known child logger names in the properties file which can be verbose.

First idea: If we look at the CSS specifity we know that .mydiv{ color:red} is not as specific as div.mydiv{color: green} so a div.mydiv contains text in red? Inheriance means if not specified what is anti-inheritance.

Unlike CSS, JUL has a runtime logger tree and a properties file. That runtime logger tree is dynamically adjusted as executing code demands loggers. The properties are only ever used if code demands a logger. Specifying a logger name in the properties file doesn't mean a thing unless the logger is created by code. This can change the parents of a logger and therefore the level. Give it a spin:

package so;

import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.util.Properties;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;

public class TheMissingParent {

    private static final Logger[] LAZY_ONE;
    static {
        LAZY_ONE = new Logger[] { Logger.getLogger("org.apache.catalina"),
                Logger.getLogger("org.apache.catalina.realm.RealmBase") };
    }

    private static volatile Logger[] LAZY_TWO;

    public static void main(String[] args) {
        loadProperties();
        printAncestors(LAZY_ONE);
        findlLongLostParents();
        System.out.println("====");
        printAncestors(LAZY_ONE);
    }

    private static void loadProperties() {
        Properties props = new Properties();
        props.put("org.apache.catalina.realm.level", "FINER");

        try(ByteArrayOutputStream out = new ByteArrayOutputStream()) {
            props.store(out, "");
            LogManager.getLogManager().readConfiguration(new ByteArrayInputStream(out.toByteArray()));
        } catch (IOException ioe) {
            throw new AssertionError(ioe);
        }
    }

    private static void findlLongLostParents() {
        LAZY_TWO = new Logger[] {Logger.getLogger("org.apache.catalina.realm") };
    }

    private static void printAncestors(Logger[] loggers) {
        // System.out.println(loggers.toString());
        for (Logger l : loggers) {
            printAncestors(l);
            System.out.println();
        }
    }

    private static void printAncestors(Logger l) {
        if (l != null) {
            printAncestors(l.getParent());
            System.out.print("<-");
            String name = l.getName();
            if (name != null && name.isEmpty()) {
                System.out.append("\"\"");
            } else {
                System.out.append(name);
            }

            for(Logger p = l; p != null; p = p.getParent()) {
                Level lvl = p.getLevel();
                if (lvl != null) {
                    System.out.append('{').append(lvl.getName()).append('}');
                    break;
                }
            }
        }
    }
}

This will output:

<-""{INFO}<-org.apache.catalina{INFO}
<-""{INFO}<-org.apache.catalina{INFO}<-org.apache.catalina.realm.RealmBase{INFO}
====
<-""{INFO}<-org.apache.catalina{INFO}
<-""{INFO}<-org.apache.catalina{INFO}<-org.apache.catalina.realm{FINER}<-org.apache.catalina.realm.RealmBase{FINER}

This is the core issue. If Tomcat (or some custom code) never demands a org.apache.catalina.realm logger that line in the properties file is just dead code.

Second, if you say so, noone specified to org.apache.catalina nor org.apache nor org nor `` to be level INFO, so where would the value INFO came from?

That behavior is described in the LoggerManager class level docs:

If neither of these properties is defined then, as described above, the LogManager will read its initial configuration from a properties file "lib/logging.properties" in the JRE directory.

The root logger named as empty string "" is the parent of all loggers. The root logger is always created.