testComplianceEnable supports variable number of audit messages (#1920)

peternied · github-actions[bot] · commit 8ae263e0cffc · 2022-06-29T19:22:05.000Z
We were seeing test failures where on higher end computers there would be duplicate audit messages for the index mapping creation. Then when run inside GitHub Actions there would only be 2 messages. This doesn't look like an overt product issue, overlogging of requests, but the test case was not handling it well. Also improved the failure message response for faster future debugging. Signed-off-by: Peter Nied <petern@amazon.com> (cherry picked from commit 1904db5)
diff --git a/src/test/java/org/opensearch/security/auditlog/compliance/ComplianceAuditlogTest.java b/src/test/java/org/opensearch/security/auditlog/compliance/ComplianceAuditlogTest.java
@@ -14,6 +14,7 @@
 import java.io.IOException;
 import java.util.Collections;
 import java.util.List;
+import java.util.stream.Collectors;
 
 import com.google.common.collect.ImmutableMap;
 import org.apache.http.Header;
@@ -32,6 +33,7 @@
 import org.opensearch.security.auditlog.AbstractAuditlogiUnitTest;
 import org.opensearch.security.auditlog.AuditTestUtils;
 import org.opensearch.security.auditlog.config.AuditConfig;
+import org.opensearch.security.auditlog.impl.AuditCategory;
 import org.opensearch.security.auditlog.impl.AuditMessage;
 import org.opensearch.security.auditlog.integration.TestAuditlogImpl;
 import org.opensearch.security.auditlog.integration.TestAuditlogImpl.MessagesNotFoundException;
@@ -41,9 +43,9 @@
 import org.opensearch.security.test.helper.rest.RestHelper.HttpResponse;
 
 import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.core.AnyOf.anyOf;
 import static org.hamcrest.core.IsEqual.equalTo;
 import static org.junit.Assert.assertThrows;
-import static org.junit.Assert.assertTrue;
 
 public class ComplianceAuditlogTest extends AbstractAuditlogiUnitTest {
 
@@ -111,10 +113,27 @@ public void testComplianceEnable() throws Exception {
         updateAuditConfig(AuditTestUtils.createAuditPayload(auditConfig));
 
         // make an event happen
-        TestAuditlogImpl.doThenWaitForMessages(() -> {
-            rh.executePutRequest("emp/_doc/0?refresh", "{\"Designation\" : \"CEO\", \"Gender\" : \"female\", \"Salary\" : 100}");
-        }, 7);
-        assertTrue(TestAuditlogImpl.messages.toString().contains("COMPLIANCE_DOC_WRITE"));
+        List<AuditMessage> messages;
+        try {
+            messages = TestAuditlogImpl.doThenWaitForMessages(() -> {
+                rh.executePutRequest("emp/_doc/0?refresh", "{\"Designation\" : \"CEO\", \"Gender\" : \"female\", \"Salary\" : 100}");
+                System.out.println(rh.executeGetRequest("_cat/shards?v"));
+            }, 7);
+        }  catch (final MessagesNotFoundException ex) {
+            // indices:admin/mapping/auto_put can be logged twice, this handles if they were not found
+            assertThat("Too many missing audit log messages", ex.getMissingCount(), equalTo(2));
+            messages = ex.getFoundMessages();
+        }
+
+        messages.stream().filter(msg -> msg.getCategory().equals(AuditCategory.COMPLIANCE_DOC_WRITE))
+            .findFirst().orElseThrow(() -> new RuntimeException("Missing COMPLIANCE message"));
+
+        final List<AuditMessage> indexCreation = messages.stream().filter(msg -> "indices:admin/auto_create".equals(msg.getPrivilege())).collect(Collectors.toList());
+        assertThat(indexCreation.size(), equalTo(2));
+
+        final List<AuditMessage> mappingCreation = messages.stream().filter(msg -> "indices:admin/mapping/auto_put".equals(msg.getPrivilege())).collect(Collectors.toList());
+        assertThat(mappingCreation.size(), anyOf(equalTo(4), equalTo(2)));
+       
         // disable compliance
         auditConfig = new AuditConfig(true, AuditConfig.Filter.DEFAULT , ComplianceConfig.from(ImmutableMap.of("enabled", false, "write_watched_indices", Collections.singletonList("emp")), additionalSettings));
         updateAuditConfig(AuditTestUtils.createAuditPayload(auditConfig));
diff --git a/src/test/java/org/opensearch/security/auditlog/integration/TestAuditlogImpl.java b/src/test/java/org/opensearch/security/auditlog/integration/TestAuditlogImpl.java
@@ -16,6 +16,7 @@
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicReference;
+import java.util.stream.Collectors;
 
 import org.opensearch.common.settings.Settings;
 import org.opensearch.security.auditlog.impl.AuditMessage;
@@ -67,10 +68,10 @@ public static List<AuditMessage> doThenWaitForMessages(final Runnable action, fi
         
         try {
             action.run();
-            final int maxSecondsToWaitForMessages = 1; 
+            final int maxSecondsToWaitForMessages = 1;
             final boolean foundAll = latch.await(maxSecondsToWaitForMessages, TimeUnit.SECONDS);
             if (!foundAll) {
-                throw new MessagesNotFoundException(expectedCount, (int)latch.getCount());
+                throw new MessagesNotFoundException(expectedCount, messages);
             }
             if (messages.size() != expectedCount) {
                 throw new RuntimeException("Unexpected number of messages, was expecting " + expectedCount + ", recieved " + messages.size());
@@ -96,10 +97,12 @@ public boolean isHandlingBackpressure() {
     public static class MessagesNotFoundException extends RuntimeException {
         private final int expectedCount;
         private final int missingCount;
-        public MessagesNotFoundException(final int expectedCount, final int missingCount) {
-            super("Did not recieve all " + expectedCount +" audit messages after a short wait, missing " + missingCount + " messages");
+        private final List<AuditMessage> foundMessages;
+        public MessagesNotFoundException(final int expectedCount, List<AuditMessage> foundMessages) {
+            super(MessagesNotFoundException.createDetailMessage(expectedCount, foundMessages));
             this.expectedCount = expectedCount;
-            this.missingCount = missingCount;
+            this.missingCount = expectedCount - foundMessages.size();
+            this.foundMessages = foundMessages;
         }
 
         public int getExpectedCount() {
@@ -109,5 +112,20 @@ public int getExpectedCount() {
         public int getMissingCount() {
             return missingCount;
         }
+
+        public List<AuditMessage> getFoundMessages() {
+            return foundMessages;
+        }
+
+        private static String createDetailMessage(final int expectedCount, final List<AuditMessage> foundMessages) {
+            return new StringBuilder()
+                .append("Did not recieve all " + expectedCount + " audit messages after a short wait. ")
+                .append("Missing " + (expectedCount - foundMessages.size()) + " messages.")
+                .append("Messages found during this time: \n\n")
+                .append(foundMessages.stream()
+                    .map(AuditMessage::toString)
+                    .collect(Collectors.joining("\n")))
+                .toString();
+        }
     }
 }
