From d8134402bd2c925d4156b9fca47ae4c1d4d34a12 Mon Sep 17 00:00:00 2001 From: Igor Motov Date: Mon, 9 Jul 2018 13:40:23 -0700 Subject: [PATCH] Add opaque_id to audit logging (#31878) Logs opaque_id if it is available with all audit log messages. Relates #31521 --- .../audit/logfile/LoggingAuditTrail.java | 183 ++++++++++-------- .../audit/logfile/LoggingAuditTrailTests.java | 91 +++++---- 2 files changed, 151 insertions(+), 123 deletions(-) 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 3b9a42179a577..54e10925a985a 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 @@ -23,6 +23,7 @@ import org.elasticsearch.common.util.concurrent.ThreadContext; import org.elasticsearch.node.Node; import org.elasticsearch.rest.RestRequest; +import org.elasticsearch.tasks.Task; import org.elasticsearch.threadpool.ThreadPool; import org.elasticsearch.transport.TransportMessage; import org.elasticsearch.xpack.core.security.authc.Authentication; @@ -181,11 +182,11 @@ public void authenticationSuccess(String realm, User user, RestRequest request) if (events.contains(AUTHENTICATION_SUCCESS) && (eventFilterPolicyRegistry.ignorePredicate() .test(new AuditEventMetaInfo(Optional.of(user), Optional.of(realm), Optional.empty(), Optional.empty())) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [authentication_success]\t{}, realm=[{}], uri=[{}], params=[{}], request_body=[{}]", - localNodeInfo.prefix, principal(user), realm, request.uri(), request.params(), restRequestContent(request)); + logger.info("{}[rest] [authentication_success]\t{}, realm=[{}], uri=[{}], params=[{}]{}, request_body=[{}]", + localNodeInfo.prefix, principal(user), realm, request.uri(), request.params(), opaqueId(), restRequestContent(request)); } else { - logger.info("{}[rest] [authentication_success]\t{}, realm=[{}], uri=[{}], params=[{}]", localNodeInfo.prefix, - principal(user), realm, request.uri(), request.params()); + logger.info("{}[rest] [authentication_success]\t{}, realm=[{}], uri=[{}], params=[{}]{}", + localNodeInfo.prefix, principal(user), realm, request.uri(), request.params(), opaqueId()); } } } @@ -198,13 +199,13 @@ public void authenticationSuccess(String realm, User user, String action, Transp .test(new AuditEventMetaInfo(Optional.of(user), Optional.of(realm), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [authentication_success]\t{}, {}, realm=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [authentication_success]\t{}, {}, realm=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), principal(user), realm, action, - arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName()); + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [authentication_success]\t{}, {}, realm=[{}], action=[{}], request=[{}]", + logger.info("{}[transport] [authentication_success]\t{}, {}, realm=[{}], action=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), principal(user), realm, action, - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } } } @@ -218,12 +219,13 @@ public void anonymousAccessDenied(String action, TransportMessage message) { .test(new AuditEventMetaInfo(Optional.empty(), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [anonymous_access_denied]\t{}, action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [anonymous_access_denied]\t{}, action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), action, - arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName()); + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [anonymous_access_denied]\t{}, action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [anonymous_access_denied]\t{}, action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), action, + message.getClass().getSimpleName(), opaqueId()); } } } @@ -234,11 +236,11 @@ public void anonymousAccessDenied(RestRequest request) { if (events.contains(ANONYMOUS_ACCESS_DENIED) && (eventFilterPolicyRegistry.ignorePredicate().test(AuditEventMetaInfo.EMPTY) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [anonymous_access_denied]\t{}, uri=[{}], request_body=[{}]", localNodeInfo.prefix, - hostAttributes(request), request.uri(), restRequestContent(request)); + logger.info("{}[rest] [anonymous_access_denied]\t{}, uri=[{}]{}, request_body=[{}]", localNodeInfo.prefix, + hostAttributes(request), request.uri(), opaqueId(), restRequestContent(request)); } else { - logger.info("{}[rest] [anonymous_access_denied]\t{}, uri=[{}]", localNodeInfo.prefix, hostAttributes(request), - request.uri()); + logger.info("{}[rest] [anonymous_access_denied]\t{}, uri=[{}]{}", localNodeInfo.prefix, + hostAttributes(request), request.uri(), opaqueId()); } } } @@ -251,13 +253,13 @@ public void authenticationFailed(AuthenticationToken token, String action, Trans .test(new AuditEventMetaInfo(Optional.of(token), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [authentication_failed]\t{}, principal=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [authentication_failed]\t{}, principal=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), token.principal(), action, - arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName()); + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [authentication_failed]\t{}, principal=[{}], action=[{}], request=[{}]", + logger.info("{}[transport] [authentication_failed]\t{}, principal=[{}], action=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), token.principal(), action, - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } } } @@ -268,10 +270,11 @@ public void authenticationFailed(RestRequest request) { if (events.contains(AUTHENTICATION_FAILED) && (eventFilterPolicyRegistry.ignorePredicate().test(AuditEventMetaInfo.EMPTY) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [authentication_failed]\t{}, uri=[{}], request_body=[{}]", localNodeInfo.prefix, - hostAttributes(request), request.uri(), restRequestContent(request)); + logger.info("{}[rest] [authentication_failed]\t{}, uri=[{}]{}, request_body=[{}]", localNodeInfo.prefix, + hostAttributes(request), request.uri(), opaqueId(), restRequestContent(request)); } else { - logger.info("{}[rest] [authentication_failed]\t{}, uri=[{}]", localNodeInfo.prefix, hostAttributes(request), request.uri()); + logger.info("{}[rest] [authentication_failed]\t{}, uri=[{}]{}", localNodeInfo.prefix, + hostAttributes(request), request.uri(), opaqueId()); } } } @@ -284,12 +287,13 @@ public void authenticationFailed(String action, TransportMessage message) { .test(new AuditEventMetaInfo(Optional.empty(), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [authentication_failed]\t{}, action=[{}], indices=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + logger.info("{}[transport] [authentication_failed]\t{}, action=[{}], indices=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), action, + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [authentication_failed]\t{}, action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [authentication_failed]\t{}, action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), action, + message.getClass().getSimpleName(), opaqueId()); } } } @@ -301,11 +305,12 @@ public void authenticationFailed(AuthenticationToken token, RestRequest request) && (eventFilterPolicyRegistry.ignorePredicate() .test(new AuditEventMetaInfo(Optional.of(token), Optional.empty(), Optional.empty())) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [authentication_failed]\t{}, principal=[{}], uri=[{}], request_body=[{}]", localNodeInfo.prefix, - hostAttributes(request), token.principal(), request.uri(), restRequestContent(request)); + logger.info("{}[rest] [authentication_failed]\t{}, principal=[{}], uri=[{}]{}, request_body=[{}]", + localNodeInfo.prefix, hostAttributes(request), token.principal(), request.uri(), opaqueId(), + restRequestContent(request)); } else { - logger.info("{}[rest] [authentication_failed]\t{}, principal=[{}], uri=[{}]", localNodeInfo.prefix, hostAttributes(request), - token.principal(), request.uri()); + logger.info("{}[rest] [authentication_failed]\t{}, principal=[{}], uri=[{}]{}", + localNodeInfo.prefix, hostAttributes(request), token.principal(), request.uri(), opaqueId()); } } } @@ -320,13 +325,13 @@ public void authenticationFailed(String realm, AuthenticationToken token, String if (indices.isPresent()) { logger.info( "{}[transport] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], action=[{}], indices=[{}], " - + "request=[{}]", + + "request=[{}]{}", localNodeInfo.prefix, realm, originAttributes(threadContext, message, localNodeInfo), token.principal(), action, - arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName()); + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], action=[{}], request=[{}]", + logger.info("{}[transport] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], action=[{}], request=[{}]{}", localNodeInfo.prefix, realm, originAttributes(threadContext, message, localNodeInfo), token.principal(), action, - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } } } @@ -338,12 +343,13 @@ public void authenticationFailed(String realm, AuthenticationToken token, RestRe && (eventFilterPolicyRegistry.ignorePredicate() .test(new AuditEventMetaInfo(Optional.of(token), Optional.of(realm), Optional.empty())) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], uri=[{}], request_body=[{}]", - localNodeInfo.prefix, realm, hostAttributes(request), token.principal(), request.uri(), + logger.info("{}[rest] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], uri=[{}]{}, " + + "request_body=[{}]", + localNodeInfo.prefix, realm, hostAttributes(request), token.principal(), request.uri(), opaqueId(), restRequestContent(request)); } else { - logger.info("{}[rest] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], uri=[{}]", localNodeInfo.prefix, realm, - hostAttributes(request), token.principal(), request.uri()); + logger.info("{}[rest] [realm_authentication_failed]\trealm=[{}], {}, principal=[{}], uri=[{}]{}", + localNodeInfo.prefix, realm, hostAttributes(request), token.principal(), request.uri(), opaqueId()); } } } @@ -358,14 +364,14 @@ public void accessGranted(Authentication authentication, String action, Transpor Optional.of(effectiveRealmName(authentication)), Optional.of(roleNames), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [access_granted]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [access_granted]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), subject(authentication), arrayToCommaDelimitedString(roleNames), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [access_granted]\t{}, {}, roles=[{}], action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), subject(authentication), - arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [access_granted]\t{}, {}, roles=[{}], action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), subject(authentication), + arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName(), opaqueId()); } } } @@ -379,14 +385,14 @@ public void accessDenied(Authentication authentication, String action, Transport Optional.of(effectiveRealmName(authentication)), Optional.of(roleNames), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [access_denied]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [access_denied]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), subject(authentication), arrayToCommaDelimitedString(roleNames), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [access_denied]\t{}, {}, roles=[{}], action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), subject(authentication), - arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [access_denied]\t{}, {}, roles=[{}], action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), subject(authentication), + arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName(), opaqueId()); } } } @@ -396,10 +402,11 @@ localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), s public void tamperedRequest(RestRequest request) { if (events.contains(TAMPERED_REQUEST) && (eventFilterPolicyRegistry.ignorePredicate().test(AuditEventMetaInfo.EMPTY) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [tampered_request]\t{}, uri=[{}], request_body=[{}]", localNodeInfo.prefix, hostAttributes(request), - request.uri(), restRequestContent(request)); + logger.info("{}[rest] [tampered_request]\t{}, uri=[{}]{}, request_body=[{}]", localNodeInfo.prefix, + hostAttributes(request), request.uri(), opaqueId(), restRequestContent(request)); } else { - logger.info("{}[rest] [tampered_request]\t{}, uri=[{}]", localNodeInfo.prefix, hostAttributes(request), request.uri()); + logger.info("{}[rest] [tampered_request]\t{}, uri=[{}]{}", localNodeInfo.prefix, hostAttributes(request), + request.uri(), opaqueId()); } } } @@ -412,12 +419,13 @@ public void tamperedRequest(String action, TransportMessage message) { .test(new AuditEventMetaInfo(Optional.empty(), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [tampered_request]\t{}, action=[{}], indices=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + logger.info("{}[transport] [tampered_request]\t{}, action=[{}], indices=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), action, + arrayToCommaDelimitedString(indices.get()), message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [tampered_request]\t{}, action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [tampered_request]\t{}, action=[{}], request=[{}]{}", localNodeInfo.prefix, + originAttributes(threadContext, message, localNodeInfo), action, message.getClass().getSimpleName(), + opaqueId()); } } } @@ -431,13 +439,13 @@ public void tamperedRequest(User user, String action, TransportMessage request) .test(new AuditEventMetaInfo(Optional.of(user), Optional.empty(), Optional.empty(), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [tampered_request]\t{}, {}, action=[{}], indices=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, request, localNodeInfo), principal(user), action, - arrayToCommaDelimitedString(indices.get()), request.getClass().getSimpleName()); + logger.info("{}[transport] [tampered_request]\t{}, {}, action=[{}], indices=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, request, localNodeInfo), principal(user), action, + arrayToCommaDelimitedString(indices.get()), request.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [tampered_request]\t{}, {}, action=[{}], request=[{}]", localNodeInfo.prefix, + logger.info("{}[transport] [tampered_request]\t{}, {}, action=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, request, localNodeInfo), principal(user), action, - request.getClass().getSimpleName()); + request.getClass().getSimpleName(), opaqueId()); } } } @@ -446,16 +454,16 @@ public void tamperedRequest(User user, String action, TransportMessage request) @Override public void connectionGranted(InetAddress inetAddress, String profile, SecurityIpFilterRule rule) { if (events.contains(CONNECTION_GRANTED) && (eventFilterPolicyRegistry.ignorePredicate().test(AuditEventMetaInfo.EMPTY) == false)) { - logger.info("{}[ip_filter] [connection_granted]\torigin_address=[{}], transport_profile=[{}], rule=[{}]", localNodeInfo.prefix, - NetworkAddress.format(inetAddress), profile, rule); + logger.info("{}[ip_filter] [connection_granted]\torigin_address=[{}], transport_profile=[{}], rule=[{}]{}", + localNodeInfo.prefix, NetworkAddress.format(inetAddress), profile, rule, opaqueId()); } } @Override public void connectionDenied(InetAddress inetAddress, String profile, SecurityIpFilterRule rule) { if (events.contains(CONNECTION_DENIED) && (eventFilterPolicyRegistry.ignorePredicate().test(AuditEventMetaInfo.EMPTY) == false)) { - logger.info("{}[ip_filter] [connection_denied]\torigin_address=[{}], transport_profile=[{}], rule=[{}]", localNodeInfo.prefix, - NetworkAddress.format(inetAddress), profile, rule); + logger.info("{}[ip_filter] [connection_denied]\torigin_address=[{}], transport_profile=[{}], rule=[{}]{}", + localNodeInfo.prefix, NetworkAddress.format(inetAddress), profile, rule, opaqueId()); } } @@ -467,15 +475,14 @@ public void runAsGranted(Authentication authentication, String action, Transport Optional.of(effectiveRealmName(authentication)), Optional.of(roleNames), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [run_as_granted]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [run_as_granted]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), arrayToCommaDelimitedString(roleNames), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [run_as_granted]\t{}, {}, roles=[{}], action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), - arrayToCommaDelimitedString(roleNames), action, - message.getClass().getSimpleName()); + logger.info("{}[transport] [run_as_granted]\t{}, {}, roles=[{}], action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), + arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName(), opaqueId()); } } } @@ -489,14 +496,14 @@ public void runAsDenied(Authentication authentication, String action, TransportM Optional.of(effectiveRealmName(authentication)), Optional.of(roleNames), indices)) == false) { final LocalNodeInfo localNodeInfo = this.localNodeInfo; if (indices.isPresent()) { - logger.info("{}[transport] [run_as_denied]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]", + logger.info("{}[transport] [run_as_denied]\t{}, {}, roles=[{}], action=[{}], indices=[{}], request=[{}]{}", localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), arrayToCommaDelimitedString(roleNames), action, arrayToCommaDelimitedString(indices.get()), - message.getClass().getSimpleName()); + message.getClass().getSimpleName(), opaqueId()); } else { - logger.info("{}[transport] [run_as_denied]\t{}, {}, roles=[{}], action=[{}], request=[{}]", localNodeInfo.prefix, - originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), - arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName()); + logger.info("{}[transport] [run_as_denied]\t{}, {}, roles=[{}], action=[{}], request=[{}]{}", + localNodeInfo.prefix, originAttributes(threadContext, message, localNodeInfo), runAsSubject(authentication), + arrayToCommaDelimitedString(roleNames), action, message.getClass().getSimpleName(), opaqueId()); } } } @@ -508,12 +515,13 @@ public void runAsDenied(Authentication authentication, RestRequest request, Stri && (eventFilterPolicyRegistry.ignorePredicate().test(new AuditEventMetaInfo(Optional.of(authentication.getUser()), Optional.of(effectiveRealmName(authentication)), Optional.of(roleNames), Optional.empty())) == false)) { if (includeRequestBody) { - logger.info("{}[rest] [run_as_denied]\t{}, {}, roles=[{}], uri=[{}], request_body=[{}]", localNodeInfo.prefix, - hostAttributes(request), runAsSubject(authentication), arrayToCommaDelimitedString(roleNames), request.uri(), - restRequestContent(request)); + logger.info("{}[rest] [run_as_denied]\t{}, {}, roles=[{}], uri=[{}], request_body=[{}]{}", + localNodeInfo.prefix, hostAttributes(request), runAsSubject(authentication), + arrayToCommaDelimitedString(roleNames), request.uri(), restRequestContent(request), opaqueId()); } else { - logger.info("{}[rest] [run_as_denied]\t{}, {}, roles=[{}], uri=[{}]", localNodeInfo.prefix, hostAttributes(request), - runAsSubject(authentication), arrayToCommaDelimitedString(roleNames), request.uri()); + logger.info("{}[rest] [run_as_denied]\t{}, {}, roles=[{}], uri=[{}]{}", localNodeInfo.prefix, + hostAttributes(request), runAsSubject(authentication), arrayToCommaDelimitedString(roleNames), request.uri(), + opaqueId()); } } } @@ -558,6 +566,15 @@ protected static String originAttributes(ThreadContext threadContext, TransportM return restOriginTag(threadContext).orElse(transportOriginTag(message).orElse(localNodeInfo.localOriginTag)); } + private String opaqueId() { + String opaqueId = threadContext.getHeader(Task.X_OPAQUE_ID); + if (opaqueId != null) { + return ", opaque_id=[" + opaqueId + "]"; + } else { + return ""; + } + } + private static Optional restOriginTag(ThreadContext threadContext) { final InetSocketAddress restAddress = RemoteHostHeader.restRemoteAddress(threadContext); if (restAddress == null) { 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 408d3e797e5a3..1059e22abd663 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 @@ -25,6 +25,7 @@ import org.elasticsearch.common.xcontent.XContentType; import org.elasticsearch.mock.orig.Mockito; import org.elasticsearch.rest.RestRequest; +import org.elasticsearch.tasks.Task; import org.elasticsearch.test.ESTestCase; import org.elasticsearch.test.rest.FakeRestRequest; import org.elasticsearch.test.rest.FakeRestRequest.Builder; @@ -122,6 +123,7 @@ protected String expectedMessage() { private ClusterService clusterService; private ThreadContext threadContext; private boolean includeRequestBody; + private String opaqueId; @Before public void init() throws Exception { @@ -145,6 +147,13 @@ public void init() throws Exception { when(clusterService.getClusterSettings()).thenReturn(clusterSettings); prefix = LoggingAuditTrail.LocalNodeInfo.resolvePrefix(settings, localNode); threadContext = new ThreadContext(Settings.EMPTY); + if (randomBoolean()) { + String id = randomAlphaOfLength(10); + threadContext.putHeader(Task.X_OPAQUE_ID, id); + opaqueId = ", opaque_id=[" + id + "]"; + } else { + opaqueId = ""; + } } public void testAnonymousAccessDeniedTransport() throws Exception { @@ -155,10 +164,10 @@ public void testAnonymousAccessDeniedTransport() throws Exception { auditTrail.anonymousAccessDenied("_action", message); if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [anonymous_access_denied]\t" + origins + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [anonymous_access_denied]\t" + origins + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -179,10 +188,10 @@ public void testAnonymousAccessDeniedRest() throws Exception { auditTrail.anonymousAccessDenied(request); if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [anonymous_access_denied]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri], request_body=[" + expectedMessage + "]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, prefix + "[rest] [anonymous_access_denied]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId); } // test disabled @@ -202,10 +211,10 @@ public void testAuthenticationFailed() throws Exception { if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_failed]\t" + origins + ", principal=[_principal], action=[_action], indices=[" + indices(message) + - "], request=[MockIndicesRequest]"); + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_failed]\t" + origins + - ", principal=[_principal], action=[_action], request=[MockMessage]"); + ", principal=[_principal], action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -224,10 +233,10 @@ public void testAuthenticationFailedNoToken() throws Exception { auditTrail.authenticationFailed("_action", message); if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_failed]\t" + origins + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_failed]\t" + origins + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -248,11 +257,11 @@ public void testAuthenticationFailedRest() throws Exception { auditTrail.authenticationFailed(new MockToken(), request); if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [authentication_failed]\torigin_address=[" + - NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri], request_body=[" + + NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, prefix + "[rest] [authentication_failed]\torigin_address=[" + - NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]"); + NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]" + opaqueId); } // test disabled @@ -273,10 +282,10 @@ public void testAuthenticationFailedRestNoToken() throws Exception { auditTrail.authenticationFailed(request); if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [authentication_failed]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri], request_body=[" + expectedMessage + "]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, prefix + "[rest] [authentication_failed]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId); } // test disabled @@ -303,10 +312,10 @@ public void testAuthenticationFailedRealm() throws Exception { if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [realm_authentication_failed]\trealm=[_realm], " + origins + ", principal=[_principal], action=[_action], indices=[" + indices(message) + "], " + - "request=[MockIndicesRequest]"); + "request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [realm_authentication_failed]\trealm=[_realm], " + origins + - ", principal=[_principal], action=[_action], request=[MockMessage]"); + ", principal=[_principal], action=[_action], request=[MockMessage]" + opaqueId); } } @@ -327,11 +336,11 @@ public void testAuthenticationFailedRealmRest() throws Exception { auditTrail.authenticationFailed("_realm", new MockToken(), request); if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [realm_authentication_failed]\trealm=[_realm], origin_address=[" + - NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri], request_body=[" + + NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, prefix + "[rest] [realm_authentication_failed]\trealm=[_realm], origin_address=[" + - NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]"); + NetworkAddress.format(address) + "], principal=[_principal], uri=[_uri]" + opaqueId); } } @@ -353,10 +362,10 @@ public void testAccessGranted() throws Exception { : "principal=[_username], realm=[authRealm]") + ", roles=[" + role + "]"; if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", " + userInfo + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", " + userInfo + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -384,11 +393,11 @@ public void testAccessGrantedInternalSystemAction() throws Exception { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", principal=[" + SystemUser.INSTANCE.principal() + "], realm=[authRealm], roles=[" + role + "], action=[internal:_action], indices=[" + indices(message) - + "], request=[MockIndicesRequest]"); + + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", principal=[" + SystemUser.INSTANCE.principal() + "], realm=[authRealm], roles=[" + role - + "], action=[internal:_action], request=[MockMessage]"); + + "], action=[internal:_action], request=[MockMessage]" + opaqueId); } } @@ -410,10 +419,10 @@ public void testAccessGrantedInternalSystemActionNonSystemUser() throws Exceptio : "principal=[_username], realm=[authRealm]") + ", roles=[" + role + "]"; if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", " + userInfo + - ", action=[internal:_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[internal:_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [access_granted]\t" + origins + ", " + userInfo + - ", action=[internal:_action], request=[MockMessage]"); + ", action=[internal:_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -442,10 +451,10 @@ public void testAccessDenied() throws Exception { : "principal=[_username], realm=[authRealm]") + ", roles=[" + role + "]"; if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [access_denied]\t" + origins + ", " + userInfo + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [access_denied]\t" + origins + ", " + userInfo + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -466,10 +475,10 @@ public void testTamperedRequestRest() throws Exception { auditTrail.tamperedRequest(request); if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [tampered_request]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri], request_body=[" + expectedMessage + "]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, prefix + "[rest] [tampered_request]\torigin_address=[" + - NetworkAddress.format(address) + "], uri=[_uri]"); + NetworkAddress.format(address) + "], uri=[_uri]" + opaqueId); } // test disabled @@ -489,10 +498,10 @@ public void testTamperedRequest() throws Exception { auditTrail.tamperedRequest(action, message); if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [tampered_request]\t" + origins + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [tampered_request]\t" + origins + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -516,10 +525,10 @@ public void testTamperedRequestWithUser() throws Exception { auditTrail.tamperedRequest(user, action, message); if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [tampered_request]\t" + origins + ", " + userInfo + - ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + ", action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [tampered_request]\t" + origins + ", " + userInfo + - ", action=[_action], request=[MockMessage]"); + ", action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -537,7 +546,7 @@ public void testConnectionDenied() throws Exception { final SecurityIpFilterRule rule = new SecurityIpFilterRule(false, "_all"); auditTrail.connectionDenied(inetAddress, "default", rule); assertMsg(logger, Level.INFO, String.format(Locale.ROOT, prefix + - "[ip_filter] [connection_denied]\torigin_address=[%s], transport_profile=[%s], rule=[deny %s]", + "[ip_filter] [connection_denied]\torigin_address=[%s], transport_profile=[%s], rule=[deny %s]" + opaqueId, NetworkAddress.format(inetAddress), "default", "_all")); // test disabled @@ -562,7 +571,8 @@ public void testConnectionGranted() throws Exception { auditTrail = new LoggingAuditTrail(settings, clusterService, logger, threadContext); auditTrail.connectionGranted(inetAddress, "default", rule); assertMsg(logger, Level.INFO, String.format(Locale.ROOT, prefix + "[ip_filter] [connection_granted]\torigin_address=[%s], " + - "transport_profile=[default], rule=[allow default:accept_all]", NetworkAddress.format(inetAddress))); + "transport_profile=[default], rule=[allow default:accept_all]" + opaqueId, + NetworkAddress.format(inetAddress))); } public void testRunAsGranted() throws Exception { @@ -577,12 +587,12 @@ public void testRunAsGranted() throws Exception { assertMsg(logger, Level.INFO, prefix + "[transport] [run_as_granted]\t" + origins + ", principal=[_username], realm=[authRealm], run_as_principal=[running as], run_as_realm=[lookRealm], roles=[" - + role + "], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + + role + "], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [run_as_granted]\t" + origins + ", principal=[_username], realm=[authRealm], run_as_principal=[running as], run_as_realm=[lookRealm], roles=[" - + role + "], action=[_action], request=[MockMessage]"); + + role + "], action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -605,12 +615,12 @@ public void testRunAsDenied() throws Exception { assertMsg(logger, Level.INFO, prefix + "[transport] [run_as_denied]\t" + origins + ", principal=[_username], realm=[authRealm], run_as_principal=[running as], run_as_realm=[lookRealm], roles=[" - + role + "], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + + role + "], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [run_as_denied]\t" + origins + ", principal=[_username], realm=[authRealm], run_as_principal=[running as], run_as_realm=[lookRealm], roles=[" - + role + "], action=[_action], request=[MockMessage]"); + + role + "], action=[_action], request=[MockMessage]" + opaqueId); } // test disabled @@ -667,10 +677,11 @@ public void testAuthenticationSuccessRest() throws Exception { if (includeRequestBody) { assertMsg(logger, Level.INFO, prefix + "[rest] [authentication_success]\t" + userInfo + ", realm=[_realm], uri=[_uri], params=[" + params - + "], request_body=[" + expectedMessage + "]"); + + "]" + opaqueId + ", request_body=[" + expectedMessage + "]"); } else { assertMsg(logger, Level.INFO, - prefix + "[rest] [authentication_success]\t" + userInfo + ", realm=[_realm], uri=[_uri], params=[" + params + "]"); + prefix + "[rest] [authentication_success]\t" + userInfo + ", realm=[_realm], uri=[_uri], params=[" + params + + "]" + opaqueId); } // test disabled @@ -701,10 +712,10 @@ public void testAuthenticationSuccessTransport() throws Exception { auditTrail.authenticationSuccess(realm, user, "_action", message); if (message instanceof IndicesRequest) { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_success]\t" + origins + ", " + userInfo - + ", realm=[_realm], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]"); + + ", realm=[_realm], action=[_action], indices=[" + indices(message) + "], request=[MockIndicesRequest]" + opaqueId); } else { assertMsg(logger, Level.INFO, prefix + "[transport] [authentication_success]\t" + origins + ", " + userInfo - + ", realm=[_realm], action=[_action], request=[MockMessage]"); + + ", realm=[_realm], action=[_action], request=[MockMessage]" + opaqueId); } // test disabled