2

I made a wrapper for log4j2 logger based on this topic: How do I add a prefix to log4j messages (at the object level)

here is that i have:

import org.apache.log4j.Logger;

public class LogWrapper
{
    private Logger log;
    private String prefix;

    public LogWrapper(Logger log, String prefix) {
        this.log = log;
        this.prefix = prefix;
    }

    public void info(String msg)
    {
        log.error(prefix + "| " + msg);
    }
    public void error(String msg)
    {
        log.error(prefix + "| " + msg);
    }
}

usage:

public class MyClass {
    private final LogWrapper logger;
    public MyClass(String username) {
        logger = new LogWrapper(Logger.getLogger(MyClass.class.getName()), username);
    }
}

Problem:

As the output i have a links to LogWrapper class

2016-07-12 21:15:17,543 ERROR [pool-3-thread-1] global.LogWrapper (LogWrapper.java:17) - blab bla bla

'LogWrapper.java:17' it doesn't point on the line in MyClass where the logger was called.

How to solve it?

Remko Popma
  • 35,130
  • 11
  • 92
  • 114
user1935987
  • 3,136
  • 9
  • 56
  • 108

2 Answers2

2

The built-in mechanism provided by Log4j to put prefixes in your log output is the ThreadContext map. How to do this:

Code:

// usually at some entry point from where these values won't change 
ThreadContext.put("user.ip", ipAdr);
ThreadContext.put("user.account", userAccount);

Configuration:

<PatternLayout pattern="%d %p %c{1.} [%t] %X{user.ip} %X{user.account} %m%n"/>

Now any logging after values have been put into the ThreadContext will show with the desired prefixes.

A custom logger wrapper can be used to achieve something similar but is quite a lot more work.

Log4j remembers the fully qualified class name (FQCN) of the logger and uses this to walk the stack trace for every log event when configured to print location. (Be aware that logging with location is slow and may impact the performance of your application.)

The problem with the custom logger wrapper is that it has a different FQCN than the actual logger, so Log4j can't find the place where your custom logger was called.

The solution is to provide the correct FQCN. The easiest way to do this is to let Log4j generate the logger wrapper for you. Log4j comes with a Logger wrapper generator tool. This tool was originally meant to support custom log levels and is documented here: https://logging.apache.org/log4j/2.x/manual/customloglevels.html#CustomLoggers

The generated logger code will take care of the FQCN and you can use it as a base for the further enhancements you have in mind.

Remko Popma
  • 35,130
  • 11
  • 92
  • 114
  • I'm trying to do it with ThreadContext, but the `user.account` never appears in log string. What can be a reason? BTW, compiler do not accept ` %X{"user.account"}`. only without quotes is ok " %X{user.account}" – user1935987 Jul 13 '16 at 04:49
  • Thanks, I've removed the quotes from my answer. About output not appearing, can you try with just %X? That should show _all_ key-value pairs that were put in the ThreadContext. Also, are you logging from the same thread that put the `user.account` key-value pair in the ThreadContext? – Remko Popma Jul 13 '16 at 04:57
  • Tried with just `%X`. Same. Yes, i'm logging in the same class where i set `ThreadContext`. So must be the same thread. – user1935987 Jul 13 '16 at 05:03
  • Same class does not necessarily mean same thread... Can you experiment by calling `ThreadContext.put("key", "value");` immediately before calling `logger.info("test message");`? (Use some fixed string value that is not empty or null.) – Remko Popma Jul 13 '16 at 05:11
  • yes can. for now - i'm logging `[pool-2-thread-1]` thread, so it shows the same thread everywhere. – user1935987 Jul 13 '16 at 05:13
  • `ThreadContext.put("user", username); logger.info("log after thread context");` tried this - same, nothing is logging from context – user1935987 Jul 13 '16 at 06:05
  • guess also have to mention that all the threads in app executed by `ThreadPoolExecutor` – user1935987 Jul 13 '16 at 06:08
  • Very strange... Please try `ThreadContext.put("user", "FIXEDVALUE"); logger.info("original value is{}", ThreadContext.get("user"));` This should help us figure out where the value is disappearing. – Remko Popma Jul 13 '16 at 06:12
  • `logger.info("original value is: "+ ThreadContext.get("user"));` is logging "FIXEDVALUE" but it in not added in appender `2016-07-13 13:56:54,091 INFO [pool-2-thread-1] MyClass (MyClass.java:36) - original value is: FIXEDVALUE` this is the pattern: `d{yyy-MM-dd HH:mm:ss} [%t] %X{user} %-5level %logger{36} - %msg%n` – user1935987 Jul 13 '16 at 07:01
  • Aha! That cannot be the correct Layout pattern: the output shows INFO level before the thread name and shows location info (class + line number), but the pattern has the thread name first and `%logger{36}` which doesn't print location info. Are you updating the wrong config file? – Remko Popma Jul 13 '16 at 07:06
  • so what is the right order? if i out that after all, but before message - same outpur - no value from context. `%d{yyy-MM-dd HH:mm:ss} [%t] %-5level %logger{36} %X{user} - %msg%n` – user1935987 Jul 13 '16 at 07:33
  • No that's not what I meant. Any order is fine, but the Layout pattern you showed cannot produce the output you showed, so I think you may be modifying the wrong log4j2.xml configuration file... Are you sure Log4j is using a configuration file containing %X in the Layout? – Remko Popma Jul 13 '16 at 07:38
  • Mystery solved?! (Man, I deserve so many upvotes for this... :-D ) – Remko Popma Jul 13 '16 at 07:56
  • 1
    yes it does. i was editing a file appender, but not the STDOUT :D – user1935987 Jul 13 '16 at 08:00
2

Actually, the problem is that the Location information isn't what you want it to be. That happens when you create a wrapper as you have done. To fix it, Log4j needs the fully qualified class name (FQCN) of the Logger class. It isn't that hard to manually create a class that does that, but the easy way is to follow the instructions in the Log4j manual at http://logging.apache.org/log4j/2.x/manual/customloglevels.html#CustomLoggers

rgoers
  • 8,696
  • 1
  • 22
  • 24