HADOOP-17389. KMS should log full UGI principal. (#2476)

Signed-off-by: Akira Ajisaka <aajisaka@apache.org>
Reviewed-by: Jim Brennan <jbrennan@apache.org>
(cherry picked from commit 8c234fc0d4)
This commit is contained in:
Ahmed Hussein 2020-12-03 18:33:30 -06:00 committed by Jim Brennan
parent 4628647067
commit 30c9f3920f
3 changed files with 50 additions and 42 deletions

View File

@ -191,7 +191,7 @@ private void logEvent(final OpStatus status, AuditEvent event) {
private void op(final OpStatus opStatus, final Object op,
final UserGroupInformation ugi, final String key, final String remoteHost,
final String extraMsg) {
final String user = ugi == null ? null: ugi.getShortUserName();
final String user = ugi == null ? null: ugi.getUserName();
if (!Strings.isNullOrEmpty(user) && !Strings.isNullOrEmpty(key)
&& (op != null)
&& AGGREGATE_OPS_WHITELIST.contains(op)) {

View File

@ -77,7 +77,7 @@ class AuditEvent {
this.user = null;
this.impersonator = null;
} else {
this.user = ugi.getShortUserName();
this.user = ugi.getUserName();
if (ugi.getAuthenticationMethod()
== UserGroupInformation.AuthenticationMethod.PROXY) {
this.impersonator = ugi.getRealUser().getUserName();

View File

@ -40,7 +40,6 @@
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.Timeout;
import org.mockito.Mockito;
public class TestKMSAudit {
@ -50,6 +49,8 @@ public class TestKMSAudit {
private PrintStream capturedOut;
private KMSAudit kmsAudit;
private UserGroupInformation luser =
UserGroupInformation.createUserForTesting("luser@REALM", new String[0]);
private static class FilterOut extends FilterOutputStream {
public FilterOut(OutputStream out) {
@ -95,10 +96,7 @@ private String getAndResetLogOutput() {
}
@Test
@SuppressWarnings("checkstyle:linelength")
public void testAggregation() throws Exception {
UserGroupInformation luser = Mockito.mock(UserGroupInformation.class);
Mockito.when(luser.getShortUserName()).thenReturn("luser");
kmsAudit.ok(luser, KMSOp.DECRYPT_EEK, "k1", "testmsg");
kmsAudit.ok(luser, KMSOp.DECRYPT_EEK, "k1", "testmsg");
kmsAudit.ok(luser, KMSOp.DECRYPT_EEK, "k1", "testmsg");
@ -120,27 +118,30 @@ public void testAggregation() throws Exception {
kmsAudit.evictCacheForTesting();
String out = getAndResetLogOutput();
System.out.println(out);
Assert.assertTrue(
out.matches(
"OK\\[op=DECRYPT_EEK, key=k1, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
boolean doesMatch = out.matches(
"OK\\[op=DECRYPT_EEK, key=k1, user=luser@REALM, accessCount=1, "
+ "interval=[^m]{1,4}ms\\] testmsg"
// Not aggregated !!
+ "OK\\[op=DELETE_KEY, key=k1, user=luser\\] testmsg"
+ "OK\\[op=ROLL_NEW_VERSION, key=k1, user=luser\\] testmsg"
+ "OK\\[op=INVALIDATE_CACHE, key=k1, user=luser\\] testmsg"
+ "OK\\[op=DELETE_KEY, key=k1, user=luser@REALM\\] testmsg"
+ "OK\\[op=ROLL_NEW_VERSION, key=k1, user=luser@REALM\\] testmsg"
+ "OK\\[op=INVALIDATE_CACHE, key=k1, user=luser@REALM\\] testmsg"
// Aggregated
+ "OK\\[op=DECRYPT_EEK, key=k1, user=luser, accessCount=6, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=DECRYPT_EEK, key=k1, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK, key=k1, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK, key=k1, user=luser, accessCount=3, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK_BATCH, key=k1, user=luser\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK_BATCH, key=k1, user=luser\\] testmsg"));
+ "OK\\[op=DECRYPT_EEK, key=k1, user=luser@REALM, accessCount=6, "
+ "interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=DECRYPT_EEK, key=k1, user=luser@REALM, accessCount=1, "
+ "interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK, key=k1, user=luser@REALM, "
+ "accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK, key=k1, user=luser@REALM, "
+ "accessCount=3, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK_BATCH, key=k1, user=luser@REALM\\] testmsg"
+ "OK\\[op=REENCRYPT_EEK_BATCH, key=k1, user=luser@REALM\\] "
+ "testmsg");
Assert.assertTrue(doesMatch);
}
@Test
@SuppressWarnings("checkstyle:linelength")
public void testAggregationUnauth() throws Exception {
UserGroupInformation luser = Mockito.mock(UserGroupInformation.class);
Mockito.when(luser.getShortUserName()).thenReturn("luser");
kmsAudit.unauthorized(luser, KMSOp.GENERATE_EEK, "k2");
kmsAudit.evictCacheForTesting();
kmsAudit.ok(luser, KMSOp.GENERATE_EEK, "k3", "testmsg");
@ -159,25 +160,29 @@ public void testAggregationUnauth() throws Exception {
// The UNAUTHORIZED will trigger cache invalidation, which then triggers
// the aggregated OK (accessCount=5). But the order of the UNAUTHORIZED and
// the aggregated OK is arbitrary - no correctness concerns, but flaky here.
Assert.assertTrue(out.matches(
"UNAUTHORIZED\\[op=GENERATE_EEK, key=k2, user=luser\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=5, interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=GENERATE_EEK, key=k3, user=luser\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg")
|| out.matches(
"UNAUTHORIZED\\[op=GENERATE_EEK, key=k2, user=luser\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=GENERATE_EEK, key=k3, user=luser\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=5, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"));
boolean doesMatch = out.matches(
"UNAUTHORIZED\\[op=GENERATE_EEK, key=k2, user=luser@REALM\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=1,"
+ " interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=5,"
+ " interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=GENERATE_EEK, key=k3, user=luser@REALM\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=1,"
+ " interval=[^m]{1,4}ms\\] testmsg");
doesMatch = doesMatch || out.matches(
"UNAUTHORIZED\\[op=GENERATE_EEK, key=k2, user=luser@REALM\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=1,"
+ " interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=GENERATE_EEK, key=k3, user=luser@REALM\\] "
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=5,"
+ " interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k3, user=luser@REALM, accessCount=1,"
+ " interval=[^m]{1,4}ms\\] testmsg");
Assert.assertTrue(doesMatch);
}
@Test
@SuppressWarnings("checkstyle:linelength")
public void testAuditLogFormat() throws Exception {
UserGroupInformation luser = Mockito.mock(UserGroupInformation.class);
Mockito.when(luser.getShortUserName()).thenReturn("luser");
kmsAudit.ok(luser, KMSOp.GENERATE_EEK, "k4", "testmsg");
kmsAudit.ok(luser, KMSOp.GENERATE_EEK, "testmsg");
kmsAudit.evictCacheForTesting();
@ -187,12 +192,15 @@ public void testAuditLogFormat() throws Exception {
String out = getAndResetLogOutput();
System.out.println(out);
Assert.assertTrue(out.matches(
"OK\\[op=GENERATE_EEK, key=k4, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, user=luser\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k4, user=luser, accessCount=1, interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=DECRYPT_EEK, key=k4, user=luser\\] "
+ "ERROR\\[user=luser\\] Method:'method' Exception:'testmsg'"
+ "UNAUTHENTICATED RemoteHost:remotehost Method:method URL:url ErrorMsg:'testmsg'"));
"OK\\[op=GENERATE_EEK, key=k4, user=luser@REALM, accessCount=1, "
+ "interval=[^m]{1,4}ms\\] testmsg"
+ "OK\\[op=GENERATE_EEK, user=luser@REALM\\] testmsg"
+ "OK\\[op=GENERATE_EEK, key=k4, user=luser@REALM, accessCount=1,"
+ " interval=[^m]{1,4}ms\\] testmsg"
+ "UNAUTHORIZED\\[op=DECRYPT_EEK, key=k4, user=luser@REALM\\] "
+ "ERROR\\[user=luser@REALM\\] Method:'method' Exception:'testmsg'"
+ "UNAUTHENTICATED RemoteHost:remotehost Method:method URL:url "
+ "ErrorMsg:'testmsg'"));
}
@SuppressWarnings("unchecked")