001/*
002 * Licensed to the Apache Software Foundation (ASF) under one or more
003 * contributor license agreements. See the NOTICE file distributed with
004 * this work for additional information regarding copyright ownership.
005 * The ASF licenses this file to You under the Apache license, Version 2.0
006 * (the "License"); you may not use this file except in compliance with
007 * the License. You may obtain a copy of the License at
008 *
009 *      http://www.apache.org/licenses/LICENSE-2.0
010 *
011 * Unless required by applicable law or agreed to in writing, software
012 * distributed under the License is distributed on an "AS IS" BASIS,
013 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
014 * See the license for the specific language governing permissions and
015 * limitations under the license.
016 */
017package org.apache.logging.log4j.core.async;
018
019import java.util.List;
020
021import org.apache.logging.log4j.Level;
022import org.apache.logging.log4j.Marker;
023import org.apache.logging.log4j.ThreadContext;
024import org.apache.logging.log4j.ThreadContext.ContextStack;
025import org.apache.logging.log4j.core.ContextDataInjector;
026import org.apache.logging.log4j.core.Logger;
027import org.apache.logging.log4j.core.LoggerContext;
028import org.apache.logging.log4j.core.config.Configuration;
029import org.apache.logging.log4j.core.config.LoggerConfig;
030import org.apache.logging.log4j.core.config.Property;
031import org.apache.logging.log4j.core.config.ReliabilityStrategy;
032import org.apache.logging.log4j.core.impl.ContextDataFactory;
033import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory;
034import org.apache.logging.log4j.core.util.Clock;
035import org.apache.logging.log4j.core.util.ClockFactory;
036import org.apache.logging.log4j.core.util.NanoClock;
037import org.apache.logging.log4j.message.Message;
038import org.apache.logging.log4j.message.MessageFactory;
039import org.apache.logging.log4j.message.ReusableMessage;
040import org.apache.logging.log4j.spi.AbstractLogger;
041import org.apache.logging.log4j.status.StatusLogger;
042import org.apache.logging.log4j.util.StackLocatorUtil;
043import org.apache.logging.log4j.util.StringMap;
044
045import com.lmax.disruptor.EventTranslatorVararg;
046import com.lmax.disruptor.dsl.Disruptor;
047
048/**
049 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
050 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
051 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
052 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
053 * <p>
054 * To use AsyncLogger, specify the System property
055 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
056 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
057 * <p>
058 * Note that for performance reasons, this logger does not include source location by default. You need to specify
059 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
060 * log4j.xml configuration will produce either a "?" character or no output at all.
061 * <p>
062 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
063 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
064 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
065 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
066 */
067public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
068    // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
069    // Specifically, try to keep the hot methods to 35 bytecodes or less:
070    // this is within the MaxInlineSize threshold and makes these methods candidates for
071    // immediate inlining instead of waiting until they are designated "hot enough".
072
073    private static final StatusLogger LOGGER = StatusLogger.getLogger();
074    private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
075    private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector();
076
077    private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
078
079    private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
080    private final AsyncLoggerDisruptor loggerDisruptor;
081
082    private volatile boolean includeLocation; // reconfigurable
083    private volatile NanoClock nanoClock; // reconfigurable
084
085    /**
086     * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
087     *
088     * @param context context of this logger
089     * @param name name of this logger
090     * @param messageFactory message factory of this logger
091     * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
092     */
093    public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
094            final AsyncLoggerDisruptor loggerDisruptor) {
095        super(context, name, messageFactory);
096        this.loggerDisruptor = loggerDisruptor;
097        includeLocation = privateConfig.loggerConfig.isIncludeLocation();
098        nanoClock = context.getConfiguration().getNanoClock();
099    }
100
101    /*
102     * (non-Javadoc)
103     *
104     * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration)
105     */
106    @Override
107    protected void updateConfiguration(final Configuration newConfig) {
108        nanoClock = newConfig.getNanoClock();
109        includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation();
110        super.updateConfiguration(newConfig);
111    }
112
113    // package protected for unit tests
114    NanoClock getNanoClock() {
115        return nanoClock;
116    }
117
118    private RingBufferLogEventTranslator getCachedTranslator() {
119        RingBufferLogEventTranslator result = threadLocalTranslator.get();
120        if (result == null) {
121            result = new RingBufferLogEventTranslator();
122            threadLocalTranslator.set(result);
123        }
124        return result;
125    }
126
127    @Override
128    public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
129            final Throwable thrown) {
130        getTranslatorType().log(fqcn, level, marker, message, thrown);
131    }
132
133    @Override
134    public void log(final Level level, final Marker marker, final String fqcn, final StackTraceElement location,
135        final Message message, final Throwable throwable) {
136        getTranslatorType().log(fqcn, location, level, marker, message, throwable);
137    }
138
139
140    abstract class TranslatorType {
141        abstract void log(final String fqcn, final StackTraceElement location, final Level level, final Marker marker,
142            final Message message, final Throwable thrown);
143
144        abstract void log(final String fqcn, final Level level, final Marker marker,
145                          final Message message, final Throwable thrown);
146    }
147
148    private final TranslatorType threadLocalTranslatorType = new TranslatorType() {
149        @Override
150        void log(String fqcn, StackTraceElement location, Level level, Marker marker, Message message,
151            Throwable thrown) {
152            logWithThreadLocalTranslator(fqcn, location, level, marker, message, thrown);
153        }
154
155        @Override
156        void log(String fqcn, Level level, Marker marker, Message message, Throwable thrown) {
157            logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);
158        }
159    };
160
161    private final TranslatorType varargTranslatorType = new TranslatorType() {
162        @Override
163        void log(String fqcn, StackTraceElement location, Level level, Marker marker, Message message,
164            Throwable thrown) {
165            logWithVarargTranslator(fqcn, location, level, marker, message, thrown);
166        }
167
168        @Override
169        void log(String fqcn, Level level, Marker marker, Message message, Throwable thrown) {
170            // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps
171            logWithVarargTranslator(fqcn, level, marker, message, thrown);
172        }
173    };
174
175    private TranslatorType getTranslatorType() {
176        return loggerDisruptor.isUseThreadLocals() ? threadLocalTranslatorType : varargTranslatorType;
177    }
178
179    private boolean isReused(final Message message) {
180        return message instanceof ReusableMessage;
181    }
182
183    /**
184     * Enqueues the specified log event data for logging in a background thread.
185     * <p>
186     * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
187     * unnecessary objects with each event.
188     *
189     * @param fqcn fully qualified name of the caller
190     * @param level level at which the caller wants to log the message
191     * @param marker message marker
192     * @param message the log message
193     * @param thrown a {@code Throwable} or {@code null}
194     */
195    private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
196            final Message message, final Throwable thrown) {
197        // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
198
199        final RingBufferLogEventTranslator translator = getCachedTranslator();
200        initTranslator(translator, fqcn, level, marker, message, thrown);
201        initTranslatorThreadValues(translator);
202        publish(translator);
203    }
204
205    /**
206     * Enqueues the specified log event data for logging in a background thread.
207     * <p>
208     * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
209     * unnecessary objects with each event.
210     *
211     * @param fqcn fully qualified name of the caller
212     * @param location the Location of the caller.
213     * @param level level at which the caller wants to log the message
214     * @param marker message marker
215     * @param message the log message
216     * @param thrown a {@code Throwable} or {@code null}
217     */
218    private void logWithThreadLocalTranslator(final String fqcn, final StackTraceElement location, final Level level,
219        final Marker marker, final Message message, final Throwable thrown) {
220        // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
221
222        final RingBufferLogEventTranslator translator = getCachedTranslator();
223        initTranslator(translator, fqcn, location, level, marker, message, thrown);
224        initTranslatorThreadValues(translator);
225        publish(translator);
226    }
227
228    private void publish(final RingBufferLogEventTranslator translator) {
229        if (!loggerDisruptor.tryPublish(translator)) {
230            handleRingBufferFull(translator);
231        }
232    }
233
234    private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
235        if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
236            // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
237            AsyncQueueFullMessageUtil.logWarningToStatusLogger();
238            logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
239                    translator.thrown);
240            return;
241        }
242        final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
243        switch (eventRoute) {
244            case ENQUEUE:
245                loggerDisruptor.enqueueLogMessageWhenQueueFull(translator);
246                break;
247            case SYNCHRONOUS:
248                logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
249                        translator.thrown);
250                break;
251            case DISCARD:
252                break;
253            default:
254                throw new IllegalStateException("Unknown EventRoute " + eventRoute);
255        }
256    }
257
258    private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
259        final StackTraceElement location, final Level level, final Marker marker,
260        final Message message, final Throwable thrown) {
261
262        translator.setBasicValues(this, name, marker, fqcn, level, message, //
263            // don't construct ThrowableProxy until required
264            thrown,
265
266            // needs shallow copy to be fast (LOG4J2-154)
267            ThreadContext.getImmutableStack(), //
268
269            location,
270            CLOCK, //
271            nanoClock //
272        );
273    }
274
275    private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
276            final Level level, final Marker marker, final Message message, final Throwable thrown) {
277
278        translator.setBasicValues(this, name, marker, fqcn, level, message, //
279                // don't construct ThrowableProxy until required
280                thrown,
281
282                // needs shallow copy to be fast (LOG4J2-154)
283                ThreadContext.getImmutableStack(), //
284
285                // location (expensive to calculate)
286                calcLocationIfRequested(fqcn), //
287                CLOCK, //
288                nanoClock //
289        );
290    }
291
292    private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
293        // constant check should be optimized out when using default (CACHED)
294        if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
295            translator.updateThreadValues();
296        }
297    }
298
299    /**
300     * Returns the caller location if requested, {@code null} otherwise.
301     *
302     * @param fqcn fully qualified caller name.
303     * @return the caller location if requested, {@code null} otherwise.
304     */
305    private StackTraceElement calcLocationIfRequested(final String fqcn) {
306        // location: very expensive operation. LOG4J2-153:
307        // Only include if "includeLocation=true" is specified,
308        // exclude if not specified or if "false" was specified.
309        return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null;
310    }
311
312    /**
313     * Enqueues the specified log event data for logging in a background thread.
314     * <p>
315     * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
316     * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
317     *
318     * @param fqcn fully qualified name of the caller
319     * @param level level at which the caller wants to log the message
320     * @param marker message marker
321     * @param message the log message
322     * @param thrown a {@code Throwable} or {@code null}
323     */
324    private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
325            final Message message, final Throwable thrown) {
326        // Implementation note: candidate for optimization: exceeds 35 bytecodes.
327
328        final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
329        if (disruptor == null) {
330            LOGGER.error("Ignoring log event after Log4j has been shut down.");
331            return;
332        }
333        // if the Message instance is reused, there is no point in freezing its message here
334        if (!isReused(message)) {
335            InternalAsyncUtil.makeMessageImmutable(message);
336        }
337        StackTraceElement location = null;
338        // calls the translateTo method on this AsyncLogger
339        if (!disruptor.getRingBuffer().tryPublishEvent(this,
340                this, // asyncLogger: 0
341                (location = calcLocationIfRequested(fqcn)), // location: 1
342                fqcn, // 2
343                level, // 3
344                marker, // 4
345                message, // 5
346                thrown)) { // 6
347            handleRingBufferFull(location, fqcn, level, marker, message, thrown);
348        }
349    }
350
351    /**
352     * Enqueues the specified log event data for logging in a background thread.
353     * <p>
354     * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
355     * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
356     *
357     * @param fqcn fully qualified name of the caller
358     * @param location location of the caller.
359     * @param level level at which the caller wants to log the message
360     * @param marker message marker
361     * @param message the log message
362     * @param thrown a {@code Throwable} or {@code null}
363     */
364    private void logWithVarargTranslator(final String fqcn, final StackTraceElement location, final Level level,
365        final Marker marker, final Message message, final Throwable thrown) {
366        // Implementation note: candidate for optimization: exceeds 35 bytecodes.
367
368        final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
369        if (disruptor == null) {
370            LOGGER.error("Ignoring log event after Log4j has been shut down.");
371            return;
372        }
373        // if the Message instance is reused, there is no point in freezing its message here
374        if (!isReused(message)) {
375            InternalAsyncUtil.makeMessageImmutable(message);
376        }
377        // calls the translateTo method on this AsyncLogger
378        if (!disruptor.getRingBuffer().tryPublishEvent(this,
379            this, // asyncLogger: 0
380            location, // location: 1
381            fqcn, // 2
382            level, // 3
383            marker, // 4
384            message, // 5
385            thrown)) { // 6
386            handleRingBufferFull(location, fqcn, level, marker, message, thrown);
387        }
388    }
389
390    /*
391     * (non-Javadoc)
392     *
393     * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
394     */
395    @Override
396    public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
397        // Implementation note: candidate for optimization: exceeds 35 bytecodes.
398        final AsyncLogger asyncLogger = (AsyncLogger) args[0];
399        final StackTraceElement location = (StackTraceElement) args[1];
400        final String fqcn = (String) args[2];
401        final Level level = (Level) args[3];
402        final Marker marker = (Marker) args[4];
403        final Message message = (Message) args[5];
404        final Throwable thrown = (Throwable) args[6];
405
406        // needs shallow copy to be fast (LOG4J2-154)
407        final ContextStack contextStack = ThreadContext.getImmutableStack();
408
409        final Thread currentThread = Thread.currentThread();
410        final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
411        event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
412                // config properties are taken care of in the EventHandler thread
413                // in the AsyncLogger#actualAsyncLog method
414                CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
415                contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
416                CLOCK, nanoClock);
417    }
418
419    /**
420     * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
421     * toString() method
422     *
423     * @param fqcn fully qualified caller name
424     * @param level log level
425     * @param marker optional marker
426     * @param message log message
427     * @param thrown optional exception
428     */
429    void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
430            final Message message, final Throwable thrown) {
431        // bypass RingBuffer and invoke Appender directly
432        final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
433        strategy.log(this, getName(), fqcn, marker, level, message, thrown);
434    }
435
436    private void handleRingBufferFull(final StackTraceElement location,
437                                      final String fqcn,
438                                      final Level level,
439                                      final Marker marker,
440                                      final Message msg,
441                                      final Throwable thrown) {
442        if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
443            // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
444            AsyncQueueFullMessageUtil.logWarningToStatusLogger();
445            logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
446            return;
447        }
448        final EventRoute eventRoute = loggerDisruptor.getEventRoute(level);
449        switch (eventRoute) {
450            case ENQUEUE:
451                loggerDisruptor.enqueueLogMessageWhenQueueFull(this,
452                        this, // asyncLogger: 0
453                        location, // location: 1
454                        fqcn, // 2
455                        level, // 3
456                        marker, // 4
457                        msg, // 5
458                        thrown); // 6
459                break;
460            case SYNCHRONOUS:
461                logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
462                break;
463            case DISCARD:
464                break;
465            default:
466                throw new IllegalStateException("Unknown EventRoute " + eventRoute);
467        }
468    }
469
470    /**
471     * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
472     * Merges the contents of the configuration map into the contextData, after replacing any variables in the property
473     * values with the StrSubstitutor-supplied actual values.
474     *
475     * @param event the event to log
476     */
477    public void actualAsyncLog(final RingBufferLogEvent event) {
478        final LoggerConfig privateConfigLoggerConfig = privateConfig.loggerConfig;
479        final List<Property> properties = privateConfigLoggerConfig.getPropertyList();
480
481        if (properties != null) {
482            onPropertiesPresent(event, properties);
483        }
484
485        privateConfigLoggerConfig.getReliabilityStrategy().log(this, event);
486    }
487
488    @SuppressWarnings("ForLoopReplaceableByForEach") // Avoid iterator allocation
489    private void onPropertiesPresent(final RingBufferLogEvent event, final List<Property> properties) {
490        StringMap contextData = getContextData(event);
491        for (int i = 0, size = properties.size(); i < size; i++) {
492            final Property prop = properties.get(i);
493            if (contextData.getValue(prop.getName()) != null) {
494                continue; // contextMap overrides config properties
495            }
496            final String value = prop.isValueNeedsLookup() //
497                    ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) //
498                    : prop.getValue();
499            contextData.putValue(prop.getName(), value);
500        }
501        event.setContextData(contextData);
502    }
503
504    private static StringMap getContextData(final RingBufferLogEvent event) {
505        StringMap contextData = (StringMap) event.getContextData();
506        if (contextData.isFrozen()) {
507            final StringMap temp = ContextDataFactory.createContextData();
508            temp.putAll(contextData);
509            return temp;
510        }
511        return contextData;
512    }
513}