Issue apache#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>