Skip to content

Commit

Permalink
HADOOP-17389. KMS should log full UGI principal. (#2476)
Browse files Browse the repository at this point in the history 
Signed-off-by: Akira Ajisaka <aajisaka@apache.org>
Reviewed-by: Jim Brennan <jbrennan@apache.org>
(cherry picked from commit 8c234fc)
  • Loading branch information
@amahussein @Hexiaoqiao
amahussein authored and Hexiaoqiao committed Dec 8, 2020
1 parent 1d5ee50 commit 39b4f9d
Show file tree
Hide file tree
Showing 3 changed files with 50 additions and 42 deletions.
2 changes: 1 addition & 1 deletion ...on-project/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAudit.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)) {
Expand Down
2 changes: 1 addition & 1 deletion ...ject/hadoop-kms/src/main/java/org/apache/hadoop/crypto/key/kms/server/KMSAuditLogger.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
88 changes: 48 additions & 40 deletions ...roject/hadoop-kms/src/test/java/org/apache/hadoop/crypto/key/kms/server/TestKMSAudit.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,6 @@
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.Timeout;
import org.mockito.Mockito;

public class TestKMSAudit {

Expand All @@ -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) {
Expand Down Expand Up @@ -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");
Expand All @@ -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");
Expand All @@ -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();
Expand All @@ -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")
Expand Down

0 comments on commit 39b4f9d

Please sign in to comment.