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

SOLR-12732: TestLogWatcher failure on Jenkins. Deal with superclass logging bleeding into first watcher in the test

This commit is contained in:
Erick Erickson 2019-03-11 12:55:08 -07:00
parent 3a1603dab3
commit 28c8171fe6
1 changed files with 39 additions and 24 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -27,8 +27,9 @@ import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.lang.invoke.MethodHandles;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
public class TestLogWatcher extends SolrTestCaseJ4 {
private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
@ -40,50 +41,64 @@ public class TestLogWatcher extends SolrTestCaseJ4 {
}
// Create several log watchers and ensure that new messages go to the new watcher.
// NOTE: Since the superclass logs messages, it's possible that there are one or more
// messages in the queue at the start, especially with asynch logging.
// All we really care about is that new watchers get the new messages, so test for that
// explicitly. See SOLR-12732.
@Test
public void testLog4jWatcher() throws InterruptedException {
LogWatcher watcher = null;
int lim = random().nextInt(3) + 2;
// Every time through this loop, insure that, of all the test messages that have been logged, only the current
// test message is present. NOTE: there may be log messages from the superclass the first time around.
List<String> oldMessages = new ArrayList<>(lim);
for (int idx = 0; idx < lim; ++idx) {
watcher = LogWatcher.newRegisteredLogWatcher(config, null);
// First ensure there's nothing in the new watcher.
long lastEvent = watcher.getLastEvent();
if (lastEvent != -1L) { // Dump some information to try to understand failure.
AtomicBoolean ab = new AtomicBoolean();
SolrDocumentList events = watcher.getHistory(-1, ab);
System.out.println("Found value is: " + ab.toString());
System.out.println("Dumping all events in this watcher:");
for (SolrDocument doc : events) {
System.out.println(" Event:'" + doc.toString() +"'");
}
fail("lastEvent was not -1, was: '" + lastEvent + "'");
}
// Now log a message and ensure that the new watcher sees it.
String msg = "This is a test message: " + idx;
log.warn(msg);
// Loop to give the logger time to process the async message and notify the new watcher.
TimeOut timeOut = new TimeOut(10, TimeUnit.SECONDS, TimeSource.NANO_TIME);
boolean foundMsg = false;
// In local testing this loop usually succeeds 1-2 tries.
boolean foundNewMsg = false;
boolean foundOldMessage = false;
// In local testing this loop usually succeeds 1-2 tries, so it's not very expensive to loop.
do {
// Returns an empty (but non-null) list even if there are no messages yet.
SolrDocumentList events = watcher.getHistory(-1, null);
for (SolrDocument doc : events) {
if (doc.get("message").equals(msg)) {
foundMsg = true;
break;
String oneMsg = (String) doc.get("message");
if (oneMsg.equals(msg)) {
foundNewMsg = true;
}
// Check that no old messages bled over into this watcher.
for (String oldMsg : oldMessages) {
if (oneMsg.equals(oldMsg)) {
foundOldMessage = true;
}
}
}
Thread.sleep(10);
} while (foundMsg == false && timeOut.hasTimedOut() == false);
if (foundNewMsg == false) {
Thread.sleep(10);
}
} while (foundNewMsg == false && timeOut.hasTimedOut() == false);
assertTrue("Should have found message " + msg + " in loop: " + idx, foundMsg);
if (foundNewMsg == false || foundOldMessage) {
System.out.println("Dumping all events in failed watcher:");
SolrDocumentList events = watcher.getHistory(-1, null);
for (SolrDocument doc : events) {
System.out.println(" Event:'" + doc.toString() + "'");
}
System.out.println("Recorded old messages");
for (String oldMsg : oldMessages) {
System.out.println(" " + oldMsg);
}
fail("Did not find expected message state, dumped current watcher's messages above, last message added: '" + msg + "'");
}
oldMessages.add(msg);
}
}
}