Refactored zerolog.ConsoleWriter to allow customization #92

karmi · 2018-07-28T18:43:20Z

As outlined in #84, this patch refactors the zerolog.ConsoleWriter in two ways:

The default formatting has been changed to be more sparse and visually attractive
The formatting logic has been extracted to separate functions, so it can be changed from the user code

I had to change the design of the prototype in order to maintain the backwards compatibility: the prototype has defined default formatting functions (formatters) on the concrete instance of ConsoleWriter, but without using an initializer, these would be empty. Therefore, I've added a number of defensive checks into ConsoleWriter.Write(), and a ConsoleWriter.Reset() method. This is not ideal, but I agree that maintaining backwards compatibility is an important goal, and the behaviour is predictable in my testing.

I've added a benchmark test to make sure I inadverently don't harm the performance: the performance has stayed roughly the same. The tests and examples have been run with the -race parameter.

I've updated the screenshot to reflect the new look, and added a comprehensive example to the README.

karmi · 2018-07-28T19:58:44Z

The TravisCI build failed with could not write event: cannot decode event: invalid character 'Â¿' looking for beginning of value--- FAIL: TestConsoleLogger, which is surprising, since I can't reproduce it locally — the test runs fine bothin isolation as well as part of the whole suite...

rs · 2018-07-30T00:45:35Z

Please use this screenshot:

karmi · 2018-07-30T06:22:26Z

Hello, screenshot updated, commit amended & force-pushed.

rs · 2018-07-30T09:02:32Z

This travis issue is meh. Any clue?

karmi · 2018-07-30T09:10:27Z

@rs, unfortunately no clue... :/ I've run both of the commands in .travis.yml locally, and it runs just fine. What I wanna try is to run the tests inside a Docker container, to replicate the Travis environment more closely. I'll let you know when I do that.

karmi · 2018-07-30T10:27:54Z

I've found it — the call to decodeIfBinaryToBytes() was missing from the new Write() method, and that was (mysteriously) failing on Travis, but not locally. (Any idea why?)

I've squashed the commit into the main one and pushed the new branch.

rs · 2018-07-30T16:45:02Z

Oh ok make sense. It’s due to the second line in the script section of the travis file with the tag to test binary logging.

karmi · 2018-07-30T16:50:17Z

Ah, right! Maybe I forgot to check the output of the second test script properly when running it locally.

karmi · 2018-07-30T16:56:28Z

I've just checked again, and indeed, when I run go test -v -tags binary_log -race ./... locally, it does fail without the decodeIfBinaryToBytes() call — sorry about that!

rs · 2018-07-31T22:47:26Z

README.md

