Source code analysis logback log output exception stack

Background:

In our daily development, using logback logs to print error logs is the most commonly used function, such as the following code:

logger.error("user login in exception, userId={}", userId, e);

If there is an abnormal output, there will be the following abnormal log output:

user login in exception, userId=user id,
java.lang.RuntimeException: User does not exist
at com.user.UserServiceImpl.getUser(UserServiceImpl.java:144)
at com.user.UserController.getUser(UserController.java:269)

So do we know how logback prints out the exception stack? If we write like this:

logger.error("user login in exception={},userId={}",e,userId);

Put the exception in front of the userId variable, can it still print out the exception stack?

Source code tracking:

Let’s first track the LoggingEvent object constructed in logger.error:

public LoggingEvent(String fqcn, Logger logger, Level level, String message, Throwable throwable, Object[] argArray) {<!-- -->
        this.fqnOfLoggerClass = fqcn;
        this. loggerName = logger. getName();
        this. loggerContext = logger. getLoggerContext();
        this.loggerContextVO = loggerContext.getLoggerContextRemoteView();
        this.level = level;

        this. message = message;
        this.argumentArray = argArray;

        if (throwable == null) {<!-- -->
            throwable = extractThrowableAnRearrangeArguments(argArray);
        }

        if (throwable != null) {<!-- -->
            this.throwableProxy = new ThrowableProxy(throwable);
            LoggerContext lc = logger. getLoggerContext();
            if (lc.isPackagingDataEnabled()) {<!-- -->
                this.throwableProxy.calculatePackagingData();
            }
        }

        timeStamp = System. currentTimeMillis();
    }
\t

Focus on the extractThrowableAnRearrangeArguments method. The function of this method is to determine whether the last parameter in the parameter array is a throwable exception class. Here it is [useId,e]. Obviously, the last parameter here is an exception class.

 private Throwable extractThrowableAnRearrangeArguments(Object[] argArray) {<!-- -->
        Throwable extractedThrowable = EventArgUtil. extractThrowable(argArray);
        if (EventArgUtil. successfulExtraction(extractedThrowable)) {<!-- -->
            this.argumentArray = EventArgUtil.trimmedCopy(argArray);
        }
        return extractedThrowable;
    }

Continue to look down, if it is an abnormal class, a new abnormal proxy class will be created

this.throwableProxy = new ThrowableProxy(throwable);

Then we track until the PatternLayout class outputs specific log content, first look at the structure of the PatternLayout class:

static {<!-- -->
        defaultConverterMap.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);

        defaultConverterMap.put("d", DateConverter.class.getName());
        defaultConverterMap.put("date", DateConverter.class.getName());

        defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
        defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());

        defaultConverterMap.put("level", LevelConverter.class.getName());
        defaultConverterMap.put("le", LevelConverter.class.getName());
        defaultConverterMap.put("p", LevelConverter.class.getName());

        defaultConverterMap.put("t", ThreadConverter.class.getName());
        defaultConverterMap.put("thread", ThreadConverter.class.getName());

        defaultConverterMap.put("lo", LoggerConverter.class.getName());
        defaultConverterMap.put("logger", LoggerConverter.class.getName());
        defaultConverterMap.put("c", LoggerConverter.class.getName());

        defaultConverterMap.put("m", MessageConverter.class.getName());
        defaultConverterMap.put("msg", MessageConverter.class.getName());
        defaultConverterMap.put("message", MessageConverter.class.getName());

        defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
        defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());

        defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
        defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());

        defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
        defaultConverterMap.put("line", LineOfCallerConverter.class.getName());

        defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
        defaultConverterMap.put("file", FileOfCallerConverter.class.getName());

        defaultConverterMap.put("X", MDCConverter.class.getName());
        defaultConverterMap.put("mdc", MDCConverter.class.getName());

        defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
        defaultConverterMap.put("exception", ThrowableProxyConverter.class.getName());
        defaultConverterMap.put("rEx", RootCauseFirstThrowableProxyConverter.class.getName());
        defaultConverterMap.put("rootException", RootCauseFirstThrowableProxyConverter.class.getName());
        defaultConverterMap.put("throwable", ThrowableProxyConverter.class.getName());

        defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
        defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class.getName());
        defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class.getName());

        defaultConverterMap.put("nopex", NopThrowableInformationConverter.class.getName());
        defaultConverterMap.put("nopexception", NopThrowableInformationConverter.class.getName());

        defaultConverterMap.put("cn", ContextNameConverter.class.getName());
        defaultConverterMap.put("contextName", ContextNameConverter.class.getName());

        defaultConverterMap.put("caller", CallerDataConverter.class.getName());

        defaultConverterMap.put("marker", MarkerConverter.class.getName());

        defaultConverterMap.put("property", PropertyConverter.class.getName());

        defaultConverterMap.put("n", LineSeparatorConverter.class.getName());

        defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
        defaultConverterMap.put("red", RedCompositeConverter.class.getName());
        defaultConverterMap.put("green", GreenCompositeConverter.class.getName());
        defaultConverterMap.put("yellow", YellowCompositeConverter.class.getName());
        defaultConverterMap.put("blue", BlueCompositeConverter.class.getName());
        defaultConverterMap.put("magenta", MagentaCompositeConverter.class.getName());
        defaultConverterMap.put("cyan", CyanCompositeConverter.class.getName());
        defaultConverterMap.put("white", WhiteCompositeConverter.class.getName());
        defaultConverterMap.put("gray", GrayCompositeConverter.class.getName());
        defaultConverterMap.put("boldRed", BoldRedCompositeConverter.class.getName());
        defaultConverterMap.put("boldGreen", BoldGreenCompositeConverter.class.getName());
        defaultConverterMap.put("boldYellow", BoldYellowCompositeConverter.class.getName());
        defaultConverterMap.put("boldBlue", BoldBlueCompositeConverter.class.getName());
        defaultConverterMap.put("boldMagenta", BoldMagentaCompositeConverter.class.getName());
        defaultConverterMap.put("boldCyan", BoldCyanCompositeConverter.class.getName());
        defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
        defaultConverterMap.put("highlight", HighlightingCompositeConverter.class.getName());

        defaultConverterMap.put("lsn", LocalSequenceNumberConverter.class.getName());
}

