background

"Log4j2-TF-7-AsyncLoggerConfig-8" Id=52 BLOCKED on sun.misc.URLClassPath@26eb1b56 owned by "Log4j2-TF-7-AsyncLoggerConfig-4" Id=17
    at sun.misc.URLClassPath.getNextLoader(URLClassPath.java:479)
    -  blocked on sun.misc.URLClassPath@26eb1b56
    at sun.misc.URLClassPath.getResource(URLClassPath.java:248)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:448)
    at com.alipay.sofa.ark.container.service.classloader.AbstractClasspathClassLoader.resolveLocalClass(AbstractClasspathClassLoader.java:302)
    at com.alipay.sofa.ark.container.service.classloader.PluginClassLoader.loadClassInternal(PluginClassLoader.java:102)
	  // Plug in loading  
		at com.alipay.sofa.ark.container.service.classloader.AbstractClasspathClassLoader.loadClass(AbstractClasspathClassLoader.java:71)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:380)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:563)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:689)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:138)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:122)
    at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:564)
    at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:63)
    at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
    at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
    at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
    at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:268)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:115)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:112)
    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:98)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
    at java.lang.Thread.run(Thread.java:861)
Copy code

Log4j2 related classes are exported in sofaark plug-in. Therefore, when log4j2 classes need to be loaded, they will be entrusted to PluginClassLoader for loading.

Configuring% throwable in PatternLayout has different effects on converters

SOFABoot starts loading log4j2 the configuration file

Parse the configuration file and create different PCs according to each configuration in PatternLayout

Rule mapping list

Find the corresponding Converter, create this object through reflection, and then place it in patternConverters.

Under what circumstances will an extended throwablepatternconverter be generated?

There are two conditions that will produce this Converter

Configure "xex", "xtrowable", "xexception"

If the PatternLayout in the configuration file of log4j2 is configured with "xex", "xtrowable" and "xexception", it can be known from the above analysis that when parsing, where the rules match the corresponding converterName, it will be created.

Created when% throwable is not configured

Why? Let's look at the next code:

// Create a corresponding PatternFormatter for PatternLayout to output the log according to the specified rules.
// PatternFormatter depends on Converter to execute format

// 1.alwaysWriteExceptions is true by default and can only be configured and modified in the configuration file.
public List<PatternFormatter> parse(final String pattern, final boolean alwaysWriteExceptions,
           final boolean disableAnsi, final boolean noConsoleNoAnsi) {
    final List<PatternFormatter> list = new ArrayList<>();
    final List<PatternConverter> converters = new ArrayList<>();
    final List<FormattingInfo> fields = new ArrayList<>();

    parse(pattern, converters, fields, disableAnsi, noConsoleNoAnsi, true);

    final Iterator<FormattingInfo> fieldIter = fields.iterator();
    boolean handlesThrowable = false;
	// The collection of all converters corresponding to the current Logger. The converters here are based on the above parse pattern 
    // Generated by the style of pattern,
    for (final PatternConverter converter : converters) {
        if (converter instanceof NanoTimePatternConverter) {
            // LOG4J2-1074 Switch to actual clock if nanosecond timestamps are required in config.
            // LOG4J2-1248 set config nanoclock
            if (config != null) {
                config.setNanoClock(new SystemNanoClock());
            }
        }
        LogEventPatternConverter pc;
        if (converter instanceof LogEventPatternConverter) { 
            pc = (LogEventPatternConverter) converter;
            // At present, the official convert is, and the handlesThrowable of Throwable returns true
            // Therefore, if there is no% throwable in the pattern, false will always be returned here
            handlesThrowable |= pc.handlesThrowable();
        } else {
            pc = new LiteralPatternConverter(config, Strings.EMPTY, true);
        }

        FormattingInfo field;
        if (fieldIter.hasNext()) {
            field = fieldIter.next();
        } else {
            field = FormattingInfo.getDefault();
        }
        list.add(new PatternFormatter(pc, field));
    }
	// alwaysWriteExceptions = true
    // handlesThrowable is true when configuring% throwable, and others are false
    // That is, when% throwable is not configured for the current Logger, an ExtendedThrowablePatternConverter will be created
    // As the default exception handling Converter
    if (alwaysWriteExceptions && !handlesThrowable) {
        final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, null);
        list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
    }
    return list;
}
Copy code

Conclusion: different types of patternconverters are generated according to different element types in the pattern. If% throwable is configured in the log file, a ThrowablePatternConverter will be generated correspondingly. If% throwable is not configured, the extended ThrowablePatternConverter is used by default.

converter difference analysis

Different patternconverters are used to format the corresponding data during log output, so the core method of corresponding PatternConverter is the format method. Let's take a look at the difference between the format methods of ThrowablePatternConverter and extended ThrowablePatternConverter.

ThrowablePatternConverter#format

@Override
public void format(final LogEvent event, final StringBuilder buffer) {
    final Throwable t = event.getThrown();

    if (isSubShortOption()) {
        formatSubShortOption(t, getSuffix(event), buffer);
    }
    else if (t != null && options.anyLines()) {
        formatOption(t, getSuffix(event), buffer);
    }
}
Copy code

