Java Logging: show the source line number of the caller (not the logging helper method)

Question

The numerous (sigh...) logging frameworks for Java all do a nice job of showing the line number of the source file name for the method that created the log message:

log.info("hey");

 [INFO] [Foo:413] hey

But if have a helper method in between, the actual caller will be the helper method, and that is not too informative.

log_info("hey");

[INFO] [LoggingSupport:123] hey

Is there a way to tell the logging system to remove one frame from the callstack when figuring out the source location to print?

I suppose that this is implementation specific; what I need is Log4J via Commons Logging, but I am interested to hear about other options.

Answer 1

Alternative answer.

It is possible to ask log4j to exclude the helper class by using the method

Category.log(String callerFQCN, Priority level, Object message, Throwable t)

and specifying the helper class as 'callerFQCN'.

For example here is a class using a helper:

public class TheClass {
    public static void main(String...strings) {
        LoggingHelper.log("Message using full log method in logging helper.");
        LoggingHelper.logNotWorking("Message using class info method");
}}

and the code of the helper:

public class LoggingHelper {
private static Logger LOG = Logger.getLogger(LoggingHelper.class);

public static void log(String message) {
    LOG.log(LoggingHelper.class.getCanonicalName(), Level.INFO, message, null);
}

public static void logNotWorking(String message) {
    LOG.info(message);
} }

The first method will output your expected result.

Line(TheClass.main(TheClass.java:4)) Message using full log method in logging helper.
Line(LoggingHelper.logNotWorking(LoggingHelper.java:12)) Message using class info method

When using this method, Log4j will work as usual, avoiding calculating the stack trace if it is not required.

Answer 2

Please note that giving the line number is something very costly, either for what you get naturally from Log4j or the following. You have to accept that cost...

You could use the following APIs:

    StackTraceElement[] stackTraces = Thread.currentThread().getStackTrace();
    StackTraceElement stackTraceElement = ...;
    stackTraceElement.getLineNumber();

---

Updated:

You would have to calculate it yourself. So:

• ask log4j not to output it (in your logging format),
• and insert yourself the line number explicitement in the beginning of your message (the String you send to log4j).

Depending how you prefer your loggers, your helper method may:

• use an explicit Logger (passed as a parameter I guess), when appropriate (we sometimes define specific loggers for specific context ; for example, we have a logger for sending our database requests, no matter what class does it ; this allow us to reduce to one place the changes made to our configuration file, when we want to (de-)activate them ...)
• use a Logger for the calling class : in this case, instead of passing the parameter, you can deduce the caller class name likewise...

Answer 3

Comes out that there is a very simple solution, just add FQCN (The wrapper class' fully qualified class name) to your logger helper:

public class MyLogger extends Logger {

private static final String FQCN = MyLogger.class.getName() + ".";

protected MyLogger(String name) {
    super(name);
}

public void info(final Object msg) {
    super.log(FQCN, Level.INFO, msg, null);
}

//etc...

In Your working class you just do:

public class MyClass {

private static final Logger LOG = MyLogger.getLogger();   

private void test()
{
    LOG.info("test");
}

}

Answer 4

Adding details to KLE answer. (sorry, noob user, don't know better way than creating a separate answer )

Instead of sticking the line number to the message, you can put it in the MDC context. See org.apache.log4j.MDC

For example:

StackTraceElement[] stackTraces = Thread.currentThread().getStackTrace();
StackTraceElement stackTraceElement = ...;
int l = stackTraceElement.getLineNumber();

MDC.put("myLineNumber", l);

That allows users to use mylineNumber in their log4j configuration file

<layout class="org.apache.log4j.PatternLayout">
    <param name="ConversionPattern" 
           value="Line(%X{myLineNumber})- %m%n"/>
</layout>

Note: that allows the user to control where and how the line number appears in the message. However, since getting the stacktrace is very costly, you still need to find a way to switch off the feature.

Answer 5

For Log4j2 the answer is provided completely by the use of logger wrappers as described in the Log4j2 manual under Example Usage of a Generated Logger Wrapper. One can simply generate (using the org.apache.logging.log4j.core.tools.Generate$ExtendedLogger tools illustrated there) a logger wrapper with a single STUB level, and then adapt that to create custom logging methods mimicking the use of the logIfEnabled(FQCN, LEVEL, Marker, message, Throwable) - possibly ignoring the STUB level and using the regular ones - then if desired, deleting or commenting out the STUB level and its methods). For this purpose the FormattedMessage can be helpful.

The source line, while expensive, can then be easily shown as part of the full location information by using the %l location conversion pattern element in the PatternLayout given in the configuration, or more specifically using the %L line number and/or the %M method conversion.

Now with complete example at: Java Logging: Log4j Version2.x: show the method of an end-client caller (not an intermediate logging helper method)

Answer 6

This isn't possible out of the box. The best you can do in this case is to create the logger in the caller and pass it to the util method. This way, you can at least get an idea where the call has come from.

Answer 7

If you have your own logging utility methods, you could add linenumber and filename to the logging argument list and take the cpp route. i.e. Preprocess you source to replace tags like _ LINE _ and _ FILE _ before you do the compile. As an added bonus this would not take nerly as much resources as figuring out at runtime.

Answer 8

Maybe you can implement the log helper function using the stack trace element, get the line numbers, and bypass the frames with method with some specific annotations, like,

public @interface SkipFrame {}

// helper function
@SkipFrame // not necessary on the concrete log function
void log(String... message) {
    // getStackTrace()...
    int callerDepth = 2;  // a constant number depends on implementation
    StackTraceElement callerElement = null; 
    for (StackTraceElement e: stackTrace) {
         String className, methodName = e.getClassName, getMethodName()...
         Class callClass = Class.forName(className);
         // since there maybe several methods with the same name
         // here skip those overloaded methods
         Method callMethod = guessWhichMethodWithoutSignature(callClass, methodName);
         SkipFrame skipFrame = callMethod.getAnnotation(SkipFrame.class); 
         if (skipFrame != null)
             continue; // skip this stack trace element
         if (callerDepth-- == 0) {
             callerElement = e; 
             break;
         }
     }
     assert callerDepth == 0; 
     assert callerElement != null;
     Log4j.info(callerElement.getLineNumber()... + "message... "); 
}

@SkipFrame
void logSendMail(Mail mailObject) {
    log("Send mail " + mailObject.getSubject()); 
}

Thus, if the helper function is nested, or there are more utilized helper functions, just mark the SkipFrame annotation on all of them and you will get the correct source line number what you really wanted.