Timestamp in Kibana different than in log files

[howiecamp]

In NLog I'm configuring a custom time source for Eastern Standard Time:

TimeSource.Current = new NLogHelpers.CustomTimeZoneTimeSource() { Zone = "Eastern Standard Time" };

And my NLog Elasticsearch configuration looks like this:

        ElasticSearchTarget esTarget = new ElasticSearchTarget();
        esTarget.Index = _elasticsearchIndex;
        esTarget.Uri = _elasticsearchUri;
        esTarget.RequireAuth = true;
        esTarget.Username = _elasticsearchUsername;
        esTarget.Password = _elasticsearchPassword;
        esTarget.Layout = _layout;
        esTarget.IncludeAllProperties = true;

        // See https://github.com/NLog/NLog/wiki/BufferingWrapper-target
        BufferingTargetWrapper buffWrapperTarget = new BufferingTargetWrapper();
        buffWrapperTarget.Name = "eswrapper";
        buffWrapperTarget.BufferSize = 20;
        buffWrapperTarget.FlushTimeout = -1;
        buffWrapperTarget.SlidingTimeout = true;
        buffWrapperTarget.OverflowAction = BufferingTargetWrapperOverflowAction.Flush;
        buffWrapperTarget.WrappedTarget = esTarget;

        _config.AddTarget(buffWrapperTarget);
        LoggingRule esRule = new LoggingRule("*", LogLevel.Info, buffWrapperTarget);
        _config.LoggingRules.Add(esRule);

I've also got file logging configured - an example log line is:

2018-08-10 4:26:59 PM|INFO|MyApp|Test log message

Here is the corresponding log entry as shown in Kibana:

Oddly (to me) the timestamp shows 12:26:59 PM. My current time is UTC-4, so if anything I'd expect that timestamp to be UTC, in otherwords, 8:26:59 PM, but it is showing as Eastern minus 4, which I don't understand. In the body of the log message you see that the correct time (4:26 PM - matches the log file) is shown.

The NLog Elasticsearch target does not appear to send a separate timestamp value (or does it?), so when setting up the index mapping in Kibana there's no timestamp field to choose from - so I just pick @timestamp. Where is the @timestamp as shown in Kibana coming from?

I'm asking this here before on Stackoverflow or the Elasticsearch forum because I want to understand the behavior of the target and if/how it's sending that timestamp value.

[markmcdowell]

The elasticsearch target populates the @timestamp from the log event. See:

https://github.com/ReactiveMarkets/NLog.Targets.ElasticSearch/blob/2e4738f18f9342a251cbcef3ef9e28be351a9974/src/NLog.Targets.ElasticSearch/ElasticSearchTarget.cs#L175

It may be that nlog always keeps the time in UTC and it formats it on output, i'm not certain on what it does.

[howiecamp]

This is helpful, thank you. What's odd is that even if NLog always kept the time in UTC is that the time I'm getting is not UTC but rather 4 hours behind EDT, which is UTC-8. So it's going in the wrong direction...

[snakefoot]

NLog doesn't do any conversion from the configured Time-Source. LogEventInfo.Timestamp will in this case return the local time.

My guess is that ElasticSearch always expects the timestamp to be in UTC. So this line:

https://github.com/ReactiveMarkets/NLog.Targets.ElasticSearch/blob/2e4738f18f9342a251cbcef3ef9e28be351a9974/src/NLog.Targets.ElasticSearch/ElasticSearchTarget.cs#L175

Should be changed to:

{"@timestamp", logEvent.TimeStamp.ToUniversalTime()},

[howiecamp]

@snakefoot Confused about something - if Elasticsearch always expects the timestamp in UTC then wouldn't that change be part of your codebase? I feel like I'm missing something...

[snakefoot]

@howiecamp What code base is "your codebase" ? If you mean NLog codebase, then you already know about how to configure NLog TimeSource. You can just use UTC if you like (Not like Elasticsearch is the only target for NLog).

If you mean "NLog.Targets.ElasticSearch"-code-base, then you should probably talk with @markmcdowell whether my suggestion is correct or not.

[howiecamp]

@Snakefoot Something else I just saw. As a test I changed my timesource from Eastern:

TimeSource.Current = new NLogHelpers.CustomTimeZoneTimeSource() { Zone = "Eastern Standard Time" };

to UTC:

TimeSource.Current = new AccurateUtcTimeSource();

and what I found was interesting. The timestamps - (1) and (2) below - didn't change at all. In fact those timestamp values only seem effected by Kibana's timezone (tz) setting. What did change to UTC was the time shown in the log message itself. For example in my log files:

and in Kibana:

Thoughts?

Final question - Why does the Elasticsearch target include the full layout, e.g.:

"${date:format=yyyy-MM-dd h\:mm\:ss tt}|${level:uppercase=true}|${logger}|${callsite}|${message}"

as the "message" field as shown in Kibana as opposed to just the actual ${message} part? Not complaining, just asking.

[snakefoot]

@howiecamp Sounds like you are saying that the kibana-timestamps are saved correctly, and are displayed according to kibana-timezone. But the Kibana-timezone doesn't affect any timestamp included inside the ${message}, which seems natural. So your issue has now been resolved, and can be closed.

Regarding the Layout, then you have full control of the layout, and can modify it to just be ${message}. The idea is to use field to include the individual parts of the log-events (Ex. ${callsite}, ${machinename}, ${threadid}, etc.). See also the wiki:

https://github.com/ReactiveMarkets/NLog.Targets.ElasticSearch/wiki

[howiecamp]

Thanks for your help. I agree, can be closed. I neglected to realize that the field is just a layout string, so as you said I can modify it to be just= ${message} itself, or whatever else, if I want. Further, I think I'm going to stop messing with the auto-generated timestamp and include my own application-specific timestamp in the event info by extending NLog.