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.

Build

Related: Calling log4j's log methods indirectly (from a helper method) – Ravenna

Related Wrapping the slf4j API for those who look for a solution using the slf4j facade – Riggins

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.

Shevlo

I also seek this solution, but as far as I can tell the method you describe is for the log4j1.2 API, which offers Category.log(String callerFQCN, Priority level, Object message, Throwable t). There does not seem to be an equivalent for Logger in the log4J 2.5 API. Can anybody offer an answer compatible with direct use of Log4J 2.x ? – Ravenna

Java Logging: Log4j Version2.x: show the method of the caller (not an intermediate logging helper method) – Ravenna

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...

Bennett

I suppose that Log4J is doing something like this. What I want to do is tell it to skip another frame in its calculation. It would be okay for me to do all the calculation myself, but I would still need to somehow pass this info into the logging system, otherwise the log formatting options will not recognize my fancy line numbers. – Build

Yes, 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). (I add this to the answer) – Bennett

The cost is much less in modern JVM's. – Pukka

Are you really suggesting you should manually insert the line number on each logged message? That's not very maintainable. Actually, I would quit my job if I saw this on the project I'm assigned to. – Trudi

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");
}

}

Many

How does this get you the line number? – Checkered

@SamuelEdwinWard The logging framework will figure out the line number. The FQCN string will just tell the logger how many stack frames to ignore. – Busload

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.

Shevlo

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)

Ravenna

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.

Busload

Yes, that would give me the correct logger category name (but still the wrong line number). It's an improvement... – Build

I am thinking that maybe I should have the helper method just create the log message (string), and then call the logger directly: log.info(getLogMessage("hey")) – Build

This is now possible using the logger wrapper facility of log4j2, and the logIfEnabled method, which can interrogate the stack trace for a nominated FQCN fully qualified class name, see my answer and links above – Ravenna

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.

Perspicacity

Does Java have such a preprocessor facility? – Build

Write a classloader or just preprocess a jar file that scans classes for logging statements and replace placeholders accordingly. – Xerography

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.

Pammy

Answer 9

If someone is still stumbling upon this, see my solution with SLF4J in How to log the caller of a method instead of the method which is calling the Logger

You can use the slf4j-caller-info-maven-plugin to log the caller of your LoggingSupport.

Longways