Use child loggers broadly in PolicyManager (#124896)

* Use child loggers broadly in PolicyManager

* Pass ModuleEntitlements to notEntitled

* Store logger name instead of object.

Some of our unit tests check for equality of `ModuleEntitlements` objects,
and they are entitled to do so (no pun intended).

* Alright, let's cache 'em

* Memoize at point of creation, not point of use

* Explanatory comments

Author: prdoyle

libs/entitlement/src/main/java/org/elasticsearch/entitlement/runtime/policy/PolicyManager.java

@@ -59,7 +59,10 @@
 import static java.util.zip.ZipFile.OPEN_READ;
 
 public class PolicyManager {
-    private static final Logger logger = LogManager.getLogger(PolicyManager.class);
+    /**
+     * Use this if you don't have a {@link ModuleEntitlements} in hand.
+     */
+    private static final Logger generalLogger = LogManager.getLogger(PolicyManager.class);
 
     static final String UNKNOWN_COMPONENT_NAME = "(unknown)";
     static final String SERVER_COMPONENT_NAME = "(server)";
@@ -76,7 +79,8 @@ public class PolicyManager {
     record ModuleEntitlements(
         String componentName,
         Map<Class<? extends Entitlement>, List<Entitlement>> entitlementsByType,
-        FileAccessTree fileAccess
+        FileAccessTree fileAccess,
+        Logger logger
     ) {
 
         ModuleEntitlements {
@@ -101,8 +105,13 @@ private FileAccessTree getDefaultFileAccess(String componentName, Path component
     }
 
     // pkg private for testing
-    ModuleEntitlements defaultEntitlements(String componentName, Path componentPath) {
-        return new ModuleEntitlements(componentName, Map.of(), getDefaultFileAccess(componentName, componentPath));
+    ModuleEntitlements defaultEntitlements(String componentName, Path componentPath, String moduleName) {
+        return new ModuleEntitlements(
+            componentName,
+            Map.of(),
+            getDefaultFileAccess(componentName, componentPath),
+            getLogger(componentName, moduleName)
+        );
     }
 
     // pkg private for testing
@@ -116,7 +125,8 @@ ModuleEntitlements policyEntitlements(String componentName, Path componentPath,
         return new ModuleEntitlements(
             componentName,
             entitlements.stream().collect(groupingBy(Entitlement::getClass)),
-            FileAccessTree.of(componentName, moduleName, filesEntitlement, pathLookup, componentPath, exclusivePaths)
+            FileAccessTree.of(componentName, moduleName, filesEntitlement, pathLookup, componentPath, exclusivePaths),
+            getLogger(componentName, moduleName)
         );
     }
 
@@ -255,17 +265,17 @@ private void neverEntitled(Class<?> callerClass, Supplier<String> operationDescr
             return;
         }
 
-        String componentName = getEntitlements(requestingClass).componentName();
+        ModuleEntitlements entitlements = getEntitlements(requestingClass);
         notEntitled(
             Strings.format(
                 "component [%s], module [%s], class [%s], operation [%s]",
-                componentName,
+                entitlements.componentName(),
                 requestingClass.getModule().getName(),
                 requestingClass,
                 operationDescription.get()
             ),
             callerClass,
-            componentName
+            entitlements
         );
     }
 
@@ -323,7 +333,7 @@ public void checkFileRead(Class<?> callerClass, File file) {
     private static boolean isPathOnDefaultFilesystem(Path path) {
         var pathFileSystemClass = path.getFileSystem().getClass();
         if (path.getFileSystem().getClass() != DEFAULT_FILESYSTEM_CLASS) {
-            logger.trace(
+            generalLogger.trace(
                 () -> Strings.format(
                     "File entitlement trivially allowed: path [%s] is for a different FileSystem class [%s], default is [%s]",
                     path.toString(),
@@ -383,7 +393,7 @@ public void checkFileRead(Class<?> callerClass, Path path, boolean followLinks)
                     realPath == null ? path : Strings.format("%s -> %s", path, realPath)
                 ),
                 callerClass,
-                entitlements.componentName()
+                entitlements
             );
         }
     }
@@ -413,7 +423,7 @@ public void checkFileWrite(Class<?> callerClass, Path path) {
                     path
                 ),
                 callerClass,
-                entitlements.componentName()
+                entitlements
             );
         }
     }
@@ -502,18 +512,19 @@ private void checkFlagEntitlement(
                     PolicyParser.getEntitlementTypeName(entitlementClass)
                 ),
                 callerClass,
-                classEntitlements.componentName()
+                classEntitlements
             );
         }
-        logger.debug(
-            () -> Strings.format(
-                "Entitled: component [%s], module [%s], class [%s], entitlement [%s]",
-                classEntitlements.componentName(),
-                requestingClass.getModule().getName(),
-                requestingClass,
-                PolicyParser.getEntitlementTypeName(entitlementClass)
-            )
-        );
+        classEntitlements.logger()
+            .debug(
+                () -> Strings.format(
+                    "Entitled: component [%s], module [%s], class [%s], entitlement [%s]",
+                    classEntitlements.componentName(),
+                    requestingClass.getModule().getName(),
+                    requestingClass,
+                    PolicyParser.getEntitlementTypeName(entitlementClass)
+                )
+            );
     }
 
     public void checkWriteProperty(Class<?> callerClass, String property) {
@@ -524,15 +535,16 @@ public void checkWriteProperty(Class<?> callerClass, String property) {
 
         ModuleEntitlements entitlements = getEntitlements(requestingClass);
         if (entitlements.getEntitlements(WriteSystemPropertiesEntitlement.class).anyMatch(e -> e.properties().contains(property))) {
-            logger.debug(
-                () -> Strings.format(
-                    "Entitled: component [%s], module [%s], class [%s], entitlement [write_system_properties], property [%s]",
-                    entitlements.componentName(),
-                    requestingClass.getModule().getName(),
-                    requestingClass,
-                    property
-                )
-            );
+            entitlements.logger()
+                .debug(
+                    () -> Strings.format(
+                        "Entitled: component [%s], module [%s], class [%s], entitlement [write_system_properties], property [%s]",
+                        entitlements.componentName(),
+                        requestingClass.getModule().getName(),
+                        requestingClass,
+                        property
+                    )
+                );
             return;
         }
         notEntitled(
@@ -544,22 +556,34 @@ public void checkWriteProperty(Class<?> callerClass, String property) {
                 property
             ),
             callerClass,
-            entitlements.componentName()
+            entitlements
         );
     }
 
-    private void notEntitled(String message, Class<?> callerClass, String componentName) {
+    private void notEntitled(String message, Class<?> callerClass, ModuleEntitlements entitlements) {
         var exception = new NotEntitledException(message);
         // Don't emit a log for muted classes, e.g. classes containing self tests
         if (mutedClasses.contains(callerClass) == false) {
-            var moduleName = callerClass.getModule().getName();
-            var loggerSuffix = "." + componentName + "." + ((moduleName == null) ? ALL_UNNAMED : moduleName);
-            var notEntitledLogger = LogManager.getLogger(PolicyManager.class.getName() + loggerSuffix);
-            notEntitledLogger.warn("Not entitled:", exception);
+            entitlements.logger().warn("Not entitled:", exception);
         }
         throw exception;
     }
 
+    private static Logger getLogger(String componentName, String moduleName) {
+        var loggerSuffix = "." + componentName + "." + ((moduleName == null) ? ALL_UNNAMED : moduleName);
+        return MODULE_LOGGERS.computeIfAbsent(PolicyManager.class.getName() + loggerSuffix, LogManager::getLogger);
+    }
+
+    /**
+     * We want to use the same {@link Logger} object for a given name, because we want {@link ModuleEntitlements}
+     * {@code equals} and {@code hashCode} to work.
+     * <p>
+     * This would not be required if LogManager
+     * <a href="https://github.com/elastic/elasticsearch/issues/87511">memoized the loggers</a>,
+     * but here we are.
+     */
+    private static final ConcurrentHashMap<String, Logger> MODULE_LOGGERS = new ConcurrentHashMap<>();
+
     public void checkManageThreadsEntitlement(Class<?> callerClass) {
         checkEntitlementPresent(callerClass, ManageThreadsEntitlement.class);
     }
@@ -592,7 +616,7 @@ private ModuleEntitlements computeEntitlements(Class<?> requestingClass) {
         if (pluginName != null) {
             var pluginEntitlements = pluginsEntitlements.get(pluginName);
             if (pluginEntitlements == null) {
-                return defaultEntitlements(pluginName, sourcePaths.get(pluginName));
+                return defaultEntitlements(pluginName, sourcePaths.get(pluginName), requestingModule.getName());
             } else {
                 return getModuleScopeEntitlements(
                     pluginEntitlements,
@@ -613,7 +637,7 @@ private ModuleEntitlements computeEntitlements(Class<?> requestingClass) {
             );
         }
 
-        return defaultEntitlements(UNKNOWN_COMPONENT_NAME, null);
+        return defaultEntitlements(UNKNOWN_COMPONENT_NAME, null, requestingModule.getName());
     }
 
     private static String getScopeName(Module requestingModule) {
@@ -634,7 +658,7 @@ static Path getComponentPathFromClass(Class<?> requestingClass) {
             return Paths.get(codeSource.getLocation().toURI());
         } catch (Exception e) {
             // If we get a URISyntaxException, or any other Exception due to an invalid URI, we return null to safely skip this location
-            logger.info(
+            generalLogger.info(
                 "Cannot get component path for [{}]: [{}] cannot be converted to a valid Path",
                 requestingClass.getName(),
                 codeSource.getLocation().toString()
@@ -651,7 +675,7 @@ private ModuleEntitlements getModuleScopeEntitlements(
     ) {
         var entitlements = scopeEntitlements.get(scopeName);
         if (entitlements == null) {
-            return defaultEntitlements(componentName, componentPath);
+            return defaultEntitlements(componentName, componentPath, scopeName);
         }
         return policyEntitlements(componentName, componentPath, scopeName, entitlements);
     }
@@ -694,18 +718,18 @@ Optional<StackFrame> findRequestingFrame(Stream<StackFrame> frames) {
      * @return true if permission is granted regardless of the entitlement
      */
     private static boolean isTriviallyAllowed(Class<?> requestingClass) {
-        if (logger.isTraceEnabled()) {
-            logger.trace("Stack trace for upcoming trivially-allowed check", new Exception());
+        if (generalLogger.isTraceEnabled()) {
+            generalLogger.trace("Stack trace for upcoming trivially-allowed check", new Exception());
         }
         if (requestingClass == null) {
-            logger.debug("Entitlement trivially allowed: no caller frames outside the entitlement library");
+            generalLogger.debug("Entitlement trivially allowed: no caller frames outside the entitlement library");
             return true;
         }
         if (systemModules.contains(requestingClass.getModule())) {
-            logger.debug("Entitlement trivially allowed from system module [{}]", requestingClass.getModule().getName());
+            generalLogger.debug("Entitlement trivially allowed from system module [{}]", requestingClass.getModule().getName());
             return true;
         }
-        logger.trace("Entitlement not trivially allowed");
+        generalLogger.trace("Entitlement not trivially allowed");
         return false;
     }
 

libs/entitlement/src/test/java/org/elasticsearch/entitlement/runtime/policy/PolicyManagerTests.java

@@ -102,12 +102,12 @@ public void testGetEntitlementsThrowsOnMissingPluginUnnamedModule() {
 
         assertEquals(
             "No policy for the unnamed module",
-            policyManager.defaultEntitlements("plugin1", plugin1SourcePath),
+            policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName()),
             policyManager.getEntitlements(callerClass)
         );
 
         assertEquals(
-            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath)),
+            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName())),
             policyManager.moduleEntitlementsMap
         );
     }
@@ -132,12 +132,12 @@ public void testGetEntitlementsThrowsOnMissingPolicyForPlugin() {
 
         assertEquals(
             "No policy for this plugin",
-            policyManager.defaultEntitlements("plugin1", plugin1SourcePath),
+            policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName()),
             policyManager.getEntitlements(callerClass)
         );
 
         assertEquals(
-            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath)),
+            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName())),
             policyManager.moduleEntitlementsMap
         );
     }
@@ -160,18 +160,24 @@ public void testGetEntitlementsFailureIsCached() {
         var callerClass = this.getClass();
         var requestingModule = callerClass.getModule();
 
-        assertEquals(policyManager.defaultEntitlements("plugin1", plugin1SourcePath), policyManager.getEntitlements(callerClass));
         assertEquals(
-            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath)),
+            policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName()),
+            policyManager.getEntitlements(callerClass)
+        );
+        assertEquals(
+            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName())),
             policyManager.moduleEntitlementsMap
         );
 
         // A second time
