Add remaining security tests (elastic/x-pack-elasticsearch#2797)

This adds all of the security tests I think SQL is going to need for the initial release. SQL is still missing an entire scenario though: SSL enabled. Either way, this removes some `NOCOMMIT`s in `qa/sql/security`. Adding the SSL testing can come later.

Original commit: elastic/x-pack-elasticsearch@851620b606

dev-tools/ci

@@ -72,7 +72,6 @@ case $key in
             "-x:x-pack-elasticsearch:sql:jdbc:forbiddenPatterns"
             "-x:x-pack-elasticsearch:sql:server:forbiddenPatterns"
             "-x:x-pack-elasticsearch:qa:sql:forbiddenPatterns"
-            "-x:x-pack-elasticsearch:qa:sql:security:forbiddenPatterns"
         )
         ;;
     releaseTest)

qa/sql/security/src/test/java/org/elasticsearch/xpack/qa/sql/security/CliSecurityIT.java

@@ -5,6 +5,7 @@
  */
 package org.elasticsearch.xpack.qa.sql.security;
 
+import org.elasticsearch.common.CheckedConsumer;
 import org.elasticsearch.xpack.qa.sql.cli.RemoteCli;
 
 import static org.elasticsearch.xpack.qa.sql.cli.CliIntegrationTestCase.elasticsearchAddress;
@@ -39,19 +40,35 @@ public class CliSecurityIT extends SqlSecurityTestCase {
 
         @Override
         public void expectMatchesAdmin(String adminSql, String user, String userSql) throws Exception {
+            expectMatchesAdmin(adminSql, user, userSql, cli -> {});
+        }
+
+        @Override
+        public void expectScrollMatchesAdmin(String adminSql, String user, String userSql) throws Exception {
+            expectMatchesAdmin(adminSql, user, userSql, cli -> {
+                assertEquals("fetch size set to [90m1[0m", cli.command("fetch size = 1"));
+                assertEquals("fetch separator set to \"[90m -- fetch sep -- [0m\"",
+                        cli.command("fetch separator = \" -- fetch sep -- \""));
+            });
+        }
+
+        public void expectMatchesAdmin(String adminSql, String user, String userSql,
+                CheckedConsumer<RemoteCli, Exception> customizer) throws Exception {
             List<String> adminResult = new ArrayList<>();
             try (RemoteCli cli = new RemoteCli(adminEsUrlPrefix() + elasticsearchAddress())) {
+                customizer.accept(cli);
                 adminResult.add(cli.command(adminSql));
                 String line;
                 do {
                     line = cli.readLine();
                     adminResult.add(line);
-                } while (false == line.equals("[0m"));
+                } while (false == (line.equals("[0m") || line.equals("")));
                 adminResult.add(line);
             }
 
             Iterator<String> expected = adminResult.iterator();
             try (RemoteCli cli = new RemoteCli(userPrefix(user) + elasticsearchAddress())) {
+                customizer.accept(cli);
                 assertTrue(expected.hasNext());
                 assertEquals(expected.next(), cli.command(userSql));
                 String line;
@@ -59,7 +76,7 @@ public class CliSecurityIT extends SqlSecurityTestCase {
                     line = cli.readLine();
                     assertTrue(expected.hasNext());
                     assertEquals(expected.next(), line);
-                } while (false == line.equals("[0m"));
+                } while (false == (line.equals("[0m") || line.equals("")));
                 assertTrue(expected.hasNext());
                 assertEquals(expected.next(), line);
                 assertFalse(expected.hasNext());

qa/sql/security/src/test/java/org/elasticsearch/xpack/qa/sql/security/JdbcSecurityIT.java

@@ -10,6 +10,7 @@ import java.sql.Connection;
 import java.sql.DriverManager;
 import java.sql.ResultSet;
 import java.sql.SQLException;
+import java.sql.Statement;
 import java.util.List;
 import java.util.Map;
 import java.util.Properties;
@@ -49,6 +50,18 @@ public class JdbcSecurityIT extends SqlSecurityTestCase {
             }
         }
 
