From d9bf6070661e519176fde5ea7049d19a46b30fd4 Mon Sep 17 00:00:00 2001 From: Ahmed Hussein <50450311+amahussein@users.noreply.github.com> Date: Thu, 3 Dec 2020 18:33:30 -0600 Subject: [PATCH] HADOOP-17389. KMS should log full UGI principal. (#2476) Signed-off-by: Akira Ajisaka Reviewed-by: Jim Brennan (cherry picked from commit 8c234fc0d4472b65ff555a79acb9a12f2dae3b27) --- .../crypto/key/kms/server/KMSAudit.java | 2 +- .../crypto/key/kms/server/KMSAuditLogger.java | 2 +- .../crypto/key/kms/server/TestKMSAudit.java | 88 ++++++++++--------- 3 files changed, 50 insertions(+), 42 deletions(-) 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 13a2d5c57a7..f546168e9be 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 @@ public class KMSAudit { 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 2e2ba1d6a1b..2534a44912c 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 @@ interface KMSAuditLogger { 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 09145be28a0..2f47ed794ac 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.Before; 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 @@ public class TestKMSAudit { } @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 class TestKMSAudit { 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 class TestKMSAudit { // 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 class TestKMSAudit { 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")