日志框架LOG4J2系列六——log4j2使用包装器

本文旨在解决使用log4j2使用包装器时，不能打印正确行号问题

slf4j+log4j2组合使用时，有时会使用包装器LoggerWrapper（装饰器LoggerDecorator）对原生的Logger能力进行增强，如修改日志的入参或对日志增加一些定位信息。如对日志的输入增加统一的前缀logPrefix

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);
    }
    // ... 其他日志方法
}

在使用时通过统一的一个工厂内提供LoggerWrapper作为logger使用

public class MyLogger {
    public Logger logger(Class<?> clazz) {
        Logger logger = LoggerFactory.getLogger(clazz);
        // 未业务打印的日志都携带一个 “MyLogger”的标记，与其他包内的日志区分开来
		return new LoggerWrapper("MyLogger", logger);
    }
}

在其他业务类使用时可以按如下方式使用

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

期望日志为打印业务日志的类名与行号，使用log4j2的[%c %L]配置，实际日志输出

[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

发现log4j2打印的行号错误，都打印相同的行号，且是LoggerWrapper.info()方法的行数，不是实际业务打印日志的行数。当使用包装器后如果只按上述配置可能会存在此问题。log4j2将自定义的logger也识别为业务代码。

解决此问题的方法是指定log4j2的FQCN。Log4j 会记住 Logger 的全限定类名(FQCN)，并在打印位置时使用它在每个日志事件中堆栈进行遍历，打印全限定类名(FQCN)的上一个堆栈的行号。上述LoggerWrapper没有指定FQCN，导致Log4j2认为FQCN是其内部的Logger，他的上一层日志事件是this.logger.info(logPrefix + message, arg);，导致行号永远是LoggerWrapper的内部位置。

正确使用方式应该要实现LocationAwareLogger

public class LoggerWrapper implements LocationAwareLogger {
	private final LocationAwareLogger logger;
    private final String logPrefix;
    // 指定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 && args.length > 0) {
            FormattingTuple formatted = MessageFormatter.arrayFormat(format, args);
            if (exception == null && formatted.getThrowable() != null) {
                exception = formatted.getThrowable();
            }
            message = formatted.getMessage();
        }
        // 将FQCN传入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);
    }
    // ... 其他日志方法
}

此时可以打印正常的日志行号

[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

具体实现可以参考kafka-client的LogContext类如下所示：

/*
 * 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 && args.length > 0) {
                FormattingTuple formatted = MessageFormatter.arrayFormat(format, args);
                if (exception == null && 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));
        }
    }

}