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.Property;
030import org.apache.logging.log4j.core.config.ReliabilityStrategy;
031import org.apache.logging.log4j.core.impl.ContextDataFactory;
032import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory;
033import org.apache.logging.log4j.core.util.Clock;
034import org.apache.logging.log4j.core.util.ClockFactory;
035import org.apache.logging.log4j.core.util.NanoClock;
036import org.apache.logging.log4j.message.Message;
037import org.apache.logging.log4j.message.MessageFactory;
038import org.apache.logging.log4j.message.ReusableMessage;
039import org.apache.logging.log4j.status.StatusLogger;
040import org.apache.logging.log4j.util.StackLocatorUtil;
041import org.apache.logging.log4j.util.StringMap;
042
043import com.lmax.disruptor.EventTranslatorVararg;
044import com.lmax.disruptor.dsl.Disruptor;
045
046/**
047 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
048 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
049 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
050 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
051 * <p>
052 * To use AsyncLogger, specify the System property
053 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
054 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
055 * <p>
056 * Note that for performance reasons, this logger does not include source location by default. You need to specify
057 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
058 * log4j.xml configuration will produce either a "?" character or no output at all.
059 * <p>
060 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
061 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
062 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
063 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
064 */
065public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
066    // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
067    // Specifically, try to keep the hot methods to 35 bytecodes or less:
068    // this is within the MaxInlineSize threshold and makes these methods candidates for
069    // immediate inlining instead of waiting until they are designated "hot enough".
070
071    private static final StatusLogger LOGGER = StatusLogger.getLogger();
072    private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
073    private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector();
074
075    private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
076
077    private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
078    private final AsyncLoggerDisruptor loggerDisruptor;
079
080    private volatile boolean includeLocation; // reconfigurable
081    private volatile NanoClock nanoClock; // reconfigurable
082
083    /**
084     * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
085     *
086     * @param context context of this logger
087     * @param name name of this logger
088     * @param messageFactory message factory of this logger
089     * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
090     */
091    public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
092            final AsyncLoggerDisruptor loggerDisruptor) {
093        super(context, name, messageFactory);
094        this.loggerDisruptor = loggerDisruptor;
095        includeLocation = privateConfig.loggerConfig.isIncludeLocation();
096        nanoClock = context.getConfiguration().getNanoClock();
097    }
098
099    /*
100     * (non-Javadoc)
101     *
102     * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration)
103     */
104    @Override
105    protected void updateConfiguration(final Configuration newConfig) {
106        nanoClock = newConfig.getNanoClock();
107        includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation();
108        super.updateConfiguration(newConfig);
109    }
110
111    // package protected for unit tests
112    NanoClock getNanoClock() {
113        return nanoClock;
114    }
115
116    private RingBufferLogEventTranslator getCachedTranslator() {
117        RingBufferLogEventTranslator result = threadLocalTranslator.get();
118        if (result == null) {
119            result = new RingBufferLogEventTranslator();
120            threadLocalTranslator.set(result);
121        }
122        return result;
123    }
124
125    @Override
126    public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
127            final Throwable thrown) {
128
129        if (loggerDisruptor.isUseThreadLocals()) {
130            logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);
131        } else {
132            // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps
133            logWithVarargTranslator(fqcn, level, marker, message, thrown);
134        }
135    }
136
137    private boolean isReused(final Message message) {
138        return message instanceof ReusableMessage;
139    }
140
141    /**
142     * Enqueues the specified log event data for logging in a background thread.
143     * <p>
144     * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
145     * unnecessary objects with each event.
146     *
147     * @param fqcn fully qualified name of the caller
148     * @param level level at which the caller wants to log the message
149     * @param marker message marker
150     * @param message the log message
151     * @param thrown a {@code Throwable} or {@code null}
152     */
153    private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
154            final Message message, final Throwable thrown) {
155        // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
156
157        final RingBufferLogEventTranslator translator = getCachedTranslator();
158        initTranslator(translator, fqcn, level, marker, message, thrown);
159        initTranslatorThreadValues(translator);
160        publish(translator);
161    }
162
163    private void publish(final RingBufferLogEventTranslator translator) {
164        if (!loggerDisruptor.tryPublish(translator)) {
165            handleRingBufferFull(translator);
166        }
167    }
168
169    private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
170        if (Logger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
171            // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
172            final Message message = AsyncQueueFullMessageUtil.transform(translator.message);
173            logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, message,
174                    translator.thrown);
175            return;
176        }
177        final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
178        switch (eventRoute) {
179            case ENQUEUE:
180                loggerDisruptor.enqueueLogMessageInfo(translator);
181                break;
182            case SYNCHRONOUS:
183                logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
184                        translator.thrown);
185                break;
186            case DISCARD:
187                break;
188            default:
189                throw new IllegalStateException("Unknown EventRoute " + eventRoute);
190        }
191    }
192
193    private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
194            final Level level, final Marker marker, final Message message, final Throwable thrown) {
195
196        translator.setBasicValues(this, name, marker, fqcn, level, message, //
197                // don't construct ThrowableProxy until required
198                thrown,
199
200                // needs shallow copy to be fast (LOG4J2-154)
201                ThreadContext.getImmutableStack(), //
202
203                // location (expensive to calculate)
204                calcLocationIfRequested(fqcn), //
205                CLOCK.currentTimeMillis(), //
206                nanoClock.nanoTime() //
207        );
208    }
209
210    private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
211        // constant check should be optimized out when using default (CACHED)
212        if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
213            translator.updateThreadValues();
214        }
215    }
216
217    /**
218     * Returns the caller location if requested, {@code null} otherwise.
219     *
220     * @param fqcn fully qualified caller name.
221     * @return the caller location if requested, {@code null} otherwise.
222     */
223    private StackTraceElement calcLocationIfRequested(final String fqcn) {
224        // location: very expensive operation. LOG4J2-153:
225        // Only include if "includeLocation=true" is specified,
226        // exclude if not specified or if "false" was specified.
227        return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null;
228    }
229
230    /**
231     * Enqueues the specified log event data for logging in a background thread.
232     * <p>
233     * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
234     * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
235     *
236     * @param fqcn fully qualified name of the caller
237     * @param level level at which the caller wants to log the message
238     * @param marker message marker
239     * @param message the log message
240     * @param thrown a {@code Throwable} or {@code null}
241     */
242    private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
243            final Message message, final Throwable thrown) {
244        // Implementation note: candidate for optimization: exceeds 35 bytecodes.
245
246        final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
247        if (disruptor == null) {
248            LOGGER.error("Ignoring log event after Log4j has been shut down.");
249            return;
250        }
251        // if the Message instance is reused, there is no point in freezing its message here
252        if (!isReused(message)) {
253            InternalAsyncUtil.makeMessageImmutable(message);
254        }
255        StackTraceElement location = null;
256        // calls the translateTo method on this AsyncLogger
257        if (!disruptor.getRingBuffer().tryPublishEvent(this,
258                this, // asyncLogger: 0
259                (location = calcLocationIfRequested(fqcn)), // location: 1
260                fqcn, // 2
261                level, // 3
262                marker, // 4
263                message, // 5
264                thrown)) { // 6
265            handleRingBufferFull(location, fqcn, level, marker, message, thrown);
266        }
267    }
268
269    /*
270     * (non-Javadoc)
271     *
272     * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
273     */
274    @Override
275    public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
276        // Implementation note: candidate for optimization: exceeds 35 bytecodes.
277        final AsyncLogger asyncLogger = (AsyncLogger) args[0];
278        final StackTraceElement location = (StackTraceElement) args[1];
279        final String fqcn = (String) args[2];
280        final Level level = (Level) args[3];
281        final Marker marker = (Marker) args[4];
282        final Message message = (Message) args[5];
283        final Throwable thrown = (Throwable) args[6];
284
285        // needs shallow copy to be fast (LOG4J2-154)
286        final ContextStack contextStack = ThreadContext.getImmutableStack();
287
288        final Thread currentThread = Thread.currentThread();
289        final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
290        event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
291                // config properties are taken care of in the EventHandler thread
292                // in the AsyncLogger#actualAsyncLog method
293                CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
294                contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
295                CLOCK.currentTimeMillis(), nanoClock.nanoTime());
296    }
297
298    /**
299     * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
300     * toString() method
301     *
302     * @param fqcn fully qualified caller name
303     * @param level log level
304     * @param marker optional marker
305     * @param message log message
306     * @param thrown optional exception
307     */
308    void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
309            final Message message, final Throwable thrown) {
310        // bypass RingBuffer and invoke Appender directly
311        final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
312        strategy.log(this, getName(), fqcn, marker, level, message, thrown);
313    }
314
315    private void handleRingBufferFull(final StackTraceElement location,
316                                      final String fqcn,
317                                      final Level level,
318                                      final Marker marker,
319                                      final Message msg,
320                                      final Throwable thrown) {
321        if (Logger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
322            // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
323            final Message message = AsyncQueueFullMessageUtil.transform(msg);
324            logMessageInCurrentThread(fqcn, level, marker, message, thrown);
325            return;
326        }
327        final EventRoute eventRoute = loggerDisruptor.getEventRoute(level);
328        switch (eventRoute) {
329            case ENQUEUE:
330                loggerDisruptor.getDisruptor().getRingBuffer().publishEvent(this,
331                        this, // asyncLogger: 0
332                        location, // location: 1
333                        fqcn, // 2
334                        level, // 3
335                        marker, // 4
336                        msg, // 5
337                        thrown); // 6
338                break;
339            case SYNCHRONOUS:
340                logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
341                break;
342            case DISCARD:
343                break;
344            default:
345                throw new IllegalStateException("Unknown EventRoute " + eventRoute);
346        }
347    }
348
349    /**
350     * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
351     * Merges the contents of the configuration map into the contextData, after replacing any variables in the property
352     * values with the StrSubstitutor-supplied actual values.
353     *
354     * @param event the event to log
355     */
356    public void actualAsyncLog(final RingBufferLogEvent event) {
357        final List<Property> properties = privateConfig.loggerConfig.getPropertyList();
358
359        if (properties != null) {
360            StringMap contextData = (StringMap) event.getContextData();
361            if (contextData.isFrozen()) {
362                final StringMap temp = ContextDataFactory.createContextData();
363                temp.putAll(contextData);
364                contextData = temp;
365            }
366            for (int i = 0; i < properties.size(); i++) {
367                final Property prop = properties.get(i);
368                if (contextData.getValue(prop.getName()) != null) {
369                    continue; // contextMap overrides config properties
370                }
371                final String value = prop.isValueNeedsLookup() //
372                        ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) //
373                        : prop.getValue();
374                contextData.putValue(prop.getName(), value);
375            }
376            event.setContextData(contextData);
377        }
378
379        final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
380        strategy.log(this, event);
381    }
382}