How to get a Logger for a subclass?

Question

I have a subclass and a superclass. In the superclass I have a method that logs something. When I create an instance of the subclass the logger creates a logging message for the super class. Why is this Happening?

Code example:

SuperClass.java

import java.util.logging.Level;
import java.util.logging.Logger;

public abstract class SuperClass {
    public void logAndPrintClass(){
        String name = this.getClass().getName();
        System.out.println(name);
        Logger logger = Logger.getLogger(name);
        logger.log(Level.INFO, "Logmessage");
    }
}

SubClass.java

public class SubClass extends SuperClass {
}

TestLogBubClass.java

public class TestLogBubClass {

    public static void main(String[] args){
        SuperClass obj = new SubClass();
        obj.logAndPrintClass();
    }
}

Output:

SubClass
Mar 15, 2013 6:30:04 PM SuperClass logAndPrintClass
INFO: Logmessage

As you can see the name of the class is correctly printed, but incorrectly represented in the log message.

Night

Answer 1

This reason is in the JavaDoc for LogRecord:

Note that if the client application has not specified an explicit source method name and source class name, then the LogRecord class will infer them automatically when they are first accessed (due to a call on getSourceMethodName or getSourceClassName) by analyzing the call stack.

The call stack in this case ends at a method defined by SuperClass, so the LogRecord assumes that it's the class being invoked. If you want to see this in action, execute this code:

public class Example {

    public static class Superclass {
        public void foo() {
            new Exception().printStackTrace();
        }
    }

    public static class Subclass extends Superclass {
        // nothing here
    }

    public static void main(String[] argv)
    throws Exception
    {
        Superclass s = new Subclass();
        s.foo();
    }
}

Edit: I don't use j.u.l, but was hoping that there would be an easy way to configure the output (like every other logger implementation provides). It appears that you'll have to implement your own Formatter class, and specify it using the java.util.logging.ConsoleHandler.formatter property.

I'd recommend if possible switching to SLF4J. You can bridge all existing j.u.l code through SLF4J to an actual logger that gives you more control over its output (like Log4J or Logback).

Brod

Answer 2

This java.util.logging code is pretty strange.. The Logging doesn't use the name, but tries to find out the source-class itself (which then is logged). Have a look into the method private void inferCaller() in the class java.util.logging.LogRecord.

Ginzburg

Answer 3

@Parsifal explained why this happens, I'll try to explain a workaround.

If you would like to see the exact class, where method is being called, I would recommend using log4j or slf4j. If you do need to use java.util.Logger, then please take a look at jul-to-slf4j.

I've tried and for me with the same classes input looks like the following in my standard output:

SubClass

Mar 15, 2013 8:39:44 PM SuperClass logAndPrintClass

INFO: Logmessage

20:39:44,478 INFO SubClass:12 - Logmessage

And in the log-file there is only:

20:39:44,478 INFO SubClass:12 - Logmessage

It might look not that good, but in some cases this might be as suitable workaround.

Deandra

Answer 4

I think I have a workaround, even if I can't provide a full explanation.

Overriding the logAndPrintClass with just a super call, like this, in SubClass:

class SubClass extends SuperClass {
    protected void logAndPrintClass(){ super.logAndPrintClass(); }
}

I still got the same output.

SubClass
Mar 15, 2013 11:22:10 AM SuperClass logAndPrintClass
INFO: Logmessage

Then I simply copied the method body into the subclass:

class SubClass extends SuperClass {
    protected void logAndPrintClass(){
        String name = this.getClass().getName();
        System.out.println(name);
        Logger logger = Logger.getLogger(name);
        logger.log(Level.INFO, "Logmessage");
    }
}

Then I got different output:

SubClass
Mar 15, 2013 11:23:31 AM SubClass logAndPrintClass

I don't know why this works, but the only difference I seem to find is that the Logger object is now being instantiated inside the subclass instead of inside the superclass.

Aerification

It's actually that the LogRecord object, which is hidden behind the call to logger.log() is being created in the subclass. – Brod

I don't want to override the method in every subclass for the sake of logging. In production code the does more than just print and log a message. The code in the question is just the simplest example that has the same behavior. – Night