This article aims to solve the problem of not printing the correct line number when using log4j2 using a wrapper
When slf4j + log4j2 is used in combination, the wrapper LoggerWrapper (decorator LoggerDecorator) is sometimes used to enhance the native Logger capabilities, such as modifying the input parameters of the log or adding some positioning information to the log. For example, add a unified prefix logPrefix to the log input.
public class LoggerWrapper implements Logger {<!-- -->
private final Logger logger;
private final String logPrefix;
public LoggerWrapper(String logPrefix, Logger logger) {<!-- -->
this.logPrefix = logPrefix;
this.logger = logger;
}
@Override
public void info(String message, Object arg) {<!-- -->
this.logger.info(logPrefix + message, arg);
}
// ... other logging methods
}
When used, LoggerWrapper is provided as a logger through a unified factory.
public class MyLogger {<!-- -->
public Logger logger(Class<?> clazz) {<!-- -->
Logger logger = LoggerFactory.getLogger(clazz);
// Logs that are not printed by the business carry a "MyLogger" tag to distinguish them from logs in other packages.
return new LoggerWrapper("MyLogger", logger);
}
}
When used in other business classes, it can be used as follows:
public class MyBussiness {<!-- -->
private static final Logger LOGGER = MyLogger.logger(MyBussiness.class);
public void doSomething1() {<!-- -->
LOGGER.info("MyBussiness doSomething1");
}
public void doSomething2() {<!-- -->
LOGGER.info("MyBussiness doSomething2");
}
}
The expected log is the class name and line number of the printed business log, use log4j2’s [%c %L] configuration, and the actual log output
[2023-11-01 16:00:00,000 + 0800] [INFO][main][MyBussiness 12] MyBussiness doSomething1 [2023-11-01 16:00:00,000 + 0800] [INFO][main][MyBussiness 12] MyBussiness doSomething2
It was found that the line numbers printed by log4j2 were wrong. They all printed the same line number, and it was the number of lines of the LoggerWrapper.info() method, not the number of lines of the actual business printing log. This problem may exist when using the wrapper and only configuring as above. Log4j2 also recognizes custom loggers as business codes.
The solution to this problem is to specify the FQCN of log4j2. Log4j will remember the Logger’s Fully Qualified Class Name (FQCN) and use it to traverse the stack in each log event when printing the position, printing the previous stack of fully qualified class name (FQCN) line number. The above LoggerWrapper does not specify FQCN, causing Log4j2 to think that FQCN is its internal Logger, and its upper level log event is this.logger.info(logPrefix + message, arg);, causing the line number to always be the internal position of LoggerWrapper.
Correct usage should implement LocationAwareLogger
public class LoggerWrapper implements LocationAwareLogger {<!-- -->
private final LocationAwareLogger logger;
private final String logPrefix;
//Specify FQCN
private final String FQCN = LoggerWrapper.class.getName();
public LoggerWrapper(String logPrefix, LocationAwareLogger logger) {<!-- -->
this.logPrefix = logPrefix;
this.logger = logger;
}
private void writeLog(Marker marker, int level, Throwable exception, String format, Object... args) {<!-- -->
String message = format;
if (args != null & amp; & amp; args.length > 0) {<!-- -->
FormattingTuple formatted = MessageFormatter.arrayFormat(format, args);
if (exception == null & amp; & amp; formatted.getThrowable() != null) {<!-- -->
exception = formatted.getThrowable();
}
message = formatted.getMessage();
}
// Pass FQCN into the Log4j2 logger
logger.log(marker, FQCN, level, addPrefix(message), null, exception);
}
@Override
public void info(String message, Object arg) {<!-- -->
writeLog(null, LocationAwareLogger.INFO_INT, null, message, arg);
}
// ... other logging methods
}
At this time, the normal log line number can be printed
[2023-11-01 16:00:00,000 + 0800] [INFO][main][MyBussiness 5] MyBussiness doSomething1 [2023-11-01 16:00:00,000 + 0800] [INFO][main][MyBussiness 8] MyBussiness doSomething2
For specific implementation, please refer to the LogContext class of kafka-client as shown below:
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to You under the Apache License, Version 2.0
* (the "License"); you may not use this file except in compliance with
* the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package org.apache.kafka.common.utils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.helpers.FormattingTuple;
import org.slf4j.helpers.MessageFormatter;
import org.slf4j.spi.LocationAwareLogger;
/**
* This class provides a way to instrument loggers with a common context which can be used to
* automatically enrich log messages. For example, in the KafkaConsumer, it is often useful to know
* the groupId of the consumer, so this can be added to a context object which can then be passed to
* all of the dependent components in order to build new loggers. This removes the need to manually
* add the groupId to each message.
*/
public class LogContext {<!-- -->
private final String logPrefix;
public LogContext(String logPrefix) {<!-- -->
this.logPrefix = logPrefix == null ? "" : logPrefix;
}
public LogContext() {<!-- -->
this("");
}
public Logger logger(Class<?> clazz) {<!-- -->
Logger logger = LoggerFactory.getLogger(clazz);
if (logger instanceof LocationAwareLogger) {<!-- -->
return new LocationAwareKafkaLogger(logPrefix, (LocationAwareLogger) logger);
} else {<!-- -->
return new LocationIgnorantKafkaLogger(logPrefix, logger);
}
}
public String logPrefix() {<!-- -->
return logPrefix;
}
private static abstract class AbstractKafkaLogger implements Logger {<!-- -->
private final String prefix;
protected AbstractKafkaLogger(final String prefix) {<!-- -->
this.prefix = prefix;
}
protected String addPrefix(final String message) {<!-- -->
return prefix + message;
}
}
private static class LocationAwareKafkaLogger extends AbstractKafkaLogger {<!-- -->
private final LocationAwareLogger logger;
private final String fqcn;
LocationAwareKafkaLogger(String logPrefix, LocationAwareLogger logger) {<!-- -->
super(logPrefix);
this.logger = logger;
this.fqcn = LocationAwareKafkaLogger.class.getName();
}
@Override
public String getName() {<!-- -->
return logger.getName();
}
@Override
public void info(String msg) {<!-- -->
writeLog(null, LocationAwareLogger.INFO_INT, msg, null, null);
}
private void writeLog(Marker marker, int level, String format, Object[] args, Throwable exception) {<!-- -->
String message = format;
if (args != null & amp; & amp; args.length > 0) {<!-- -->
FormattingTuple formatted = MessageFormatter.arrayFormat(format, args);
if (exception == null & amp; & amp; formatted.getThrowable() != null) {<!-- -->
exception = formatted.getThrowable();
}
message = formatted.getMessage();
}
logger.log(marker, fqcn, level, addPrefix(message), null, exception);
}
}
private static class LocationIgnorantKafkaLogger extends AbstractKafkaLogger {<!-- -->
private final Logger logger;
LocationIgnorantKafkaLogger(String logPrefix, Logger logger) {<!-- -->
super(logPrefix);
this.logger = logger;
}
@Override
public String getName() {<!-- -->
return logger.getName();
}
@Override
public void info(String message) {<!-- -->
logger.info(addPrefix(message));
}
}
}