Repository: rs/zerolog
Pull request #415 (2022-02-21 01:00:35)

Show local time in console
I think that in console we should be showing only local time. It is meant for developers, so local time is the best.


Patch:
diff --git a/README.md b/README.md
index 06e6a6d..95666b3 100644
--- a/README.md
+++ b/README.md
@@ -399,6 +399,8 @@ log.Logger = log.With().Str("foo", "bar").Logger()
 
 ### Add file and line number to log
 
+Equivalent of `Llongfile`:
+
 ```go
 log.Logger = log.With().Caller().Logger()
 log.Info().Msg("hello world")
@@ -406,6 +408,25 @@ log.Info().Msg("hello world")
 // Output: {"level": "info", "message": "hello world", "caller": "/go/src/your_project/some_file:21"}
 ```
 
+Equivalent of `Lshortfile`:
+
+```go
+zerolog.CallerMarshalFunc = func(file string, line int) string {
+    short := file
+    for i := len(file) - 1; i > 0; i-- {
+        if file[i] == '/' {
+            short = file[i+1:]
+            break
+        }
+    }
+    file = short
+    return file + ":" + strconv.Itoa(line)
+}
+log.Logger = log.With().Caller().Logger()
+log.Info().Msg("hello world")
+
+// Output: {"level": "info", "message": "hello world", "caller": "some_file:21"}
+```
 
 ### Thread-safe, lock-free, non-blocking writer
 
