Issue #1550: remove multiple isFiltered invocations

Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.

log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java

@@ -20,23 +20,36 @@
 import java.io.File;
 import java.io.FileReader;
 
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.Appender;
+import org.apache.logging.log4j.core.Filter;
 import org.apache.logging.log4j.core.config.AppenderRef;
+import org.apache.logging.log4j.core.config.Configuration;
 import org.apache.logging.log4j.core.config.ConfigurationFactory;
 import org.apache.logging.log4j.core.config.DefaultConfiguration;
 import org.apache.logging.log4j.core.config.LoggerConfig;
+import org.apache.logging.log4j.core.config.NullConfiguration;
 import org.apache.logging.log4j.core.test.CoreLoggerContexts;
 import org.apache.logging.log4j.core.test.categories.AsyncLoggers;
+import org.apache.logging.log4j.message.SimpleMessage;
 import org.junit.BeforeClass;
 import org.junit.Test;
 import org.junit.experimental.categories.Category;
 
 import static org.junit.Assert.*;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
 
 @Category(AsyncLoggers.class)
 public class AsyncLoggerConfigTest {
 
+ private static final String FQCN = AsyncLoggerConfigTest.class.getName();
+
  @BeforeClass
  public static void beforeClass() {
  System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, "AsyncLoggerConfigTest.xml");
@@ -81,4 +94,29 @@ public void testIncludeLocationDefaultsToFalse() {
  assertFalse("Include location should default to false for async loggers",
  loggerConfig.isIncludeLocation());
  }
+
+ @Test
+ public void testSingleFilterInvocation() {
+ final Configuration configuration = new NullConfiguration();
+ final Filter filter = mock(Filter.class);
+ final LoggerConfig config = AsyncLoggerConfig.newAsyncBuilder()
+ .withLoggerName(FQCN)
+ .withConfig(configuration)
+ .withLevel(Level.INFO)
+ .withtFilter(filter)
+ .build();
+ final Appender appender = mock(Appender.class);
+ when(appender.isStarted()).thenReturn(true);
+ when(appender.getName()).thenReturn("test");
+ config.addAppender(appender, null, null);
+ final AsyncLoggerConfigDisruptor disruptor = (AsyncLoggerConfigDisruptor) configuration.getAsyncLoggerConfigDelegate();
+ disruptor.start();
+ try {
+ config.log(FQCN, FQCN, null, Level.INFO, new SimpleMessage(), null);
+ verify(appender, times(1)).append(any());
+ verify(filter, times(1)).filter(any());
+ } finally {
+ disruptor.stop();
+ }
+ }
 }

log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/LoggerConfigTest.java

@@ -21,17 +21,29 @@
 import java.util.concurrent.atomic.AtomicReference;
 
 import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.Appender;
+import org.apache.logging.log4j.core.Filter;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent.Builder;
 import org.apache.logging.log4j.message.SimpleMessage;
 import org.junit.jupiter.api.Test;
 
