Add structured logging to json and support for syslog #11

mattkanwisher · 2015-10-10T22:47:56Z

We use kibana currently to manage our centralized logging, adding json support will allow native integration with tools like this and logstash. In addition I added syslogger support so people don't need to do manual piping to syslog

juliusv · 2015-10-21T14:14:56Z

@fabxc @brian-brazil @beorn7 So I've been neglecting this PR here for a while, but talked to @mattkanwisher from DigitalOcean at VelocityConf in NYC about this.

What do you think? Is it worth adding these features to our logging library directly? It would mean that any user of the logging library needs to call the SetFormatter() (or whatever it will be named in the end) initialization method to initialize logging properly. That's because there are multiple interdependent flags, so configuring the logger can't just be solved in each flag's custom parsing code, like we currently do it with the log level.

Alternatively, what about adding only JSON support, because that is harder to solve externally? Prometheus would then still focus on only logging to stderr and leave any syslog support up to a wrapper.

brian-brazil · 2015-10-21T14:23:38Z

I think having syslog out of the box would be useful, as pretty much everything log-related integrates with it. JSON seems a little more custom, so we should probably draw a line in the sand now rather than dealing with feature creep later.

mattkanwisher · 2015-10-21T14:26:36Z

@brian-brazil structured logging isn't really a feature creep as the library already is doing it. Honestly the current structured logging isn't useful to ingest into logging systems like kibana. We can do something where have a Database like DSN to specify logging settings "rsylog:local7?format=json" or something.

juliusv · 2015-10-21T14:42:43Z

Yeah, it's harder to structure the logs externally once they're already outputted unstructured.

Supporting machine-readable structured output would however mean that any subsequent change to the format (whether through switching to a different underlying library than logrus or else) we'll have to treat as a breaking interface change in all components using the library (with only human-readable format, you usually don't care). Just a thing to keep in mind.

taotetek · 2015-10-21T14:50:49Z

Please note that syslog-ng and rsyslog both support JSON parsing natively. See:

Which is part of our interest in @Cee JSON support.

beorn7 · 2015-10-21T14:52:13Z

Not really deep into this subject right now. Intuitively, I'd say if our logging is structured internally, we should have a way to output it in a structured form.
Happy to accept any outcome...

mattkanwisher · 2015-10-21T14:54:28Z

@juliusv we can certainly change the code so the interface doesn't change for all components downstream

mattkanwisher · 2015-10-21T15:46:24Z

@juliusv ok fixed the interface is no longer changed downstream. Do we have any other issues here?

./prometheus -log.format="logger:syslog?json=true&appname=bob&local=local7

grobie · 2015-10-21T17:13:01Z

log/log.go

+			origLogger.Formatter = fmter
+		}
+	}
+	return nil


Try to reduce indentation in go.

if appname == "" || local == "" { return nil } fmter, err := newSyslogger(appname, local, origLogger.Formatter) if err != nil { fmt.Fprintf(os.Stderr, "error creating syslog formatter: %v\n", err) origLogger.Errorf("can't connect logger to syslogs: %v", err) return nil } origLogger.Formatter = fmter return nil

I don't really understand, why your method signature includes a error return value. You never check for the return value and always return nil anyway.

grobie · 2015-10-21T17:19:51Z

log/syslog_formatter.go

+		return syslog.LOG_LOCAL6
+	case "7":
+		return syslog.LOG_LOCAL7
+	}


This seems to be easier solved by a map than by running through a switch statement every time?

