Provide opt-in flag to avoid fields name clash when log format is json (

#15969)

Adds log.format.json.fix_duplicate_message_fields feature flag to rename the clashing fields when json logging format (log.format) is selected.
In case two message fields clashes on structured log message, then the second is renamed attaching _1 suffix to the field name.
By default the feature is disabled and requires user to explicitly enable the behaviour.

Co-authored-by: Rob Bavey <[email protected]>

config/logstash.yml

@@ -314,6 +314,8 @@
 #   * json
 #
 # log.format: plain
+# log.format.json.fix_duplicate_message_fields: false
+#
 # path.logs:
 #
 # ------------ Other Settings --------------

docker/data/logstash/env2yaml/env2yaml.go

@@ -71,6 +71,7 @@ var validSettings = []string{
 	"http.port",        // DEPRECATED: prefer `api.http.port`
 	"log.level",
 	"log.format",
+	"log.format.json.fix_duplicate_message_fields",
 	"modules",
 	"metric.collect",
 	"path.logs",

docs/static/running-logstash-command-line.asciidoc

@@ -230,6 +230,9 @@ With this command, Logstash concatenates three config files, `/tmp/one`, `/tmp/t
    Specify if Logstash should write its own logs in JSON form (one event per line) or in plain text
    (using Ruby's Object#inspect). The default is "plain".
 
+*`--log.format.json.fix_duplicate_message_fields ENABLED`*::
+  Avoid `message` field collision using JSON log format. Possible values are `false` (default) and `true`.
+
 *`--path.settings SETTINGS_DIR`*::
   Set the directory containing the `logstash.yml` <<logstash-settings-file,settings file>> as well
   as the log4j logging configuration. This can also be set through the LS_SETTINGS_DIR environment variable.

docs/static/settings-file.asciidoc

@@ -336,6 +336,10 @@ The log level. Valid options are:
 | The log format. Set to `json` to log in JSON format, or `plain` to use `Object#.inspect`.
 | `plain`
 
+| `log.format.json.fix_duplicate_message_fields`
+| When the log format is `json` avoid collision of field names in log lines.
+| `false`
+
 | `path.logs`
 | The directory where Logstash will write its log to.
 | `LOGSTASH_HOME/logs`

docs/static/troubleshoot/ts-logstash.asciidoc

@@ -204,3 +204,65 @@ As the logging library used in Logstash is synchronous, heavy logging can affect
 *Solution*
 
 Reset the logging level to `info`.
+
+[[ts-pipeline-logging-json-duplicated-message-field]]
+==== Logging in json format can write duplicate `message` fields
+
+*Symptoms*
+
+When log format is `json` and certain log events (for example errors from JSON codec plugin)
+contains two instances of the `message` field.
+
+Without setting this flag, json log would contain objects like:
+
+[source,json]
+-----
+{
+   "level":"WARN",
+   "loggerName":"logstash.codecs.jsonlines",
+   "timeMillis":1712937761955,
+   "thread":"[main]<stdin",
+   "logEvent":{
+      "message":"JSON parse error, original data now in message field",
+      "message":"Unexpected close marker '}': expected ']' (for Array starting at [Source: (String)\"{\"name\": [}\"; line: 1, column: 10])\n at [Source: (String)\"{\"name\": [}\"; line: 1, column: 12]",
+      "exception":"LogStash::Json::ParserError",
+      "data":"{\"name\": [}"
+   }
+}
+-----
+
+Please note the duplication of `message` field, while being technically valid json, it is not always parsed correctly.
+
+*Solution*
+In `config/logstash.yml` enable the strict json flag:
+
+[source,yaml]
+-----
+log.format.json.fix_duplicate_message_fields: true
+-----
+
+or pass the command line switch
+
+[source]
+-----
+bin/logstash --log.format.json.fix_duplicate_message_fields true
+-----
+
+With `log.format.json.fix_duplicate_message_fields` enabled the duplication of `message` field is removed,
+adding to the field name a `_1` suffix:
+
+[source,json]
+-----
+{
+   "level":"WARN",
+   "loggerName":"logstash.codecs.jsonlines",
+   "timeMillis":1712937629789,
+   "thread":"[main]<stdin",
+   "logEvent":{
+      "message":"JSON parse error, original data now in message field",
+      "message_1":"Unexpected close marker '}': expected ']' (for Array starting at [Source: (String)\"{\"name\": [}\"; line: 1, column: 10])\n at [Source: (String)\"{\"name\": [}\"; line: 1, column: 12]",
+      "exception":"LogStash::Json::ParserError",
+      "data":"{\"name\": [}"
+   }
+}
+-----

logstash-core/lib/logstash/environment.rb

@@ -72,6 +72,7 @@ module Environment
            Setting::Boolean.new("help", false),
            Setting::Boolean.new("enable-local-plugin-development", false),
             Setting::String.new("log.format", "plain", true, ["json", "plain"]),
+           Setting::Boolean.new("log.format.json.fix_duplicate_message_fields", false),
            Setting::Boolean.new("api.enabled", true).with_deprecated_alias("http.enabled"),
             Setting::String.new("api.http.host", "127.0.0.1").with_deprecated_alias("http.host"),
          Setting::PortRange.new("api.http.port", 9600..9700).with_deprecated_alias("http.port"),
@@ -124,6 +125,7 @@ module Environment
   SETTINGS.on_post_process do |settings|
     # Configure Logstash logging facility. This needs to be done as early as possible to
     # make sure the logger has the correct settings tnd the log level is correctly defined.
+    java.lang.System.setProperty("ls.log.format.json.fix_duplicate_message_fields", settings.get("log.format.json.fix_duplicate_message_fields").to_s)
     java.lang.System.setProperty("ls.logs", settings.get("path.logs"))
     java.lang.System.setProperty("ls.log.format", settings.get("log.format"))
     java.lang.System.setProperty("ls.log.level", settings.get("log.level"))

logstash-core/lib/logstash/runner.rb

@@ -232,6 +232,11 @@ class LogStash::Runner < Clamp::StrictCommand
     :attribute_name => "log.format",
     :default => LogStash::SETTINGS.get_default("log.format")
 
+  option ["--log.format.json.fix_duplicate_message_fields"], "FORMAT_JSON_STRICT",
+    I18n.t("logstash.runner.flag.log_format_json_fix_duplicate_message_fields"),
+    :attribute_name => "log.format.json.fix_duplicate_message_fields",
+    :default => LogStash::SETTINGS.get_default("log.format.json.fix_duplicate_message_fields")
+
   option ["--path.settings"], "SETTINGS_DIR",
     I18n.t("logstash.runner.flag.path_settings"),
     :attribute_name => "path.settings",

logstash-core/locales/en.yml

@@ -423,6 +423,8 @@ en:
         log_format: |+
           Specify if Logstash should write its own logs in JSON form (one
           event per line) or in plain text (using Ruby's Object#inspect)
+        log_format_json_fix_duplicate_message_fields: |+
+          Enable to avoid duplication of message fields in JSON form.
         debug: |+
           Set the log level to debug.
           DEPRECATED: use --log.level=debug instead.

logstash-core/src/main/java/org/logstash/log/CustomLogEventSerializer.java

@@ -69,7 +69,9 @@ private void writeStructuredMessage(StructuredMessage message, JsonGenerator gen
         }
 
         for (final Map.Entry<Object, Object> entry : message.getParams().entrySet()) {
-            final String paramName = entry.getKey().toString();
+            // Given that message params is a map and the generator just started a new object, containing
+            // only one 'message' field, it could clash only on this field; fixit post-fixing it with '_1'
+            final String paramName = renameParamNameIfClashingWithMessage(entry);
             final Object paramValue = entry.getValue();
 
             try {
@@ -94,6 +96,16 @@ private void writeStructuredMessage(StructuredMessage message, JsonGenerator gen
         }
     }
 
+    private static String renameParamNameIfClashingWithMessage(Map.Entry<Object, Object> entry) {
+        final String paramName = entry.getKey().toString();
+        if ("message".equals(paramName)) {
+            if ("true".equalsIgnoreCase(System.getProperty("ls.log.format.json.fix_duplicate_message_fields"))) {
+                return "message_1";
+            }
+        }
+        return paramName;
+    }
+
     private boolean isValueSafeToWrite(Object value) {
         return value == null ||
                value instanceof String ||

logstash-core/src/test/java/org/logstash/log/CustomLogEventTests.java

@@ -59,9 +59,11 @@
 import static junit.framework.TestCase.assertFalse;
 import static junit.framework.TestCase.assertEquals;
 import static junit.framework.TestCase.assertNotNull;
+import static org.junit.Assert.assertTrue;
 
 public class CustomLogEventTests {
     private static final String CONFIG = "log4j2-test1.xml";
+    public static final String STRICT_JSON_PROPERTY_NAME = "ls.log.format.json.fix_duplicate_message_fields";
 
     @ClassRule
     public static LoggerContextRule CTX = new LoggerContextRule(CONFIG);
@@ -174,4 +176,34 @@ public void testJSONLayoutWithRubyObjectArgument() throws JsonProcessingExceptio
         assertEquals(1, logEventMapValue.get("first"));
         assertEquals(2, logEventMapValue.get("second"));
     }
+
+    @Test
+    @SuppressWarnings("unchecked")
+    public void testJSONLayoutWhenParamsContainsAnotherMessageField() throws JsonProcessingException {
+        String prevSetting = System.getProperty(STRICT_JSON_PROPERTY_NAME);
+        System.setProperty(STRICT_JSON_PROPERTY_NAME, Boolean.TRUE.toString());
+
+        ListAppender appender = CTX.getListAppender("JSONEventLogger").clear();
+        Logger logger = LogManager.getLogger("JSONEventLogger");
+
+        Map<String, String> paramsWithAnotherMessageField = Collections.singletonMap("message", "something to say");
+        logger.error("here is a map: {}", paramsWithAnotherMessageField);
+
+        List<String> messages = appender.getMessages();
+        assertEquals(1, messages.size());
+
+        Map<String, Object> loggedMessage = ObjectMappers.JSON_MAPPER.readValue(messages.get(0), Map.class);
+        assertEquals(5, loggedMessage.size());
+
+        Map<String, Object> actualLogEvent = (Map<String, Object>) loggedMessage.get("logEvent");
+        assertEquals("here is a map: {}", actualLogEvent.get("message"));
+        assertEquals("something to say", actualLogEvent.get("message_1"));
+
+        // tear down
+        if (prevSetting == null) {
+            System.clearProperty(STRICT_JSON_PROPERTY_NAME);
+        } else {
+            System.setProperty(STRICT_JSON_PROPERTY_NAME, prevSetting);
+        }
+    }
 }