What is the ideal way to create a singleton wrapper on top of log4j2

[mehulparmariitr]

What is the ideal way to create a singleton wrapper on top of log4j2? I created this singleton wrapper but realised it will not get the correct class name because of multiple threads using it. Should the wrapper be even Singleton?

public class Log4JLogger {
    private static volatile Log4JLogger instance;
    private static Logger logger;
    private static volatile Map<String, Logger> loggerMap;
    private Log4JLogger(Class<?> clazz){
            loggerMap = new ConcurrentHashMap<>();
            loggerMap.put(clazz.getName(),LogManager.getLogger(clazz));
    }

    public static Log4JLogger getLog4JLogger(Class<?> clazz) {

        if (instance == null) {
            synchronized (Log4JLogger.class)
            {
                if (instance == null) {
                    instance = new Log4JLogger(clazz);
                }
                else if (!loggerMap.containsKey(clazz.getName())) {
                    loggerMap.put(clazz.getName(), LogManager.getLogger(clazz));
                }
                instance.logger = loggerMap.get(clazz.getName());
            }
        }
        return instance;
    }

    public void entering() {
        if (logger.isEnabled(org.apache.logging.log4j.Level.TRACE)) {
            logger.traceEntry();
        }
    }

[ppkarwasz]

@mehulparmariitr,

We discourage the use of wrappers since:

• they (slightly) decrease performance,
• they require users to acquire expertise that is not necessary. E.g. you need to learn about location detection and reducing garbage collections,
• they prevent the usage of an increasing amount of rewrite rules (cf. OpenRewrite Logging).

Loggers use multiple methods to retrieve the location of the caller. The problem with you code is that the detected caller of Logger.traceEntry() is always Log4jLogger. To change this you need to use the SPI ExtendedLogger that allows you to specify which classes to ignore, when looking for the caller.

Your class should look like this:

public class Log4JLogger {

    private static final Adapter ADAPTER = new Adapter();
    private static final String FQCN = Log4JLogger.class.getName();

    public static Log4JLogger getLog4JLogger(Class<?> clazz) {
        return ADAPTER.getLogger(clazz.getCanonicalName());
    }

    private final ExtendedLogger logger;

    private Log4jLogger(final ExtendedLogger logger) {
        this.logger = logger;
    }

    public void entering() {
        logger.logIfEnabled(FQCN, Level.TRACE, null, "ENTER");
    }

    private static class Adapter extends AbstractLoggerAdapter<Log4jLogger> {
        protected Log4jLogger newLogger(final String name, final LoggerContext context) {
            return new Log4jLogger(context.getLogger(name));
        }
    }
}

[ppkarwasz]

The fqcn parameter is the fully qualified class name of the logger class.

Log4j Core uses it to walk the call stack and:

• ignore all the stack frames with a className != fqcn (these correspond to internals of Log4j Core),
• ignore all the stack frames with a className == fqcn,
• return the following stack frame. This stack frame will have a className != fqcn.

The methods in your Log4jLogger can call each other. By passing "Log4jLogger" as fqcn you are sure that the location that the location will be set to the caller of the first Log4jLogger method.

[mehulparmariitr]

Q1) Any documentation that I can read to more clearly understand that how loggernames are decided and what is fqcn. Meanwhile the params are not getting published, any specific reason?

public void entering(Object param) {
        ((ExtendedLogger) logger).logIfEnabled(Log4JLogger.class.getName(), Level.TRACE, null, "ENTER",param);
    }


    /**
     * Function entry log convenience method (varargs-style).
     *
     * @param params
     *            varargs
     */
    public void entering(Object[] params) {
        ((ExtendedLogger) logger).logIfEnabled(Log4JLogger.class.getName(), Level.TRACE, null, "ENTER",params);
    }

Q2) Also %C is printing public class Log4JLogger. Shouldn't it print the name of caller service class? Is it because my wrapper class comes first after the actual logger class and service class comes third?

[ppkarwasz]

@mehulparmariitr,