var localMapping = map[string]syslog.Priority{ "0": syslog.LOG_LOCAL0, "1": syslog.LOG_LOCAL1, // ... } func getLocal(level string) syslog.Priority { p, ok := localMapping[level] if !ok { return syslog.LOG_LOCAL0 } return p }

The function only runs once ever

Nevermind, it's only used during initialization anyways.

grobie · 2015-10-21T17:22:30Z

log/log.go

 func init() {
 	// In order for this flag to take effect, the user of the package must call
 	// flag.Parse() before logging anything.
 	flag.Var(levelFlag{}, "log.level", "Only log messages with the given severity or above. Valid levels: [debug, info, warn, error, fatal].")
+	flag.Var(formatLog{}, "log.format", "If set use a syslog logger or json logging. Example: logger:syslog?appname=bob&local=local7 or logger:stdout@?json=true ")


So this example shows local=local7. The getLocal method in the formatter only knows about local=7 though. Am I missing where you remove the local part from local7?

Example is wrong good catch should say local=7, updated

grobie · 2015-10-21T17:28:46Z

log/syslog_formatter.go

+
+var ceeTag = []byte("@cee:")
+
+var _ logrus.Formatter = &syslogger{}


What is the purpose of this line?

not needed removed, this was copied from our internal logging library that also uses logrus

grobie · 2015-10-21T18:10:13Z

log/log.go

 func init() {
 	// In order for this flag to take effect, the user of the package must call
 	// flag.Parse() before logging anything.
 	flag.Var(levelFlag{}, "log.level", "Only log messages with the given severity or above. Valid levels: [debug, info, warn, error, fatal].")
+	flag.Var(formatLog{}, "log.format", "If set use a syslog logger or json logging. Example: logger:syslog?appname=bob&local=7 or logger:stdout@?json=true ")


What's the purpose of the @ sign in the stdout example?

grobie · 2015-10-21T18:16:25Z

👍

Structured logs are so much easier to deal with, I'd always prefer them. Especially as Prometheus de-facto already uses structured logging, having a well defined format makes a lot of sense.

Syslog is so common that we should support. The majority of software I've been working with only supports syslog style logging and nothing else.

grobie · 2015-10-21T18:19:44Z

log/log.go

+		setJsonFormatter()
+	}
+
+	if u.Opaque == "syslog" {


What do you think about being explicit about the acceptable loggers? Might help to avoid confusion.

switch u.Opague { case "syslog": // ... case "stdout": default: return fmt.Error("unsupported logger", u.Opague) }

i like the switch fixed

grobie · 2015-10-21T18:29:00Z

log/log.go

+		return setFormatterSylog(appname, local)
+	case "stdout":
+	default:
+		return fmt.Errorf("unsupported logger", u.Opaque)


Ah sorry, I forgot there isn't a fmt.Error method like the log.Error one. Please add the missing %s to print the logger value (go vet should also mark this problem).

fixed, make vet doesn't cover common ill do it manually ;)

juliusv · 2015-10-21T19:20:09Z

log/log.go

+	fmter, err := newSyslogger(appname, local, origLogger.Formatter)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "error creating syslog formatter: %v\n", err)
+		origLogger.Errorf("can9't connect logger to syslogs: %v", err)


"can9't" -> "can't"

juliusv · 2015-10-21T19:29:42Z

log/log.go

 	// flag.Parse() before logging anything.
 	flag.Var(levelFlag{}, "log.level", "Only log messages with the given severity or above. Valid levels: [debug, info, warn, error, fatal].")
+	flag.Var(formatLog{}, "log.format", "If set use a syslog logger or JSON logging. Example: logger:syslog?appname=bob&local=7 or logger:stdout?json=true ")


Naming consistency: if we name the above levelFlag, then we should also name this one logFormatFlag instead of formatLog.

mattkanwisher · 2015-10-21T19:36:53Z

Cool updated all the feedback

juliusv · 2015-10-21T19:42:36Z

log/log.go

+
+// String implements flag.Value.
+func (f logFormatFlag) String() string {
+	return origLogger.Level.String()


This now should return something different than the log level? Guess this was a copy-and-paste from the levelFlag.String() implementation?

See also the wrong default values in the flag help output now:

-log.format "info" If set use a syslog logger or JSON logging. Example: logger:syslog?appname=bob&local=7 or logger:stdout?json=true -log.level "info" Only log messages with the given severity or above. Valid levels: [debug, info, warn, error, fatal].

so I'm just going to return the original log format uri, since thats probably the most useful

(I guess it should return the empty string for an empty default value?)

Probably, I'm not sure how useful this really is. Normally I woudn't do custom struct flags

Yeah, what you did is actually correct I think.

juliusv · 2015-10-21T20:02:19Z

log/log.go

+	fmter, err := newSyslogger(appname, local, origLogger.Formatter)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "error creating syslog formatter: %v\n", err)
+		origLogger.Errorf("can't connect logger to syslogs: %v", err)


Is this supposed to read "syslogs" instead of "syslog"?

mattkanwisher · 2015-10-21T20:03:10Z

I think we have 5 hours in on this PR now ;) how about we merge this sucker

juliusv · 2015-10-21T20:27:28Z

log/syslog_formatter.go

+	}, err
+}
+
+func getLocal(level string) syslog.Priority {


Would getPriority be a clearer name for this?

no maybe Facility would be better https://en.wikipedia.org/wiki/Syslog but its not a priority

Well, it returns a syslog.Priority. The stdlib docs say:

"The Priority is a combination of the syslog facility and severity."

So I guess priority would actually be correct here...

This method won't ever return severity, so I don't think getPriority makes sense. +1 for getFacility, but getLevel is fine as well. It's not a complicated method.

juliusv · 2015-10-21T20:35:20Z

Looks good to me now, but want another person to do a final 👍 and merge, since it's touching the whole ecosystem and I'm vacationing :)

grobie · 2015-10-21T20:42:23Z

log/syslog_formatter.go

+	case "7":
+		return syslog.LOG_LOCAL7
+	}
+	return syslog.LOG_LOCAL0


@mattkanwisher So I was thinking about this after the introduction of the switch Opague. It might be a good idea to not return a default value for all unknown levels, but to return an error. That way a user will have immediate feedback what's wrong with local=local7 instead of trying to understand why their log messages are delivered using the wrong facility. What do you think?

ok sure returning error now

grobie · 2015-10-21T20:51:29Z

Awesome! Thanks so much for sticking with us ;)

grobie · 2015-10-21T20:56:36Z

log/log.go

@@ -39,10 +41,64 @@ func (f levelFlag) Set(level string) error {
 	return nil
 }