We can see DateConverter date converter, ThreadConverter thread converter, ThrowableProxyConverter exception converter, etc. impressively listed,
That is, a log will be converted by these converters. Combined with the previous ThrowableProxy, let’s take a look at how ThrowableProxyConverter outputs the exception stack:

protected void subjoinSTEPArray(StringBuilder buf, int indent, IThrowableProxy tp) {<!-- -->
        StackTraceElementProxy[] stepArray = tp.getStackTraceElementProxyArray();
        int commonFrames = tp. getCommonFrames();

        boolean unrestrictedPrinting = lengthOption > stepArray.length;

        int maxIndex = (unrestrictedPrinting) ? stepArray. length : lengthOption;
        if (commonFrames > 0 & amp; & amp; unrestrictedPrinting) {<!-- -->
            maxIndex -= commonFrames;
        }

        int ignoredCount = 0;
        for (int i = 0; i < maxIndex; i ++ ) {<!-- -->
            StackTraceElementProxy element = stepArray[i];
            if (!isIgnoredStackTraceLine(element.toString())) {<!-- -->
                ThrowableProxyUtil.indent(buf, indent);
                printStackLine(buf, ignoredCount, element);
                ignoredCount = 0;
                buf.append(CoreConstants.LINE_SEPARATOR);
            } else {<!-- -->
                 + + ignoredCount;
                if (maxIndex < stepArray. length) {<!-- -->
                     + + maxIndex;
                }
            }
        }
        if (ignoredCount > 0) {<!-- -->
            printIgnoredCount(buf, ignoredCount);
            buf.append(CoreConstants.LINE_SEPARATOR);
        }

        if (commonFrames > 0 & amp; & amp; unrestrictedPrinting) {<!-- -->
            ThrowableProxyUtil.indent(buf, indent);
            buf.append("... ").append(tp.getCommonFrames()).append("common frames omitted").append(CoreConstants.LINE_SEPARATOR);
        }
    }

Focus on viewing

printStackLine(buf, ignoredCount, element);
                ignoredCount = 0;
                buf.append(CoreConstants.LINE_SEPARATOR);

This is where the exception stack is printed. Here, a newline character is printed every time an abnormal line is printed, so you can see the complete stack in the log, ok, this is the source code process of logback stack printing exception stack log.

Questions:

Then let’s look at the question raised at the beginning: print the error log like this,

logger.error("user login in exception={},userId={}",e,userId);

Can the exception stack be printed out?
The answer is obviously no, because it has been said before that logback only judges whether the last parameter of the parameter group is an exception class. Obviously, the last parameter of [e, userId] here is userId, not an exception class, so there will be no exception stack Print it out, as for the output of the placeholder in the middle, it is just the content of e.toString, which is completely different from the exception stack.