The format option is to write the Throwable stackTracer to the buffer

ExtendedThrowablePatternConverter#format

@Override
public void format(final LogEvent event, final StringBuilder toAppendTo) {
    // There is an extra getThrownProxy here
    final ThrowableProxy proxy = event.getThrownProxy();
    final Throwable throwable = event.getThrown();
    if ((throwable != null || proxy != null) && options.anyLines()) {
        if (proxy == null) {
            super.format(event, toAppendTo);
            return;
        }
        String suffix = getSuffix(event);
        final String extStackTrace = proxy.getExtendedStackTraceAsString(options.getIgnorePackages(), options.getTextRenderer(), suffix);
        final int len = toAppendTo.length();
        if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
            toAppendTo.append(' ');
        }
        if (!options.allLines() || !Strings.LINE_SEPARATOR.equals(options.getSeparator())) {
            final StringBuilder sb = new StringBuilder();
            final String[] array = extStackTrace.split(Strings.LINE_SEPARATOR);
            final int limit = options.minLines(array.length) - 1;
            for (int i = 0; i <= limit; ++i) {
                sb.append(array[i]);
                if (i < limit) {
                    sb.append(options.getSeparator());
                }
            }
            toAppendTo.append(sb.toString());
        } else {
            toAppendTo.append(extStackTrace);
        }
    }
}
Copy code

Final ThrowableProxy = event. Getthrownproxy() combined with the uppermost exception stack, when building the ThrowableProxy object instance, it will serialize the data in the stack, build CacheEntry (toextended stacktrace), and trigger the class loading action.

A proxy is used to represent a throwable that may not exist in a different class loader or JVM. When an application deserializes a ThrowableProxy, the throwable may not be set, but the throwable's information is preserved in other fields of the proxy like the message and stack trace.

Attachment 1: waiting strategy for Disruptor consumers

-DAsyncLoggerConfig.WaitStrategy=xxx

Dark shading is the default policy

Attachment 2: the length of the Disruptor queue and configure the queue blocking and discarding policy

• -Dlog4j2.AsyncQueueFullPolicy=Default/Discard (default)
• -Dlog4j2.DiscardThreshold=ERROR/INFO /... (default info)

1. DefaultAsyncQueueFullPolicy ---- wait queue, turn to synchronous operation policy (default)

public class DefaultAsyncQueueFullPolicy implements AsyncQueueFullPolicy {
    @Override
    public EventRoute getRoute(final long backgroundThreadId, final Level level) {

        // LOG4J2-1518: prevent deadlock when RingBuffer is full and object being logged calls
        // Logger.log in application thread
        // See also LOG4J2-471: prevent deadlock when RingBuffer is full and object
        // being logged calls Logger.log() from its toString() method in background thread
        return EventRoute.SYNCHRONOUS;
    }
}
Copy code

2. Discarding asyncqueuefullpolicy --- discards the log policy according to the log level

@Override
public EventRoute getRoute(final long backgroundThreadId, final Level level) {
    if (level.isLessSpecificThan(thresholdLevel)) {
        if (discardCount.getAndIncrement() == 0) {
            LOGGER.warn("Async queue is full, discarding event with level {}. " +
                        "This message will only appear once; future events from {} " +
                        "are silently discarded until queue capacity becomes available.",
                        level, thresholdLevel);
        }
        return EventRoute.DISCARD;
    }
    return super.getRoute(backgroundThreadId, level);
}
Copy code

Attachment 3: default queue size of Disruptor

• -DAsyncLogger.RingBufferSize=xxx

// propertyName -> AsyncLoggerConfig.RingBufferSize
static int calculateRingBufferSize(final String propertyName) {
    // Constants.enable_threadlocations defaults to false
    // RINGBUFFER_NO_GC_DEFAULT_SIZE 4096
    // 256 * 1024=262144
    int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE;
    final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName,
                                                                                        String.valueOf(ringBufferSize));
    try {
        int size = Integer.parseInt(userPreferredRBSize);
        // RINGBUFFER_MIN_SIZE=128
        if (size < RINGBUFFER_MIN_SIZE) {
            size = RINGBUFFER_MIN_SIZE;
            LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize,
                        RINGBUFFER_MIN_SIZE);
        }
        ringBufferSize = size;
    } catch (final Exception ex) {
        LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize);
    }
    return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}
Copy code

Constant.enable_threadlocations is divided into web and non web applications. For non web applications, it is true by default, and for web applications, it is false by default. The judgment basis is whether the classpath has a javax.servlet.Servlet class. It can be set manually through - Dlog4j2.is.webapp=true/false.

ps: -Dlog4j2.enable.threadlocals: This system property can be used to switch off the use of threadlocals, which will partly disable Log4j's garbage-free behaviour: to be fully garbage-free, Log4j stores objects in ThreadLocal fields to reuse them, otherwise new objects are created for each log event. Note that this property is not effective when Log4j detects it is running in a web application.