The time value is wrong when outputting the log to console.

[bagualing]

Code：

package main

import (
    "fmt"
    "os"
    "time"

    "github.com/rs/zerolog"
    "github.com/rs/zerolog/log"
)

func main() {
    timeFormat := "2006-01-02 15:04:05"

    t := time.Now()
    fmt.Print("local zone: ")
    fmt.Println(t.Local().Zone())
    fmt.Println("def:", t.Format(timeFormat))
    fmt.Println("loc:", t.Local().Format(timeFormat))
    fmt.Println("utc:", t.UTC().Format(timeFormat))

    zerolog.TimeFieldFormat = timeFormat
    log.Print("hello world")

    log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: timeFormat})
    log.Info().Msg("Wrong time")
}

Output:

local zone: CST 28800 def: 2022-09-23 21:19:29 loc: 2022-09-23 21:19:29 utc: 2022-09-23 13:19:29 {"level":"debug","time":"2022-09-23 21:19:29","message":"hello world"} 2022-09-24 05:19:29 INF Wrong time

The local time is 2022-09-23 21:19:29 and the UTC time is 2022-09-23 13:19:29, but the console output time is 2022-09-24 05:19:29 . This issue is caused by #415 .

[pscheid92]

Ok, I think I understood the code base and how the behaviour above occurs. And I think it is an unfortunate case of "works as designed by Go". I have no idea if there is a need for a change; or how to fix this holistically.

Inner workings of ConsoleWriter

A ConsoleWriter takes the structured log output of zerolog as an argument and uses a json.Decoder to recreate a key-value map from it.

https://github.com/rs/zerolog/blob/55aaf043cf4d84249a6d2344ef18d82279d08955/console.go#L118-L125

It extracts the time field as a string in the format specified by zerolog.TimeFieldFormat. For instance, this byte array is copied from a debug session (using the default time format).

{"level":"info","time":"2022-10-06T20:04:38+02:00","message":"wrong time default"}

Later, zerolog uses the closure as returned by consoleDefaultFormatTimestamp() to parse & format the extracted time.

https://github.com/rs/zerolog/blob/55aaf043cf4d84249a6d2344ef18d82279d08955/console.go#L339-L345

It uses zerolog.TimeFieldFormat to parse the extracted time from string to time.Time. That is rightfully so because that is the exact time layout used to format the time in the first place.

Then it uses the time format layout given to the ConsoleWriter on creation by TimeFormat:

zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: "<here time format for console writer output>"}

So we take the parsed time.Time, convert it into our local time zone and format it as specified by TimeFormat:

ts.Local().Format(timeFormat) 

The result is the time string, as we see it printed later.

Reason for the observed behaviour

The time.Parse() method handles time layouts without a time zone indicator by assuming UTC.

Source: Go documentation for time package

In the absence of a time zone indicator, time.Parse() returns a time in UTC.

Remember above that we use zerolog.TimeFieldFormat to format and then parse the time again? In your example, the format is "2006-01-02 15:04:05" ... no time zone indicator.

Let's say ConsoleWriter sees the following log:

{"level":"info","time":"2022-10-06 20:54:52","message":"wrong time default"}

Parsing it again leads to "2022-10-06 20:54:52 UTC" (due to the missing time zone indicator). The formatting with ts.Local().Format(timeFormat) then converts from UTC to your local time zone again. Adding or subtracting the hours accordingly. Leading to the wrong output.

Solution

Add a time zone indicator to your layout so Go doesn't end up assuming UTC.

timeFormat := "2006-01-02 15:04:05 MST"

---

Maybe a diagram is more accessible than my kind of unstructured thoughts.

This happens when we use a time format without a time zone indicator. Go assumes UTC, and we falsely convert from UTC to our time zone again.

On the other hand: If we use a time format with a time zone indicator, Go can restore the time zone, doesn't convert, and the result is correct.

[bagualing]

@pscheid92 Thanks for your detailed answer, it's very clear.

I have a question: Is it possible to replace time.Parse() with time.ParseInLocation() to solve this problem?

zerolog/console.go

        case string:
            //ts, err := time.Parse(TimeFieldFormat, tt)
            ts, err := time.ParseInLocation(TimeFieldFormat, tt, time.Local)
            if err != nil {
                t = tt
            } else {
                t = ts.Local().Format(timeFormat)
            }

[pscheid92]

🤔 Could be a solution I think.

Go Documentation

ParseInLocation is like Parse but differs in two important ways. First, in the absence of time zone information, Parse interprets a time as UTC; ParseInLocation interprets the time as in the given location.

But I still try to wrap my head around the second remark:

Second, when given a zone offset or abbreviation, Parse tries to match it against the Local location; ParseInLocation uses the given location.

WDYT @rs?

[pscheid92]

Playing around with it locally looked good to me 🤔

[rs]

I'm fine with a local tz default on console writer.