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 8c234fc0d4472b65ff555a79acb9a12f2dae3b27)
diff --git a/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAudit.java b/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAudit.java
index 13a2d5c..f546168 100644
--- a/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAudit.java
+++ b/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAudit.java
@@ -191,7 +191,7 @@
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)) {
diff --git a/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAuditLogger.java b/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAuditLogger.java
index 2e2ba1d..2534a44 100644
--- a/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAuditLogger.java
+++ b/hadoop-common-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAuditLogger.java
@@ -77,7 +77,7 @@
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();
diff --git a/hadoop-common-project/hadoop-kms/src/test/java/org/apache/hadoop/crypto/key/kms/server/TestKMSAudit.java b/hadoop-common-project/hadoop-kms/src/test/java/org/apache/hadoop/crypto/key/kms/server/TestKMSAudit.java
index 09145be..2f47ed7 100644
--- a/hadoop-common-project/hadoop-kms/src/test/java/org/apache/hadoop/crypto/key/kms/server/TestKMSAudit.java
+++ b/hadoop-common-project/hadoop-kms/src/test/java/org/apache/hadoop/crypto/key/kms/server/TestKMSAudit.java
@@ -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 @@
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 @@
}
@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 @@
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 @@
// 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 @@
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")
