Option to convert client timestamps to the local time zone

[nblumhardt]

Some Serilog sinks, such as Console(), show timestamps in whatever time zone they're specified in. This makes logs from the client look inconsistent with logs from the server, since Serilog.Sinks.BrowserConsole sends events with UTC timestamps.

(There's no issue with the timestamps themselves - it's just a display problem.)

We might need to add options.ConvertToServerTimeZone or similar to deal with this.

[conficient]

Yes, I'd agree with converting the timestamps to the server's timezone so that they are consistent. Otherwise the client log events would be hard to align with server events correctly

[nblumhardt]

@conficient thanks for the note!

If the events are being forwarded off to some kind of log server, they'll all line up correctly - just in case it wasn't clear in my issue description. It's mainly an issue when writing to the console sink or plain-text log files, since the date formatting in these cases doesn't show the offset (in my case, +10 for the server logs, and 0 or Z in the JSON payloads being forwarded by the client.

If the destination sink accepts ISO 8601 timestamps, then the time zones will be reported correctly, and everything will interleave correctly in the display.

[tleylan]

Perhaps this can be solved by including some sort of GetTime() override? I assume the default behavior just checks the system time which Blazor (due to Mono is my understanding) only uses UTC. The following two lines demonstrate the issue.

2019-11-16 11:34:42.911 -05:00 [INF] HTTP GET /Message responded 200 in 1365.8701 ms
2019-11-16 16:34:58.325 +00:00 [INF] 11/16/2019 11:34:58 AM Demo1Base.IncrementCounter()

The first is on the server (the timestamp is local). The second one was sent by Serilog from the browser. Note the built-in time is UTC however I've included the actual browser time in the message.

I use a library https://github.com/Blazored/Localisation to get the actual time on the browser but I don't know how to get Serilog to use it.

[nblumhardt]

Hi @tleylan - I don't think client-side adjustment will help, this is a server-side behavior; the client (Blazor) is sending the correct timestamp, but there's no way for the client to know what time zone the server requires.

What we need is in:

serilog-sinks-browserhttp/src/Serilog.AspNetCore.Ingestion/AspNetCore/Ingestion/SerilogIngestionMiddleware.cs

Line 71 in 7b5e9eb

_log.Write(evt);

Here we could do:

if (_convertToLocalTime)
{
    var converted = new LogEvent(evt.Timestamp.ToLocalTime(), ...);
    _log.Write(converted);
}
else
{
    _log.Write(evt);
}

(Pseudocode warning :-))

[tleylan]

Hi @nblumhardt I appreciate your reply. Blazor sends UTC but doesn't include an offset. So the time here 2019-11-16 16:34:58.325 +00:00 [INF] is correct we just don't know the timezone (it was EST).
And I think you're correct we don't know what time the server wants.

It seems that if I could adjust the server generated items 2019-11-16 11:34:42.911 -05:00 [INF] to UTC with no offset then the timestamps would at least be sequential. I know where my server is so I could always calculate the actual time. Is there an easy way for my server timestamps to report an adjusted time with an +00:00 offset?

[nblumhardt]

@tleylan I just remembered: https://github.com/nblumhardt/serilog-sinks-timewarp/blob/master/Serilog.Sinks.TimeWarp/Program.cs

This would do it:

Log.Logger = new LoggerConfiguration()
    .WriteTo.TimeWarp(EveryDayIsLikeSunday,
        evt => evt.Timestamp.ToLocalTime(), // or ToUniversalTime()
        writeTo => writeTo.Console())
    .CreateLogger();

In an ideal world, Console() and File() would support specifying the output time zone, but packaging up TimeWarp() (or a more generic event transformation mechanism) may be a useful alternative.

The source for WriteTo.TimeWarp() is in the linked file; would be great to hear whether this does the job for you! 😎

[tleylan]

@nblumhardt There really is a sink for everything :-) Thank you I will definitely check it out.

@nblumhardt Well I checked it out and I have problems. I think I'll move the conversation to Gitter so you're not the only person having to help me.

[jwdonahue]

Log time stamps should always be UTC, everywhere, all the time. There is no other correct log time stamp. I was shocked to find that my console logging was local time. Even though it specifies the offset (default format), There certainly shouldn't be any difference in file logs vs console log time stamps. Finding that state just might be a show stopper for me.

Maybe a UTC time stamp enricher, and drop the serilog timestamp format specifier will work around this mess?

[jwdonahue]

So I solved my issue with it displaying local TZ:

    public class LogEnricher : ILogEventEnricher
    {
        private const string _dateTimeFormat = "yyyy-MM-dd HH:mm:ss.fff -00:00";
        private const string _timeFormat = "HH:mm:ss.fff -00:00";

        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            Verify.IsNotNull(propertyFactory);

            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                "ThreadId", Thread.CurrentThread.ManagedThreadId)!);

            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                "UTCDateTimeStamp", DateTime.UtcNow.ToString(_dateTimeFormat)!)!);

            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                "UTCTimeStamp", DateTime.UtcNow.ToString(_timeFormat)!)!);

        }
    }

        public static string ConsoleLoggerFormatString { get; set; } =
            "{UTCTimeStamp} [{Level:u3}] {Message:l}{Exception}{NewLine}";

        public static string FileLoggerFormatString { get; set; } =
            "{UTCDateTimeStamp} [{Level:u3}] {ThreadId} {Message:lj}{NewLine}{Exception}";

Using these on the server and clients, ensures that all of my logs are as time sync'd as they can be, without having to do any error prone math in my head.

[filmico]

Based on the @jwdonahue sample, I tweaked it a bit to add a Local Date Time correction.
I know this is not a good practice as it is better to store the UTC time and the Time Zone Info to be able to convert from one to the other but for this special case I was in need to just save the logs in local time.

        // Templace Local Time (Time Zone Removed)
        const string customTemplate = "{LocalTimeStamp} [{Level}] {Message}{NewLine}{Exception}";

        // Logger Definition
        ILogger logger = new LoggerConfiguration()
            .MinimumLevel.Debug()
            //.MinimumLevel.Information()
            .WriteTo.File(
                outputTemplate: customTemplate,
                path: pathFile,
            )
            .Enrich.With(new DateTimeEnricher())     // This will user the enricher class defined below
            .CreateLogger();

        // Enricher
        public class DateTimeEnricher : ILogEventEnricher
        {
            private const string _dateTimeFormat = "yyyy-MM-dd HH:mm:ss.fff -00:00";
            private const string _dateTimeFormat2 = "yyyy-MM-dd HH:mm:ss.fff";
            private const string _timeFormat = "HH:mm:ss.fff -00:00";

            public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
            {
                logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "UTCDateTimeStamp", DateTime.UtcNow.ToString(_dateTimeFormat)));

                logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "UTCTimeStamp", DateTime.UtcNow.ToString(_timeFormat)));

                logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "LocalTimeStamp", logEvent.Timestamp.ToLocalTime().ToString(_dateTimeFormat2)));
            }
        }