-import static org.junit.jupiter.api.Assertions.*;
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertNotSame;
+import static org.junit.jupiter.api.Assertions.assertNull;
+import static org.junit.jupiter.api.Assertions.assertSame;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
 
 /**
  * Tests for LoggerConfig.
  */
 public class LoggerConfigTest {
 
+ private static final String FQCN = LoggerConfigTest.class.getName();
+
  private static LoggerConfig createForProperties(final Property[] properties) {
  return LoggerConfig.createLogger(true, Level.INFO, "name", "false", new AppenderRef[0], properties,
  new NullConfiguration(), null);
@@ -109,4 +121,24 @@ public void testLevel() {
  assertEquals(config2.getLevel(), Level.ERROR, "Unexpected Level");
  assertNull(config2.getExplicitLevel(),"Unexpected explicit level");
  }
+
+ @Test
+ public void testSingleFilterInvocation() {
+ final Configuration configuration = new NullConfiguration();
+ final Filter filter = mock(Filter.class);
+ final LoggerConfig config = LoggerConfig.newBuilder()
+ .withLoggerName(FQCN)
+ .withConfig(configuration)
+ .withLevel(Level.INFO)
+ .withtFilter(filter)
+ .build();
+ final Appender appender = mock(Appender.class);
+ when(appender.isStarted()).thenReturn(true);
+ when(appender.getName()).thenReturn("test");
+ config.addAppender(appender, null, null);
+
+ config.log(FQCN, FQCN, null, Level.INFO, new SimpleMessage(), null);
+ verify(appender, times(1)).append(any());
+ verify(filter, times(1)).filter(any());
+ }
 }

log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java

@@ -126,15 +126,17 @@ protected void log(final LogEvent event, final LoggerConfigPredicate predicate)
  // This is the first AsnycLoggerConfig encountered by this LogEvent
  ASYNC_LOGGER_ENTERED.set(Boolean.TRUE);
  try {
- // Detect the first time we encounter an AsyncLoggerConfig. We must log
- // to all non-async loggers first.
- super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
- // Then pass the event to the background thread where
- // all async logging is executed. It is important this
- // happens at most once and after all synchronous loggers
- // have been invoked, because we lose parameter references
- // from reusable messages.
- logToAsyncDelegate(event);
+ if (!isFiltered(event)) {
+ // Detect the first time we encounter an AsyncLoggerConfig. We must log
+ // to all non-async loggers first.
+ processLogEvent(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
+ // Then pass the event to the background thread where
+ // all async logging is executed. It is important this
+ // happens at most once and after all synchronous loggers
+ // have been invoked, because we lose parameter references
+ // from reusable messages.
+ logToAsyncDelegate(event);
+ }
  } finally {
  ASYNC_LOGGER_ENTERED.set(Boolean.FALSE);
  }
@@ -149,13 +151,11 @@ protected void callAppenders(final LogEvent event) {
  }
 
  private void logToAsyncDelegate(final LogEvent event) {
- if (!isFiltered(event)) {
- // Passes on the event to a separate thread that will call
- // asyncCallAppenders(LogEvent).
- populateLazilyInitializedFields(event);
- if (!delegate.tryEnqueue(event, this)) {
- handleQueueFull(event);
- }
+ // Passes on the event to a separate thread that will call
+ // asyncCallAppenders(LogEvent).
+ populateLazilyInitializedFields(event);
+ if (!delegate.tryEnqueue(event, this)) {
+ handleQueueFull(event);
  }
  }
 
@@ -187,7 +187,8 @@ void logInBackgroundThread(final LogEvent event) {
  * default {@link LoggerConfig} definitions), which will be invoked on the <b>calling thread</b>.
  */
  void logToAsyncLoggerConfigsOnCurrentThread(final LogEvent event) {
- log(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY);
+ // skip the filter, which was already called on the logging thread
+ processLogEvent(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY);
  }
 
  private String displayName() {

log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java

@@ -611,9 +611,9 @@ public void log(final LogEvent event) {
  /**
  * Logs an event.
  *
- * @param event The log event.
- * @param predicate predicate for which LoggerConfig instances to append to.
- * A null value is equivalent to a true predicate.
+ * @param event  The log event.
+ * @param predicate predicate for which LoggerConfig instances to append to. A
+ * {@literal null} value is equivalent to a true predicate.
  */
  protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
  if (!isFiltered(event)) {
@@ -631,9 +631,16 @@ public ReliabilityStrategy getReliabilityStrategy() {
  return reliabilityStrategy;
  }
 
- private void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) {
+ /**
+ * Logs an event, bypassing filters.
+ *
+ * @param event The log event.
+ * @param predicate predicate for which LoggerConfig instances to append to. A
+ * {@literal null} value is equivalent to a true predicate.
+ */
+ protected void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) {
  event.setIncludeLocation(isIncludeLocation());
- if (predicate.allow(this)) {
+ if (predicate == null || predicate.allow(this)) {
  callAppenders(event);
  }
  logParent(event, predicate);

src/changelog/.2.x.x/1550_multiple_filter_invocations.xml

@@ -0,0 +1,25 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+ ~ Licensed to the Apache Software Foundation (ASF) under one or more
+ ~ contributor license agreements. See the NOTICE file distributed with
+ ~ this work for additional information regarding copyright ownership.
+ ~ The ASF licenses this file to you under the Apache License, Version 2.0
+ ~ (the "License"); you may not use this file except in compliance with
+ ~ the License. You may obtain a copy of the License at
+ ~
+ ~ http://www.apache.org/licenses/LICENSE-2.0
+ ~
+ ~ Unless required by applicable law or agreed to in writing, software
+ ~ distributed under the License is distributed on an "AS IS" BASIS,
+ ~ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ ~ See the License for the specific language governing permissions and
+ ~ limitations under the License.
+ -->
+<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+ xmlns="http://logging.apache.org/log4j/changelog"
+ xsi:schemaLocation="http://logging.apache.org/log4j/changelog https://logging.apache.org/log4j/changelog-0.1.1.xsd"
+ type="changed">
+ <issue id="1550" link="https://github.com/apache/logging-log4j2/pull/1550"/>
+ <author id="github:ppkarwasz"/>
+ <description format="asciidoc">Removes additional `isFiltered` checks in `AsyncLoggerConfig`.</description>
+</entry>