+func setSyslogFormatter(appname, facility string) error {
+	if appname != "" && facility != "" {


Wait, this should have been changed to be the other way around. appname == "" || facility == "".

good catch fixed

grobie · 2015-10-21T20:58:17Z

log/log.go

@@ -39,10 +41,64 @@ func (f levelFlag) Set(level string) error {
 	return nil
 }

+func setSyslogFormatter(appname, facility string) error {
+	if appname != "" && facility != "" {
+		return nil


Might be good to return an error here instead of nil. This code path is only reached if someone set logger:syslog. We should tell them that appname and facility are mandatory.

If you think it makes sense, we could alternatively set facility to some default value.

fabxc · 2015-10-22T07:35:33Z

Chiming in late – I derived this package a few weeks back exactly because I wanted more structured logging. While changing a structured log message is more explicitly breaking, it is still an order of magnitude better than parsing unstructured logs.

In the end we have to decide whether our logging output is ruled by our semantic versioning or not – I doubt that it makes sense.

Syslog and JSON support is fine I suppose since it is handled by our underlying library anyway.

Thanks for writing this and everyone else for reviewing 👍

fabxc · 2015-10-22T07:41:35Z

log/log.go

+		appname := u.Query().Get("appname")
+		facility := u.Query().Get("local")
+		return setSyslogFormatter(appname, facility)
+	case "stdout":


logrus defaults to stderr though. So People will provide stdout, and will get stderr, while providing stderr will fail.

sirupsen/logrus@f8f0884

nice catch fixed

fabxc · 2015-10-22T07:51:27Z

Thanks a bunch! 👍

Add structured logging to json and support for syslog

3ec519f Merge pull request prometheus#12 from weaveworks/prefix-unit-test-sched 856790f Use golang package name as a prefix on unit test schedules. 7f5fa57 Merge pull request prometheus#11 from weaveworks/10-dont-delete-sshed-gce-nodes 0bff9b4 Don't delete GCE nodes for running (but failed) builds 03aed8f Merge pull request prometheus#9 from weaveworks/configure-pac-domain c04c534 socks: Make main shExpMatch expression configurable git-subtree-dir: tools git-subtree-split: 3ec519f704ed7d334ca48abcb6211885f204f630

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from a615aae to 9d412ae Compare October 21, 2015 17:19

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from 9d412ae to ccb8dbf Compare October 21, 2015 17:21

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from ccb8dbf to f484759 Compare October 21, 2015 17:23

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from f484759 to ca23863 Compare October 21, 2015 17:33

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from ca23863 to 2bc32b3 Compare October 21, 2015 18:14

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch 2 times, most recently from 83d9663 to 4958f27 Compare October 21, 2015 18:25

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch 2 times, most recently from dc5811e to ea15603 Compare October 21, 2015 19:08

juliusv reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from c502b7b to ede23f3 Compare October 21, 2015 19:27

juliusv reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from ede23f3 to 6185762 Compare October 21, 2015 19:31

juliusv reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from 6185762 to c1cf9a8 Compare October 21, 2015 19:44

juliusv reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from c1cf9a8 to 392819d Compare October 21, 2015 20:03

juliusv reviewed Oct 21, 2015
View reviewed changes

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from 392819d to 1afb844 Compare October 21, 2015 20:45

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from 1afb844 to 041550d Compare October 21, 2015 20:58

grobie reviewed Oct 21, 2015
View reviewed changes

mattkanwisher force-pushed the master branch 2 times, most recently from 7341a0f to b1f2ce5 Compare October 21, 2015 21:01

fabxc reviewed Oct 22, 2015
View reviewed changes

mattkanwisher force-pushed the master branch from b1f2ce5 to 145dc7e Compare October 22, 2015 07:48

Add structured logging to json and support for syslog

a01ae36

mattkanwisher force-pushed the master branch from 145dc7e to a01ae36 Compare October 22, 2015 07:48

fabxc added a commit that referenced this pull request Oct 22, 2015

Merge pull request #11 from mattkanwisher/master

369ec04

Add structured logging to json and support for syslog

fabxc merged commit 369ec04 into prometheus:master Oct 22, 2015

brian-brazil mentioned this pull request Oct 27, 2015

FTBFS on Windows prometheus/prometheus#1186

Closed


		var ceeTag = []byte("@cee:")

		var _ logrus.Formatter = &syslogger{}

Add structured logging to json and support for syslog #11

Add structured logging to json and support for syslog #11

Conversation

mattkanwisher commented Oct 10, 2015

juliusv commented Oct 21, 2015

brian-brazil commented Oct 21, 2015

mattkanwisher commented Oct 21, 2015

juliusv commented Oct 21, 2015

taotetek commented Oct 21, 2015

beorn7 commented Oct 21, 2015

mattkanwisher commented Oct 21, 2015

mattkanwisher commented Oct 21, 2015

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

grobie commented Oct 21, 2015

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

mattkanwisher commented Oct 21, 2015

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

mattkanwisher commented Oct 21, 2015

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

juliusv commented Oct 21, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

grobie commented Oct 21, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fabxc commented Oct 22, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fabxc commented Oct 22, 2015