Merge pull request #3667 from adangel:issue-3644-invalidlogmessageformat

[java] InvalidLogMessageFormat - fix false positive with logstash #3667

* pr-3667:
  Use Set instead of array
  [java] InvalidLogMessageFormat - fix false positive with logstash

docs/pages/release_notes.md

@@ -49,6 +49,7 @@ not support all features of the latest EcmaScript standard.
 *   java-design
     *   [#3679](https://github.com/pmd/pmd/issues/3679): \[java] Make FinalFieldCouldBeStatic detect constant variable
 *   java-errorprone
+    *   [#3644](https://github.com/pmd/pmd/issues/3644): \[java] InvalidLogMessageFormat: false positives with logstash structured logging
     *   [#3686](https://github.com/pmd/pmd/issues/3686): \[java] ReturnEmptyCollectionRatherThanNull - false negative with conditioned returns
     *   [#3701](https://github.com/pmd/pmd/issues/3701): \[java] MissingStaticMethodInNonInstantiatableClass false positive with method inner classes
 *   java-performance

pmd-java/src/main/java/net/sourceforge/pmd/lang/java/rule/errorprone/InvalidLogMessageFormatRule.java

@@ -9,6 +9,7 @@ import java.util.Arrays;
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.HashSet;
+import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
@@ -48,6 +49,14 @@ public class InvalidLogMessageFormatRule extends AbstractJavaRule {
 
     private static final Map<String, Set<String>> LOGGERS;
 
+    /**
+     * Whitelisted methods of net.logstash.logback.argument.StructuredArguments
+     */
+    private static final Set<String> STRUCTURED_ARGUMENTS_METHODS = Collections.unmodifiableSet(new HashSet<>(
+            Arrays.asList("a", "array", "defer", "e",
+                    "entries", "f", "fields", "keyValue",
+                    "kv", "r", "raw", "v", "value")));
+
     static {
         Map<String, Set<String>> loggersMap = new HashMap<>();
 
@@ -116,16 +125,25 @@ public class InvalidLogMessageFormatRule extends AbstractJavaRule {
         final List<ASTExpression> argumentList = parentNode.getFirstChildOfType(ASTPrimarySuffix.class)
                 .getFirstDescendantOfType(ASTArgumentList.class).findChildrenOfType(ASTExpression.class);
 
-        if (argumentList.get(0).getType() != null && !argumentList.get(0).getType().equals(String.class)) {
+        // remove any arguments before the string message - these might be method calls for
-            if (argumentList.size() == 1) {
+        // logstash markers or structured arguments
-                // no need to check for message params in case no string and no params found
+        // this also removes any non-string value, e.g. a slf4j-Marker
-                return data;
+        // if the type cannot be determined, it is considered not to be a string...
+        Iterator<ASTExpression> iterator = argumentList.iterator();
+        while (iterator.hasNext()) {
+            ASTExpression argument = iterator.next();
+            if (!TypeTestUtil.isA(String.class, argument)) {
+                iterator.remove();
             } else {
-                // ignore the first argument if it is a known non-string value, e.g. a slf4j-Marker
+                break;
-                argumentList.remove(0);
             }
         }
 
+        if (argumentList.isEmpty()) {
+            // no need to check for message params in case no string message found
+            return data;
+        }
+
         // remove the message parameter
         final ASTExpression messageParam = argumentList.remove(0);
 
@@ -146,6 +164,12 @@ public class InvalidLogMessageFormatRule extends AbstractJavaRule {
             removeThrowableParam(argumentList);
         }
         
+        // remove any logstash structured arguments at the end
+        // but only, if there are not enough placeholders
+        if (argumentList.size() > expectedArguments) {
+            removePotentialStructuredArguments(argumentList.size() - expectedArguments, argumentList);
+        }
+
         int providedArguments = argumentList.size();
 
         // last argument could be an array with parameters
@@ -319,4 +343,50 @@ public class InvalidLogMessageFormatRule extends AbstractJavaRule {
         }
         return stringLiterals;
     }
+
+    /**
+     * Removes up to {@code maxArgumentsToRemove} arguments from the end of the {@code argumentList},
+     * if the argument is a method call to one of the whitelisted StructuredArguments methods.
+     *
+     * @param maxArgumentsToRemove
+     * @param argumentList
+     */
+    private void removePotentialStructuredArguments(int maxArgumentsToRemove, List<ASTExpression> argumentList) {
+        int removed = 0;
+        while (!argumentList.isEmpty() && removed < maxArgumentsToRemove) {
+            int lastIndex = argumentList.size() - 1;
+            ASTExpression argument = argumentList.get(lastIndex);
+            if (isStructuredArgumentMethodCall(argument)) {
+                argumentList.remove(lastIndex);
+                removed++;
+            } else {
+                // stop if something else is encountered
+                break;
+            }
+        }
+    }
+
+    /*
+     * └─ Expression == argument
+     *    └─ PrimaryExpression
+     *       ├─ PrimaryPrefix
+     *       │  └─ Name: eg. "keyValue" or "StructuredArguments.keyValue"
+     *       └─ PrimarySuffix
+     *          └─ Arguments
+     */
+    private boolean isStructuredArgumentMethodCall(ASTExpression argument) {
+        if (argument.getNumChildren() == 1 && argument.getChild(0) instanceof ASTPrimaryExpression) {
+            ASTPrimaryExpression primary = (ASTPrimaryExpression) argument.getChild(0);
+            if (primary.getNumChildren() == 2 && primary.getChild(1) instanceof ASTPrimarySuffix) {
+                ASTPrimaryPrefix prefix = (ASTPrimaryPrefix) primary.getChild(0);
+                ASTPrimarySuffix suffix = (ASTPrimarySuffix) primary.getChild(1);
+                if (suffix.isArguments() && prefix.getNumChildren() == 1 && prefix.getChild(0) instanceof ASTName) {
+                    ASTName name = (ASTName) prefix.getChild(0);
+                    return name.getImage().startsWith("StructuredArguments.")
+                        || STRUCTURED_ARGUMENTS_METHODS.contains(name.getImage());
+                }
+            }
+        }
+        return false;
+    }
 }

pmd-java/src/test/resources/net/sourceforge/pmd/lang/java/rule/errorprone/xml/InvalidLogMessageFormat.xml

@@ -811,8 +811,8 @@ public class InvalidLogMessageFormatTest {
 
     <test-code>
         <description>ignore slf4j-Markers when detecting the number of arguments #2250</description>
-        <expected-problems>2</expected-problems>
+        <expected-problems>1</expected-problems>
-        <expected-linenumbers>11,17</expected-linenumbers>
+        <expected-linenumbers>11</expected-linenumbers>
         <code><![CDATA[
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -830,7 +830,11 @@ public class InvalidLogMessageFormatTest {
         logger.warn(marker, "foo {}", "bar"); // correct: marker and one argument
 
         final var otherMarker = MarkerFactory.getMarker("OTHER_MARKER");
-        logger.warn(otherMarker, "foo"); // gets flagged as we can't statically determine the type of the "otherMarker" variable
+        // we can't statically determine the type of the "otherMarker" variable, so we assume it is not a string and ignore it
+        logger.warn(otherMarker, "foo");
+
+        final var message = "foo {} {}";
+        logger.warn(message, "a", "b"); // correct: first var is the message with expects two parameters
     }
 }
         ]]></code>
@@ -1039,6 +1043,45 @@ public class Foo {
             logger.trace(logMessage, param);
         }
     }
+}
+        ]]></code>
+    </test-code>
+
+    <test-code>
+        <description>[java] InvalidLogMessageFormat: false positives with logstash structured logging #3644</description>
+        <expected-problems>2</expected-problems>
+        <expected-linenumbers>27,29</expected-linenumbers>
+        <code><![CDATA[
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import net.logstash.logback.argument.StructuredArguments;
+import static net.logstash.logback.marker.Markers.*;
+import static net.logstash.logback.argument.StructuredArguments.*;
+
+public class Foo {
+    private static final Logger LOGGER = LoggerFactory.getLogger(Foo.class);
+
+    public void withMarkers() {
+        // Add "foo:bar" to the JSON output
+        LOGGER.info(append("foo", "bar"), "Some log message");
+        // Add "foo:bar,name:value" to the JSON output
+        LOGGER.info(append("foo", "bar").and(append("name", "value")), "Some log message");
+    }
+
+    public void withStructuredArguments() {
+        // Add "foo:bar" to JSON output and "bar" to log message
+        LOGGER.info("log message {}", value("foo", "bar"));
+        // Add "foo:bar" to JSON output only
+        LOGGER.info("log message", keyValue("foo", "bar"));
+        // Add "foo:bar" to JSON output only
+        LOGGER.info("log message", StructuredArguments.keyValue("foo", "bar"));
+        // Add "foo:bar" to JSON output only, but one parameter
+        LOGGER.info("log message: {}", "used parameter", keyValue("foo", "bar"));
+        // Add "foo:bar" to JSON output only - too many arguments!
+        LOGGER.info("log message", "unused parameter", keyValue("foo", "bar"));
+        // Add "foo:bar" to JSON output only - too less arguments!
+        LOGGER.info("log message {} {}", keyValue("foo", "bar"));
+    }
 }
         ]]></code>
     </test-code>