+To customize the configuration and formatting:
+
+```go
+output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}.Reset()


I'm not found of this API with the need to call Reset and SetFormatter updating a global config. Why can't we store the formatter settings in the ConsoleWriter type?

karmi · 2018-08-06T08:14:13Z

I don't like it much either :)

I haven't found a better way to keep 100% backwards compatibility with existing user code using zerolog.ConsoleWriter. As I said, in the github.com/karmi/consolelog prototype, I've used an "initializer" function to create a new ConsoleWriter, which is passed to zerolog.New():

output := consolelog.NewConsoleWriter()
logger := zerolog.New(output).With().Timestamp().Logger()

In this way, when a user would customize the consolelog.ConsoleWriter, like this:

output = consolelog.NewConsoleWriter(
		func(w *consolelog.ConsoleWriter) {
			w.TimeFormat = time.Stamp
			w.SetFormatter(
				zerolog.LevelFieldName,
				func(i interface{}) string { return strings.ToUpper(fmt.Sprintf("%-5s", i)) })			
		},
	)

it would register the customization only for the particular object — in other words, when you would then create another output with the bare NewConsoleWriter() function, it would have the default formatting.

In the prototype, all the formatters, the time format, and the parts order have been indeed stored as properties of ConsoleWriter; https://github.com/karmi/consolelog/blob/cf60d6a7b0da4c2bd928702aaaee4aeef0f093e5/consolelog.go#L44-L49.

But since I imagine users have existing code where the only "initialization" they do is something like log.Output(zerolog.ConsoleWriter{Out: os.Stderr}), I didn't want to break backwards compatibility here, and force them to update the code to switch the literal initialization to the initializer function...

After a lot of thinking and fiddling, I've realized that I can export a Reset() method, which would re-initialize the package variables for any new ConsoleWriter, mirroring the init() logic.

Maybe there's a better way around this? Or maybe I'm over-thinking the backwards compatibility too much?

(Sorry for a delay with the reply, I'm on a vacation.)

rs · 2018-08-07T17:12:21Z

I'm not sure the initializer function design is indicated here. We don't you just expose the SetFormatter function and make sure the default formatters (when not set) are the sensible defaults?

rs · 2018-08-31T16:47:32Z

@karmi: are you still willing to work on this PR?

karmi · 2018-09-02T15:46:20Z

Yes, absolutely — I was offline for most of August.

[Why] don't you just expose the SetFormatter function and make sure the default formatters (when not set) are the sensible defaults?

You mean as the package level function, or on the ConsoleWriter object, as it is now? Again, maybe I'm missing something, but what I wanted to achieve was sensible defaults which would not override any "bare" initialization of another console writer the user might do — which has led me to the Reset() method...

I'll have another look on the codebase, maybe another solution will jump out at me.

In order to allow customizing the console output, the `zerolog.ConsoleWriter` output has been refactored, with the formatting logic extracted to separate functions in `consoleFormatters`, and with the `SetFormatter()` method to re-define the defaults. Also, the default has been changed to be more sparse and visually attractive. The logic has been extracted from an external prototype package at <https://github.com/karmi/consolelog>. A comprehensive example has been added to the README, and a number of tests has been added as well. Closes rs#84

* Removed the global registry (map) of default formatters * Therefore, removed the `init()` function * Therefore, removed the `Reset()` method * Added default formatters as package level variables (`consoleDefaultFormatTimestamp`, ...), not as entries in the global registry * Added custom formatters as fields on the `ConsoleWriter` struct, not as entries in the registry * Removed `SetFormatter()` and `Formatter()` methods, and look up proper formatter (custom one or default) during formatting (`writeFields()`, `writeParts()`) * Adjusted the test examples * Minor source code cleanups Related: rs#92

karmi · 2018-10-30T10:49:40Z

Travis failed on Go 1.9 with:

--- FAIL: TestNewWriter (0.00s)
	diode_test.go:29: Diode New Writer Test failed. got:, want:{"level":"debug","message":"test"}

I've tried to reproduce locally with Go 1.9.2 and the test didn't fail — I'll amend the commit and force push to trigger another build.

* Removed the global registry (map) of default formatters * Therefore, removed the `init()` function * Therefore, removed the `Reset()` method * Added default formatters as package level variables (`consoleDefaultFormatTimestamp`, ...), not as entries in the global registry * Added custom formatters as fields on the `ConsoleWriter` struct, not as entries in the registry * Removed `SetFormatter()` and `Formatter()` methods, and look up proper formatter (custom one or default) during formatting (`writeFields()`, `writeParts()`) * Adjusted the test examples * Minor source code cleanups Related: rs#92

karmi · 2018-10-30T11:49:28Z

I've took another stab at refactoring the functionality, and would like to get some feedback on the latest version of console.go.

The most important part is removing the global registry (map) of formatters, and therefore removing the need for any Reset() method, the init() function and other weird semantics.

The default formatters are added as package level variables (consoleDefaultFormatTimestamp, ...) and custom Formatters are added as regular fields of the ConsoleWriter struct. (Example of setting the fields directly here, example of using the constructor function option here.)

I've plugged this version into a real project where I'm using zerolog, and it behaves well. It still doesn't provide a way how to customize formatting a specific field (component) in my case, but that's not something which has to be solved right away...

I can imagine there's yet another approach possible, eg. adding a ConsoleFormatter struct, and attaching methods to it, and opening up the logic even more, but again, not sure if it has to be solved at once.

rs · 2018-10-30T16:34:54Z

README.md

+To customize the configuration and formatting:
+
+```go
+output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}.Reset()


You forgot to update the doc to remove the .Reset() here.

Argh, sorry about that, fixed in fc34c71!

rs · 2018-10-30T16:36:47Z

Looks good. Please fix the doc and I'll merge.

karmi · 2018-11-05T09:32:44Z

Thanks! Do you want me to rebase & squash the commits or do you prefer to do it on your side?

wvh · 2018-11-07T13:45:20Z

Hello,

The new ConsoleWriter creates consoleDefaultPartsOrder on init instead of when creating an instance of itself, so if someone changes the default fields – such as MessageFieldName – ConsoleWriter will try to print the wrong field names.

For instance, if I set MessageFieldName to "msg", the console writer will try to print the original "message" field:

