You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@lucene.apache.org by er...@apache.org on 2018/09/08 05:51:55 UTC
lucene-solr:master: SOLR-12055: Enable async logging by default -
rollback
Repository: lucene-solr
Updated Branches:
refs/heads/master 8f498920b -> 3b62f23f7
SOLR-12055: Enable async logging by default - rollback
Project: http://git-wip-us.apache.org/repos/asf/lucene-solr/repo
Commit: http://git-wip-us.apache.org/repos/asf/lucene-solr/commit/3b62f23f
Tree: http://git-wip-us.apache.org/repos/asf/lucene-solr/tree/3b62f23f
Diff: http://git-wip-us.apache.org/repos/asf/lucene-solr/diff/3b62f23f
Branch: refs/heads/master
Commit: 3b62f23f72ed826d363b81826be9caf0a2edbd1b
Parents: 8f49892
Author: Erick Erickson <Er...@gmail.com>
Authored: Fri Sep 7 22:51:50 2018 -0700
Committer: Erick Erickson <Er...@gmail.com>
Committed: Fri Sep 7 22:51:50 2018 -0700
----------------------------------------------------------------------
solr/CHANGES.txt | 9 --
solr/core/src/test-files/log4j2.xml | 12 +--
.../apache/solr/handler/RequestLoggingTest.java | 27 ++----
.../org/apache/solr/logging/TestLogWatcher.java | 91 +++++++++-----------
solr/server/resources/log4j2-console.xml | 8 +-
solr/server/resources/log4j2.xml | 30 +++----
6 files changed, 74 insertions(+), 103 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/CHANGES.txt
----------------------------------------------------------------------
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index 7d30c0c..797acfc 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -100,11 +100,6 @@ Upgrade Notes
WINDOWS USERS: This JIRA corrects a bug in the start scripts that put example logs under ...\server, solr.log is
now under ...\example. (Erick Erickson)
-* 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
----------------------
@@ -322,12 +317,8 @@ Bug Fixes
* SOLR-12704: Guard AddSchemaFieldsUpdateProcessorFactory against null field names and field values.
(Steve Rowe, Varun Thacker)
-* SOLR-12728: RequestLoggingTest fails on occasion, not reproducible (Erick Erickson)
-
* SOLR-12733: SolrMetricReporterTest failure (Erick Erickson, David Smiley)
-* SOLR-12732: TestLogWatcher failure on Jenkins (Erick Erickson)
-
Optimizations
----------------------
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/core/src/test-files/log4j2.xml
----------------------------------------------------------------------
diff --git a/solr/core/src/test-files/log4j2.xml b/solr/core/src/test-files/log4j2.xml
index 5447843..7d0ebf7 100644
--- a/solr/core/src/test-files/log4j2.xml
+++ b/solr/core/src/test-files/log4j2.xml
@@ -27,13 +27,13 @@
</Console>
</Appenders>
<Loggers>
- <AsyncLogger name="org.apache.zookeeper" level="WARN"/>
- <AsyncLogger name="org.apache.hadoop" level="WARN"/>
- <AsyncLogger name="org.apache.directory" level="WARN"/>
- <AsyncLogger name="org.apache.solr.hadoop" level="INFO"/>
+ <Logger name="org.apache.zookeeper" level="WARN"/>
+ <Logger name="org.apache.hadoop" level="WARN"/>
+ <Logger name="org.apache.directory" level="WARN"/>
+ <Logger name="org.apache.solr.hadoop" level="INFO"/>
- <AsyncRoot level="INFO">
+ <Root level="INFO">
<AppenderRef ref="STDERR"/>
- </AsyncRoot>
+ </Root>
</Loggers>
</Configuration>
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java
----------------------------------------------------------------------
diff --git a/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java b/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java
index ae08e9a..e203e80 100644
--- a/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java
+++ b/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java
@@ -48,15 +48,17 @@ 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(
PatternLayout
.newBuilder()
.withPattern("%-5p [%t]: %m%n")
- .build(),
+ .build(),
null, writer, "RequestLoggingTest", false, true);
appender.start();
+
}
@Test
@@ -73,7 +75,7 @@ public class RequestLoggingTest extends SolrTestCaseJ4 {
public void testLogBeforeExecute(Logger logger) {
Level level = logger.getLevel();
-
+
LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
LoggerConfig config = ctx.getConfiguration().getLoggerConfig(logger.getName());
config.setLevel(Level.DEBUG);
@@ -82,23 +84,10 @@ public class RequestLoggingTest extends SolrTestCaseJ4 {
try {
assertQ(req("q", "*:*"));
- Matcher matcher = null;
- boolean foundDebugMsg = false;
- String output = "";
- for (int msgIdx = 0; msgIdx < 100; ++msgIdx) {
- output = writer.toString();
- matcher = Pattern.compile("DEBUG.*q=\\*:\\*.*").matcher(output);
- if (matcher.find()) {
- foundDebugMsg = true;
- break;
- }
- try {
- Thread.sleep(10);
- } catch (InterruptedException ie) {
- ;
- }
- }
- assertTrue("Should have found debug-level message. Found " + output, foundDebugMsg);
+
+ String output = writer.toString();
+ Matcher matcher = Pattern.compile("DEBUG.*q=\\*:\\*.*").matcher(output);
+ assertTrue(matcher.find());
final String group = matcher.group();
final String msg = "Should not have post query information";
assertFalse(msg, group.contains("hits"));
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
----------------------------------------------------------------------
diff --git a/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java b/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
index a93a11b..6f7987f 100644
--- a/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
+++ b/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
@@ -16,7 +16,6 @@
*/
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;
@@ -27,63 +26,55 @@ import org.slf4j.LoggerFactory;
import java.lang.invoke.MethodHandles;
import java.util.concurrent.atomic.AtomicBoolean;
-public class TestLogWatcher extends SolrTestCaseJ4 {
+import static org.junit.Assert.assertEquals;
+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 before() {
- config = new LogWatcherConfig(true, null, "INFO", 1);
+ public void setUp() {
+ config = new LogWatcherConfig(true, null, null, 50);
}
- // Create several log watchers and ensure that new messages go to the new watcher.
@Test
public void testLog4jWatcher() {
- LogWatcher watcher;
- 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);
-
- // First ensure there's nothing in the new watcher.
-
- // Every time you put a message in the queue, you wait for it to come out _before_ creating
- // a new watcher so it should be fine.
- if (looper(watcher, null) == false) {
- fail("There should be no messages when a new watcher finally gets registered! In loop: " + idx);
- }
-
- // Now log a message and ensure that the new watcher sees it.
- log.warn(msg);
-
- // Loop to give the logger time to process the async message and notify the new watcher.
- if (looper(watcher, msg) == false) {
- fail("Should have found message " + msg + ". In loop: " + idx);
- }
- }
+ 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");
+
}
- private boolean looper(LogWatcher watcher, String msg) {
- // In local testing this loop usually succeeds 1-2 tries.
- boolean success = false;
- boolean testingNew = msg == null;
- for (int msgIdx = 0; msgIdx < 100 && success == false; ++msgIdx) {
- if (testingNew) { // check that there are no entries registered for the watcher
- success = watcher.getLastEvent() == -1;
- } else { // check that the expected message is there.
- // 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)) {
- success = true;
- }
- }
- }
- try {
- Thread.sleep(10);
- } catch (InterruptedException ie) {
- ;
- }
- }
- return success;
+
+ // 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");
+
}
+
}
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/server/resources/log4j2-console.xml
----------------------------------------------------------------------
diff --git a/solr/server/resources/log4j2-console.xml b/solr/server/resources/log4j2-console.xml
index 698227b..f32f4c1 100644
--- a/solr/server/resources/log4j2-console.xml
+++ b/solr/server/resources/log4j2-console.xml
@@ -29,11 +29,11 @@
</Console>
</Appenders>
<Loggers>
- <AsyncLogger name="org.apache.zookeeper" level="WARN"/>
- <AsyncLogger name="org.apache.hadoop" level="WARN"/>
+ <Logger name="org.apache.zookeeper" level="WARN"/>
+ <Logger name="org.apache.hadoop" level="WARN"/>
- <AsyncRoot level="INFO">
+ <Root level="INFO">
<AppenderRef ref="STDERR"/>
- </AsyncRoot>
+ </Root>
</Loggers>
</Configuration>
http://git-wip-us.apache.org/repos/asf/lucene-solr/blob/3b62f23f/solr/server/resources/log4j2.xml
----------------------------------------------------------------------
diff --git a/solr/server/resources/log4j2.xml b/solr/server/resources/log4j2.xml
index d9c05d8..17bcf4c 100644
--- a/solr/server/resources/log4j2.xml
+++ b/solr/server/resources/log4j2.xml
@@ -27,8 +27,8 @@
</PatternLayout>
</Console>
- <RollingRandomAccessFile
- name="MainLogFile"
+ <RollingFile
+ name="RollingFile"
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"/>
- </RollingRandomAccessFile>
+ </RollingFile>
- <RollingRandomAccessFile
- name="SlowLogFile"
+ <RollingFile
+ name="SlowFile"
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"/>
- </RollingRandomAccessFile>
+ </RollingFile>
</Appenders>
<Loggers>
- <AsyncLogger name="org.apache.hadoop" level="warn"/>
- <AsyncLogger name="org.apache.solr.update.LoggingInfoStream" level="off"/>
- <AsyncLogger name="org.apache.zookeeper" level="warn"/>
- <AsyncLogger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
- <AppenderRef ref="SlowLogFile"/>
- </AsyncLogger>
+ <Logger name="org.apache.hadoop" level="warn"/>
+ <Logger name="org.apache.solr.update.LoggingInfoStream" level="off"/>
+ <Logger name="org.apache.zookeeper" level="warn"/>
+ <Logger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
+ <AppenderRef ref="SlowFile"/>
+ </Logger>
- <AsyncRoot level="info">
- <AppenderRef ref="MainLogFile"/>
+ <Root level="info">
+ <AppenderRef ref="RollingFile"/>
<AppenderRef ref="STDOUT"/>
- </AsyncRoot>
+ </Root>
</Loggers>
</Configuration>