[lucene-solr] branch branch_8x updated: SOLR-12732: TestLogWatcher failure on Jenkins. Deal with superclass logging bleeding into first watcher in the test

[er...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

erick pushed a commit to branch branch_8x
in repository https://gitbox.apache.org/repos/asf/lucene-solr.git


The following commit(s) were added to refs/heads/branch_8x by this push:
     new 6f6fbf0  SOLR-12732: TestLogWatcher failure on Jenkins. Deal with superclass logging bleeding into first watcher in the test
6f6fbf0 is described below

commit 6f6fbf0be2eea8373051a76bcdebf3c5019e5d6c
Author: Erick Erickson <Er...@gmail.com>
AuthorDate: Mon Mar 11 13:00:26 2019 -0700

    SOLR-12732: TestLogWatcher failure on Jenkins. Deal with superclass logging bleeding into first watcher in the test
---
 .../org/apache/solr/logging/TestLogWatcher.java    | 63 +++++++++++++---------
 1 file changed, 39 insertions(+), 24 deletions(-)

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 cd3b180..2caf3e0 100644
--- a/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
+++ b/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java
@@ -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);
     }
   }
 }