LogStashFormatter can produce json output with duplicate properties

[hpetith]

Assume the following log format string (sample code in .NET):

log.Information("Received {message} at {timestamp}.", aMessage, aTimestamp);

The SeriLog json looks like this, no problem:

{
  "Timestamp": "2016-11-03T16:28:55.0094294+00:00",
  "Level": "Information",
  "MessageTemplate": "Received {message} at {timestamp}",
  "message": "Received foobar at 2016-10-03T 15:28:55.0094294+00:00",
  "Properties": {
    "message": "foobar",
    "timestamp": "2016-10-03T 15:28:55.0094294+00:00",
  }
}

When going through the LogStashFormatter, the flattened json has duplicate properties:

{
  "timestamp": "2016-11-03T16:28:55.0094294+00:00",
  "level": "Information",
  "message": "Received foobar at 2016-10-03T 15:28:55.0094294+00:00",
  "message": "foobar",
  "timestamp": "2016-10-03T 15:28:55.0094294+00:00",
}

This is invalid json. Depending on the behavior of the json parser used downstream, either the first or the last occurrence of properties with the same name wins, or the parser throws an error.

Of course this can be fixed in the application by forbidding the usage of log format string parameters names "message", "timestamp" and "level". This requires the application to know which logging sink is used downstream. With another logging sink downstream, the constraint does not exist (or would be different). Also, this does not solve the problem. Assume the application uses the log format string parameter "applicationClass", and somewhere downstream the log events are annotated by configuration with a property named "applicationClass" - the problem is the same.

The root of the problem is the fact that the LogStashFormatter flattens all properties from different levels into the top most json namespace. This mixes the LogStash format meta level properties, the format string parameter level, and the property annotation level into a single flat namespace.

LogStashFormatter should handle this in a better way. Knowing this is easily said: the obvious fixes (keeping the separation between the aspects by introducing structure, or adding prefixes/postfixes to the property names) will break existing downstream processing.

[tbdrake]

I came across this while working on #55 and wanted to add that this behavior was surprising to me, but it didn't cause as much of a problem as I would have thought in our system. And it seems that JSON with duplicate keys is still technically valid (though not recommended) based on the references in this stackoverflow answer.

The behavior I saw in our system was that the later key's value shows up in logs and the preceding duplicate keys' values do not. For example with the log JSON below, "traceId":"test" would show up and "traceId":"0af7651916cd43dd8448eb211c80319c" would not:

{
  "timestamp": "2016-11-03T16:28:55.0094294+00:00",
  "level": "Information",
  "message": "Received foobar at 2016-10-03T 15:28:55.0094294+00:00",
  "traceId":"0af7651916cd43dd8448eb211c80319c",
  "spanId":"b7ad6b7169203331",
  "traceId":"test"
}

Our project uses Serilog.Sinks.Network to send to a https://hub.docker.com/r/fluent/fluent-bit 2.1.8 container with the Logstash_Format option (see here) on. The fluent-bit container sends to an Amazon OpenSearch cluster.