time field not used in the default _time field of Splunk index for batched events

[stokpop]

splunk-library-javalogging version: 1.11.0
Splunk version: 8.2.2

We use splunk appender via logback. We use json formatter and sending batched log events to the HEC event endpoint (we do not use raw mode).

We expect to see the _time field in Splunk to contain the exact time as the logback message shows.

What we see is a _time without milliseconds and we see the same timestamp for all log events in one batch call. This timestamp in not equal to the time field in the log event messages.

After investigation we found that we need to have a time field in the meta/header info and not in the event part of the json message. See example 3 in HEC docs.

We checked this in a local test run by adding this line in com.splunk.logging.serialization.HecJsonSerializer#serialize (starting at line 51):

public String serialize(HttpEventCollectorEventInfo info) {
    Map<String, Object> event;
    if (this.eventHeaderSerializer != null) {
        event = eventHeaderSerializer.serializeEventHeader(info, new HashMap<>(template));
    } else {
        event = new HashMap<>(template);
        // added to get the _time field in sync: time field needs to be in the meta data of the event
        // see https://docs.splunk.com/Documentation/Splunk/8.2.2/Data/FormateventsforHTTPEventCollector
        event.put(TIME_FIELD, String.format(Locale.US, "%.3f", info.getTime()));
    }

It seems that a similar line was present in 1.7.3 before, can this behaviour be added back? This relates to #197 and the issues mentioned there.

(We could possibly use a custom EventBodySerializer to work around this (as mentioned in #197 also), but that feels like a workaround.)

One batch message before the fix:

{
    "index": "splunk_index",
    "sourcetype": "source_type",
    "source": "source",
    "event":
    {
        "severity": "INFO",
        "logger": "org.springframework.boot.actuate.endpoint.web.EndpointLinksResolver",
        "time": "1635150189.714",
        "thread": "main",
        "message":
        {
            "message": "Exposing 26 endpoint(s) beneath base path '/actuator'"
        }
    }
}

One batch message after the fix. Notice that the time field is now in there twice, it might be better to remove it from the event part:

{
    "index": "splunk_index",
    "sourcetype": "source_type",
    "source": "source",
    "time": "1635150451.888",
    "event":
    {
        "severity": "INFO",
        "logger": "org.springframework.boot.actuate.endpoint.web.EndpointLinksResolver",
        "time": "1635150451.888",
        "thread": "main",
        "message":
        {
            "message": "Exposing 26 endpoint(s) beneath base path '/actuator'"
        }
    }
}

[stokpop]

Hi @fantavlik and @tdhellmann, how can we get this in a release? This PR exists: #198 which is similar, but also removes some code. Can I help?

[bparmar-splunk]

Hi @stokpop,
I am closing this issue as PR related to this issue is merged.

Thanks.