diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/DFSConfigKeys.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/DFSConfigKeys.java index 0e10bc61c99..1ab7edd6adc 100755 --- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/DFSConfigKeys.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/DFSConfigKeys.java @@ -628,6 +628,12 @@ public class DFSConfigKeys extends CommonConfigurationKeys { public static final String DFS_NAMENODE_READ_LOCK_REPORTING_THRESHOLD_MS_KEY = "dfs.namenode.read-lock-reporting-threshold-ms"; public static final long DFS_NAMENODE_READ_LOCK_REPORTING_THRESHOLD_MS_DEFAULT = 5000L; + + public static final String DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_KEY + = "dfs.namenode.access-control-enforcer-reporting-threshold-ms"; + public static final long DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_DEFAULT + = 1000L; + // Threshold for how long the lock warnings must be suppressed public static final String DFS_LOCK_SUPPRESS_WARNING_INTERVAL_KEY = "dfs.lock.suppress.warning.interval"; diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSDirectory.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSDirectory.java index d4fed21e98e..52ba4729a71 100644 --- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSDirectory.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSDirectory.java @@ -87,6 +87,8 @@ import java.util.concurrent.RecursiveAction; import static org.apache.hadoop.fs.CommonConfigurationKeys.FS_PROTECTED_DIRECTORIES; import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_NAMENODE_ACCESSTIME_PRECISION_DEFAULT; import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_NAMENODE_ACCESSTIME_PRECISION_KEY; +import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_DEFAULT; +import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_KEY; import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_QUOTA_BY_STORAGETYPE_ENABLED_DEFAULT; import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_QUOTA_BY_STORAGETYPE_ENABLED_KEY; import static org.apache.hadoop.hdfs.DFSConfigKeys.DFS_PROTECTED_SUBDIRECTORIES_ENABLE; @@ -181,6 +183,8 @@ public class FSDirectory implements Closeable { * ACL-related operations. */ private final boolean aclsEnabled; + /** Threshold to print a warning. */ + private final long accessControlEnforcerReportingThresholdMs; /** * Support for POSIX ACL inheritance. Not final for testing purpose. */ @@ -388,6 +392,10 @@ public class FSDirectory implements Closeable { DFS_PROTECTED_SUBDIRECTORIES_ENABLE, DFS_PROTECTED_SUBDIRECTORIES_ENABLE_DEFAULT); + this.accessControlEnforcerReportingThresholdMs = conf.getLong( + DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_KEY, + DFS_NAMENODE_ACCESS_CONTROL_ENFORCER_REPORTING_THRESHOLD_MS_DEFAULT); + Preconditions.checkArgument(this.inodeXAttrsLimit >= 0, "Cannot set a negative limit on the number of xattrs per inode (%s).", DFSConfigKeys.DFS_NAMENODE_MAX_XATTRS_PER_INODE_KEY); @@ -1869,7 +1877,8 @@ public class FSDirectory implements Closeable { UserGroupInformation ugi) throws AccessControlException { return new FSPermissionChecker( fsOwner, superGroup, ugi, getUserFilteredAttributeProvider(ugi), - useAuthorizationWithContextAPI); + useAuthorizationWithContextAPI, + accessControlEnforcerReportingThresholdMs); } void checkOwner(FSPermissionChecker pc, INodesInPath iip) diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSPermissionChecker.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSPermissionChecker.java index c7430e38cd0..00b726b928a 100644 --- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSPermissionChecker.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSPermissionChecker.java @@ -21,10 +21,13 @@ import java.io.IOException; import java.util.ArrayList; import java.util.Collection; import java.util.List; +import java.util.Optional; import java.util.Stack; +import java.util.function.LongFunction; import org.apache.hadoop.util.Preconditions; import org.apache.hadoop.ipc.CallerContext; +import org.apache.hadoop.util.Time; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.apache.hadoop.fs.FSExceptionMessages; @@ -87,19 +90,21 @@ public class FSPermissionChecker implements AccessControlEnforcer { private final boolean isSuper; private final INodeAttributeProvider attributeProvider; private final boolean authorizeWithContext; + private final long accessControlEnforcerReportingThresholdMs; private static ThreadLocal operationType = new ThreadLocal<>(); protected FSPermissionChecker(String fsOwner, String supergroup, UserGroupInformation callerUgi, INodeAttributeProvider attributeProvider) { - this(fsOwner, supergroup, callerUgi, attributeProvider, false); + this(fsOwner, supergroup, callerUgi, attributeProvider, false, 0); } protected FSPermissionChecker(String fsOwner, String supergroup, UserGroupInformation callerUgi, INodeAttributeProvider attributeProvider, - boolean useAuthorizationWithContextAPI) { + boolean useAuthorizationWithContextAPI, + long accessControlEnforcerReportingThresholdMs) { this.fsOwner = fsOwner; this.supergroup = supergroup; this.callerUgi = callerUgi; @@ -117,6 +122,38 @@ public class FSPermissionChecker implements AccessControlEnforcer { } else { authorizeWithContext = useAuthorizationWithContextAPI; } + this.accessControlEnforcerReportingThresholdMs + = accessControlEnforcerReportingThresholdMs; + } + + private String checkAccessControlEnforcerSlowness( + long elapsedMs, AccessControlEnforcer ace, + boolean checkSuperuser, AuthorizationContext context) { + return checkAccessControlEnforcerSlowness(elapsedMs, + accessControlEnforcerReportingThresholdMs, ace.getClass(), checkSuperuser, + context.getPath(), context.getOperationName(), + context.getCallerContext()); + } + + /** @return the warning message if there is any. */ + static String checkAccessControlEnforcerSlowness( + long elapsedMs, long thresholdMs, Class clazz, + boolean checkSuperuser, String path, String op, Object caller) { + if (!LOG.isWarnEnabled()) { + return null; + } + if (thresholdMs <= 0) { + return null; + } + if (elapsedMs > thresholdMs) { + final String message = clazz + " ran for " + + elapsedMs + "ms (threshold=" + thresholdMs + "ms) to check " + + (checkSuperuser ? "superuser" : "permission") + + " on " + path + " for " + op + " from caller " + caller; + LOG.warn(message, new Throwable("TRACE")); + return message; + } + return null; } public static void setOperationType(String opType) { @@ -139,9 +176,70 @@ public class FSPermissionChecker implements AccessControlEnforcer { return attributeProvider; } + @FunctionalInterface + interface CheckPermission { + void run() throws AccessControlException; + } + + static String runCheckPermission(CheckPermission checker, + LongFunction checkElapsedMs) throws AccessControlException { + final String message; + final long start = Time.monotonicNow(); + try { + checker.run(); + } finally { + final long end = Time.monotonicNow(); + message = checkElapsedMs.apply(end - start); + } + return message; + } + private AccessControlEnforcer getAccessControlEnforcer() { - return (attributeProvider != null) - ? attributeProvider.getExternalAccessControlEnforcer(this) : this; + final AccessControlEnforcer e = Optional.ofNullable(attributeProvider) + .map(p -> p.getExternalAccessControlEnforcer(this)) + .orElse(this); + if (e == this) { + return this; + } + // For an external AccessControlEnforcer, check for slowness. + return new AccessControlEnforcer() { + @Override + public void checkPermission( + String filesystemOwner, String superGroup, UserGroupInformation ugi, + INodeAttributes[] inodeAttrs, INode[] inodes, byte[][] pathByNameArr, + int snapshotId, String path, int ancestorIndex, boolean doCheckOwner, + FsAction ancestorAccess, FsAction parentAccess, FsAction access, + FsAction subAccess, boolean ignoreEmptyDir) + throws AccessControlException { + runCheckPermission( + () -> e.checkPermission(filesystemOwner, superGroup, ugi, + inodeAttrs, inodes, pathByNameArr, snapshotId, path, + ancestorIndex, doCheckOwner, ancestorAccess, parentAccess, + access, subAccess, ignoreEmptyDir), + elapsedMs -> checkAccessControlEnforcerSlowness(elapsedMs, + accessControlEnforcerReportingThresholdMs, + e.getClass(), false, path, operationType.get(), + CallerContext.getCurrent())); + } + + @Override + public void checkPermissionWithContext(AuthorizationContext context) + throws AccessControlException { + runCheckPermission( + () -> e.checkPermissionWithContext(context), + elapsedMs -> checkAccessControlEnforcerSlowness(elapsedMs, + e, false, context)); + } + + @Override + public void checkSuperUserPermissionWithContext( + AuthorizationContext context) throws AccessControlException { + runCheckPermission( + () -> e.checkSuperUserPermissionWithContext(context), + elapsedMs -> checkAccessControlEnforcerSlowness(elapsedMs, + e, true, context)); + } + }; } private AuthorizationContext getAuthorizationContextForSuperUser( diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestAuthorizationContext.java b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestAuthorizationContext.java index 1f52cf33ba1..f9d98d781e4 100644 --- a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestAuthorizationContext.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestAuthorizationContext.java @@ -103,7 +103,7 @@ public class TestAuthorizationContext { thenReturn(mockEnforcer); FSPermissionChecker checker = new FSPermissionChecker( - fsOwner, superGroup, ugi, mockINodeAttributeProvider, false); + fsOwner, superGroup, ugi, mockINodeAttributeProvider, false, 0); when(iip.getPathSnapshotId()).thenReturn(snapshotId); when(iip.getINodesArray()).thenReturn(inodes); @@ -128,7 +128,7 @@ public class TestAuthorizationContext { // force it to use the new, checkPermissionWithContext API. FSPermissionChecker checker = new FSPermissionChecker( - fsOwner, superGroup, ugi, mockINodeAttributeProvider, true); + fsOwner, superGroup, ugi, mockINodeAttributeProvider, true, 0); String operationName = "abc"; FSPermissionChecker.setOperationType(operationName); diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSPermissionChecker.java b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSPermissionChecker.java index 6312e92fd07..f13ed7efdcb 100644 --- a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSPermissionChecker.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSPermissionChecker.java @@ -40,6 +40,7 @@ import static org.mockito.Mockito.mock; import java.io.IOException; import java.util.Arrays; +import java.util.function.LongFunction; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.Path; @@ -52,6 +53,7 @@ import org.apache.hadoop.hdfs.server.namenode.FSDirectory.DirOp; import org.apache.hadoop.hdfs.server.namenode.snapshot.Snapshot; import org.apache.hadoop.security.AccessControlException; import org.apache.hadoop.security.UserGroupInformation; +import org.junit.Assert; import org.junit.Before; import org.junit.Test; import org.mockito.invocation.InvocationOnMock; @@ -446,4 +448,29 @@ public class TestFSPermissionChecker { parent.addChild(inodeFile); return inodeFile; } + + @Test + public void testCheckAccessControlEnforcerSlowness() throws Exception { + final long thresholdMs = 10; + final LongFunction checkAccessControlEnforcerSlowness = + elapsedMs -> FSPermissionChecker.checkAccessControlEnforcerSlowness( + elapsedMs, thresholdMs, INodeAttributeProvider.AccessControlEnforcer.class, + false, "/foo", "mkdir", "client"); + + final String m1 = FSPermissionChecker.runCheckPermission( + () -> FSPermissionChecker.LOG.info("Fast runner"), + checkAccessControlEnforcerSlowness); + Assert.assertNull(m1); + + final String m2 = FSPermissionChecker.runCheckPermission(() -> { + FSPermissionChecker.LOG.info("Slow runner"); + try { + Thread.sleep(20); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw new IllegalStateException(e); + } + }, checkAccessControlEnforcerSlowness); + Assert.assertNotNull(m2); + } }