honeymoose
/
OpenSearch
mirror of https://github.com/honeymoose/OpenSearch.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Switch sql audit tests from index to the log file (elastic/x-pack-elasticsearch#2753) 

This is *way* faster because we don't have to wait for the audit
events from previous test runs to drain into the index. And we
don't have to wait for the index's refresh cycle. We have to parse
the log lines which is a bit more brittle but it feels worth it
at this point.

Original commit: elastic/x-pack-elasticsearch@4b1758fc32
This commit is contained in:
Nik Everett 2017-10-14 12:27:51 +00:00 committed by GitHub
parent 269b656cf2
commit 770bc9516c
3 changed files with 143 additions and 160 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

15
qa/sql/security/build.gradle
View File

@ -7,15 +7,7 @@ dependencies {
integTestCluster {
// Setup auditing so we can use it in some tests
setting 'xpack.security.audit.enabled', 'true'
setting 'xpack.security.audit.outputs', '[logfile, index]'
// Only log the events we need so we don't have as much to sort through
setting 'xpack.security.audit.index.events.include', '[access_denied, access_granted]'
// Try and speed up audit logging without overwelming it
setting 'xpack.security.audit.index.flush_interval', '250ms'
// NOCOMMIT reenable after https://github.com/elastic/x-pack-elasticsearch/issues/2705 for lower overhead tests
// see the NOCOMMIT in RestSqlSecurityIT#cleanAuditLogs and revert to 1 minute once this is reenabled
// setting 'xpack.security.audit.index.settings.index.number_of_shards', '1'
// setting 'xpack.security.audit.index.settings.index.refresh_interval', '250ms'
setting 'xpack.security.audit.outputs', 'logfile'
// Setup roles used by tests
extraConfigFile 'x-pack/roles.yml', 'roles.yml'
/* Setup the one admin user that we run the tests as.
@ -35,6 +27,11 @@ integTestCluster {
}
}
integTestRunner {
systemProperty 'tests.audit.logfile',
"${ -> integTest.nodes[0].homeDir}/logs/${ -> integTest.nodes[0].clusterName }_access.log"
}
run {
// Enabled audit logging so we can test it
setting 'xpack.security.audit.enabled', 'true'

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

@ -9,11 +9,13 @@ 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.logging.log4j.util.Strings;
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.io.PathUtils;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.xcontent.XContentBuilder;
import org.elasticsearch.common.xcontent.XContentHelper;
@ -23,16 +25,21 @@ 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;
import java.security.AccessController;
import java.security.PrivilegedAction;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.concurrent.TimeUnit;
import java.util.regex.Pattern;
import static java.util.Collections.emptyList;
import static java.util.Collections.emptyMap;
@ -41,14 +48,37 @@ 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.containsString;
import static org.hamcrest.Matchers.empty;
import static org.hamcrest.Matchers.hasItems;
public class RestSqlSecurityIT extends ESRestTestCase {
private static final String SQL_ACTION_NAME = "indices:data/read/sql";
private 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
* the file and that must be done by setting a system property and reading it in
* {@code plugin-security.policy}. So we may as well have gradle set the property.
*/
private static final Path AUDIT_LOG_FILE;
static {
String auditLogFileString = System.getProperty("tests.audit.logfile");
if (null == auditLogFileString) {
throw new IllegalStateException("tests.audit.logfile must be set to run this test. It is automatically "
+ "set by gradle. If you must set it yourself then it should be the absolute path to the audit "
+ "log file generated by running x-pack with audit logging enabled.");
}
AUDIT_LOG_FILE = PathUtils.get(auditLogFileString);
}
private static boolean oneTimeSetup = false;
private static boolean auditFailure = false;
/**
* How much of the audit log was written before the test started.
*/
private long auditLogWrittenBeforeTestStart;
/**
* All tests run as a an administrative user but use
* <code>es-security-runas-user</code> to become a less privileged user when needed.
@ -82,48 +112,30 @@ public class RestSqlSecurityIT extends ESRestTestCase {
bulk.append("{\"a\": \"test\"}\n");
client().performRequest("PUT", "/_bulk", singletonMap("refresh", "true"),
new StringEntity(bulk.toString(), ContentType.APPLICATION_JSON));
/* Wait for the audit log to go quiet and then clear it to protect
* us from log events coming from other tests. */
cleanAuditLog();
oneTimeSetup = true;
}
/**
* Wait for any running bulk tasks to complete because those
* are likely audit log events and will cause the tests to
* hang at best and at worst. Then remove all audit logs.
*/
@Before
public void cleanAuditLog() throws Exception {
assertBusy(() -> {
Set<String> bulks = new HashSet<>();
Map<?, ?> nodes = (Map<?, ?>) entityAsMap(adminClient().performRequest("GET", "_tasks")).get("nodes");
for (Map.Entry<?, ?> node : nodes.entrySet()) {
Map<?, ?> nodeInfo = (Map<?, ?>) node.getValue();
Map<?, ?> nodeTasks = (Map<?, ?>) nodeInfo.get("tasks");
for (Map.Entry<?, ?> taskAndName : nodeTasks.entrySet()) {
Map<?, ?> task = (Map<?, ?>) taskAndName.getValue();
String action = task.get("action").toString();
if ("indices:data/write/bulk".equals(action) || "indices:data/write/bulk[s]".equals(action)) {
bulks.add(task.toString());
}
}
}
if (false == bulks.isEmpty()) {
String bulksString = Strings.join(bulks, '\n');
logger.info("Waiting on bulk writes to finish:\n{}", bulksString);
fail("Waiting on bulk writes to finish:\n" + bulksString);
}
}, 4, TimeUnit.MINUTES);
// NOCOMMIT 1 minute used to be plenty before we
try {
clearAuditEvents();
} catch (ResponseException e) {
// 404 here just means we don't have any audit log index which shouldn't fail
if (e.getResponse().getStatusLine().getStatusCode() != 404) {
throw e;
}
public void setInitialAuditLogOffset() throws IOException {
SecurityManager sm = System.getSecurityManager();
if (sm != null) {
sm.checkPermission(new SpecialPermission());
}
AccessController.doPrivileged((PrivilegedAction<Void>) () -> {
if (false == Files.exists(AUDIT_LOG_FILE)) {
auditLogWrittenBeforeTestStart = 0;
return null;
}
if (false == Files.isRegularFile(AUDIT_LOG_FILE)) {
throw new IllegalStateException("expected tests.audit.logfile [" + AUDIT_LOG_FILE + "]to be a plain file but wasn't");
}
try {
auditLogWrittenBeforeTestStart = Files.size(AUDIT_LOG_FILE);
} catch (IOException e) {
throw new RuntimeException(e);
}
return null;
});
}
@AfterClass
@ -169,9 +181,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
ResponseException e = expectThrows(ResponseException.class, () -> runSql("SELECT * FROM test", "no_access"));
assertThat(e.getMessage(), containsString("403 Forbidden"));
assertAuditEvents(m -> "access_denied".equals(m.get("event_type"))
&& m.get("indices") == null
&& "no_access".equals(m.get("principal")));
assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
}
public void testQueryWrongAccess() throws Exception {
@ -182,14 +192,10 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertAuditEvents(
/* This user has permission to run sql queries so they are
* given preliminary authorization. */
m -> "access_granted".equals(m.get("event_type"))
&& null == m.get("indices")
&& "wrong_access".equals(m.get("principal")),
audit(true, SQL_ACTION_NAME, "wrong_access", empty()),
/* But as soon as they attempt to resolve an index that
* they don't have access to they get denied. */
m -> "access_denied".equals(m.get("event_type"))
&& singletonList("test").equals(m.get("indices"))
&& "wrong_access".equals(m.get("principal")));
audit(false, SQL_ACTION_NAME, "wrong_access", hasItems("test")));
}
public void testQuerySingleFieldGranted() throws Exception {
@ -198,7 +204,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(runSql("SELECT a FROM test", null), runSql("SELECT * FROM test", "only_a"));
assertAuditForSqlGetTableSyncGranted("test_admin", "test");
assertAuditForSqlGetTableSyncGranted("only_a", "test");
clearAuditEvents();
// clearAuditEvents(); NOCOMMIT
expectBadRequest(() -> runSql("SELECT c FROM test", "only_a"), containsString("line 1:8: Unknown column [c]"));
/* The user has permission to query the index but one of the
* columns that they explicitly mention is hidden from them
@ -215,7 +221,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(runSql("SELECT a, b FROM test", null), runSql("SELECT * FROM test", "not_c"));
assertAuditForSqlGetTableSyncGranted("test_admin", "test");
assertAuditForSqlGetTableSyncGranted("not_c", "test");
clearAuditEvents();
// clearAuditEvents(); NOCOMMIT
expectBadRequest(() -> runSql("SELECT c FROM test", "not_c"), containsString("line 1:8: Unknown column [c]"));
/* The user has permission to query the index but one of the
* columns that they explicitly mention is hidden from them
@ -243,7 +249,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
expected.put("size", 2);
assertResponse(expected, runSql("SHOW TABLES", null));
assertAuditEvents(
audit(true, SQL_ACTION_NAME, "test_admin", null),
audit(true, SQL_ACTION_NAME, "test_admin", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "test_admin", hasItems("test", "bort")));
}
@ -252,9 +258,9 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(runSql("SHOW TABLES", null), runSql("SHOW TABLES", "full_access"));
assertAuditEvents(
audit(true, SQL_ACTION_NAME, "test_admin", null),
audit(true, SQL_ACTION_NAME, "test_admin", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "test_admin", hasItems("test", "bort")),
audit(true, SQL_ACTION_NAME, "full_access", null),
audit(true, SQL_ACTION_NAME, "full_access", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "full_access", hasItems("test", "bort")));
}
@ -263,18 +269,17 @@ public class RestSqlSecurityIT extends ESRestTestCase {
ResponseException e = expectThrows(ResponseException.class, () -> runSql("SHOW TABLES", "no_access"));
assertThat(e.getMessage(), containsString("403 Forbidden"));
assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", null));
assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
}
public void testShowTablesWithLimitedAccess() throws Exception {
createUser("read_bort", "read_bort");
assertResponse(runSql("SHOW TABLES LIKE 'bort'", null), runSql("SHOW TABLES", "read_bort"));
assertAuditForSqlGetTableSyncGranted("test_admin", "bort");
assertAuditEvents(
audit(true, SQL_ACTION_NAME, "test_admin", null),
audit(true, SQL_ACTION_NAME, "test_admin", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "test_admin", contains("bort")),
audit(true, SQL_ACTION_NAME, "read_bort", null),
audit(true, SQL_ACTION_NAME, "read_bort", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "read_bort", contains("bort")));
}
@ -288,7 +293,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(expected, runSql("SHOW TABLES LIKE 'test'", "read_bort"));
assertAuditEvents(
audit(true, SQL_ACTION_NAME, "read_bort", null),
audit(true, SQL_ACTION_NAME, "read_bort", empty()),
audit(true, SQL_INDICES_ACTION_NAME, "read_bort", contains("*", "-*")));
}
@ -319,9 +324,7 @@ public class RestSqlSecurityIT extends ESRestTestCase {
ResponseException e = expectThrows(ResponseException.class, () -> runSql("DESCRIBE test", "no_access"));
assertThat(e.getMessage(), containsString("403 Forbidden"));
assertAuditEvents(m -> "access_denied".equals(m.get("event_type"))
&& m.get("indices") == null
&& "no_access".equals(m.get("principal")));
assertAuditEvents(audit(false, SQL_ACTION_NAME, "no_access", empty()));
}
public void testDescribeWithWrongAccess() throws Exception {
@ -332,17 +335,12 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertAuditEvents(
/* This user has permission to run sql queries so they are
* given preliminary authorization. */
m -> "access_granted".equals(m.get("event_type"))
&& null == m.get("indices")
&& "wrong_access".equals(m.get("principal")),
audit(true, SQL_ACTION_NAME, "wrong_access", empty()),
/* But as soon as they attempt to resolve an index that
* they don't have access to they get denied. */
m -> "access_denied".equals(m.get("event_type"))
&& singletonList("test").equals(m.get("indices"))
&& "wrong_access".equals(m.get("principal")));
audit(false, SQL_INDICES_ACTION_NAME, "wrong_access", hasItems("test")));
}
public void testDescribeSingleFieldGranted() throws Exception {
createUser("only_a", "read_test_a");
@ -355,7 +353,6 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(expected, runSql("DESCRIBE test", "only_a"));
assertAuditForSqlGetTableSyncGranted("only_a", "test");
clearAuditEvents();
}
public void testDescribeSingleFieldExcepted() throws Exception {
@ -372,7 +369,6 @@ public class RestSqlSecurityIT extends ESRestTestCase {
assertResponse(expected, runSql("DESCRIBE test", "not_c"));
assertAuditForSqlGetTableSyncGranted("not_c", "test");
clearAuditEvents();
}
public void testDescribeDocumentExclued() throws Exception {
@ -423,14 +419,8 @@ public class RestSqlSecurityIT extends ESRestTestCase {
private void assertAuditForSqlGetTableSyncGranted(String user, String index) throws Exception {
assertAuditEvents(
m -> "access_granted".equals(m.get("event_type"))
&& SQL_ACTION_NAME.equals(m.get("action"))
&& m.get("indices") == null
&& user.equals(m.get("principal")),
m -> "access_granted".equals(m.get("event_type"))
&& SQL_ACTION_NAME.equals(m.get("action"))
&& singletonList(index).equals(m.get("indices"))
&& user.equals(m.get("principal")));
audit(true, SQL_ACTION_NAME, user, empty()),
audit(true, SQL_ACTION_NAME, user, hasItems(index)));
}
/**
@ -442,65 +432,77 @@ public class RestSqlSecurityIT extends ESRestTestCase {
+ "guarantee that we fully cleaned up after the last test.", auditFailure);
try {
assertBusy(() -> {
XContentBuilder search = JsonXContent.contentBuilder().prettyPrint();
search.startObject(); {
search.startObject("query"); {
search.startObject("bool"); {
search.startArray("should"); {
search.startObject(); {
search.startObject("match").field("action", SQL_ACTION_NAME).endObject();
}
search.endObject();
search.startObject(); {
search.startObject("match").field("action", SQL_INDICES_ACTION_NAME).endObject();
}
search.endObject();
}
search.endArray();
}
search.endObject();
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);
}
search.endObject();
});
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++));
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);
}
search.endObject();
Map<String, Object> audit;
try {
audit = toMap(client().performRequest("POST", "/.security_audit_log-*/_search?size=1000",
emptyMap(), new StringEntity(search.string(), ContentType.APPLICATION_JSON)));
} catch (ResponseException e) {
throw new AssertionError("ES failed to respond. Wrapping in assertion so we retry. Hopefully this is transient.", e);
}
Map<?, ?> hitsOuter = (Map<?, ?>) audit.get("hits");
if (hitsOuter == null) {
fail("expected some hit but got:\n" + audit);
}
List<?> hits = (List<?>) hitsOuter.get("hits");
verifier: for (CheckedFunction<Map<?, ?>, Boolean, Exception> eventChecker : eventCheckers) {
for (Object hit : hits) {
Map<?, ?> source = (Map<?, ?>)((Map<?, ?>) hit).get("_source");
if (eventChecker.apply(source)) {
for (Map<String, Object> log : logs) {
if (eventChecker.apply(log)) {
continue verifier;
}
}
fail("didn't find audit event we were looking for. found " + hits);
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);
}
}, 1, TimeUnit.MINUTES);
});
} 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.");
Map<String, Object> audit = toMap(
client().performRequest("POST", "/.security_audit_log-*/_search?size=50&sort=@timestamp:desc"));
Map<?, ?> hitsOuter = (Map<?, ?>) audit.get("hits");
List<?> hits = hitsOuter == null ? null : (List<?>) hitsOuter.get("hits");
if (hits == null || hits.isEmpty()) {
logger.warn("Didn't find any audit logs. Here is the whole response:\n{}", audit);
} else {
logger.warn("Here are the last 500 indexed audit logs:");
for (Object hit : hits) {
logger.warn(hit.toString());
}
}
throw e;
}
}
@ -511,26 +513,6 @@ public class RestSqlSecurityIT extends ESRestTestCase {
return m -> eventType.equals(m.get("event_type"))
&& action.equals(m.get("action"))
&& principal.equals(m.get("principal"))
&& (indicesMatcher == null ? false == m.containsKey("indices") : indicesMatcher.matches(m.get("indices")));
}
private void clearAuditEvents() throws Exception {
try {
assertBusy(() -> {
try {
adminClient().performRequest("POST", "/.security_audit_log-*/_delete_by_query", emptyMap(),
new StringEntity("{\"query\":{\"match_all\":{}}}", ContentType.APPLICATION_JSON));
} catch (ResponseException e) {
logger.info("Conflict while clearing audit logs");
if (e.getResponse().getStatusLine().getStatusCode() == 409) {
throw new AssertionError("Conflict while clearing audit log. Wrapping in assertion so we retry.", e);
}
throw e;
}
});
} catch (AssertionError e) {
auditFailure = true;
throw e;
}
&& indicesMatcher.matches(m.get("indices"));
}
}

4
qa/sql/security/src/test/resources/plugin-security.policy Normal file
View File

@ -0,0 +1,4 @@
grant {
// Needed to read the audit log file
permission java.io.FilePermission "${tests.audit.logfile}", "read";
};