View Javadoc
1   /*
2    * Licensed to the Apache Software Foundation (ASF) under one or more
3    * contributor license agreements. See the NOTICE file distributed with
4    * this work for additional information regarding copyright ownership.
5    * The ASF licenses this file to You under the Apache license, Version 2.0
6    * (the "License"); you may not use this file except in compliance with
7    * the License. You may obtain a copy of the License at
8    *
9    *      http://www.apache.org/licenses/LICENSE-2.0
10   *
11   * Unless required by applicable law or agreed to in writing, software
12   * distributed under the License is distributed on an "AS IS" BASIS,
13   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14   * See the license for the specific language governing permissions and
15   * limitations under the license.
16   */
17  package org.apache.logging.log4j.core.async;
18  
19  import java.util.List;
20  
21  import org.apache.logging.log4j.Level;
22  import org.apache.logging.log4j.Marker;
23  import org.apache.logging.log4j.ThreadContext;
24  import org.apache.logging.log4j.ThreadContext.ContextStack;
25  import org.apache.logging.log4j.core.ContextDataInjector;
26  import org.apache.logging.log4j.core.Logger;
27  import org.apache.logging.log4j.core.LoggerContext;
28  import org.apache.logging.log4j.core.config.Configuration;
29  import org.apache.logging.log4j.core.config.LoggerConfig;
30  import org.apache.logging.log4j.core.config.Property;
31  import org.apache.logging.log4j.core.config.ReliabilityStrategy;
32  import org.apache.logging.log4j.core.impl.ContextDataFactory;
33  import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory;
34  import org.apache.logging.log4j.core.util.Clock;
35  import org.apache.logging.log4j.core.util.ClockFactory;
36  import org.apache.logging.log4j.core.util.NanoClock;
37  import org.apache.logging.log4j.message.Message;
38  import org.apache.logging.log4j.message.MessageFactory;
39  import org.apache.logging.log4j.message.ReusableMessage;
40  import org.apache.logging.log4j.spi.AbstractLogger;
41  import org.apache.logging.log4j.status.StatusLogger;
42  import org.apache.logging.log4j.util.StackLocatorUtil;
43  import org.apache.logging.log4j.util.StringMap;
44  
45  import com.lmax.disruptor.EventTranslatorVararg;
46  import com.lmax.disruptor.dsl.Disruptor;
47  
48  /**
49   * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
50   * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
51   * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
52   * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
53   * <p>
54   * To use AsyncLogger, specify the System property
55   * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
56   * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
57   * <p>
58   * Note that for performance reasons, this logger does not include source location by default. You need to specify
59   * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
60   * log4j.xml configuration will produce either a "?" character or no output at all.
61   * <p>
62   * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
63   * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
64   * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
65   * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
66   */
67  public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
68      // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
69      // Specifically, try to keep the hot methods to 35 bytecodes or less:
70      // this is within the MaxInlineSize threshold and makes these methods candidates for
71      // immediate inlining instead of waiting until they are designated "hot enough".
72  
73      private static final StatusLogger LOGGER = StatusLogger.getLogger();
74      private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
75      private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector();
76  
77      private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
78  
79      private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
80      private final AsyncLoggerDisruptor loggerDisruptor;
81  
82      private volatile boolean includeLocation; // reconfigurable
83      private volatile NanoClock nanoClock; // reconfigurable
84  
85      /**
86       * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
87       *
88       * @param context context of this logger
89       * @param name name of this logger
90       * @param messageFactory message factory of this logger
91       * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
92       */
93      public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
94              final AsyncLoggerDisruptor loggerDisruptor) {
95          super(context, name, messageFactory);
96          this.loggerDisruptor = loggerDisruptor;
97          includeLocation = privateConfig.loggerConfig.isIncludeLocation();
98          nanoClock = context.getConfiguration().getNanoClock();
99      }
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             translator.clear();
241             return;
242         }
243         final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
244         switch (eventRoute) {
245             case ENQUEUE:
246                 loggerDisruptor.enqueueLogMessageWhenQueueFull(translator);
247                 break;
248             case SYNCHRONOUS:
249                 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
250                         translator.thrown);
251                 translator.clear();
252                 break;
253             case DISCARD:
254                 translator.clear();
255                 break;
256             default:
257                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
258         }
259     }
260 
261     private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
262         final StackTraceElement location, final Level level, final Marker marker,
263         final Message message, final Throwable thrown) {
264 
265         translator.setBasicValues(this, name, marker, fqcn, level, message, //
266             // don't construct ThrowableProxy until required
267             thrown,
268 
269             // needs shallow copy to be fast (LOG4J2-154)
270             ThreadContext.getImmutableStack(), //
271 
272             location,
273             CLOCK, //
274             nanoClock //
275         );
276     }
277 
278     private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
279             final Level level, final Marker marker, final Message message, final Throwable thrown) {
280 
281         translator.setBasicValues(this, name, marker, fqcn, level, message, //
282                 // don't construct ThrowableProxy until required
283                 thrown,
284 
285                 // needs shallow copy to be fast (LOG4J2-154)
286                 ThreadContext.getImmutableStack(), //
287 
288                 // location (expensive to calculate)
289                 calcLocationIfRequested(fqcn), //
290                 CLOCK, //
291                 nanoClock //
292         );
293     }
294 
295     private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
296         // constant check should be optimized out when using default (CACHED)
297         if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
298             translator.updateThreadValues();
299         }
300     }
301 
302     /**
303      * Returns the caller location if requested, {@code null} otherwise.
304      *
305      * @param fqcn fully qualified caller name.
306      * @return the caller location if requested, {@code null} otherwise.
307      */
308     private StackTraceElement calcLocationIfRequested(final String fqcn) {
309         // location: very expensive operation. LOG4J2-153:
310         // Only include if "includeLocation=true" is specified,
311         // exclude if not specified or if "false" was specified.
312         return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null;
313     }
314 
315     /**
316      * Enqueues the specified log event data for logging in a background thread.
317      * <p>
318      * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
319      * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
320      *
321      * @param fqcn fully qualified name of the caller
322      * @param level level at which the caller wants to log the message
323      * @param marker message marker
324      * @param message the log message
325      * @param thrown a {@code Throwable} or {@code null}
326      */
327     private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
328             final Message message, final Throwable thrown) {
329         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
330 
331         final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
332         if (disruptor == null) {
333             LOGGER.error("Ignoring log event after Log4j has been shut down.");
334             return;
335         }
336         // if the Message instance is reused, there is no point in freezing its message here
337         if (!isReused(message)) {
338             InternalAsyncUtil.makeMessageImmutable(message);
339         }
340         StackTraceElement location = null;
341         // calls the translateTo method on this AsyncLogger
342         if (!disruptor.getRingBuffer().tryPublishEvent(this,
343                 this, // asyncLogger: 0
344                 (location = calcLocationIfRequested(fqcn)), // location: 1
345                 fqcn, // 2
346                 level, // 3
347                 marker, // 4
348                 message, // 5
349                 thrown)) { // 6
350             handleRingBufferFull(location, fqcn, level, marker, message, thrown);
351         }
352     }
353 
354     /**
355      * Enqueues the specified log event data for logging in a background thread.
356      * <p>
357      * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
358      * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
359      *
360      * @param fqcn fully qualified name of the caller
361      * @param location location of the caller.
362      * @param level level at which the caller wants to log the message
363      * @param marker message marker
364      * @param message the log message
365      * @param thrown a {@code Throwable} or {@code null}
366      */
367     private void logWithVarargTranslator(final String fqcn, final StackTraceElement location, final Level level,
368         final Marker marker, final Message message, final Throwable thrown) {
369         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
370 
371         final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
372         if (disruptor == null) {
373             LOGGER.error("Ignoring log event after Log4j has been shut down.");
374             return;
375         }
376         // if the Message instance is reused, there is no point in freezing its message here
377         if (!isReused(message)) {
378             InternalAsyncUtil.makeMessageImmutable(message);
379         }
380         // calls the translateTo method on this AsyncLogger
381         if (!disruptor.getRingBuffer().tryPublishEvent(this,
382             this, // asyncLogger: 0
383             location, // location: 1
384             fqcn, // 2
385             level, // 3
386             marker, // 4
387             message, // 5
388             thrown)) { // 6
389             handleRingBufferFull(location, fqcn, level, marker, message, thrown);
390         }
391     }
392 
393     /*
394      * (non-Javadoc)
395      *
396      * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
397      */
398     @Override
399     public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
400         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
401         final AsyncLogger asyncLogger = (AsyncLogger) args[0];
402         final StackTraceElement location = (StackTraceElement) args[1];
403         final String fqcn = (String) args[2];
404         final Level level = (Level) args[3];
405         final Marker marker = (Marker) args[4];
406         final Message message = (Message) args[5];
407         final Throwable thrown = (Throwable) args[6];
408 
409         // needs shallow copy to be fast (LOG4J2-154)
410         final ContextStack contextStack = ThreadContext.getImmutableStack();
411 
412         final Thread currentThread = Thread.currentThread();
413         final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
414         event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
415                 // config properties are taken care of in the EventHandler thread
416                 // in the AsyncLogger#actualAsyncLog method
417                 CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
418                 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
419                 CLOCK, nanoClock);
420     }
421 
422     /**
423      * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
424      * toString() method
425      *
426      * @param fqcn fully qualified caller name
427      * @param level log level
428      * @param marker optional marker
429      * @param message log message
430      * @param thrown optional exception
431      */
432     void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
433             final Message message, final Throwable thrown) {
434         // bypass RingBuffer and invoke Appender directly
435         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
436         strategy.log(this, getName(), fqcn, marker, level, message, thrown);
437     }
438 
439     private void handleRingBufferFull(final StackTraceElement location,
440                                       final String fqcn,
441                                       final Level level,
442                                       final Marker marker,
443                                       final Message msg,
444                                       final Throwable thrown) {
445         if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
446             // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
447             AsyncQueueFullMessageUtil.logWarningToStatusLogger();
448             logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
449             return;
450         }
451         final EventRoute eventRoute = loggerDisruptor.getEventRoute(level);
452         switch (eventRoute) {
453             case ENQUEUE:
454                 loggerDisruptor.enqueueLogMessageWhenQueueFull(this,
455                         this, // asyncLogger: 0
456                         location, // location: 1
457                         fqcn, // 2
458                         level, // 3
459                         marker, // 4
460                         msg, // 5
461                         thrown); // 6
462                 break;
463             case SYNCHRONOUS:
464                 logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
465                 break;
466             case DISCARD:
467                 break;
468             default:
469                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
470         }
471     }
472 
473     /**
474      * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
475      * Merges the contents of the configuration map into the contextData, after replacing any variables in the property
476      * values with the StrSubstitutor-supplied actual values.
477      *
478      * @param event the event to log
479      */
480     public void actualAsyncLog(final RingBufferLogEvent event) {
481         final LoggerConfig privateConfigLoggerConfig = privateConfig.loggerConfig;
482         final List<Property> properties = privateConfigLoggerConfig.getPropertyList();
483 
484         if (properties != null) {
485             onPropertiesPresent(event, properties);
486         }
487 
488         privateConfigLoggerConfig.getReliabilityStrategy().log(this, event);
489     }
490 
491     @SuppressWarnings("ForLoopReplaceableByForEach") // Avoid iterator allocation
492     private void onPropertiesPresent(final RingBufferLogEvent event, final List<Property> properties) {
493         StringMap contextData = getContextData(event);
494         for (int i = 0, size = properties.size(); i < size; i++) {
495             final Property prop = properties.get(i);
496             if (contextData.getValue(prop.getName()) != null) {
497                 continue; // contextMap overrides config properties
498             }
499             final String value = prop.isValueNeedsLookup() //
500                     ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) //
501                     : prop.getValue();
502             contextData.putValue(prop.getName(), value);
503         }
504         event.setContextData(contextData);
505     }
506 
507     private static StringMap getContextData(final RingBufferLogEvent event) {
508         StringMap contextData = (StringMap) event.getContextData();
509         if (contextData.isFrozen()) {
510             final StringMap temp = ContextDataFactory.createContextData();
511             temp.putAll(contextData);
512             return temp;
513         }
514         return contextData;
515     }
516 }