new logging system for metrictank

[Dieterbe]

currently we use github.com/raintank/worldping-api/pkg/log which is unmaintained and whose output is hard to parse programatically

here's what I want out of a new log system:

• low overhead in terms of cpu time and allocations
• format that's friendly to both human and computer. i.e. structured but not too verbose. something like "human friendly logfmt" as shown at https://brandur.org/logfmt#human though I have a few remarks to it:
  • a few values will always be specified (datetime, level and module like input-carbon, cluster-kakfa, etc) so don't need the verbose k=v syntax for them and can just be the first few words of the log file by convention
  • want logs in ms resolution, not secondly. this can be handy in troubleshooting scenarios
    so I'm thinking something like:

2017-12-31 23:59:59 123 INFO clu-kafka msg starts here. kafka messed up  blah key=val otherkey='val has whitespace'

• ability to configure different levels for different modules. (using grep to filter out what I don't want at runtime is becoming less and less effective. e.g. if you only want debug for that one module and nothing else)
• runtime changeable debug levels. maybe. i expect this to come with a small perf tax which i would rather avoid. so far I think restarting the process to get debug logs has worked ok. also it assures runtime config can't drift (e.g. we forget to reset MT's runtime settings after having "temporarily" modified them)
• get 3rd party libs like sarama/macaron to log in the same format as MT (this might be hard to do and could be dropped as requirement)

a list of some interesting libraries, and any comments:
(barely scratching the surface here, there's much more to explore)

go-kit/log

https://github.com/go-kit/kit/tree/master/log
needs more investigation

github.com/kr/logfmt

awoods 8:11 AM i dont like https://godoc.org/github.com/kr/logfmt as its you need to unmarshal your log payload, and that can return an error.

github.com/golang/glog

awoods like this library because:

1. supports unlimited number of verbosity levels via glog.V(). This is great for MT so we can see debug request logs without seeing debug ingestion logs.
2. verbosity can be set using filename regex matches. ie -vmodule=cassandra_store=1
3. stack traces can be triggered for logging events at specific file lines.
4. log messages can be wrapped in if glog.V(1) { to prevent expensive queries to get data for log messages from having to execute unless the desired verbosity is set.

BUT:

Peter Bourgon [10:19 AM]
it's a really badly behaved library, with an arcane API, which makes no sense to use outside of Google's internal infrastructure and historical context

note that peter is very well respected in the go community, he knows what he's talking about. but in my opinion his advice can be a bit quixotic. but an interesting data point.

[woodsaj]

I suspect that Peter's issue is that the only way to configure glog is via flag variables and there is no control over modifying the msg format. But i dont think that is an issue for us, and if it is we can easily fork the library.

So i still really like golang/glog. with the exception of formating (which we can address by making it a coding standard that we all adhere to.) glog does everything we want.

• low overhead: i havent done any benchmarks, but i dont expect Google would produce a bloated, slow logging library
• ability to configure different levels for different modules.: glog does not support setting verbosity on a per package basis, but is does support setting on a filename basis. Which should be good enough, and in many cases probably better.
• runtime changeable debug levels: though glog uses flag, you can call flag.Set("v", newLevel) at anytime to change the log verbosity.
• get 3rd party libs like sarama/macaron to log in the same format as MT: For macaron, we can just use our own logger middleware instead of macaron.Logger. For sarama, and memberlist we cant change the content of the log messages but we can push them through glog for standard formatting with regards to timestamps, level, file etc...

[tehlers320]

It would be nice to invoke an API command to turn on/off certain logging aspects.

This one for me is spamming 100s of thousands per day due to docker container churn.

18:01:00 [I] metric 1.a161bf5ed60b1a8c322d9b1afc307693 is stale. Purging data from memory.
logs 05001959a9d04b5d9ab7c0234adce842d1961062177199482378da04b4f5e825 2017/06/22 18:01:00 [I] metric 1.e0cb269363bc1c1c316c2a1ef3ba57ca is stale. Purging data from memory.
logs 05001959a9d04b5d9ab7c0234adce842d1961062177199482378da04b4f5e825 2017/06/22 18:01:00 [I] metric 1.169ca5c728b25a088f501ee350a14378 is stale. Purging data from memory.

However the metric is useful and you may not want to drop to debug to see it.
log4j can do something similar via JMX bean you can turn up/down logging on an individual metric. Or simply turning on debug briefly via an api call for simplicity sake.

[shanson7]

I think an important feature would be not evaluating log statements that aren't going to be printed. By the nature of logging, most statements are NOT printed (for instance, debug/trace level is the most verbose, yet normally turned off). Being faster in the negative case is likely more important that being faster in the positive case.

[Dieterbe]

we've decided to standardize all our software on https://github.com/sirupsen/logrus
according to https://github.com/imkira/go-loggers-bench#textnegative it has a very minimal overhead in the level-disabled case.