The encapsulated LogUtils utility class has an error printing line numbers, and the output log is the line number in LogUtils

[scwlkq]

Description

The encapsulated LogUtils utility class has an error printing line numbers, and the output log is the line number in LogUtils.
封装的LogUtils工具类打印行号错误，输出的日志是LogUtils里的行号。

Configuration

Version: [Log4j version]

Operating system: [OS and version]

JDK: [JDK distribution and version]

Logs

[Stacktraces, errors, etc. relevant applications logs.]

Reproduction

[An isolated test reproducing the test.
JUnit tests similar to the ones in the code base are extremely appreciated.]

[scwlkq]

[Pil0tXia]

Providing a more detailed console screenshot.

[ppkarwasz]

Hi @scwlkq,

Log4j does not provide any class named LogUtils, it must be a class from your project.

Can you add an excerpt of the class code?

[scwlkq]

import org.slf4j.Logger;
import org.slf4j.Marker;

import lombok.experimental.UtilityClass;

@UtilityClass
public final class LogUtils {

    public static boolean isTraceEnabled(Logger logger) {
        return logger.isTraceEnabled();
    }

    public static boolean isTraceEnabled(Logger logger, Marker marker) {
        return logger.isTraceEnabled(marker);
    }

    public static void trace(Logger logger, String msg) {
        if (isTraceEnabled(logger)) {
            logger.trace(msg);
        }
    }

    public static void trace(Logger logger, String format, Object arg) {
        if (isTraceEnabled(logger)) {
            logger.trace(format, arg);
        }
    }

    public static void trace(Logger logger, String msg, Throwable t) {
        if (isTraceEnabled(logger)) {
            logger.trace(msg, t);
        }
    }

    public static void trace(Logger logger, String format, Object... arguments) {
        if (isTraceEnabled(logger)) {
            logger.trace(format, arguments);
        }
    }

    public static void trace(Logger logger, String format, Object arg1, Object arg2) {
        if (isTraceEnabled(logger)) {
            logger.trace(format, arg1, arg2);
        }
    }

    public static void trace(Logger logger, Marker marker, String msg) {
        if (isTraceEnabled(logger, marker)) {
            logger.trace(marker, msg);
        }
    }

    public static void trace(Logger logger, Marker marker, String format, Object arg) {
        if (isTraceEnabled(logger, marker)) {
            logger.trace(marker, format, arg);
        }
    }

    public static boolean isDebugEnabled(Logger logger) {
        return logger.isDebugEnabled();
    }

    public static void debug(Logger logger, String msg) {
        if (isDebugEnabled(logger)) {
            logger.debug(msg);
        }
    }

    public static void debug(Logger logger, String format, Object arg) {
        if (isDebugEnabled(logger)) {
            logger.debug(format, arg);
        }
    }

    public static void debug(Logger logger, String format, Object arg1, Object arg2) {
        if (isDebugEnabled(logger)) {
            logger.debug(format, arg1, arg2);
        }
    }

    public static void debug(Logger logger, String format, Object... arguments) {
        if (isDebugEnabled(logger)) {
            logger.debug(format, arguments);
        }
    }

    public static void debug(Logger logger, String msg, Throwable t) {
        if (isDebugEnabled(logger)) {
            logger.debug(msg, t);
        }
    }

    public static boolean isInfoEnabled(Logger logger) {
        return logger.isInfoEnabled();
    }

    public static void info(Logger logger, String msg) {
        if (isInfoEnabled(logger)) {
            logger.info(msg);
        }
    }

    public static void info(Logger logger, String format, Object arg) {
        if (isInfoEnabled(logger)) {
            logger.info(format, arg);
        }
    }

    public static void info(Logger logger, String format, Object arg1, Object arg2) {
        if (isInfoEnabled(logger)) {
            logger.info(format, arg1, arg2);
        }
    }

    public static void info(Logger logger, String format, Object... arguments) {
        if (isInfoEnabled(logger)) {
            logger.info(format, arguments);
        }
    }

    public static void info(Logger logger, String msg, Throwable t) {
        if (isInfoEnabled(logger)) {
            logger.info(msg, t);
        }
    }

