From 1ca9d19c1e7ebd8b25ae1f535c299a429336bdd9 Mon Sep 17 00:00:00 2001 From: Albert Zaharovits Date: Thu, 20 Sep 2018 13:53:02 +0300 Subject: [PATCH] Resurrect the previous format alongside the new one --- .../core/src/main/config/log4j2.properties | 38 +++ .../audit/logfile/CapturingLogger.java | 76 ++++-- .../audit/logfile/LoggingAuditTrail.java | 14 +- .../audit/logfile/LoggingAuditTrailTests.java | 218 ++++++++++++++---- 4 files changed, 290 insertions(+), 56 deletions(-) diff --git a/x-pack/plugin/core/src/main/config/log4j2.properties b/x-pack/plugin/core/src/main/config/log4j2.properties index 1c9358f3cc490..afb1e9c02b032 100644 --- a/x-pack/plugin/core/src/main/config/log4j2.properties +++ b/x-pack/plugin/core/src/main/config/log4j2.properties @@ -1,3 +1,40 @@ +appender.deprecated_audit_rolling.type = RollingFile +appender.deprecated_audit_rolling.name = deprecated_audit_rolling +appender.deprecated_audit_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_access.log +appender.deprecated_audit_rolling.layout.type = PatternLayout +appender.deprecated_audit_rolling.layout.pattern = \ + [%d{ISO8601}]\ + %varsNotEmpty{ [%map{host.ip}]}\ + %varsNotEmpty{ [%map{host.name}]}\ + %varsNotEmpty{ [%map{node.name}]}\ + \ [%map{event.type}]\ + \ [%map{event.action}]\ + \ \ \ + %varsNotEmpty{realm=[%map{realm}], }\ + origin_type=[%map{origin.type}]\ + %varsNotEmpty{, origin_address=[%map{origin.address}]}\ + %varsNotEmpty{, principal=[%map{user.name}]}\ + %varsNotEmpty{, realm=[%map{user.realm}]}\ + %varsNotEmpty{, run_by_principal=[%map{user.run_by.name}]}\ + %varsNotEmpty{, run_as_principal=[%map{user.run_as.name}]}\ + %varsNotEmpty{, run_by_realm=[%map{user.run_by.realm}]}\ + %varsNotEmpty{, run_as_realm=[%map{user.run_as.realm}]}\ + %varsNotEmpty{, roles=[%map{deprecated.user.roles}]}\ + %varsNotEmpty{, action=[%map{action}]}\ + %varsNotEmpty{, indices=[%map{deprecated.indices}]}\ + %varsNotEmpty{, request=[%map{request.name}]}\ + %varsNotEmpty{, transport_profile=[%map{transport.profile}]}\ + %varsNotEmpty{, rule=[%map{rule}]}\ + %varsNotEmpty{, uri=[%map{deprecated.uri}]}\ + %varsNotEmpty{, opaque_id=[%map{opaque_id}]}\ + %varsNotEmpty{, request_body=[%map{request.body}]}\ + %n +appender.deprecated_audit_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_access-%d{yyyy-MM-dd}.log +appender.deprecated_audit_rolling.policies.type = Policies +appender.deprecated_audit_rolling.policies.time.type = TimeBasedTriggeringPolicy +appender.deprecated_audit_rolling.policies.time.interval = 1 +appender.deprecated_audit_rolling.policies.time.modulate = true + appender.audit_rolling.type = RollingFile appender.audit_rolling.name = audit_rolling appender.audit_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_audit.log @@ -67,6 +104,7 @@ appender.audit_rolling.policies.time.modulate = true logger.xpack_security_audit_logfile.name = org.elasticsearch.xpack.security.audit.logfile.LoggingAuditTrail logger.xpack_security_audit_logfile.level = info logger.xpack_security_audit_logfile.appenderRef.audit_rolling.ref = audit_rolling +logger.xpack_security_audit_logfile.appenderRef.deprecated_audit_rolling.ref = deprecated_audit_rolling logger.xpack_security_audit_logfile.additivity = false logger.xmlsig.name = org.apache.xml.security.signature.XMLSignature diff --git a/x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/security/audit/logfile/CapturingLogger.java b/x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/security/audit/logfile/CapturingLogger.java index ede18c8241b34..31881e7586e5a 100644 --- a/x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/security/audit/logfile/CapturingLogger.java +++ b/x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/security/audit/logfile/CapturingLogger.java @@ -30,6 +30,8 @@ */ public class CapturingLogger { + private static final String IMPLICIT_APPENDER_NAME = "__implicit"; + /** * Constructs a new {@link CapturingLogger} named as the fully qualified name of * the invoking method. One name can be assigned to a single logger globally, so @@ -52,42 +54,88 @@ public static Logger newCapturingLogger(final Level level, @Nullable StringLayou final String name = caller.getClassName() + "." + caller.getMethodName() + "." + level.toString(); final Logger logger = ESLoggerFactory.getLogger(name); Loggers.setLevel(logger, level); - final MockAppender appender = new MockAppender(name, layout); + attachNewMockAppender(logger, IMPLICIT_APPENDER_NAME, layout); + return logger; + } + + public static void attachNewMockAppender(final Logger logger, final String appenderName, @Nullable StringLayout layout) + throws IllegalAccessException { + final MockAppender appender = new MockAppender(buildAppenderName(logger.getName(), appenderName), layout); appender.start(); Loggers.addAppender(logger, appender); - return logger; } - private static MockAppender getMockAppender(final String name) { + private static String buildAppenderName(final String loggerName, final String appenderName) { + // appender name also has to be unique globally (logging context globally) + return loggerName + "." + appenderName; + } + + private static MockAppender getMockAppender(final String loggerName, final String appenderName) { final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); final Configuration config = ctx.getConfiguration(); - final LoggerConfig loggerConfig = config.getLoggerConfig(name); - return (MockAppender) loggerConfig.getAppenders().get(name); + final LoggerConfig loggerConfig = config.getLoggerConfig(loggerName); + final String mockAppenderName = buildAppenderName(loggerName, appenderName); + return (MockAppender) loggerConfig.getAppenders().get(mockAppenderName); } /** - * Checks if the logger's appender has captured any events. + * Checks if the logger's appender(s) has captured any events. * - * @param name + * @param loggerName * The unique global name of the logger. + * @param appenderNames + * Names of other appenders nested under this same logger. * @return {@code true} if no event has been captured, {@code false} otherwise. */ - public static boolean isEmpty(final String name) { - final MockAppender appender = getMockAppender(name); - return appender.isEmpty(); + public static boolean isEmpty(final String loggerName, final String... appenderNames) { + // check if implicit appender is empty + final MockAppender implicitAppender = getMockAppender(loggerName, IMPLICIT_APPENDER_NAME); + assert implicitAppender != null; + if (false == implicitAppender.isEmpty()) { + return false; + } + if (null == appenderNames) { + return true; + } + // check if any named appenders are empty + for (String appenderName : appenderNames) { + final MockAppender namedAppender = getMockAppender(loggerName, appenderName); + if (namedAppender != null && false == namedAppender.isEmpty()) { + return false; + } + } + return true; + } + + /** + * Gets the captured events for a logger by its name. Events are those of the + * implicit appender of the logger. + * + * @param loggerName + * The unique global name of the logger. + * @param level + * The priority level of the captured events to be returned. + * @return A list of captured events formated to {@code String}. + */ + public static List output(final String loggerName, final Level level) { + return output(loggerName, IMPLICIT_APPENDER_NAME, level); } /** - * Gets the captured events for a logger by its name. + * Gets the captured events for a logger and an appender by their respective + * names. There is a one to many relationship between loggers and appenders. * - * @param name + * @param loggerName * The unique global name of the logger. + * @param appenderName + * The name of an appender associated with the {@code loggerName} + * logger. * @param level * The priority level of the captured events to be returned. * @return A list of captured events formated to {@code String}. */ - public static List output(final String name, final Level level) { - final MockAppender appender = getMockAppender(name); + public static List output(final String loggerName, final String appenderName, final Level level) { + final MockAppender appender = getMockAppender(loggerName, appenderName); return appender.output(level); } diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrail.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrail.java index 359fe7cd464a4..5dfc54618b003 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrail.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrail.java @@ -611,6 +611,8 @@ LogEntryBuilder withRestUri(RestRequest request) { if (queryStringIndex > -1) { logEntry.with(URL_QUERY_FIELD_NAME, request.uri().substring(queryStringIndex + 1, queryStringLength)); } + // deprecated uri format + logEntry.with("deprecated.uri", request.uri()); return this; } @@ -626,10 +628,16 @@ LogEntryBuilder withRunAsSubject(Authentication authentication) { LogEntryBuilder withRestOrigin(RestRequest request) { assert LOCAL_ORIGIN_FIELD_VALUE.equals(logEntry.get(ORIGIN_TYPE_FIELD_NAME)); // this is the default - final InetSocketAddress socketAddress = request.getHttpChannel().getRemoteAddress(); + final String formattedAddress; + final SocketAddress socketAddress = request.getRemoteAddress(); + if (socketAddress instanceof InetSocketAddress) { + formattedAddress = NetworkAddress.format(((InetSocketAddress) socketAddress)); + } else { + formattedAddress = socketAddress.toString(); + } if (socketAddress != null) { logEntry.with(ORIGIN_TYPE_FIELD_NAME, REST_ORIGIN_FIELD_VALUE) - .with(ORIGIN_ADDRESS_FIELD_NAME, NetworkAddress.format(socketAddress)); + .with(ORIGIN_ADDRESS_FIELD_NAME, formattedAddress); } // fall through to local_node default return this; @@ -700,6 +708,8 @@ LogEntryBuilder with(String key, String value) { LogEntryBuilder with(String key, String[] values) { if (values != null) { logEntry.with(key, toQuotedJsonArray(values)); + // deprecated format required for bwc + logEntry.with("deprecated." + key, Strings.arrayToCommaDelimitedString(values)); } return this; } diff --git a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrailTests.java b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrailTests.java index 6c302c9311f3d..24958f250a598 100644 --- a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrailTests.java +++ b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/audit/logfile/LoggingAuditTrailTests.java @@ -26,6 +26,7 @@ import org.elasticsearch.common.xcontent.NamedXContentRegistry; import org.elasticsearch.common.xcontent.XContentType; import org.elasticsearch.mock.orig.Mockito; +import org.elasticsearch.node.Node; import org.elasticsearch.rest.RestRequest; import org.elasticsearch.tasks.Task; import org.elasticsearch.test.ESTestCase; @@ -128,6 +129,7 @@ protected String expectedMessage() { } private static PatternLayout patternLayout; + private static PatternLayout deprecatedPatternLayout; private Settings settings; private DiscoveryNode localNode; private ClusterService clusterService; @@ -136,6 +138,13 @@ protected String expectedMessage() { private Map commonFields; private Logger logger; private LoggingAuditTrail auditTrail; + // from: + // https://www.myintervals.com/blog/2009/05/20/iso-8601-date-validation-that-doesnt-suck/ + // but stripped off the leading ^ and trailing $ anchors + private static final String ISO8601_DATE_REGEXP = "([\\+-]?\\d{4}(?!\\d{2}\\b))((-?)((0[1-9]|1[0-2])(\\3([12]\\d|0[1-9]|3[01]))?|" + + "W([0-4]\\d|5[0-2])(-?[1-7])?|(00[1-9]|0[1-9]\\d|[12]\\d{2}|3([0-5]\\d|6[1-6])))([T\\s]((([01]\\d|2[0-3])((:?)" + + "[0-5]\\d)?|24\\:?00)([\\.,]\\d+(?!:))?)?(\\17[0-5]\\d([\\.,]\\d+)?)?([zZ]|([\\+-])([01]\\d|2[0-3]):?([0-5]\\d)?)?)?)?"; + private static final String DEPRECATED_APPENDER_NAME = "deprecated"; @BeforeClass public static void lookupPatternLayout() throws Exception { @@ -150,16 +159,25 @@ public static void lookupPatternLayout() throws Exception { // attached to the LoggingAuditTrail.class logger. assertThat(properties.getProperty("logger.xpack_security_audit_logfile.name"), is(LoggingAuditTrail.class.getName())); assertThat(properties.getProperty("logger.xpack_security_audit_logfile.appenderRef.audit_rolling.ref"), is("audit_rolling")); + assertThat(properties.getProperty("logger.xpack_security_audit_logfile.appenderRef.deprecated_audit_rolling.ref"), + is("deprecated_audit_rolling")); assertThat(properties.getProperty("appender.audit_rolling.name"), is("audit_rolling")); + assertThat(properties.getProperty("appender.deprecated_audit_rolling.name"), is("deprecated_audit_rolling")); assertThat(properties.getProperty("appender.audit_rolling.layout.type"), is("PatternLayout")); + assertThat(properties.getProperty("appender.deprecated_audit_rolling.layout.type"), is("PatternLayout")); final String patternLayoutFormat = properties.getProperty("appender.audit_rolling.layout.pattern"); assertThat(patternLayoutFormat, is(notNullValue())); patternLayout = PatternLayout.newBuilder().withPattern(patternLayoutFormat).withCharset(StandardCharsets.UTF_8).build(); + final String deprecatedPatternLayoutFormat = properties.getProperty("appender.deprecated_audit_rolling.layout.pattern"); + assertThat(deprecatedPatternLayoutFormat, is(notNullValue())); + deprecatedPatternLayout = PatternLayout.newBuilder().withPattern(deprecatedPatternLayoutFormat).withCharset(StandardCharsets.UTF_8) + .build(); } @AfterClass public static void releasePatternLayout() { patternLayout = null; + deprecatedPatternLayout = null; } @Before @@ -169,7 +187,9 @@ public void init() throws Exception { .put("xpack.security.audit.logfile.prefix.emit_node_host_address", randomBoolean()) .put("xpack.security.audit.logfile.prefix.emit_node_host_name", randomBoolean()) .put("xpack.security.audit.logfile.prefix.emit_node_name", randomBoolean()) + .put("xpack.security.audit.logfile.prefix.emit_node_id", randomBoolean()) .put("xpack.security.audit.logfile.events.emit_request_body", includeRequestBody) + .put(Node.NODE_NAME_SETTING.getKey(), randomAlphaOfLength(6)) .build(); localNode = mock(DiscoveryNode.class); when(localNode.getAddress()).thenReturn(buildNewFakeTransportAddress()); @@ -188,12 +208,15 @@ public void init() throws Exception { threadContext.putHeader(Task.X_OPAQUE_ID, randomAlphaOfLengthBetween(1, 4)); } logger = CapturingLogger.newCapturingLogger(Level.INFO, patternLayout); + CapturingLogger.attachNewMockAppender(logger, DEPRECATED_APPENDER_NAME, deprecatedPatternLayout); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); } @After public void clearLog() throws Exception { + // clear both the implicit as well as the deprecated appender CapturingLogger.output(logger.getName(), Level.INFO).clear(); + CapturingLogger.output(logger.getName(), DEPRECATED_APPENDER_NAME, Level.INFO).clear(); } public void testAnonymousAccessDeniedTransport() throws Exception { @@ -209,16 +232,17 @@ public void testAnonymousAccessDeniedTransport() throws Exception { restOrTransportOrigin(message, threadContext, checkedFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "anonymous_access_denied") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.anonymousAccessDenied("_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAnonymousAccessDeniedRest() throws Exception { @@ -240,16 +264,17 @@ public void testAnonymousAccessDeniedRest() throws Exception { .put(LoggingAuditTrail.URL_QUERY_FIELD_NAME, null); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "anonymous_access_denied") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.anonymousAccessDenied(request); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAuthenticationFailed() throws Exception { @@ -268,16 +293,17 @@ public void testAuthenticationFailed() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "authentication_failed") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.authenticationFailed(new MockToken(), "_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAuthenticationFailedNoToken() throws Exception { @@ -294,16 +320,17 @@ public void testAuthenticationFailedNoToken() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "authentication_failed") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.authenticationFailed("_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAuthenticationFailedRest() throws Exception { @@ -332,16 +359,17 @@ public void testAuthenticationFailedRest() throws Exception { .put(LoggingAuditTrail.URL_QUERY_FIELD_NAME, params.isEmpty() ? null : "foo=bar"); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "authentication_failed") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.authenticationFailed(new MockToken(), request); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAuthenticationFailedRestNoToken() throws Exception { @@ -369,16 +397,17 @@ public void testAuthenticationFailedRestNoToken() throws Exception { .put(LoggingAuditTrail.URL_QUERY_FIELD_NAME, params.isEmpty() ? null : "bar=baz"); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "authentication_failed") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.authenticationFailed(request); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAuthenticationFailedRealm() throws Exception { @@ -386,7 +415,7 @@ public void testAuthenticationFailedRealm() throws Exception { final TransportMessage message = randomBoolean() ? new MockMessage(threadContext) : new MockIndicesRequest(threadContext); final String realm = randomAlphaOfLengthBetween(1, 6); auditTrail.authenticationFailed(realm, mockToken, "_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); // test enabled settings = Settings.builder() @@ -407,6 +436,7 @@ public void testAuthenticationFailedRealm() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); } public void testAuthenticationFailedRealmRest() throws Exception { @@ -422,7 +452,7 @@ public void testAuthenticationFailedRealmRest() throws Exception { final AuthenticationToken mockToken = new MockToken(); final String realm = randomAlphaOfLengthBetween(1, 6); auditTrail.authenticationFailed(realm, mockToken, request); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); // test enabled settings = Settings.builder() @@ -445,6 +475,7 @@ public void testAuthenticationFailedRealmRest() throws Exception { .put(LoggingAuditTrail.URL_QUERY_FIELD_NAME, params.isEmpty() ? null : "_param=baz"); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); } public void testAccessGranted() throws Exception { @@ -456,25 +487,26 @@ public void testAccessGranted() throws Exception { final MapBuilder checkedFields = new MapBuilder<>(commonFields); final MapBuilder checkedArrayFields = new MapBuilder<>(); checkedFields.put(LoggingAuditTrail.EVENT_TYPE_FIELD_NAME, LoggingAuditTrail.TRANSPORT_ORIGIN_FIELD_VALUE) - .put(LoggingAuditTrail.EVENT_ACTION_FIELD_NAME, "access_granted") - .put(LoggingAuditTrail.ACTION_FIELD_NAME, "_action") - .put(LoggingAuditTrail.REQUEST_NAME_FIELD_NAME, message.getClass().getSimpleName()); + .put(LoggingAuditTrail.EVENT_ACTION_FIELD_NAME, "access_granted") + .put(LoggingAuditTrail.ACTION_FIELD_NAME, "_action") + .put(LoggingAuditTrail.REQUEST_NAME_FIELD_NAME, message.getClass().getSimpleName()); checkedArrayFields.put(LoggingAuditTrail.PRINCIPAL_ROLES_FIELD_NAME, roles); subject(authentication, checkedFields); restOrTransportOrigin(message, threadContext, checkedFields); indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "access_granted") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.accessGranted(authentication, "_action", message, roles); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAccessGrantedInternalSystemAction() throws Exception { @@ -482,7 +514,7 @@ public void testAccessGrantedInternalSystemAction() throws Exception { final String[] roles = randomArray(0, 4, String[]::new, () -> randomBoolean() ? null : randomAlphaOfLengthBetween(1, 4)); final Authentication authentication = new Authentication(SystemUser.INSTANCE, new RealmRef("_reserved", "test", "foo"), null); auditTrail.accessGranted(authentication, "internal:_action", message, roles); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); // test enabled settings = Settings.builder() @@ -504,6 +536,7 @@ public void testAccessGrantedInternalSystemAction() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); } public void testAccessGrantedInternalSystemActionNonSystemUser() throws Exception { @@ -524,16 +557,17 @@ public void testAccessGrantedInternalSystemActionNonSystemUser() throws Exceptio indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "access_granted") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.accessGranted(authentication, "internal:_action", message, roles); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testAccessDenied() throws Exception { @@ -554,16 +588,17 @@ public void testAccessDenied() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "access_denied") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.accessDenied(authentication, "_action", message, roles); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testTamperedRequestRest() throws Exception { @@ -588,16 +623,17 @@ public void testTamperedRequestRest() throws Exception { .put(LoggingAuditTrail.URL_QUERY_FIELD_NAME, params.isEmpty() ? null : "_param=baz"); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "tampered_request") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.tamperedRequest(request); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testTamperedRequest() throws Exception { @@ -614,16 +650,17 @@ public void testTamperedRequest() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "tampered_request") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.tamperedRequest("_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testTamperedRequestWithUser() throws Exception { @@ -653,16 +690,17 @@ public void testTamperedRequestWithUser() throws Exception { indicesRequest(message, checkedFields, checkedArrayFields); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap(), checkedArrayFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "tampered_request") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.tamperedRequest(user, "_action", message); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testConnectionDenied() throws Exception { @@ -680,16 +718,17 @@ public void testConnectionDenied() throws Exception { .put(LoggingAuditTrail.RULE_FIELD_NAME, "deny _all"); opaqueId(threadContext, checkedFields); assertMsg(logger, checkedFields.immutableMap()); + assertDeprecatedMsg(logger, settings, checkedFields.immutableMap()); // test disabled - CapturingLogger.output(logger.getName(), Level.INFO).clear(); + clearLog(); settings = Settings.builder() .put(settings) .put("xpack.security.audit.logfile.events.exclude", "connection_denied") .build(); auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.connectionDenied(inetAddress, profile, rule); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); } public void testConnectionGranted() throws Exception { @@ -698,7 +737,7 @@ public void testConnectionGranted() throws Exception { final String profile = randomAlphaOfLengthBetween(1, 6); auditTrail.connectionGranted(inetAddress, profile, rule); - assertEmptyLog(logger); + assertEmptyLog(logger, DEPRECATED_APPENDER_NAME); // test enabled settings = Settings.builder() @@ -723,8 +762,7 @@ public void testRunAsGranted() throws Exception { final String[] roles = randomArray(0, 4, String[]::new, () -> randomBoolean() ? null : randomAlphaOfLengthBetween(1, 4)); final Authentication authentication = new Authentication( new User("running as", new String[] { "r2" }, new User("_username", new String[] { "r1" })), - new RealmRef("authRealm", "test", "foo"), - new RealmRef("lookRealm", "up", "by")); + new RealmRef("authRealm", "test", "foo"), new RealmRef("lookRealm", "up", "by")); auditTrail.runAsGranted(authentication, "_action", message, roles); final MapBuilder checkedFields = new MapBuilder<>(commonFields); @@ -759,8 +797,7 @@ public void testRunAsDenied() throws Exception { final String[] roles = randomArray(0, 4, String[]::new, () -> randomAlphaOfLengthBetween(1, 4)); final Authentication authentication = new Authentication( new User("running as", new String[] { "r2" }, new User("_username", new String[] { "r1" })), - new RealmRef("authRealm", "test", "foo"), - new RealmRef("lookRealm", "up", "by")); + new RealmRef("authRealm", "test", "foo"), new RealmRef("lookRealm", "up", "by")); auditTrail.runAsDenied(authentication, "_action", message, roles); final MapBuilder checkedFields = new MapBuilder<>(commonFields); @@ -934,6 +971,107 @@ private void assertMsg(Logger logger, Map checkFields) { assertMsg(logger, checkFields, Collections.emptyMap()); } + private void assertDeprecatedMsg(Logger logger, Settings settings, Map checkFields) { + assertDeprecatedMsg(logger, settings, checkFields, Collections.emptyMap()); + } + + private void assertDeprecatedMsg(Logger logger, Settings settings, Map checkFields, + Map checkArrayFields) { + final List output = CapturingLogger.output(logger.getName(), DEPRECATED_APPENDER_NAME, Level.INFO); + assertThat("Exactly one log line expected. Found: " + output.size(), output.size(), is(1)); + if (checkFields == null) { + // only check msg existence + return; + } + final String logLine = output.get(0); + final StringBuilder logLineRegexpBuilder = new StringBuilder(); + if (LoggingAuditTrail.EMIT_HOST_ADDRESS_SETTING.get(settings)) { + logLineRegexpBuilder.append(" [").append(checkFields.get(LoggingAuditTrail.HOST_ADDRESS_FIELD_NAME)).append("]"); + } + if (LoggingAuditTrail.EMIT_HOST_NAME_SETTING.get(settings)) { + logLineRegexpBuilder.append(" [").append(checkFields.get(LoggingAuditTrail.HOST_NAME_FIELD_NAME)).append("]"); + } + if (LoggingAuditTrail.EMIT_NODE_NAME_SETTING.get(settings)) { + logLineRegexpBuilder.append(" [").append(checkFields.get(LoggingAuditTrail.NODE_NAME_FIELD_NAME)).append("]"); + } + logLineRegexpBuilder.append(" [").append(checkFields.get(LoggingAuditTrail.EVENT_TYPE_FIELD_NAME)).append("]"); + logLineRegexpBuilder.append(" [").append(checkFields.get(LoggingAuditTrail.EVENT_ACTION_FIELD_NAME)).append("]"); + logLineRegexpBuilder.append(" "); + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.REALM_FIELD_NAME))) { + logLineRegexpBuilder.append("realm=[").append(checkFields.get(LoggingAuditTrail.REALM_FIELD_NAME)).append("], "); + } + logLineRegexpBuilder.append("origin_type=[").append(checkFields.get(LoggingAuditTrail.ORIGIN_TYPE_FIELD_NAME)).append("]"); + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.ORIGIN_ADDRESS_FIELD_NAME))) { + logLineRegexpBuilder.append(", origin_address=[").append(checkFields.get(LoggingAuditTrail.ORIGIN_ADDRESS_FIELD_NAME)) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_FIELD_NAME))) { + logLineRegexpBuilder.append(", principal=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_FIELD_NAME)).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_REALM_FIELD_NAME))) { + logLineRegexpBuilder.append(", realm=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_REALM_FIELD_NAME)).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_BY_FIELD_NAME))) { + logLineRegexpBuilder.append(", run_by_principal=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_BY_FIELD_NAME)) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_AS_FIELD_NAME))) { + logLineRegexpBuilder.append(", run_as_principal=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_AS_FIELD_NAME)) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_BY_REALM_FIELD_NAME))) { + logLineRegexpBuilder.append(", run_by_realm=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_BY_REALM_FIELD_NAME)) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_AS_REALM_FIELD_NAME))) { + logLineRegexpBuilder.append(", run_as_realm=[").append(checkFields.get(LoggingAuditTrail.PRINCIPAL_RUN_AS_REALM_FIELD_NAME)) + .append("]"); + } + final String[] roles = checkArrayFields.get(LoggingAuditTrail.PRINCIPAL_ROLES_FIELD_NAME); + if (null != roles && roles.length > 0) { + logLineRegexpBuilder.append(", roles=[") + .append(Strings.arrayToCommaDelimitedString(checkArrayFields.get(LoggingAuditTrail.PRINCIPAL_ROLES_FIELD_NAME))) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.ACTION_FIELD_NAME))) { + logLineRegexpBuilder.append(", action=[").append(checkFields.get(LoggingAuditTrail.ACTION_FIELD_NAME)).append("]"); + } + final String[] indices = checkArrayFields.get(LoggingAuditTrail.INDICES_FIELD_NAME); + if (null != indices && indices.length > 0) { + logLineRegexpBuilder.append(", indices=[") + .append(Strings.arrayToCommaDelimitedString(checkArrayFields.get(LoggingAuditTrail.INDICES_FIELD_NAME))).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.REQUEST_NAME_FIELD_NAME))) { + logLineRegexpBuilder.append(", request=[").append(checkFields.get(LoggingAuditTrail.REQUEST_NAME_FIELD_NAME)).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.TRANSPORT_PROFILE_FIELD_NAME))) { + logLineRegexpBuilder.append(", transport_profile=[").append(checkFields.get(LoggingAuditTrail.TRANSPORT_PROFILE_FIELD_NAME)) + .append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.RULE_FIELD_NAME))) { + logLineRegexpBuilder.append(", rule=[").append(checkFields.get(LoggingAuditTrail.RULE_FIELD_NAME)).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.URL_PATH_FIELD_NAME))) { + String uri = checkFields.get(LoggingAuditTrail.URL_PATH_FIELD_NAME); + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.URL_QUERY_FIELD_NAME))) { + uri += "?" + checkFields.get(LoggingAuditTrail.URL_QUERY_FIELD_NAME); + } + logLineRegexpBuilder.append(", uri=[").append(uri).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.OPAQUE_ID_FIELD_NAME))) { + logLineRegexpBuilder.append(", opaque_id=[").append(checkFields.get(LoggingAuditTrail.OPAQUE_ID_FIELD_NAME)).append("]"); + } + if (false == Strings.isNullOrEmpty(checkFields.get(LoggingAuditTrail.REQUEST_BODY_FIELD_NAME))) { + logLineRegexpBuilder.append(", request_body=[").append(checkFields.get(LoggingAuditTrail.REQUEST_BODY_FIELD_NAME)).append("]"); + } + logLineRegexpBuilder.append(System.lineSeparator()); + + // regex for the date field + final String logLineRegexp = "^\\[" + ISO8601_DATE_REGEXP + "\\]" + Pattern.quote(logLineRegexpBuilder.toString()) + "$"; + assertThat("The regexp does not match the log line: |" + logLineRegexp + "| |" + logLine + "|", + Pattern.matches(logLineRegexp, logLine), is(true)); + } + private void assertMsg(Logger logger, Map checkFields, Map checkArrayFields) { final List output = CapturingLogger.output(logger.getName(), Level.INFO); assertThat("Exactly one logEntry expected. Found: " + output.size(), output.size(), is(1)); @@ -976,13 +1114,13 @@ private void assertMsg(Logger logger, Map checkFields, Map prepareRestContent(String uri, InetSocketAddress remoteAddress) {