@@ -560,7 +581,7 @@ func main() {
 // Output (Line 1: Console; Line 2: Stdout)
 // 12:36PM INF Hello World!
 // {"level":"info","time":"2019-11-07T12:36:38+03:00","message":"Hello World!"}
-``` 
+```
 
 ## Global Settings
 
@@ -604,7 +625,7 @@ Most fields are also available in the slice format (`Strs` for `[]string`, `Errs
 
 ## Binary Encoding
 
-In addition to the default JSON encoding, `zerolog` can produce binary logs using [CBOR](http://cbor.io) encoding. The choice of encoding can be decided at compile time using the build tag `binary_log` as follows:
+In addition to the default JSON encoding, `zerolog` can produce binary logs using [CBOR](https://cbor.io) encoding. The choice of encoding can be decided at compile time using the build tag `binary_log` as follows:
 
 ```bash
 go build -tags binary_log .
diff --git a/console.go b/console.go
index a3fb542..1c3391f 100644
--- a/console.go
+++ b/console.go
@@ -63,6 +63,9 @@ type ConsoleWriter struct {
 	// PartsExclude defines parts to not display in output.
 	PartsExclude []string
 
+	// FieldsExclude defines contextual fields to not display in output.
+	FieldsExclude []string
+
 	FormatTimestamp     Formatter
 	FormatLevel         Formatter
 	FormatCaller        Formatter
@@ -121,6 +124,7 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) {
 
 	for _, p := range w.PartsOrder {
 		w.writePart(buf, evt, p)
+		delete(evt, p)
 	}
 
 	w.writeFields(evt, buf)
@@ -137,6 +141,17 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) {
 func (w ConsoleWriter) writeFields(evt map[string]interface{}, buf *bytes.Buffer) {
 	var fields = make([]string, 0, len(evt))
 	for field := range evt {
+		var isExcluded bool
+		for _, excluded := range w.FieldsExclude {
+			if field == excluded {
+				isExcluded = true
+				break
+			}
+		}
+		if isExcluded {
+			continue
+		}
+
 		switch field {
 		case LevelFieldName, TimestampFieldName, MessageFieldName, CallerFieldName:
 			continue
@@ -317,7 +332,7 @@ func consoleDefaultFormatTimestamp(timeFormat string, noColor bool) Formatter {
 			if err != nil {
 				t = tt
 			} else {
-				t = ts.Format(timeFormat)
+				t = ts.Local().Format(timeFormat)
 			}
 		case json.Number:
 			i, err := tt.Int64()
@@ -333,7 +348,7 @@ func consoleDefaultFormatTimestamp(timeFormat string, noColor bool) Formatter {
 					nsec = int64(time.Duration(i) * time.Microsecond)
 					sec = 0
 				}
-				ts := time.Unix(sec, nsec).UTC()
+				ts := time.Unix(sec, nsec)
 				t = ts.Format(timeFormat)
 			}
 		}
diff --git a/ctx.go b/ctx.go
index 966d17e..44d3f4b 100644
--- a/ctx.go
+++ b/ctx.go
@@ -25,9 +25,9 @@ type ctxKey struct{}
 //     l.UpdateContext(func(c Context) Context {
 //         return c.Str("bar", "baz")
 //     })
-func (l *Logger) WithContext(ctx context.Context) context.Context {
+func (l Logger) WithContext(ctx context.Context) context.Context {
 	if lp, ok := ctx.Value(ctxKey{}).(*Logger); ok {
-		if lp == l {
+		if lp == &l {
 			// Do not store same logger.
 			return ctx
 		}
@@ -35,7 +35,7 @@ func (l *Logger) WithContext(ctx context.Context) context.Context {
 		// Do not store disabled logger.
 		return ctx
 	}
-	return context.WithValue(ctx, ctxKey{}, l)
+	return context.WithValue(ctx, ctxKey{}, &l)
 }
 
 // Ctx returns the Logger associated with the ctx. If no logger
diff --git a/go.mod b/go.mod
index 746596d..e5fcd6f 100644
--- a/go.mod
+++ b/go.mod
@@ -6,5 +6,5 @@ require (
 	github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534
 	github.com/mattn/go-colorable v0.1.12
 	github.com/pkg/errors v0.9.1
-	github.com/rs/xid v1.3.0
+	github.com/rs/xid v1.4.0
 )
diff --git a/go.sum b/go.sum
index d8f860b..d32e91d 100644
--- a/go.sum
+++ b/go.sum
@@ -1,5 +1,3 @@
-github.com/coreos/go-systemd/v22 v22.3.2 h1:D9/bQk5vlXQFZ6Kwuu6zaiXJ9oTPe68++AzAJc1DzSI=
-github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534 h1:rtAn27wIbmOGUs7RIbVgPEjb31ehTVniDwPGXyMxm5U=
 github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
@@ -9,8 +7,8 @@ github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9
 github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
-github.com/rs/xid v1.3.0 h1:6NjYksEUlhurdVehpc7S7dk6DAmcKv8V9gG0FsVN2U4=
-github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/xid v1.4.0 h1:qd7wPTDkN6KQx2VmMBLrpHkiyQwgFXRnkOLacUiaSNY=
+github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
 golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo=
 golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
diff --git a/log.go b/log.go
index 3ae1b5b..efd2a33 100644
--- a/log.go
+++ b/log.go
@@ -99,6 +99,7 @@
 package zerolog
 
 import (
+	"errors"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -189,6 +190,21 @@ func ParseLevel(levelStr string) (Level, error) {
 	return Level(i), nil
 }
 
+// UnmarshalText implements encoding.TextUnmarshaler to allow for easy reading from toml/yaml/json formats
+func (l *Level) UnmarshalText(text []byte) error {
+	if l == nil {
+		return errors.New("can't unmarshal a nil *Level")
+	}
+	var err error
+	*l, err = ParseLevel(string(text))
+	return err
+}
+
+// MarshalText implements encoding.TextMarshaler to allow for easy writing into toml/yaml/json formats
+func (l Level) MarshalText() ([]byte, error) {
+	return []byte(LevelFieldMarshalFunc(l)), nil
+}
+
 // A Logger represents an active logging object that generates lines
 // of JSON output to an io.Writer. Each logging operation makes a single
 // call to the Writer's Write method. There is no guarantee on access


Test patch:
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
index b9bcccf..05d9426 100644
--- a/.github/workflows/test.yml
+++ b/.github/workflows/test.yml
@@ -14,7 +14,7 @@ jobs:
         go-version: ${{ matrix.go-version }}
     - name: Checkout code
       uses: actions/checkout@v2
-    - uses: actions/cache@v2
+    - uses: actions/cache@v3.0.1
       with:
         path: ~/go/pkg/mod
         key: ${{ runner.os }}-go-${{ hashFiles('**/go.sum') }}
diff --git a/console_test.go b/console_test.go
index 2b9ccb7..0a6e88a 100644
--- a/console_test.go
+++ b/console_test.go
@@ -108,13 +108,14 @@ func TestConsoleWriter(t *testing.T) {
 		buf := &bytes.Buffer{}
 		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
 
-		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		ts := time.Unix(0, 0)
+		d := ts.UTC().Format(time.RFC3339)
 		_, err := w.Write([]byte(`{"time": "` + d + `", "level": "debug", "message": "Foobar", "foo": "bar"}`))
 		if err != nil {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "12:00AM DBG Foobar foo=bar\n"
+		expectedOutput := ts.Format(time.Kitchen) + " DBG Foobar foo=bar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -136,7 +137,7 @@ func TestConsoleWriter(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "Jan  1 00:20:34.000 DBG Foobar foo=bar\n"
+		expectedOutput := time.Unix(1234, 0).Format(time.StampMilli) + " DBG Foobar foo=bar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -158,7 +159,7 @@ func TestConsoleWriter(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "Jan  1 00:20:34.567 DBG Foobar foo=bar\n"
+		expectedOutput := time.Unix(1234, 567000000).Format(time.StampMilli) + " DBG Foobar foo=bar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -180,7 +181,7 @@ func TestConsoleWriter(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "Jan  1 00:20:34.567891 DBG Foobar foo=bar\n"
+		expectedOutput := time.Unix(1234, 567891000).Format(time.StampMicro) + " DBG Foobar foo=bar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -239,7 +240,8 @@ func TestConsoleWriter(t *testing.T) {
 		buf := &bytes.Buffer{}
 		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
 
-		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		ts := time.Unix(0, 0)
+		d := ts.UTC().Format(time.RFC3339)
 		evt := `{"time": "` + d + `", "level": "error", "message": "Foobar", "aaa": "bbb", "error": "Error"}`
 		// t.Log(evt)
 
@@ -248,7 +250,7 @@ func TestConsoleWriter(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "12:00AM ERR Foobar error=Error aaa=bbb\n"
+		expectedOutput := ts.Format(time.Kitchen) + " ERR Foobar error=Error aaa=bbb\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -264,7 +266,8 @@ func TestConsoleWriter(t *testing.T) {
 			t.Fatalf("Cannot get working directory: %s", err)
 		}
 
-		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		ts := time.Unix(0, 0)
+		d := ts.UTC().Format(time.RFC3339)
 		evt := `{"time": "` + d + `", "level": "debug", "message": "Foobar", "foo": "bar", "caller": "` + cwd + `/foo/bar.go"}`
 		// t.Log(evt)
 
@@ -273,7 +276,7 @@ func TestConsoleWriter(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "12:00AM DBG foo/bar.go > Foobar foo=bar\n"
+		expectedOutput := ts.Format(time.Kitchen) + " DBG foo/bar.go > Foobar foo=bar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -305,7 +308,8 @@ func TestConsoleWriterConfiguration(t *testing.T) {
 		buf := &bytes.Buffer{}
 		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, TimeFormat: time.RFC3339}
 
-		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		ts := time.Unix(0, 0)
+		d := ts.UTC().Format(time.RFC3339)
 		evt := `{"time": "` + d + `", "level": "info", "message": "Foobar"}`
 
 		_, err := w.Write([]byte(evt))
@@ -313,7 +317,7 @@ func TestConsoleWriterConfiguration(t *testing.T) {
 			t.Errorf("Unexpected error when writing output: %s", err)
 		}
 
-		expectedOutput := "1970-01-01T00:00:00Z INF Foobar\n"
+		expectedOutput := ts.Format(time.RFC3339) + " INF Foobar\n"
 		actualOutput := buf.String()
 		if actualOutput != expectedOutput {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
@@ -354,6 +358,23 @@ func TestConsoleWriterConfiguration(t *testing.T) {
 			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
 		}
 	})
+
+	t.Run("Sets FieldsExclude", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, FieldsExclude: []string{"foo"}}
+
+		evt := `{"level": "info", "message": "Foobar", "foo":"bar", "baz":"quux"}`
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "<nil> INF Foobar baz=quux\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
 }
 
 func BenchmarkConsoleWriter(b *testing.B) {
diff --git a/ctx_test.go b/ctx_test.go
index 18dbd26..5bc41e5 100644
--- a/ctx_test.go
+++ b/ctx_test.go
@@ -45,7 +45,7 @@ func TestCtxDisabled(t *testing.T) {
 
 	l := New(ioutil.Discard).With().Str("foo", "bar").Logger()
 	ctx = l.WithContext(ctx)
-	if Ctx(ctx) != &l {
+	if !reflect.DeepEqual(Ctx(ctx), &l) {
 		t.Error("WithContext did not store logger")
 	}
 
@@ -53,18 +53,18 @@ func TestCtxDisabled(t *testing.T) {
 		return c.Str("bar", "baz")
 	})
 	ctx = l.WithContext(ctx)
-	if Ctx(ctx) != &l {
+	if !reflect.DeepEqual(Ctx(ctx), &l) {
 		t.Error("WithContext did not store updated logger")
 	}
 
 	l = l.Level(DebugLevel)
 	ctx = l.WithContext(ctx)
-	if Ctx(ctx) != &l {
+	if !reflect.DeepEqual(Ctx(ctx), &l) {
 		t.Error("WithContext did not store copied logger")
 	}
 
 	ctx = dl.WithContext(ctx)
-	if Ctx(ctx) != &dl {
+	if !reflect.DeepEqual(Ctx(ctx), &dl) {
 		t.Error("WithContext did not override logger with a disabled logger")
 	}
 }
diff --git a/log_test.go b/log_test.go
index 2ffd47e..e49daea 100644
--- a/log_test.go
+++ b/log_test.go
@@ -907,6 +907,33 @@ func TestLevel_String(t *testing.T) {
 	}
 }
 
+func TestLevel_MarshalText(t *testing.T) {
+	tests := []struct {
+		name string
+		l    Level
+		want string
+	}{
+		{"trace", TraceLevel, "trace"},
+		{"debug", DebugLevel, "debug"},
+		{"info", InfoLevel, "info"},
+		{"warn", WarnLevel, "warn"},
+		{"error", ErrorLevel, "error"},
+		{"fatal", FatalLevel, "fatal"},
+		{"panic", PanicLevel, "panic"},
+		{"disabled", Disabled, "disabled"},
+		{"nolevel", NoLevel, ""},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if got, err := tt.l.MarshalText(); err != nil {
+				t.Errorf("MarshalText couldn't marshal: %v", tt.l)
+			} else if string(got) != tt.want {
+				t.Errorf("String() = %v, want %v", string(got), tt.want)
+			}
+		})
+	}
+}
+
 func TestParseLevel(t *testing.T) {
 	type args struct {
 		levelStr string
@@ -943,3 +970,41 @@ func TestParseLevel(t *testing.T) {
 		})
 	}
 }
+
+func TestUnmarshalTextLevel(t *testing.T) {
+	type args struct {
+		levelStr string
+	}
+	tests := []struct {
+		name    string
+		args    args
+		want    Level
+		wantErr bool
+	}{
+		{"trace", args{"trace"}, TraceLevel, false},
+		{"debug", args{"debug"}, DebugLevel, false},
+		{"info", args{"info"}, InfoLevel, false},
+		{"warn", args{"warn"}, WarnLevel, false},
+		{"error", args{"error"}, ErrorLevel, false},
+		{"fatal", args{"fatal"}, FatalLevel, false},
+		{"panic", args{"panic"}, PanicLevel, false},
+		{"disabled", args{"disabled"}, Disabled, false},
+		{"nolevel", args{""}, NoLevel, false},
+		{"-1", args{"-1"}, TraceLevel, false},
+		{"-2", args{"-2"}, Level(-2), false},
+		{"-3", args{"-3"}, Level(-3), false},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var l Level
+			err := l.UnmarshalText([]byte(tt.args.levelStr))
+			if (err != nil) != tt.wantErr {
+				t.Errorf("UnmarshalText() error = %v, wantErr %v", err, tt.wantErr)
+				return
+			}
+			if l != tt.want {
+				t.Errorf("UnmarshalText() got = %v, want %v", l, tt.want)
+			}
+		})
+	}
+}