    public static boolean isWarnEnabled(Logger logger) {
        return logger.isWarnEnabled();
    }

    public static void warn(Logger logger, String msg) {
        if (isWarnEnabled(logger)) {
            logger.warn(msg);
        }
    }

    public static void warn(Logger logger, String format, Object arg) {
        if (isWarnEnabled(logger)) {
            logger.warn(format, arg);
        }
    }

    public static void warn(Logger logger, String format, Object arg1, Object arg2) {
        if (isWarnEnabled(logger)) {
            logger.warn(format, arg1, arg2);
        }
    }

    public static void warn(Logger logger, String format, Object... arguments) {
        if (isWarnEnabled(logger)) {
            logger.warn(format, arguments);
        }
    }

    public static void warn(Logger logger, String msg, Throwable t) {
        if (isWarnEnabled(logger)) {
            logger.warn(msg, t);
        }
    }

    public static boolean isErrorEnabled(Logger logger) {
        return logger.isErrorEnabled();
    }

    public static void error(Logger logger, String msg) {
        if (isErrorEnabled(logger)) {
            logger.error(msg);
        }
    }

    public static void error(Logger logger, String format, Object arg) {
        if (isErrorEnabled(logger)) {
            logger.error(format, arg);
        }
    }

    public static void error(Logger logger, String format, Object arg1, Object arg2) {
        if (isErrorEnabled(logger)) {
            logger.error(format, arg1, arg2);
        }
    }

    public static void error(Logger logger, String format, Object... arguments) {
        if (isErrorEnabled(logger)) {
            logger.error(format, arguments);
        }
    }

    public static void error(Logger logger, String msg, Throwable t) {
        if (isErrorEnabled(logger)) {
            logger.error(msg, t);
        }
    }

}

[ppkarwasz]

@scwlkq,

Edit: in the original answer I missed the fact that you are using SLF4J instead of the Log4j API.
I adapted some content to also work with SLF4J.

Both SLF4J and Log4j API create log messages lazily only if the log level is enabled (cf. e.g. Log4j API source code), so you can safely replace:

    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        if (isTraceEnabled(logger, marker)) {
            logger.trace(marker, msg, arg);
        }
    }

in your code with:

    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        logger.trace(marker, msg, arg);
    }

Now you have two choices:

• either inline all call sites of your LogUtils class and remove it,
• or fix the location information.

Inlining the utility class

In order to inline all call sites of LogUtils and remove the class, you can use a source refactoring tool like Error Prone. With Error Prone you only need to annotate all the methods with @InlineMe:

    @InlineMe(replacement = "logger.trace(marker, msg, arg)")
    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        ...
    }

and use Error Prone's patching feature (cf. documentation).

Fix location information

