Reduce noise from NotEntitledException logging (elastic#124511) (elastic#124592)

* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.

Author: prdoyle

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

@@ -247,15 +247,17 @@ private void neverEntitled(Class<?> callerClass, Supplier<String> operationDescr
             return;
         }
 
+        String componentName = getEntitlements(requestingClass).componentName();
         notEntitled(
             Strings.format(
-                "Not entitled: component [%s], module [%s], class [%s], operation [%s]",
-                getEntitlements(requestingClass).componentName(),
+                "component [%s], module [%s], class [%s], operation [%s]",
+                componentName,
                 requestingClass.getModule().getName(),
                 requestingClass,
                 operationDescription.get()
             ),
-            callerClass
+            callerClass,
+            componentName
         );
     }
 
@@ -366,13 +368,14 @@ public void checkFileRead(Class<?> callerClass, Path path, boolean followLinks)
         if (canRead == false) {
             notEntitled(
                 Strings.format(
-                    "Not entitled: component [%s], module [%s], class [%s], entitlement [file], operation [read], path [%s]",
+                    "component [%s], module [%s], class [%s], entitlement [file], operation [read], path [%s]",
                     entitlements.componentName(),
                     requestingClass.getModule().getName(),
                     requestingClass,
                     realPath == null ? path : Strings.format("%s -> %s", path, realPath)
                 ),
-                callerClass
+                callerClass,
+                entitlements.componentName()
             );
         }
     }
@@ -395,13 +398,14 @@ public void checkFileWrite(Class<?> callerClass, Path path) {
         if (entitlements.fileAccess().canWrite(path) == false) {
             notEntitled(
                 Strings.format(
-                    "Not entitled: component [%s], module [%s], class [%s], entitlement [file], operation [write], path [%s]",
+                    "component [%s], module [%s], class [%s], entitlement [file], operation [write], path [%s]",
                     entitlements.componentName(),
                     requestingClass.getModule().getName(),
                     requestingClass,
                     path
                 ),
-                callerClass
+                callerClass,
+                entitlements.componentName()
             );
         }
     }
