SOLR-12055: Enable async logging by default

solr/CHANGES.txt

@@ -52,6 +52,12 @@ Upgrade Notes
   expanded from before to subsume those patterns previously handled by the "extract" contrib (Solr Cell / Tika).
   (David Smiley, Bar Rotstein)
 
+* SOLR-12055: Enable async logging by default. This change improves throughput for logging. This opens
+  up a small window where log messages could possibly be lost. If this is unacceptable, switching back to synchronous
+  logging can be done by changing the log4j2.xml files, no internal Solr code changed to make async logging the default.
+  (Erick Erickson)
+
+
 New Features
 ----------------------
 

solr/core/src/test-files/log4j2.xml

@@ -27,13 +27,13 @@
     </Console>
   </Appenders>
   <Loggers>
-    <Logger name="org.apache.zookeeper" level="WARN"/>
+    <AsyncLogger name="org.apache.zookeeper" level="WARN"/>
-    <Logger name="org.apache.hadoop" level="WARN"/>
+    <AsyncLogger name="org.apache.hadoop" level="WARN"/>
-    <Logger name="org.apache.directory" level="WARN"/>
+    <AsyncLogger name="org.apache.directory" level="WARN"/>
-    <Logger name="org.apache.solr.hadoop" level="INFO"/>
+    <AsyncLogger name="org.apache.solr.hadoop" level="INFO"/>
 
-    <Root level="INFO">
+    <AsyncRoot level="INFO">
       <AppenderRef ref="STDERR"/>
-    </Root>
+    </AsyncRoot>
   </Loggers>
 </Configuration>

solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java

