Add DEBUG logging for undefined role mapping field (#61887)

A role mapping with the following content:

    "rules": { "field": { "userid" : "admin" } }

will never match because `userid` is not a valid field. The correct
field is `username`.

This change adds DEBUG logging when an undefined field is referenced.

The choice to use DEBUG rather than INFO/WARN is that the set of
fields is partially dynamic (e.g. the `metadata.*` fields), so
it may be perfectly reasonable to check a field that is not defined
for that user. For example this rule:

    "rules": { "field": { "metadata.ranking" : "A" } }

would generate a log message for an unranked user, which would
erroneously suggest that such a rule is an error.
This DEBUG logging will assist in diagnosing problems, without
introducing that confusion.

Backport of: #61246

Co-authored-by: Elastic Machine <elasticmachine@users.noreply.github.com>

x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/support/mapper/expressiondsl/ExpressionModel.java

@@ -5,7 +5,11 @@
  */
 package org.elasticsearch.xpack.core.security.authc.support.mapper.expressiondsl;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.message.ParameterizedMessage;
 import org.elasticsearch.common.Numbers;
+import org.elasticsearch.common.Strings;
 
 import java.util.Collection;
 import java.util.Collections;
@@ -23,6 +27,8 @@ public class ExpressionModel {
 
     public static final Predicate<FieldExpression.FieldValue> NULL_PREDICATE = field -> field.getValue() == null;
 
+    private static final Logger logger = LogManager.getLogger();
+
     private final Map<String, Object> fieldValues;
     private final Map<String, Predicate<FieldExpression.FieldValue>> fieldPredicates;
 
@@ -54,7 +60,16 @@ public class ExpressionModel {
      */
     public boolean test(String field, List<FieldExpression.FieldValue> values) {
         final Predicate<FieldExpression.FieldValue> predicate = this.fieldPredicates.getOrDefault(field, NULL_PREDICATE);
-        return values.stream().anyMatch(predicate);
+        boolean isMatch = values.stream().anyMatch(predicate);
+        if (isMatch == false && predicate == NULL_PREDICATE && fieldPredicates.containsKey(field) == false) {
+            logger.debug(() -> new ParameterizedMessage("Attempt to test field [{}] against value(s) [{}]," +
+                " but the field [{}] does not have a value on this object;" +
+                " known fields are [{}]",
+                field, Strings.collectionToCommaDelimitedString(values),
+                field, Strings.collectionToCommaDelimitedString(fieldPredicates.keySet())));
+        }
+
+        return isMatch;
     }
 
     /**

x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/support/mapper/expressiondsl/FieldExpression.java

@@ -148,6 +148,11 @@ public final class FieldExpression implements RoleMapperExpression {
             return builder.value(value);
         }
 
+        @Override
+        public String toString() {
+            return Objects.toString(value);
+        }
+
         @Override
         public boolean equals(Object o) {
             if (this == o) {

x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/security/authc/support/mapper/expressiondsl/ExpressionModelTests.java

@@ -0,0 +1,106 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License;
+ * you may not use this file except in compliance with the Elastic License.
+ */
+
+package org.elasticsearch.xpack.core.security.authc.support.mapper.expressiondsl;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.message.Message;
+import org.elasticsearch.common.CheckedRunnable;
+import org.elasticsearch.common.logging.Loggers;
+import org.elasticsearch.test.ESTestCase;
+import org.elasticsearch.test.MockLogAppender;
+import org.elasticsearch.xpack.core.security.authc.support.mapper.expressiondsl.FieldExpression.FieldValue;
+import org.junit.Before;
+
+import java.util.ArrayList;
+import java.util.Collection;
+
+import org.elasticsearch.common.collect.List;
+
+import static org.hamcrest.Matchers.empty;
+import static org.hamcrest.Matchers.is;
+
+public class ExpressionModelTests extends ESTestCase {
+
+    @Before
+    public void enableDebugLogging() {
+        Loggers.setLevel(LogManager.getLogger(ExpressionModel.class), Level.DEBUG);
+    }
+
+    public void testCheckFailureAgainstUndefinedFieldLogsMessage() throws Exception {
+        ExpressionModel model = new ExpressionModel();
+        model.defineField("some_int", randomIntBetween(1, 99));
+
+        doWithLoggingExpectations(
+            List.of(new MockLogAppender.SeenEventExpectation(
+                "undefined field",
+                model.getClass().getName(),
+                Level.DEBUG,
+                "Attempt to test field [another_field] against value(s) [bork,bork!]," +
+                    " but the field [another_field] does not have a value on this object; known fields are [some_int]")),
+            () -> assertThat(
+                model.test("another_field", List.of(new FieldValue("bork"), new FieldValue("bork!"))),
+                is(false))
+        );
+    }
+
+    public void testCheckSuccessAgainstUndefinedFieldDoesNotLog() throws Exception {
+        ExpressionModel model = new ExpressionModel();
+        model.defineField("some_int", randomIntBetween(1, 99));
+
+        doWithLoggingExpectations(
+            List.of(new NoMessagesExpectation()),
+            () -> assertThat(model.test("another_field", List.of(new FieldValue(null))), is(true))
+        );
+    }
+
+    public void testCheckAgainstDefinedFieldDoesNotLog() throws Exception {
+        ExpressionModel model = new ExpressionModel();
+        model.defineField("some_int", randomIntBetween(1, 99));
+
+        doWithLoggingExpectations(
+            List.of(new NoMessagesExpectation()),
+            () -> assertThat(model.test("some_int", List.of(new FieldValue(randomIntBetween(100, 200)))), is(false))
+        );
+    }
+
+    private void doWithLoggingExpectations(Collection<? extends MockLogAppender.LoggingExpectation> expectations,
+                                           CheckedRunnable<Exception> body) throws Exception {
+        final Logger modelLogger = LogManager.getLogger(ExpressionModel.class);
+        final MockLogAppender mockAppender = new MockLogAppender();
+        mockAppender.start();
+        try {
+            Loggers.addAppender(modelLogger, mockAppender);
+            expectations.forEach(mockAppender::addExpectation);
+
+            body.run();
+
+            mockAppender.assertAllExpectationsMatched();
+        } finally {
+            Loggers.removeAppender(modelLogger, mockAppender);
+            mockAppender.stop();
+        }
+    }
+
+    private class NoMessagesExpectation implements MockLogAppender.LoggingExpectation {
+
+        private Collection<Message> messages = new ArrayList<>();
+
+        @Override
+        public void match(LogEvent event) {
+            messages.add(event.getMessage());
+        }
+
+        @Override
+        public void assertMatched() {
+            assertThat(messages, empty());
+        }
+    }
+
+}