@@ -483,13 +487,14 @@ private void checkFlagEntitlement(
         if (classEntitlements.hasEntitlement(entitlementClass) == false) {
             notEntitled(
                 Strings.format(
-                    "Not entitled: component [%s], module [%s], class [%s], entitlement [%s]",
+                    "component [%s], module [%s], class [%s], entitlement [%s]",
                     classEntitlements.componentName(),
                     requestingClass.getModule().getName(),
                     requestingClass,
                     PolicyParser.getEntitlementTypeName(entitlementClass)
                 ),
-                callerClass
+                callerClass,
+                classEntitlements.componentName()
             );
         }
         logger.debug(
@@ -524,21 +529,29 @@ public void checkWriteProperty(Class<?> callerClass, String property) {
         }
         notEntitled(
             Strings.format(
-                "Not entitled: component [%s], module [%s], class [%s], entitlement [write_system_properties], property [%s]",
+                "component [%s], module [%s], class [%s], entitlement [write_system_properties], property [%s]",
                 entitlements.componentName(),
                 requestingClass.getModule().getName(),
                 requestingClass,
                 property
             ),
-            callerClass
+            callerClass,
+            entitlements.componentName()
         );
     }
 
-    private void notEntitled(String message, Class<?> callerClass) {
+    private void notEntitled(String message, Class<?> callerClass, String componentName) {
         var exception = new NotEntitledException(message);
         // Don't emit a log for muted classes, e.g. classes containing self tests
         if (mutedClasses.contains(callerClass) == false) {
-            logger.warn(message, exception);
+            var moduleName = callerClass.getModule().getName();
+            var loggerSuffix = "." + componentName + "." + ((moduleName == null) ? ALL_UNNAMED : moduleName);
+            var notEntitledLogger = LogManager.getLogger(PolicyManager.class.getName() + loggerSuffix);
+            String frameInfoSuffix = StackWalker.getInstance(RETAIN_CLASS_REFERENCE)
+                .walk(this::findRequestingFrame)
+                .map(frame -> "\n\tat " + frame)
+                .orElse("");
+            notEntitledLogger.warn("Not entitled: " + message + frameInfoSuffix);
         }
         throw exception;
     }
@@ -658,19 +671,18 @@ Class<?> requestingClass(Class<?> callerClass) {
             return callerClass;
         }
         Optional<Class<?>> result = StackWalker.getInstance(RETAIN_CLASS_REFERENCE)
-            .walk(frames -> findRequestingClass(frames.map(StackFrame::getDeclaringClass)));
+            .walk(frames -> findRequestingFrame(frames).map(StackFrame::getDeclaringClass));
         return result.orElse(null);
     }
 
     /**
-     * Given a stream of classes corresponding to the frames from a {@link StackWalker},
-     * returns the module whose entitlements should be checked.
+     * Given a stream of {@link StackFrame}s, identify the one whose entitlements should be checked.
      *
      * @throws NullPointerException if the requesting module is {@code null}
      */
-    Optional<Class<?>> findRequestingClass(Stream<Class<?>> classes) {
-        return classes.filter(c -> c.getModule() != entitlementsModule)  // Ignore the entitlements library
-            .skip(1)                                           // Skip the sensitive caller method
+    Optional<StackFrame> findRequestingFrame(Stream<StackFrame> frames) {
+        return frames.filter(f -> f.getDeclaringClass().getModule() != entitlementsModule) // ignore entitlements library
+            .skip(1) // Skip the sensitive caller method
             .findFirst();
     }
 

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

@@ -23,6 +23,7 @@
 import org.junit.BeforeClass;
 
 import java.io.IOException;
+import java.lang.StackWalker.StackFrame;
 import java.lang.module.Configuration;
 import java.lang.module.ModuleFinder;
 import java.net.URL;
@@ -320,18 +321,21 @@ public void testRequestingModuleWithStackWalk() throws IOException, ClassNotFoun
         assertEquals(
             "Skip entitlement library and the instrumented method",
             requestingClass,
-            policyManager.findRequestingClass(Stream.of(entitlementsClass, instrumentedClass, requestingClass, ignorableClass)).orElse(null)
+            policyManager.findRequestingFrame(
+                Stream.of(entitlementsClass, instrumentedClass, requestingClass, ignorableClass).map(MockFrame::new)
+            ).map(StackFrame::getDeclaringClass).orElse(null)
         );
         assertEquals(
             "Skip multiple library frames",
             requestingClass,
-            policyManager.findRequestingClass(Stream.of(entitlementsClass, entitlementsClass, instrumentedClass, requestingClass))
-                .orElse(null)
+            policyManager.findRequestingFrame(
+                Stream.of(entitlementsClass, entitlementsClass, instrumentedClass, requestingClass).map(MockFrame::new)
+            ).map(StackFrame::getDeclaringClass).orElse(null)
         );
         assertThrows(
             "Non-modular caller frames are not supported",
             NullPointerException.class,
-            () -> policyManager.findRequestingClass(Stream.of(entitlementsClass, null))
+            () -> policyManager.findRequestingFrame(Stream.of(entitlementsClass, null).map(MockFrame::new))
         );
     }
 
@@ -657,4 +661,47 @@ private static ModuleLayer createLayerForJar(Path jar, String moduleName) {
         );
         return moduleController.layer();
     }
+
+    record MockFrame(Class<?> declaringClass) implements StackFrame {
+        @Override
+        public String getClassName() {
+            return getDeclaringClass().getName();
+        }
+
+        @Override
+        public String getMethodName() {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public Class<?> getDeclaringClass() {
+            return declaringClass;
+        }
+
+        @Override
+        public int getByteCodeIndex() {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public String getFileName() {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public int getLineNumber() {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public boolean isNativeMethod() {
+            throw new UnsupportedOperationException();
+        }
+
+        @Override
+        public StackTraceElement toStackTraceElement() {
+            throw new UnsupportedOperationException();
+        }
+    }
+
 }

modules/repository-gcs/src/main/config/log4j2.properties

@@ -0,0 +1,3 @@
+logger.org_elasticsearch_entitlement_runtime_policy_PolicyManager.name = org.elasticsearch.entitlement.runtime.policy.PolicyManager.repository-gcs.ALL-UNNAMED
+logger.org_elasticsearch_entitlement_runtime_policy_PolicyManager.level = error
+

modules/repository-s3/src/main/config/log4j2.properties

@@ -12,3 +12,7 @@ logger.com_amazonaws_auth_profile_internal_BasicProfileConfigFileLoader.level =
 
 logger.com_amazonaws_services_s3_internal_UseArnRegionResolver.name = com.amazonaws.services.s3.internal.UseArnRegionResolver
 logger.com_amazonaws_services_s3_internal_UseArnRegionResolver.level = error
+
+logger.org_elasticsearch_entitlement_runtime_policy_PolicyManager.name = org.elasticsearch.entitlement.runtime.policy.PolicyManager.repository-s3.software.amazon.awssdk.profiles
+logger.org_elasticsearch_entitlement_runtime_policy_PolicyManager.level = error
+