Refactor logp and add structured logging support #5901

andrewkroh · 2017-12-18T03:32:02Z

This refactors logp and adds support for structured logging. logp uses github.com/uber-go/zap in its implementation. There are no changes to the user facing logging configuration. The logger output will have some format differences, but in general will have a more consistent format across outputs.

Here is some sample output taken from the TestLogger test case.

=== RUN   TestLogger
2017-12-17T19:48:16.374-0500    INFO    logp/core_test.go:13    unnamed global logger
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:16    some message
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:17    some message with parameter x=1, y=2
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:18    some message    {"x": 1, "y": 2}
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:19    some message    {"x": 1}
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:20    some message with namespaced args       {"metrics": {"x": 1, "y": 1}}
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:21            {"empty_message": true}
2017-12-17T19:48:16.374-0500    WARN    [example]       logp/core_test.go:24    logger with context     {"x": 1, "y": 2}
2017-12-17T19:48:16.374-0500    INFO    [example]       logp/core_test.go:30    some message with struct value  {"metrics": {"x":1,"y":2}}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","caller":"logp/core_test.go:13","message":"unnamed global logger"}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:16","message":"some message"}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:17","message":"some message with parameter x=1, y=2"}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:18","message":"some message","x":1,"y":2}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:19","message":"some message","x":1}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:20","message":"some message with namespaced args","metrics":{"x":1,"y":1}}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:21","message":"","empty_message":true}
{"level":"warn","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:24","message":"logger with context","x":1,"y":2}
{"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:30","message":"some message with struct value","metrics":{"x":1,"y":2}}

Any test code that calls logp.LogInit() in libbeat needs to be updated to use logp.TestingSetup().

This refactors logp and adds support for structured logging. logp uses github.com/uber-go/zap in its implementation. There are no changes to the user facing logging configuration. The logger output will have some format differences, but in general will have a more consistent format across outputs. Here is some sample output taken from the `TestLogger` test case. ``` === RUN TestLogger 2017-12-17T19:48:16.374-0500 INFO logp/core_test.go:13 unnamed global logger 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:16 some message 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:17 some message with parameter x=1, y=2 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:18 some message {"x": 1, "y": 2} 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:19 some message {"x": 1} 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:20 some message with namespaced args {"metrics": {"x": 1, "y": 1}} 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:21 {"empty_message": true} 2017-12-17T19:48:16.374-0500 WARN [example] logp/core_test.go:24 logger with context {"x": 1, "y": 2} 2017-12-17T19:48:16.374-0500 INFO [example] logp/core_test.go:30 some message with struct value {"metrics": {"x":1,"y":2}} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","caller":"logp/core_test.go:13","message":"unnamed global logger"} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:16","message":"some message"} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:17","message":"some message with parameter x=1, y=2"} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:18","message":"some message","x":1,"y":2} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:19","message":"some message","x":1} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:20","message":"some message with namespaced args","metrics":{"x":1,"y":1}} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:21","message":"","empty_message":true} {"level":"warn","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:24","message":"logger with context","x":1,"y":2} {"level":"info","timestamp":"2017-12-17T19:48:16.374-0500","logger":"example","caller":"logp/core_test.go:30","message":"some message with struct value","metrics":{"x":1,"y":2}} ``` Any test code that calls `logp.LogInit()` in libbeat needs to be updated to use `logp.TestingSetup()`.

tsg · 2017-12-18T11:12:47Z

filebeat/fileset/fileset_test.go

-	if testing.Verbose() {
-		logp.LogInit(logp.LOG_DEBUG, "", false, true, []string{"fileset", "modules"})
-	}
+	logp.TestingSetup(logp.WithSelectors("fileset", "modules"))


tsg · 2017-12-18T11:34:24Z

libbeat/logp/logger.go

-// The Logger should be used to use with libraries havng a configurable logging
-// functionality.
+// LogOption configures a Logger.
+type LogOption = zap.Option


I think this only works in Go 1.9, right? I think that's fine, just flagging in case this blocks some use case (like gccgo).