var out io.Writer = os.Stdout
zerolog.MessageFieldName = "msg"
out = zerolog.ConsoleWriter{Out: out}
logger = zerolog.New(out).With().Timestamp().Logger()
logger.Info().Msg("this message won't show")

results in (more or less):

15:26:27.818175 INF %!s(<nil>) at=main.go:171 component=main

... note the nil message field.

karmi · 2018-11-07T14:28:40Z

@wvh, argh, that's bad... I'll look into it!

karmi · 2018-11-07T16:45:33Z

I did the simplest thing which came to my mind, and made consoleDefaultPartsOrder a function, instead of a static slice: master...karmi:fix_console_custom_parts

In this way, it's called from Write() and therefore picks up the custom name — though I don't like it from the performance point of view much...

What do you think, @rs?

rs · 2018-11-07T17:05:59Z

No big deal IMHO. The console writer is not meant for production, but for dev anyway.

karmi · 2018-11-07T17:09:30Z

@rs, right, that's what I was thinking as well, just wasn't sure. I'll send the patch as a PR.

In order to prevent incorrect output when somebody uses a different name eg. for the "MessageFieldName", the `consoleDefaultPartsOrder` variable has been switched to a function, which is called in `Write()`, in order to pick up the custom name. Related: rs#92

In order to prevent incorrect output when somebody uses a different name eg. for the "MessageFieldName", the `consoleDefaultPartsOrder` variable has been switched to a function, which is called in `Write()`, in order to pick up the custom name. Related: #92

wvh · 2018-11-08T12:45:57Z

I guess you could also force people to use the NewConsoleWriter constructor and set it there, but you'd have to make sure all struct fields can be set from the constructor or have setters exposed if you'd make the struct private.

By the way – thanks, I like the new look.

karmi · 2018-11-08T13:45:16Z

@wvh , right, that would solve the problem of initialization, but would break a lot of existing code, and that's what I wanted to prevent at all cost with the refactor...

IngmarStein · 2018-12-04T09:51:40Z

Previously, ConsoleWriter could be used concurrently. Now, these package-level configuration options have introduced a data race in Write (see below). Is it intended that callers need to add synchronisation around ConsoleWriter?

==================
WARNING: DATA RACE
Read at 0x00000310ea0d by goroutine 27:
  …/vendor/github.com/rs/zerolog.ConsoleWriter.Write()
      /go/src/…/vendor/github.com/rs/zerolog/console.go:111 +0x656
  …/vendor/github.com/rs/zerolog.(*ConsoleWriter).Write()
      <autogenerated>:1 +0xf0
  …/vendor/github.com/rs/zerolog.levelWriterAdapter.WriteLevel()
      /go/src/…/vendor/github.com/rs/zerolog/writer.go:20 +0x66
  …/vendor/github.com/rs/zerolog.(*levelWriterAdapter).WriteLevel()
      <autogenerated>:1 +0xa4
  …/vendor/github.com/rs/zerolog.(*Event).write()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:80 +0x2e0
  …/vendor/github.com/rs/zerolog.(*Event).msg()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:139 +0x296
  …/vendor/github.com/rs/zerolog.(*Event).Msg()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:110 +0x51
  …

Previous write at 0x00000310ea0d by goroutine 28:
  …/vendor/github.com/rs/zerolog.ConsoleWriter.Write()
      /go/src/…/vendor/github.com/rs/zerolog/console.go:112 +0x684
  …/vendor/github.com/rs/zerolog.(*ConsoleWriter).Write()
      <autogenerated>:1 +0xf0
  …/vendor/github.com/rs/zerolog.levelWriterAdapter.WriteLevel()
      /go/src/…/vendor/github.com/rs/zerolog/writer.go:20 +0x66
  …/vendor/github.com/rs/zerolog.(*levelWriterAdapter).WriteLevel()
      <autogenerated>:1 +0xa4
  …/vendor/github.com/rs/zerolog.(*Event).write()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:80 +0x2e0
  …/vendor/github.com/rs/zerolog.(*Event).msg()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:139 +0x296
  …/vendor/github.com/rs/zerolog.(*Event).Msg()
      /go/src/…/vendor/github.com/rs/zerolog/event.go:110 +0x51
  …

karmi · 2018-12-04T10:37:00Z

Hi @IngmarStein , I've tried locally, and was able to reproduce the race when eg. setting the timestamp option, coming from eg. this line:

zerolog/console.go

Line 103 in 8747b7b

