Apache
/
lucene
mirror of https://github.com/apache/lucene.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

SOLR-12055: Enable async logging by default - rollback

This commit is contained in:
Erick Erickson 2018-09-07 22:51:50 -07:00
parent 8f498920bd
commit 3b62f23f72
6 changed files with 70 additions and 99 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
solr/CHANGES.txt
View File

@ -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
----------------------

12
solr/core/src/test-files/log4j2.xml
View File

@ -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>

27
solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java
View File

@ -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"));

83
solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
View File

@ -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);
LogWatcher watcher = LogWatcher.newRegisteredLogWatcher(config, null);
// First ensure there's nothing in the new watcher.
assertEquals(watcher.getLastEvent(), -1);
// 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);
}
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.
if (looper(watcher, msg) == false) {
fail("Should have found message " + msg + ". In loop: " + idx);
}
}
}
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");
}
}

8
solr/server/resources/log4j2-console.xml
View File

@ -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>

30
solr/server/resources/log4j2.xml
View File

@ -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>