Reduce noise from NotEntitledException logging (#124511) (#124591)

* 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.

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

@@ -247,15 +247,17 @@ public class PolicyManager {
             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 class PolicyManager {
         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 class PolicyManager {
         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 @@ public class PolicyManager {
         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 class PolicyManager {
         }
         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 @@ public class PolicyManager {
             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.elasticsearch.test.jar.JarUtils;
 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 class PolicyManagerTests extends ESTestCase {
         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 @@ public class PolicyManagerTests extends ESTestCase {
         );
         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
+