consoleTimeFormat = consoleDefaultTimeFormat

I'll look into it, it definitely shouldn't require any synchronization from the calling code.

When the ConsoleWriter has been customized, the operations accessing variables in the `Write()` method had race condition, as reported in rs#92 (comment). A simple mutex lock has been added around the section. Example code: ```go package main import ( "fmt" "os" "sync" "time" "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) func main() { var wg sync.WaitGroup log.Logger = log.With().Timestamp().Logger().Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}) // output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339} // log := zerolog.New(output).With().Timestamp().Logger() for i := 0; i < 10000; i++ { wg.Add(1) go func(i int) { defer wg.Done() log.Info().Str("foo", "bar").Msg(fmt.Sprintf("Hello from goroutine %d", i)) }(i) } wg.Wait() } ```

karmi force-pushed the console branch from d937316 to d4b6e41 Compare July 28, 2018 19:31

karmi force-pushed the console branch from d4b6e41 to eddb013 Compare July 30, 2018 06:21

karmi force-pushed the console branch from ada5f6b to 8f792b1 Compare July 30, 2018 10:27

rs reviewed Jul 31, 2018

View reviewed changes

rs force-pushed the master branch 4 times, most recently from 1cea9c5 to 8479412 Compare September 17, 2018 17:28

karmi added 3 commits October 29, 2018 09:11

Added the "tmp" folder to .gitignore

74263ad

Added a simple benchmarking test for the ConsoleWriter

e0d9022

karmi force-pushed the console branch from 8f792b1 to b8be76a Compare October 29, 2018 08:12

karmi force-pushed the console branch from db4ff0b to 318753e Compare October 30, 2018 10:49

rs reviewed Oct 30, 2018

View reviewed changes

Fixed the README example for zerolog.ConsoleWriter

fc34c71

rs merged commit 96f91bb into rs:master Nov 5, 2018

karmi mentioned this pull request Nov 7, 2018

Fix the ConsoleWriter default parts order #113

Merged

karmi mentioned this pull request Dec 4, 2018

Fix race condition in ConsoleWriter #118

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactored zerolog.ConsoleWriter to allow customization #92

Refactored zerolog.ConsoleWriter to allow customization #92

karmi commented Jul 28, 2018

karmi commented Jul 28, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

karmi commented Jul 30, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

karmi commented Jul 30, 2018

rs Jul 31, 2018

karmi commented Aug 6, 2018 •

edited

Loading

rs commented Aug 7, 2018

rs commented Aug 31, 2018

karmi commented Sep 2, 2018

karmi commented Oct 30, 2018

karmi commented Oct 30, 2018

rs Oct 30, 2018

karmi Nov 5, 2018

rs commented Oct 30, 2018

karmi commented Nov 5, 2018

wvh commented Nov 7, 2018

karmi commented Nov 7, 2018

karmi commented Nov 7, 2018

rs commented Nov 7, 2018

karmi commented Nov 7, 2018

wvh commented Nov 8, 2018 •

edited

Loading

karmi commented Nov 8, 2018

IngmarStein commented Dec 4, 2018

karmi commented Dec 4, 2018

Refactored zerolog.ConsoleWriter to allow customization #92

Refactored zerolog.ConsoleWriter to allow customization #92

Conversation

karmi commented Jul 28, 2018

karmi commented Jul 28, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

karmi commented Jul 30, 2018

rs commented Jul 30, 2018

karmi commented Jul 30, 2018

karmi commented Jul 30, 2018

rs Jul 31, 2018

Choose a reason for hiding this comment

karmi commented Aug 6, 2018 • edited Loading

rs commented Aug 7, 2018

rs commented Aug 31, 2018

karmi commented Sep 2, 2018

karmi commented Oct 30, 2018

karmi commented Oct 30, 2018

rs Oct 30, 2018

Choose a reason for hiding this comment

karmi Nov 5, 2018

Choose a reason for hiding this comment

rs commented Oct 30, 2018

karmi commented Nov 5, 2018

wvh commented Nov 7, 2018

karmi commented Nov 7, 2018

karmi commented Nov 7, 2018

rs commented Nov 7, 2018

karmi commented Nov 7, 2018

wvh commented Nov 8, 2018 • edited Loading

karmi commented Nov 8, 2018

IngmarStein commented Dec 4, 2018

karmi commented Dec 4, 2018

karmi commented Aug 6, 2018 •

edited

Loading

wvh commented Nov 8, 2018 •

edited

Loading