+        @Override
+        public void expectScrollMatchesAdmin(String adminSql, String user, String userSql) throws Exception {
+            try (Connection admin = DriverManager.getConnection(elasticsearchAddress(), adminProperties());
+                    Connection other = DriverManager.getConnection(elasticsearchAddress(), userProperties(user))) {
+                Statement adminStatement = admin.createStatement();
+                adminStatement.setFetchSize(1);
+                Statement otherStatement = other.createStatement();
+                otherStatement.setFetchSize(1);
+                assertResultSets(adminStatement.executeQuery(adminSql), otherStatement.executeQuery(userSql));
+            }
+        }
+
         @Override
         public void expectDescribe(Map<String, String> columns, String user) throws Exception {
             try (Connection h2 = LocalH2.anonymousDb();

qa/sql/security/src/test/java/org/elasticsearch/xpack/qa/sql/security/RestSqlSecurityIT.java

@@ -6,6 +6,7 @@
 package org.elasticsearch.xpack.qa.sql.security;
 
 import org.apache.http.Header;
+import org.apache.http.HttpEntity;
 import org.apache.http.entity.ContentType;
 import org.apache.http.entity.StringEntity;
 import org.apache.http.message.BasicHeader;
@@ -27,6 +28,7 @@ import static org.elasticsearch.xpack.qa.sql.rest.RestSqlTestCase.columnInfo;
 import static java.util.Collections.emptyMap;
 import static java.util.Collections.singletonList;
 import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.empty;
 
 public class RestSqlSecurityIT extends SqlSecurityTestCase {
     private static class RestActions implements Actions {
@@ -41,7 +43,7 @@ public class RestSqlSecurityIT extends SqlSecurityTestCase {
                     Arrays.asList(1, 2, 3),
                     Arrays.asList(4, 5, 6)));
             expected.put("size", 2);
-    
+
             assertResponse(expected, runSql(null, "SELECT * FROM test ORDER BY a"));
         }
 
@@ -50,6 +52,32 @@ public class RestSqlSecurityIT extends SqlSecurityTestCase {
             assertResponse(runSql(null, adminSql), runSql(user, userSql));
         }
 
+        @Override
+        public void expectScrollMatchesAdmin(String adminSql, String user, String userSql) throws Exception {
+            Map<String, Object> adminResponse = runSql(null,
+                    new StringEntity("{\"query\": \"" + adminSql + "\", \"fetch_size\": 1}", ContentType.APPLICATION_JSON));
+            Map<String, Object> otherResponse = runSql(user,
+                    new StringEntity("{\"query\": \"" + adminSql + "\", \"fetch_size\": 1}", ContentType.APPLICATION_JSON));
+
+            String adminCursor = (String) adminResponse.remove("cursor");
+            String otherCursor = (String) otherResponse.remove("cursor");
+            assertNotNull(adminCursor);
+            assertNotNull(otherCursor);
+            assertResponse(adminResponse, otherResponse);
+            while (true) {
+                adminResponse = runSql(null, new StringEntity("{\"cursor\": \"" + adminCursor + "\"}", ContentType.APPLICATION_JSON));
+                otherResponse = runSql(user, new StringEntity("{\"cursor\": \"" + otherCursor + "\"}", ContentType.APPLICATION_JSON));
+                adminCursor = (String) adminResponse.remove("cursor");
+                otherCursor = (String) otherResponse.remove("cursor");
+                assertResponse(adminResponse, otherResponse);
+                if (adminCursor == null) {
+                    assertNull(otherCursor);
+                    return;
+                }
+                assertNotNull(otherCursor);
+            }
+        }
+
         @Override
         public void expectDescribe(Map<String, String> columns, String user) throws Exception {
             Map<String, Object> expected = new HashMap<>(3);
@@ -92,13 +120,15 @@ public class RestSqlSecurityIT extends SqlSecurityTestCase {
         }
 
         private static Map<String, Object> runSql(@Nullable String asUser, String sql) throws IOException {
+            return runSql(asUser, new StringEntity("{\"query\": \"" + sql + "\"}", ContentType.APPLICATION_JSON));
+        }
+
+        private static Map<String, Object> runSql(@Nullable String asUser, HttpEntity entity) throws IOException {
             Header[] headers = asUser == null ? new Header[0] : new Header[] {new BasicHeader("es-security-runas-user", asUser)};
-            Response response = client().performRequest("POST", "/_sql", emptyMap(),
+            Response response = client().performRequest("POST", "/_sql", emptyMap(), entity, headers);
-                    new StringEntity("{\"query\": \"" + sql + "\"}", ContentType.APPLICATION_JSON),
-                    headers);
             return toMap(response);
         }
-    
+
         private static void assertResponse(Map<String, Object> expected, Map<String, Object> actual) {
             if (false == expected.equals(actual)) {
                 NotEqualMessageBuilder message = new NotEqualMessageBuilder();
@@ -106,7 +136,7 @@ public class RestSqlSecurityIT extends SqlSecurityTestCase {
                 fail("Response does not match:\n" + message.toString());
             }
         }
-    
+
         private static Map<String, Object> toMap(Response response) throws IOException {
             try (InputStream content = response.getEntity().getContent()) {
                 return XContentHelper.convertToMap(JsonXContent.jsonXContent, content, false);
@@ -117,4 +147,37 @@ public class RestSqlSecurityIT extends SqlSecurityTestCase {
     public RestSqlSecurityIT() {
         super(new RestActions());
     }
-}
+
+    /**
+     * Test the hijacking a scroll fails. This test is only implemented for
+     * REST because it is the only API where it is simple to hijack a scroll.
+     * It should excercise the same code as the other APIs but if we were truly
+     * paranoid we'd hack together something to test the others as well.
+     */
+    public void testHijackScrollFails() throws Exception {
+        createUser("full_access", "read_all");
+
+        Map<String, Object> adminResponse = RestActions.runSql(null,
+                new StringEntity("{\"query\": \"SELECT * FROM test\", \"fetch_size\": 1}", ContentType.APPLICATION_JSON));
+
+        String cursor = (String) adminResponse.remove("cursor");
+        assertNotNull(cursor);
+
+        ResponseException e = expectThrows(ResponseException.class, () ->
+                RestActions.runSql("full_access", new StringEntity("{\"cursor\":\"" + cursor + "\"}", ContentType.APPLICATION_JSON)));
+        // TODO return a better error message for bad scrolls
+        assertThat(e.getMessage(), containsString("No search context found for id"));
+        assertEquals(404, e.getResponse().getStatusLine().getStatusCode());
+
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .expect(true, SQL_ACTION_NAME, "full_access", empty())
+            // One scroll access denied per shard
+            .expect(false, SQL_ACTION_NAME, "full_access", empty(), "InternalScrollSearchRequest")
+            .expect(false, SQL_ACTION_NAME, "full_access", empty(), "InternalScrollSearchRequest")
+            .expect(false, SQL_ACTION_NAME, "full_access", empty(), "InternalScrollSearchRequest")
+            .expect(false, SQL_ACTION_NAME, "full_access", empty(), "InternalScrollSearchRequest")
+            .expect(false, SQL_ACTION_NAME, "full_access", empty(), "InternalScrollSearchRequest")
+            .assertLogs();
+    }
+}

qa/sql/security/src/test/java/org/elasticsearch/xpack/qa/sql/security/SqlSecurityTestCase.java

@@ -5,29 +5,21 @@
  */
 package org.elasticsearch.xpack.qa.sql.security;
 
-import org.apache.http.Header;
 import org.apache.http.entity.ContentType;
 import org.apache.http.entity.StringEntity;
-import org.apache.http.message.BasicHeader;
 import org.apache.lucene.util.SuppressForbidden;
 import org.elasticsearch.SpecialPermission;
-import org.elasticsearch.client.Response;
 import org.elasticsearch.client.ResponseException;
-import org.elasticsearch.common.CheckedFunction;
-import org.elasticsearch.common.Nullable;
 import org.elasticsearch.common.Strings;
 import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.xcontent.XContentBuilder;
-import org.elasticsearch.common.xcontent.XContentHelper;
 import org.elasticsearch.common.xcontent.json.JsonXContent;
-import org.elasticsearch.test.NotEqualMessageBuilder;
 import org.elasticsearch.test.rest.ESRestTestCase;
 import org.hamcrest.Matcher;
 import org.junit.AfterClass;
 import org.junit.Before;
 import java.io.BufferedReader;
 import java.io.IOException;
-import java.io.InputStream;
 import java.nio.charset.StandardCharsets;
 import java.nio.file.Files;
 import java.nio.file.Path;
@@ -38,16 +30,15 @@ import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.HashMap;
+import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
 import java.util.TreeMap;
+import java.util.function.Function;
 import java.util.regex.Pattern;
 
-import static java.util.Collections.emptyList;
 import static java.util.Collections.emptyMap;
-import static java.util.Collections.singletonList;
 import static java.util.Collections.singletonMap;
-import static org.elasticsearch.xpack.qa.sql.rest.RestSqlTestCase.columnInfo;
 import static org.hamcrest.Matchers.contains;
 import static org.hamcrest.Matchers.empty;
 import static org.hamcrest.Matchers.hasItems;
@@ -58,16 +49,25 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
      */
     protected interface Actions {
         void queryWorksAsAdmin() throws Exception;
+        /**
+         * Assert that running some sql as a user returns the same result as running it as
+         * the administrator.
+         */
         void expectMatchesAdmin(String adminSql, String user, String userSql) throws Exception;
+        /**
+         * Same as {@link #expectMatchesAdmin(String, String, String)} but sets the scroll size
+         * to 1 and completely scrolls the results.
+         */
+        void expectScrollMatchesAdmin(String adminSql, String user, String userSql) throws Exception;
         void expectDescribe(Map<String, String> columns, String user) throws Exception;
         void expectShowTables(List<String> tables, String user) throws Exception;
-        
+
         void expectForbidden(String user, String sql) throws Exception;
         void expectUnknownColumn(String user, String sql, String column) throws Exception;
     }
 
-    private static final String SQL_ACTION_NAME = "indices:data/read/sql";
+    protected static final String SQL_ACTION_NAME = "indices:data/read/sql";
-    private static final String SQL_INDICES_ACTION_NAME = "indices:data/read/sql/tables";
+    protected static final String SQL_INDICES_ACTION_NAME = "indices:data/read/sql/tables";
     /**
      * Location of the audit log file. We could technically figure this out by reading the admin
      * APIs but it isn't worth doing because we also have to give ourselves permission to read
@@ -94,7 +94,7 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
      * The actions taken by this test.
      */
     private final Actions actions;
-    
+
     /**
      * How much of the audit log was written before the test started.
      */
@@ -179,48 +179,86 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
         }
     }
 
-    // NOCOMMIT we'll have to test scrolling as well
-    // NOCOMMIT assert that we don't have more audit logs then what we expect.
-
     public void testQueryWorksAsAdmin() throws Exception {
         actions.queryWorksAsAdmin();
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .assertLogs();
     }
 
     public void testQueryWithFullAccess() throws Exception {
         createUser("full_access", "read_all");
 
         actions.expectMatchesAdmin("SELECT * FROM test ORDER BY a", "full_access", "SELECT * FROM test ORDER BY a");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("full_access", "test");
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .expectSqlWithSyncLookup("full_access", "test")
+            .assertLogs();
+    }
+
+    public void testScrollWithFullAccess() throws Exception {
+        createUser("full_access", "read_all");
+
+        actions.expectScrollMatchesAdmin("SELECT * FROM test ORDER BY a", "full_access", "SELECT * FROM test ORDER BY a");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("test_admin", "test")
+            /* Scrolling doesn't have to access the index again, at least not through sql.
+             * If we asserted query and scroll logs then we would see the scoll. */
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expectSqlWithSyncLookup("full_access", "test")
+            .expect(true, SQL_ACTION_NAME, "full_access", empty())
+            .expect(true, SQL_ACTION_NAME, "full_access", empty())
+            .assertLogs();
     }
 
     public void testQueryNoAccess() throws Exception {
         createUser("no_access", "read_nothing");
 
         actions.expectForbidden("no_access", "SELECT * FROM test");
-        assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
+        new AuditLogAsserter()
+            .expect(false, SQL_ACTION_NAME, "no_access", empty())
+            .assertLogs();
     }
 
     public void testQueryWrongAccess() throws Exception {
         createUser("wrong_access", "read_something_else");
 
         actions.expectForbidden("wrong_access", "SELECT * FROM test");
-        assertAuditEvents(
+        new AuditLogAsserter()
-                /* This user has permission to run sql queries so they are
+            /* This user has permission to run sql queries so they are
-                 * given preliminary authorization. */
+             * given preliminary authorization. */
-                audit(true, SQL_ACTION_NAME, "wrong_access", empty()),
+            .expect(true, SQL_ACTION_NAME, "wrong_access", empty())
-                /* But as soon as they attempt to resolve an index that
+            /* But as soon as they attempt to resolve an index that
-                 * they don't have access to they get denied. */
+             * they don't have access to they get denied. */
-                audit(false, SQL_ACTION_NAME, "wrong_access", hasItems("test")));
+            .expect(false, SQL_ACTION_NAME, "wrong_access", hasItems("test"))
+            .assertLogs();
     }
 
     public void testQuerySingleFieldGranted() throws Exception {
         createUser("only_a", "read_test_a");
 
-        actions.expectMatchesAdmin("SELECT a FROM test", "only_a", "SELECT * FROM test");
+        actions.expectMatchesAdmin("SELECT a FROM test ORDER BY a", "only_a", "SELECT * FROM test ORDER BY a");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("only_a", "test");
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .expectSqlWithSyncLookup("only_a", "test")
+            .assertLogs();
+    }
+
+    public void testScrollWithSingleFieldGranted() throws Exception {
+        createUser("only_a", "read_test_a");
+
+        actions.expectScrollMatchesAdmin("SELECT a FROM test ORDER BY a", "only_a", "SELECT * FROM test ORDER BY a");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("test_admin", "test")
+            /* Scrolling doesn't have to access the index again, at least not through sql.
+             * If we asserted query and scroll logs then we would see the scoll. */
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expectSqlWithSyncLookup("only_a", "test")
+            .expect(true, SQL_ACTION_NAME, "only_a", empty())
+            .expect(true, SQL_ACTION_NAME, "only_a", empty())
+            .assertLogs();
     }
 
     public void testQueryStringSingeFieldGrantedWrongRequested() throws Exception {
@@ -233,15 +271,35 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
          * query from the audit side because all the permissions checked
          * out but it failed in SQL because it couldn't compile the
          * query without the metadata for the missing field. */
-        assertAuditForSqlGetTableSyncGranted("only_a", "test");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("only_a", "test")
+            .assertLogs();
     }
 
     public void testQuerySingleFieldExcepted() throws Exception {
         createUser("not_c", "read_test_a_and_b");
 
-        actions.expectMatchesAdmin("SELECT a, b FROM test", "not_c", "SELECT * FROM test");
+        actions.expectMatchesAdmin("SELECT a, b FROM test ORDER BY a", "not_c", "SELECT * FROM test ORDER BY a");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("not_c", "test");
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .expectSqlWithSyncLookup("not_c", "test")
+            .assertLogs();
+    }
+
+    public void testScrollWithSingleFieldExcepted() throws Exception {
+        createUser("not_c", "read_test_a_and_b");
+
+        actions.expectScrollMatchesAdmin("SELECT a, b FROM test ORDER BY a", "not_c", "SELECT * FROM test ORDER BY a");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("test_admin", "test")
+            /* Scrolling doesn't have to access the index again, at least not through sql.
+             * If we asserted query and scroll logs then we would see the scoll. */
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
+            .expectSqlWithSyncLookup("not_c", "test")
+            .expect(true, SQL_ACTION_NAME, "not_c", empty())
+            .expect(true, SQL_ACTION_NAME, "not_c", empty())
+            .assertLogs();
     }
 
     public void testQuerySingleFieldExceptionedWrongRequested() throws Exception {
@@ -254,60 +312,67 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
          * query from the audit side because all the permissions checked
          * out but it failed in SQL because it couldn't compile the
          * query without the metadata for the missing field. */
-        assertAuditForSqlGetTableSyncGranted("not_c", "test");
+        new AuditLogAsserter()
+            .expectSqlWithSyncLookup("not_c", "test")
+            .assertLogs();
     }
 
     public void testQueryDocumentExclued() throws Exception {
         createUser("no_3s", "read_test_without_c_3");
 
-        actions.expectMatchesAdmin("SELECT * FROM test WHERE c != 3", "no_3s", "SELECT * FROM test");
+        actions.expectMatchesAdmin("SELECT * FROM test WHERE c != 3 ORDER BY a", "no_3s", "SELECT * FROM test ORDER BY a");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("no_3s", "test");
+            .expectSqlWithSyncLookup("test_admin", "test")
+            .expectSqlWithSyncLookup("no_3s", "test")
+            .assertLogs();
     }
 
     public void testShowTablesWorksAsAdmin() throws Exception {
         actions.expectShowTables(Arrays.asList("bort", "test"), null);
-        assertAuditEvents(
+        new AuditLogAsserter()
-                audit(true, SQL_ACTION_NAME, "test_admin", empty()),
+            .expectSqlWithAsyncLookup("test_admin", "bort", "test")
-                audit(true, SQL_INDICES_ACTION_NAME, "test_admin", hasItems("test", "bort")));
+            .assertLogs();
     }
 
     public void testShowTablesWorksAsFullAccess() throws Exception {
         createUser("full_access", "read_all");
 
         actions.expectMatchesAdmin("SHOW TABLES", "full_access", "SHOW TABLES");
-        assertAuditEvents(
+        new AuditLogAsserter()
-                audit(true, SQL_ACTION_NAME, "test_admin", empty()),
+            .expectSqlWithAsyncLookup("test_admin", "bort", "test")
-                audit(true, SQL_INDICES_ACTION_NAME, "test_admin", hasItems("test", "bort")),
+            .expectSqlWithAsyncLookup("full_access", "bort", "test")
-                audit(true, SQL_ACTION_NAME, "full_access", empty()),
+            .assertLogs();
-                audit(true, SQL_INDICES_ACTION_NAME, "full_access", hasItems("test", "bort")));
     }
 
     public void testShowTablesWithNoAccess() throws Exception {
         createUser("no_access", "read_nothing");
 
         actions.expectForbidden("no_access", "SHOW TABLES");
-        assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
+        new AuditLogAsserter()
+            .expect(false, SQL_ACTION_NAME, "no_access", empty())
+            .assertLogs();
     }
 
     public void testShowTablesWithLimitedAccess() throws Exception {
         createUser("read_bort", "read_bort");
 
         actions.expectMatchesAdmin("SHOW TABLES LIKE 'bort'", "read_bort", "SHOW TABLES");
-        assertAuditEvents(
+        new AuditLogAsserter()
-                audit(true, SQL_ACTION_NAME, "test_admin", empty()),
+            .expectSqlWithAsyncLookup("test_admin", "bort")
-                audit(true, SQL_INDICES_ACTION_NAME, "test_admin", contains("bort")),
+            .expectSqlWithAsyncLookup("read_bort", "bort")
-                audit(true, SQL_ACTION_NAME, "read_bort", empty()),
+            .assertLogs();
-                audit(true, SQL_INDICES_ACTION_NAME, "read_bort", contains("bort")));
     }
 
-    public void testShowTablesWithLimitedAccessAndPattern() throws Exception {
+    public void testShowTablesWithLimitedAccessUnaccessableIndex() throws Exception {
         createUser("read_bort", "read_bort");
 
         actions.expectMatchesAdmin("SHOW TABLES LIKE 'not_created'", "read_bort", "SHOW TABLES LIKE 'test'");
-        assertAuditEvents(
+        new AuditLogAsserter()
-                audit(true, SQL_ACTION_NAME, "read_bort", empty()),
+            .expect(true, SQL_ACTION_NAME, "test_admin", empty())
-                audit(true, SQL_INDICES_ACTION_NAME, "read_bort", contains("*", "-*")));
+            .expect(true, SQL_INDICES_ACTION_NAME, "test_admin", contains("*", "-*"))
+            .expect(true, SQL_ACTION_NAME, "read_bort", empty())
+            .expect(true, SQL_INDICES_ACTION_NAME, "read_bort", contains("*", "-*"))
+            .assertLogs();
     }
 
     public void testDescribeWorksAsAdmin() throws Exception {
@@ -316,42 +381,51 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
         expected.put("b", "BIGINT");
         expected.put("c", "BIGINT");
         actions.expectDescribe(expected, null);
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
+            .expectSqlWithAsyncLookup("test_admin", "test")
+            .assertLogs();
     }
 
     public void testDescribeWorksAsFullAccess() throws Exception {
         createUser("full_access", "read_all");
 
         actions.expectMatchesAdmin("DESCRIBE test", "full_access", "DESCRIBE test");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("full_access", "test");
+            .expectSqlWithAsyncLookup("test_admin", "test")
+            .expectSqlWithAsyncLookup("full_access", "test")
+            .assertLogs();
     }
 
     public void testDescribeWithNoAccess() throws Exception {
         createUser("no_access", "read_nothing");
 
         actions.expectForbidden("no_access", "DESCRIBE test");
-        assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
+        new AuditLogAsserter()
+            .expect(false, SQL_ACTION_NAME, "no_access", empty())
+            .assertLogs();
     }
 
     public void testDescribeWithWrongAccess() throws Exception {
         createUser("wrong_access", "read_something_else");
 
         actions.expectForbidden("wrong_access", "DESCRIBE test");
-        assertAuditEvents(
+        new AuditLogAsserter()
-                /* This user has permission to run sql queries so they are
+            /* This user has permission to run sql queries so they are
-                 * given preliminary authorization. */
+             * given preliminary authorization. */
-                audit(true, SQL_ACTION_NAME, "wrong_access", empty()),
+            .expect(true, SQL_ACTION_NAME, "wrong_access", empty())
-                /* But as soon as they attempt to resolve an index that
+            /* But as soon as they attempt to resolve an index that
-                 * they don't have access to they get denied. */
+             * they don't have access to they get denied. */
-                audit(false, SQL_INDICES_ACTION_NAME, "wrong_access", hasItems("test")));
+            .expect(false, SQL_INDICES_ACTION_NAME, "wrong_access", hasItems("test"))
+            .assertLogs();
     }
 
     public void testDescribeSingleFieldGranted() throws Exception {
         createUser("only_a", "read_test_a");
 
         actions.expectDescribe(singletonMap("a", "BIGINT"), "only_a");
-        assertAuditForSqlGetTableSyncGranted("only_a", "test");
+        new AuditLogAsserter()
+            .expectSqlWithAsyncLookup("only_a", "test")
+            .assertLogs();
     }
 
     public void testDescribeSingleFieldExcepted() throws Exception {
@@ -361,18 +435,22 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
         expected.put("a", "BIGINT");
         expected.put("b", "BIGINT");
         actions.expectDescribe(expected, "not_c");
-        assertAuditForSqlGetTableSyncGranted("not_c", "test");
+        new AuditLogAsserter()
+            .expectSqlWithAsyncLookup("not_c", "test")
+            .assertLogs();
     }
 
     public void testDescribeDocumentExclued() throws Exception {
         createUser("no_3s", "read_test_without_c_3");
 
         actions.expectMatchesAdmin("DESCRIBE test", "no_3s", "DESCRIBE test");
-        assertAuditForSqlGetTableSyncGranted("test_admin", "test");
+        new AuditLogAsserter()
-        assertAuditForSqlGetTableSyncGranted("no_3s", "test");
+            .expectSqlWithAsyncLookup("test_admin", "test")
+            .expectSqlWithAsyncLookup("no_3s", "test")
+            .assertLogs();
     }
 
-    private void createUser(String name, String role) throws IOException {
+    protected final void createUser(String name, String role) throws IOException {
         XContentBuilder user = JsonXContent.contentBuilder().prettyPrint().startObject(); {
             user.field("password", "testpass");
             user.field("roles", role);
@@ -382,102 +460,161 @@ public abstract class SqlSecurityTestCase extends ESRestTestCase {
                 new StringEntity(user.string(), ContentType.APPLICATION_JSON));
     }
 
-    private void assertAuditForSqlGetTableSyncGranted(String user, String index) throws Exception {
-        assertAuditEvents(
-                audit(true, SQL_ACTION_NAME, user, empty()),
-                audit(true, SQL_ACTION_NAME, user, hasItems(index)));
-    }
-
     /**
-     * Asserts that audit events have been logged that match all the provided checkers.
+     * Used to assert audit logs. Logs are asserted to match in any order because
+     * we don't always scroll in the same order but each log checker must match a
+     * single log and all logs must be matched.
      */
-    @SafeVarargs
+    protected final class AuditLogAsserter {
-    private final void assertAuditEvents(CheckedFunction<Map<?, ?>, Boolean, Exception>... eventCheckers) throws Exception {
+        private final List<Function<Map<String, Object>, Boolean>> logCheckers = new ArrayList<>();
-        assertFalse("Previous test had an audit-related failure. All subsequent audit related assertions are bogus because we can't "
+
-                + "guarantee that we fully cleaned up after the last test.", auditFailure);
+        public AuditLogAsserter expectSqlWithAsyncLookup(String user, String... indices) {
-        try {
+            expect(true, SQL_ACTION_NAME, user, empty());
-            assertBusy(() -> {
+            expect(true, SQL_INDICES_ACTION_NAME, user, contains(indices));
-                SecurityManager sm = System.getSecurityManager();
+            for (String index : indices) {
-                if (sm != null) {
+                expect(true, SQL_ACTION_NAME, user, hasItems(index));
-                    sm.checkPermission(new SpecialPermission());
+            }
-                }
+            return this;
-                BufferedReader logReader = AccessController.doPrivileged((PrivilegedAction<BufferedReader>) () -> {
+        }
-                    try {
+
-                        return  Files.newBufferedReader(AUDIT_LOG_FILE, StandardCharsets.UTF_8);
+        public AuditLogAsserter expectSqlWithSyncLookup(String user, String... indices) {
-                    } catch (IOException e) {
+            expect(true, SQL_ACTION_NAME, user, empty());
-                        throw new RuntimeException(e);
+            for (String index : indices) {
+                expect(true, SQL_ACTION_NAME, user, hasItems(index));
+            }
+            return this;
+        }
+
+        public AuditLogAsserter expect(boolean granted, String action, String principal,
+                    Matcher<? extends Iterable<? extends String>> indicesMatcher) {
+            String request;
+            switch (action) {
+            case SQL_ACTION_NAME:
+                request = "SqlRequest";
+                break;
+            case SQL_INDICES_ACTION_NAME:
+                request = "Request";
+                break;
+            default:
+                throw new IllegalArgumentException("Unknown action [" + action + "]");
+            }
+            return expect(granted, action, principal, indicesMatcher, request);
+        }
+
+        public AuditLogAsserter expect(boolean granted, String action, String principal,
+                    Matcher<? extends Iterable<? extends String>> indicesMatcher, String request) {
+            String eventType = granted ? "access_granted" : "access_denied";
+            logCheckers.add(m -> eventType.equals(m.get("event_type"))
+                && action.equals(m.get("action"))
+                && principal.equals(m.get("principal"))
+                && indicesMatcher.matches(m.get("indices"))
+                && request.equals(m.get("request"))
+            );
+            return this;
+        }
+
+        public void assertLogs() throws Exception {
+            assertFalse("Previous test had an audit-related failure. All subsequent audit related assertions are bogus because we can't "
+                    + "guarantee that we fully cleaned up after the last test.", auditFailure);
+            try {
+                assertBusy(() -> {
+                    SecurityManager sm = System.getSecurityManager();
+                    if (sm != null) {
+                        sm.checkPermission(new SpecialPermission());
+                    }
+                    BufferedReader logReader = AccessController.doPrivileged((PrivilegedAction<BufferedReader>) () -> {
+                        try {
+                            return  Files.newBufferedReader(AUDIT_LOG_FILE, StandardCharsets.UTF_8);
+                        } catch (IOException e) {
+                            throw new RuntimeException(e);
+                        }
+                    });
+                    logReader.skip(auditLogWrittenBeforeTestStart);
+
+                    List<Map<String, Object>> logs = new ArrayList<>();
+                    String line;
+                    Pattern logPattern = Pattern.compile(
+                            ("PART PART PART origin_type=PART, origin_address=PART, "
+                            + "principal=PART, (?:run_as_principal=PART, )?(?:run_by_principal=PART, )?"
+                            + "action=\\[(.*?)\\], (?:indices=PART, )?request=PART")
+                                .replace(" ", "\\s+").replace("PART", "\\[([^\\]]*)\\]"));
+                    // fail(logPattern.toString());
+                    while ((line = logReader.readLine()) != null) {
+                        java.util.regex.Matcher m = logPattern.matcher(line);
+                        if (false == m.matches()) {
+                            throw new IllegalArgumentException("Unrecognized log: " + line);
+                        }
+                        int i = 1;
+                        Map<String, Object> log = new HashMap<>();
+                        /* We *could* parse the date but leaving it in the original format makes it
+                        * easier to find the lines in the file that this log comes from. */
+                        log.put("time", m.group(i++));
+                        log.put("origin", m.group(i++));
+                        String eventType = m.group(i++);
+                        if (false == ("access_denied".equals(eventType) || "access_granted".equals(eventType))) {
+                            continue;
+                        }
+                        log.put("event_type", eventType);
+                        log.put("origin_type", m.group(i++));
+                        log.put("origin_address", m.group(i++));
+                        String principal = m.group(i++);
+                        log.put("principal", principal);
+                        log.put("run_as_principal", m.group(i++));
+                        log.put("run_by_principal", m.group(i++));
+                        String action = m.group(i++);
+                        if (false == (SQL_ACTION_NAME.equals(action) || SQL_INDICES_ACTION_NAME.equals(action))) {
+                            continue;
+                        }
+                        log.put("action", action);
+                        // Use a sorted list for indices for consistent error reporting
+                        List<String> indices = new ArrayList<>(Strings.splitStringByCommaToSet(m.group(i++)));
+                        Collections.sort(indices);
+                        if ("test_admin".equals(principal)) {
+                            /* Sometimes we accidentally sneak access to the security tables. This is fine, SQL
+                            * drops them from the interface. So we might have access to them, but we don't show
+                            * them. */
+                            indices.remove(".security");
+                            indices.remove(".security-v6");
+                        }
+                        log.put("indices", indices);
+                        log.put("request", m.group(i++));
+                        logs.add(log);
+                    }
+                    List<Map<String, Object>> allLogs = new ArrayList<>(logs);
+                    List<Integer> notMatching = new ArrayList<>();
+                    checker: for (int c = 0; c < logCheckers.size(); c++) {
+                        Function<Map<String, Object>, Boolean> logChecker = logCheckers.get(c);
+                        for (Iterator<Map<String, Object>> logsItr = logs.iterator(); logsItr.hasNext();) {
+                            Map<String, Object> log = logsItr.next();
+                            if (logChecker.apply(log)) {
+                                logsItr.remove();
+                                continue checker;
+                            }
+                        }
+                        notMatching.add(c);
+                    }
+                    if (false == notMatching.isEmpty()) {
+                        fail("Some checkers " + notMatching + " didn't match any logs. All logs:" + logsMessage(allLogs)
+                            + "\nRemaining logs:" + logsMessage(logs));
+                    }
+                    if (false == logs.isEmpty()) {
+                        fail("Not all logs matched. Unmatched logs:" + logsMessage(logs));
                     }
                 });
-                logReader.skip(auditLogWrittenBeforeTestStart);
+            } catch (AssertionError e) {
+                auditFailure = true;
+                logger.warn("Failed to find an audit log. Skipping remaining tests in this class after this the missing audit"
+                        + "logs could turn up later.");
+                throw e;
+            }
+        }
 
-                List<Map<String, Object>> logs = new ArrayList<>();
+        private String logsMessage(List<Map<String, Object>> logs) {
-                String line;
+            StringBuilder logsMessage = new StringBuilder();
-                Pattern logPattern = Pattern.compile(
+            for (Map<String, Object> log : logs) {
-                        ("PART PART PART origin_type=PART, origin_address=PART, "
+                logsMessage.append('\n').append(log);
-                        + "principal=PART, (?:run_as_principal=PART, )?(?:run_by_principal=PART, )?"
+            }
-                        + "action=\\[(.*?)\\], (?:indices=PART, )?request=PART")
+            return logsMessage.toString();
-                            .replace(" ", "\\s+").replace("PART", "\\[([^\\]]*)\\]"));
-                // fail(logPattern.toString());
-                while ((line = logReader.readLine()) != null) {
-                    java.util.regex.Matcher m = logPattern.matcher(line);
-                    if (false == m.matches()) {
-                        throw new IllegalArgumentException("Unrecognized log: " + line);
-                    }
-                    int i = 1;
-                    Map<String, Object> log = new HashMap<>();
-                    /* We *could* parse the date but leaving it in the original format makes it
-                     * easier to find the lines in the file that this log comes from. */
-                    log.put("time", m.group(i++));
-                    log.put("origin", m.group(i++));
-                    String eventType = m.group(i++);
-                    if (false == ("access_denied".equals(eventType) || "access_granted".equals(eventType))) {
-                        continue;
-                    }
-                    log.put("event_type", eventType);
-                    log.put("origin_type", m.group(i++));
-                    log.put("origin_address", m.group(i++));
-                    log.put("principal", m.group(i++));
-                    log.put("run_as_principal", m.group(i++));
-                    log.put("run_by_principal", m.group(i++));
-                    String action = m.group(i++);
-                    if (false == (SQL_ACTION_NAME.equals(action) || SQL_INDICES_ACTION_NAME.equals(action))) {
-                        continue;
-                    }
-                    log.put("action", action);
-                    // Use a sorted list for indices for consistent error reporting
-                    List<String> indices = new ArrayList<>(Strings.splitStringByCommaToSet(m.group(i++)));
-                    Collections.sort(indices);
-                    log.put("indices", indices);
-                    log.put("request", m.group(i++));
-                    logs.add(log);
-                }
-                verifier: for (CheckedFunction<Map<?, ?>, Boolean, Exception> eventChecker : eventCheckers) {
-                    for (Map<String, Object> log : logs) {
-                        if (eventChecker.apply(log)) {
-                            continue verifier;
-                        }
-                    }
-                    StringBuilder logsMessage = new StringBuilder();
-                    for (Map<String, Object> log : logs) {
-                        logsMessage.append('\n').append(log);
-                    }
-                    fail("Didn't find an audit event we were looking for. Found:" + logsMessage);
-                }
-            });
-        } catch (AssertionError e) {
-            auditFailure = true;
-            logger.warn("Failed to find an audit log. Skipping remaining tests in this class after this the missing audit"
-                    + "logs could turn up later.");
-            throw e;
         }
     }
-
+}
-    private CheckedFunction<Map<?, ?>, Boolean, Exception> audit(boolean granted, String action,
-            String principal, Matcher<? extends Iterable<? extends String>> indicesMatcher) {
-        String eventType = granted ? "access_granted" : "access_denied";
-        return m -> eventType.equals(m.get("event_type"))
-            && action.equals(m.get("action"))
-            && principal.equals(m.get("principal"))
-            && indicesMatcher.matches(m.get("indices"));
-    }
-}