If you decided against inlining and you use the Log4j API, you need to use the methods of the ExtendedLogger that have a "fqcn" argument (all the loggers provided by the three implementations log4j-core, log4j-to-slf4jandlog4j-to-jul` we maintain implement that interface):

    private static final String FQCN = LogUtils.class.getName();

    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        ((ExtendedLogger) logger).logIfEnabled(FQCN, Level.TRACE, marker, msg, arg);
    }

Edit: the SLF4J version of the above is:

    private static final String FQCN = LogUtils.class.getName():

    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        final LoggingEventBuilder builder = logger.atTrace();
        if (builder instanceof CallerBoundaryAware) {
            ((CallerBoundaryAware) builder).setCallerBoundary(FQCN);
        }
       builder.addMarker(marker).log(msg, arg);
    }

[Pil0tXia]

logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

Lines 2336 to 2346 in b747810

	@Override
	public void logIfEnabled(
	final String fqcn,
	final Level level,
	final Marker marker,
	final Message message,
	final Throwable throwable) {
	if (isEnabled(level, marker, message, throwable)) {
	logMessageSafely(fqcn, level, marker, message, throwable);
	}
	}

The additional isDebugEnabled() check before log.debug() is performed in order to avoid invoking the methods referenced in the message field, thus improving logging performance.

The Fluent Logging API supports achieving the same check by using atDebug(), but the subsequent addArgument() is not concise. Besides giving LogUtils a FQCN, do we have any better alternatives?

[ppkarwasz]

@Pil0tXia,

The additional isDebugEnabled() check before log.debug() is performed in order to avoid invoking the methods referenced in the message field, thus improving logging performance.

The additional Logger#isDebugEnabled() in LogUtils should not make any difference in performance. If there is a difference it should slow down the application by introducing another conditional branch. If you have evidence of the contrary, please open a discussion with your benchmarks, maybe we are doing something wrong.

If you follow the call stack of AbstractLogger#debug, no method call is performed on the parameters and no new object is created until isEnabled is evaluated:

logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

Lines 398 to 400 in b747810

	public void debug(final Marker marker, final String message, final Object p0) {
	logIfEnabled(FQCN, Level.DEBUG, marker, message, p0);
	}

logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

Lines 2426 to 2431 in b747810

	public void logIfEnabled(
	final String fqcn, final Level level, final Marker marker, final String message, final Object p0) {
	if (isEnabled(level, marker, message, p0)) {
	logMessage(fqcn, level, marker, message, p0);
	}
	}

logging-log4j2/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

Lines 2661 to 2665 in b747810

	protected void logMessage(
	final String fqcn, final Level level, final Marker marker, final String message, final Object p0) {
	final Message msg = messageFactory.newMessage(message, p0);
	logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
	}

The Fluent Logging API supports achieving the same check by using atDebug(), but the subsequent addArgument() is not concise. Besides giving LogUtils a FQCN, do we have any better alternatives?

The Log4j API also has a fluent API called LogBuilder. It has a powerful LogBuilder#withLocation(StackTraceElement) method that allows callers to inject location information at compile-time.

Of course we don't expect anyone to call that method in their source code and we developed a Maven Log4j Transform Plugin that adds the location information directly into the *.class files. This can only work if the Log4j API is called directly. If you use a LogUtils wrapper class it will not work.

[Pil0tXia]

no method call is performed on the parameters and no new object is created until isEnabled is evaluated.

log.debug() itself does not incur the performance overhead that I mentioned. The performance overhead I mentioned is incurred in the methods that developers write themselves. For example:

log.debug("formatted msg: {}", formatMsg(rawMsg));

Even when the log level is set to info, the formatMsg(rawMsg) method will still be called and return a result before being passed as an argument to log.debug(). This is what takes time.

[ppkarwasz]

no method call is performed on the parameters and no new object is created until isEnabled is evaluated.

log.debug() itself does not incur the performance overhead that I mentioned. The performance overhead I mentioned is incurred in the methods that developers write themselves. For example:

log.debug("formatted msg: ", formatMsg(rawMsg));

We have a solution for that in the Log4j API: see Logger#debug(String, Supplier<?>..). or LogBuilder#log(String, Supplier<?>...).

You can write:

log.debug("Formatted msg: {}", () -> formatMsg(rawMsg));

or

log.atDebug().log("Formatted msg: {}", () -> formatMsg(rawMsg));

To add location information to LogBuilder you can also use BridgeAware#setEntryPoint, which appeared in 2.19.0.

[Pil0tXia]

Thank you very much! I will use the more elegant Fluent Logging API. (A detailed account can be seen at apache/eventmesh#4698)

[pandaapo]

Fix location information

...
Edit: the SLF4J version of the above is:

    private static final String FQCN = LogUtils.class.getName():

    public static void trace(Logger logger, Marker marker, String msg, Object arg) {
        final LoggingEventBuilder builder = logger.atTrace();
        if (builder instanceof CallerBoundaryAware) {
            ((CallerBoundaryAware) logger).setCallerBoundary(FQCN);
        }
       builder.addMarker(marker).log(msg, arg);
    }

There seems to be an error in your suggestion. It should be ((CallerBoundaryAware) builder).setCallerBoundary(FQCN) instead of logger, right? @ppkarwasz

[ppkarwasz]

@pandaapo,

Sure, thanks for pointing that out. I corrected the original comment.