Yes, type aliasing is only 1.9.

Should be OK in GCC8, not sure when is the release date.

Due to the alignment of Go's semiannual release schedule with GCC's annual release schedule, GCC release 7 contains the Go 1.8.3 version of gccgo. We expect that the next release, GCC 8, will contain the Go 1.10 version of gccgo.

++, I think we're good to make use of it, as go 1.10 is in beta now so I imagine it's not that long until there's a GCC version that can work with it.

ruflin · 2017-12-18T23:50:05Z

@elastic/apm This will also affect logging of the apm-server.

ruflin

Change LGTM. I'm fine to introduce this breaking change also in a minor release but we must be aware that it could break in some cases for users. For example if someone uses filebeat to fetch logs for metricbeat and has a filter for ERR things would not work anymore.

The part I'm more worried about is changing the default "log output". Does this change in this PR? I think we should definitively change it for 7.0 but not sure if we can introduce it in a minor.

For 7.0 we should also do a follow up cleanup like removing Criticalcompletely, change to JSON logging as default. We should have a follow up discussion / issue about this.

ruflin · 2017-12-18T23:53:08Z

libbeat/docs/loggingconfig.asciidoc

@@ -15,20 +15,19 @@

 The `logging` section of the +{beatname_lc}.yml+ config file contains options
 for configuring the Beats logging output. The logging system can write logs to
-the syslog or rotate log files. If logging is not explicitly configured, file
-output is used on Windows systems, and syslog output is used on Linux and OS X.
+the syslog or rotate log files. If logging is not explicitly configured the file


Sounds like a breaking change. Should we only make this for 7.0?

It didn't make this change. I just fixed the docs to match the behavior 😄 . This was changed in 5.0 I believe.

Ups :-) We should probably backport this part of the doc changes to 6.1/6.0 then. @dedemorton FYI

ruflin · 2017-12-18T23:55:04Z

libbeat/docs/loggingconfig.asciidoc

+
+Each log message consists of the following parts:
+
+* Timestamp in ISO8601 format


Did the timestamp format change or are the two (almost) the same.

They are almost the same, but RFC3339 (RFC3339 = "2006-01-02T15:04:05Z07:00") does not have sub-second precision so it's not ideal for a logger timestamp IMHO.

ruflin · 2017-12-18T23:58:21Z

libbeat/logp/core.go

+	case cfg.ToSyslog:
+		sink, err = makeSyslogOutput(cfg)
+	case cfg.ToFiles:
+		fallthrough


Thanks for keep teaching me about Golang features 👍

ruflin · 2017-12-19T00:00:37Z

libbeat/logp/core_test.go

+	"go.uber.org/zap"
+)
+
+func TestLogger(t *testing.T) {


Thanks for adding tests 🎉

ruflin · 2017-12-19T00:03:46Z

libbeat/logp/encoding.go

+	}
+}
+
+func consoleEncoderConfig() zapcore.EncoderConfig {


I wonder if we should have a base config like the consoleEncoderConfig and to the changes on top of it the same way you did for the syslogEncoder but also the jsonEncoder? It seems the jsonEncoder has also only 2 differences? Would make it easier to figure out what we do as a "base level" and which changes are specific to a logger.

I agree and noticed this myself that there was some duplication. I can clean this up in another PR.

ruflin · 2017-12-19T00:05:27Z

libbeat/logp/level.go

+	InfoLevel
+	WarnLevel
+	ErrorLevel
+	CriticalLevel // Critical exists only for config backward compatibility.


Do we use Critical somewhere in our beats code?

We previously supported critical as a config option so I had to carry it forward (logging.level: critical). I removed it from the docs.

ruflin · 2017-12-19T00:11:11Z

vendor/vendor.json

+		},
+		{
+			"checksumSHA1": "JDGx7hehaQunZySwPs7yvdUs2m8=",
+			"path": "go.uber.org/multierr",


Seems like we have multiple multierr packages? Probably no way around this.

Yeah, no way other than modifying the third-party software.

andrewkroh · 2017-12-19T00:45:29Z

The part I'm more worried about is changing the default "log output". Does this change in this PR?

No, we made the change to output to file by default a while ago. See #1437

For example if someone uses filebeat to fetch logs for metricbeat and has a filter for ERR things would not work anymore.

This is a valid concern (though hopefully ERR will still match ERROR). But I really hope the format change doesn't cause too much trouble. 🤞

roncohen · 2017-12-19T12:36:55Z

Fantastic to have structured logging in logp!

AFAIK, Kibana will use an easily readable logging format depending on whether there's a TTY or not.

I haven't had time to look into the implementation here, but it seems like it would be nice to output a human readable format when starting with -e, but allowing it to be overridden in case STDOUT is being piped through logstash for parsing or similar.

roncohen · 2018-01-03T15:42:23Z

@andrewkroh is this going in 6.2? We'd like to use it

andrewkroh · 2018-01-03T15:46:11Z

it would be nice to output a human readable format when starting with -e, but allowing it to be overridden in case STDOUT is being piped

Interesting idea. That's possibly something we could add for 7.0 (since it's kind of breaking).