For your usage case there is mostly just the Javadoc (cf. ExtendedLogger and the source code.

We will be improving our documentation in the following months, but it will be mostly for end users (a better documentation on how to use Logger or how to configure Log4j Core). Your use case falls more under the category of service provider/integrator, which concerns a small group of people.

Q1

A "logger name" (printed by %c) is any string you provide to LogManager.getLogger(String). Since retrieving a caller of a log message has been relatively slow (see the statistics on Log4j Transform), traditionally people use the fully qualified class name of some class.

Q2

Does it really print the exact string public class Log4JLogger? You can check StackLocator to see how the fqcn parameter is used in practice.

[mehulparmariitr]

Okay got it, Thanks. And why the params are not getting printed anywhere?

[ppkarwasz]

Your message format "ENTER" does not have any {} placeholders. For the non-vararg methods just hardcode the string (e.g. "ENTER params({})"). For the vararg method you can create the format string on the fly:

    public void entering(Object... params) {
        ((ExtendedLogger) logger)
                .logIfEnabled(
                        Log4JLogger.class.getName(),
                        Level.TRACE,
                        null,
                        () -> {
                            final StringBuilder sb = new StringBuilder("params(");
                            for (int i = 0; i < params.length; i++) {
                                if (i > 0) {
                                    sb.append(", ");
                                }
                                sb.append("{}");
                            }
                            sb.append(")");
                            return logger.getMessageFactory().newMessage(sb.toString(), params);
                        },
                        null);
    }

[mehulparmariitr]

(in my example %c and %C were inverted)

The main point of this discussion is that you need to replace:

    public void entering() {
        if (logger.isEnabled(org.apache.logging.log4j.Level.TRACE)) {
            logger.traceEntry();
        }
    }

with

    public void entering() {
        ((ExtendedLogger) logger).logIfEnabled(Log4JLogger.class.getName(), Level.TRACE, null, "ENTER");
    }

otherwise the location information will always be wrong.

Why we need to pass Log4JLogger.class.getName() if we dont even want to print it. What I want to print is the name of the service class who is creating the LogWrapper.

public class Service {
    private static final Log4JLogger LOGGER = Log4JLoggerFactory.getLog4JLogger(Service.class);

Also is there an alternative method to pass params in logIfEnabled, just like logger.traceEntry(null,param);

[mehulparmariitr]

12:13:35.431 [http-nio-8080-exec-1] TRACE com.abc.qi.rest.service.impl.ServiceImpl ENTER - ENTER
12:13:35.432 [http-nio-8080-exec-1] TRACE com.abc.qi.rest.service.impl.ServiceImpl EXIT - EXIT

okay it shows class name correctly now, but method name is still missing.

[ppkarwasz]

Also is there an alternative method to pass params in logIfEnabled, just like logger.traceEntry(null,param);

For the traceEntry/traceExit there are no equivalents with fqcn. IMHO these methods should be removed and replaced with a weaver that adds an equivalent trace method call. For example, to wrap traceEntry you need to use LogBuilder:

    public EntryMessage traceEntry(Object... params) {
        final LogBuilder builder = logger.atTrace();
        if (builder instanceof BridgeAware) {
            ((BridgeAware) builder).setEntryPoint(Log4jLogger.class.getName());
        }
        return (EntryMessage) builder.withMarker(AbstractLogger.ENTRY_MARKER)
                .logAndGet(() -> logger.getFlowMessageFactory().newEntryMessage(null, params));
    }

or you need to use the logMessage method:

    public EntryMessage traceEntry(ExtendedLogger logger, Object... params) {
        EntryMessage message = null;
        if (logger.isTraceEnabled(AbstractLogger.ENTRY_MARKER)) {
            logger.logMessage(
                    Log4jLogger.class.getName(),
                    Level.TRACE,
                    AbstractLogger.ENTRY_MARKER,
                    message = logger.getFlowMessageFactory().newEntryMessage(null, params),
                    null);
        }
        return message;
    }

[mehulparmariitr]

Okay write now I am okay with ((ExtendedLogger) logger).logIfEnabled(Log4JLogger.class.getName(), Level.TRACE, null, "ENTER"); But why the method name is not appearing?

[ppkarwasz]

12:13:35.431 [http-nio-8080-exec-1] TRACE com.abc.qi.rest.service.impl.ServiceImpl ENTER - ENTER
12:13:35.432 [http-nio-8080-exec-1] TRACE com.abc.qi.rest.service.impl.ServiceImpl EXIT - EXIT

okay it shows class name correctly now, but method name is still missing.

The "ENTER - ENTER" and "EXIT - EXIT" strings suggest that the pattern is %marker - %message.

[rgoers]

Like Piotr I have to ask what is your requirement? Why do you need to implement your own Logger wrapper. Doing so is an anti-pattern. Using the Log4j API already allows you to use any other logging implementation. We have seen this many times and invariably the wrappers are implemented incorrectly.

Note that Piotr mentioned using LogBuilder. It includes a withLocation() method so you can get the StackTraceElement of the caller and pass that in directly.

[mehulparmariitr]

@rgoers Can you explain why we need to pass Log4JLogger.class.getName() as FQCN if we want to print the caller class?

((ExtendedLogger) logger).logIfEnabled(Log4JLogger.class.getName(), Level.TRACE, null, "ENTER",params);

[rgoers]

Yes, I can explain it. But I really would like an answer to my question. Why do you need to implement your own Logger wrapper?

Out of the box Java does not provide caller information to called methods while compiling or linking the code. To obtain that information Log4j has to obtain a stack trace and locate the caller. This is expensive, so Loig4j defers it until it actually knows it is going to need the information. We have various ways of optimizing when we do it but we cannot rely on being a specfic depth in the stack, especially when wrappers are being used. Instead, the FQCN of the logging class is provided so when we reach that we know the stack trace element we are looking for is the one preceding it.

Note that we do have a way around this. The log4j-transformer maven plugin will convert all your logging calls to use LogBuilder with a provided stack trace element that the plugin calculates and saves. So in this case there is zero overhead at runtime to derive the caller information.

[ppkarwasz]

I should add that log4j-transformer-maven-plugin does not work with wrappers: the methods with an fqcn parameter are simply left as is.

In the future the plugin will cover well established "wrappers" (i.e. other logging APIs like Commons Logging or SLF4J), but custom wrappers will not be covered.