@@ -48,7 +48,6 @@ public class RequestLoggingTest extends SolrTestCaseJ4 {
   @Before
   public void setupAppender() {
     LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
-    LoggerConfig config = ctx.getConfiguration().getLoggerConfig("RequestLoggingTest");
 
     writer = new StringWriter();
     appender = WriterAppender.createAppender(
@@ -58,7 +57,6 @@ public class RequestLoggingTest extends SolrTestCaseJ4 {
         .build(), 
         null, writer, "RequestLoggingTest", false, true);
     appender.start();
-    
   }
 
   @Test

solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java

@@ -16,6 +16,7 @@
  */
 package org.apache.solr.logging;
 
+import org.apache.solr.SolrTestCaseJ4;
 import org.apache.solr.common.SolrDocument;
 import org.apache.solr.common.SolrDocumentList;
 import org.junit.Before;
@@ -26,55 +27,50 @@ import org.slf4j.LoggerFactory;
 import java.lang.invoke.MethodHandles;
 import java.util.concurrent.atomic.AtomicBoolean;
 
-import static org.junit.Assert.assertEquals;
+public class TestLogWatcher extends SolrTestCaseJ4 {
-import static org.junit.Assert.assertTrue;
-
-public class TestLogWatcher {
   private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
   private LogWatcherConfig config;
 
   @Before
-  public void setUp() {
+  public void before() {
-    config = new LogWatcherConfig(true, null, null, 50);
+    config = new LogWatcherConfig(true, null, "INFO", 1);
   }
 
+  // Create several log watchers and ensure that new messages go to the new watcher.
   @Test
   public void testLog4jWatcher() {
-    LogWatcher watcher = LogWatcher.newRegisteredLogWatcher(config, null);
+    LogWatcher watcher = null;
+    int lim = random().nextInt(3) + 2;
+    for (int idx = 0; idx < lim; ++idx) {
+      String msg = "This is a test message: " + idx;
+      watcher = LogWatcher.newRegisteredLogWatcher(config, null);
 
-    assertEquals(watcher.getLastEvent(), -1);
+      // First ensure there's nothing in the new watcher.
+      assertEquals(-1, watcher.getLastEvent());
 
-    log.warn("This is a test message");
+      // Now log a message and ensure that the new watcher sees it.
-
+      log.warn(msg);
-    assertTrue(watcher.getLastEvent() > -1);
-
-    SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean());
-    assertEquals(events.size(), 1);
-
-    SolrDocument event = events.get(0);
-    assertEquals(event.get("logger"), "org.apache.solr.logging.TestLogWatcher");
-    assertEquals(event.get("message"), "This is a test message");
 
+      // Loop to give the logger time to process the async message and notify the new watcher.
+      boolean foundMsg = false;
+      long last = -1;
+      // In local testing this loop usually succeeds 1-2 tries.
+      for (int msgIdx = 0; msgIdx < 100; ++msgIdx) {
+        // Returns an empty (but non-null) list even if there are no messages yet.
+        SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean());
+        for (SolrDocument doc : events) {
+          if (doc.get("message").equals(msg)) {
+            foundMsg = true;
+            break;
+          }
+        }
+        try {
+          Thread.sleep(10);
+        } catch (InterruptedException ie) {
+          ;
+        }
+      }
+      assertTrue("Should have found message " + msg + " in loop: " + idx, foundMsg);
+    }
   }
-
-  // This seems weird to do the same thing twice, this is valid. We need to test whether listeners are replaced....
-  @Test
-  public void testLog4jWatcherRepeat() {
-    LogWatcher watcher = LogWatcher.newRegisteredLogWatcher(config, null);
-
-    assertEquals(watcher.getLastEvent(), -1);
-
-    log.warn("This is a test message");
-
-    assertTrue(watcher.getLastEvent() > -1);
-
-    SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean());
-    assertEquals(events.size(), 1);
-
-    SolrDocument event = events.get(0);
-    assertEquals(event.get("logger"), "org.apache.solr.logging.TestLogWatcher");
-    assertEquals(event.get("message"), "This is a test message");
-
-  }
-
 }

solr/server/resources/log4j2-console.xml

@@ -29,11 +29,11 @@
     </Console>
   </Appenders>
   <Loggers>
-    <Logger name="org.apache.zookeeper" level="WARN"/>
+    <AsyncLogger name="org.apache.zookeeper" level="WARN"/>
-    <Logger name="org.apache.hadoop" level="WARN"/>
+    <AsyncLogger name="org.apache.hadoop" level="WARN"/>
 
-    <Root level="INFO">
+    <AsyncRoot level="INFO">
       <AppenderRef ref="STDERR"/>
-    </Root>
+    </AsyncRoot>
   </Loggers>
 </Configuration>

solr/server/resources/log4j2.xml

@@ -27,8 +27,8 @@
       </PatternLayout>
     </Console>
 
-    <RollingFile
+    <RollingRandomAccessFile
-        name="RollingFile"
+        name="MainLogFile"
         fileName="${sys:solr.log.dir}/solr.log"
         filePattern="${sys:solr.log.dir}/solr.log.%i" >
       <PatternLayout>
@@ -41,10 +41,10 @@
         <SizeBasedTriggeringPolicy size="32 MB"/>
       </Policies>
       <DefaultRolloverStrategy max="10"/>
-    </RollingFile>
+    </RollingRandomAccessFile>
 
-    <RollingFile
+    <RollingRandomAccessFile
-        name="SlowFile"
+        name="SlowLogFile"
         fileName="${sys:solr.log.dir}/solr_slow_requests.log"
         filePattern="${sys:solr.log.dir}/solr_slow_requests.log.%i" >
       <PatternLayout>
@@ -57,20 +57,20 @@
         <SizeBasedTriggeringPolicy size="32 MB"/>
       </Policies>
       <DefaultRolloverStrategy max="10"/>
-    </RollingFile>
+    </RollingRandomAccessFile>
 
   </Appenders>
   <Loggers>
-    <Logger name="org.apache.hadoop" level="warn"/>
+    <AsyncLogger name="org.apache.hadoop" level="warn"/>
-    <Logger name="org.apache.solr.update.LoggingInfoStream" level="off"/>
+    <AsyncLogger name="org.apache.solr.update.LoggingInfoStream" level="off"/>
-    <Logger name="org.apache.zookeeper" level="warn"/>
+    <AsyncLogger name="org.apache.zookeeper" level="warn"/>
-    <Logger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
+    <AsyncLogger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
-      <AppenderRef ref="SlowFile"/>
+      <AppenderRef ref="SlowLogFile"/>
-    </Logger>
+    </AsyncLogger>
 
-    <Root level="info">
+    <AsyncRoot level="info">
-      <AppenderRef ref="RollingFile"/>
+      <AppenderRef ref="MainLogFile"/>
       <AppenderRef ref="STDOUT"/>
-    </Root>
+    </AsyncRoot>
   </Loggers>
 </Configuration>