is this going in 6.2? We'd like to use it

I believe so. I think it's just waiting on the next mass merge from master to the 6.x branch.

Add go.uber.org/zap/[email protected] to vendor dir

7cf88e4

andrewkroh added libbeat review labels Dec 18, 2017

andrewkroh force-pushed the feature/libbeat/structured-logger-zap branch from 627ed2b to de9c662 Compare December 18, 2017 03:35

andrewkroh force-pushed the feature/libbeat/structured-logger-zap branch from de9c662 to 4e62c0e Compare December 18, 2017 04:39

andrewkroh mentioned this pull request Dec 18, 2017

Experiment with structured logger #5723

Closed

tsg reviewed Dec 18, 2017

View reviewed changes

andrewkroh requested a review from ruflin December 18, 2017 22:17

ruflin reviewed Dec 19, 2017

View reviewed changes

ruflin merged commit 84e021d into elastic:master Dec 19, 2017

roncohen mentioned this pull request Dec 22, 2017

Streamline logging elastic/apm-server#431

Closed

andrewkroh mentioned this pull request Jan 15, 2018

setting logging.json=true does not truly have full json logs #6064

Closed

andrewkroh added the v6.2.0 label Jan 22, 2018

andrewkroh deleted the feature/libbeat/structured-logger-zap branch April 19, 2018 23:28

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor logp and add structured logging support #5901

Refactor logp and add structured logging support #5901

andrewkroh commented Dec 18, 2017

tsg Dec 18, 2017

tsg Dec 18, 2017

ph Dec 18, 2017 •

edited

Loading

tsg Dec 18, 2017

ruflin commented Dec 18, 2017

ruflin left a comment

ruflin Dec 18, 2017

andrewkroh Dec 19, 2017 •

edited

Loading

ruflin Dec 19, 2017

ruflin Dec 18, 2017

andrewkroh Dec 19, 2017

ruflin Dec 18, 2017

ruflin Dec 19, 2017

ruflin Dec 19, 2017

andrewkroh Dec 19, 2017

ruflin Dec 19, 2017

andrewkroh Dec 19, 2017

ruflin Dec 19, 2017

andrewkroh Dec 19, 2017

andrewkroh commented Dec 19, 2017

roncohen commented Dec 19, 2017

roncohen commented Jan 3, 2018

andrewkroh commented Jan 3, 2018


		Each log message consists of the following parts:

		* Timestamp in ISO8601 format

Refactor logp and add structured logging support #5901

Refactor logp and add structured logging support #5901

Conversation

andrewkroh commented Dec 18, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ph Dec 18, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ruflin commented Dec 18, 2017

ruflin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andrewkroh Dec 19, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andrewkroh commented Dec 19, 2017

roncohen commented Dec 19, 2017

roncohen commented Jan 3, 2018

andrewkroh commented Jan 3, 2018

ph Dec 18, 2017 •

edited

Loading

andrewkroh Dec 19, 2017 •

edited

Loading