-        assertEquals(policyManager.defaultEntitlements("plugin1", plugin1SourcePath), policyManager.getEntitlements(callerClass));
+        assertEquals(
+            policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName()),
+            policyManager.getEntitlements(callerClass)
+        );
 
         // Nothing new in the map
         assertEquals(
-            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath)),
+            Map.of(requestingModule, policyManager.defaultEntitlements("plugin1", plugin1SourcePath, requestingModule.getName())),
             policyManager.moduleEntitlementsMap
         );
     }
@@ -219,12 +225,15 @@ public void testGetEntitlementsThrowsOnMissingPolicyForServer() throws ClassNotF
 
         assertEquals(
             "No policy for this module in server",
-            policyManager.defaultEntitlements(SERVER_COMPONENT_NAME, mockServerSourcePath),
+            policyManager.defaultEntitlements(SERVER_COMPONENT_NAME, mockServerSourcePath, requestingModule.getName()),
             policyManager.getEntitlements(mockServerClass)
         );
 
         assertEquals(
-            Map.of(requestingModule, policyManager.defaultEntitlements(SERVER_COMPONENT_NAME, mockServerSourcePath)),
+            Map.of(
+                requestingModule,
+                policyManager.defaultEntitlements(SERVER_COMPONENT_NAME, mockServerSourcePath, requestingModule.getName())
+            ),
             policyManager.moduleEntitlementsMap
         );
     }