TEXLUTION

TL;DR Source code and self-explanatory screenshot: https://github.com/comail/colog

The Go team made a conscious decision of not including a leveled log (debug, info, warning, etc.) solution in the standard library. Lots of people have an opinion of how logging should be done and logging libraries are fairly trivial to create, so even if they released the internal library used at Google it did non prevent logging libraries to pop up like mushrooms.

Although not a de facto standard, perhaps the most popular library is Logrus by Simon Eskildsen. Logrus is great, it supports custom formatters, context values and hooks to send events to plenty of external systems. So for comail my current project, I immediately starting using it. But then, once I started using Facebook’s graceful restart library Grace, I saw something like this:

Grace naturally uses the standard log bypassing Logrus. Now, you could argue whether an external library should be logging in your application, and in all fairness grace provides a flag to disable logging. But I’m a big fan of knowing what’s going on, and I like that libraries stick to the standard logger to do so. I could have certainly simply used a wrapper to Logrus as Logger output and move on, so perhaps it was blatant bikeshedding, but just like in that famous xkcd, CoLog was born.

The idea was to have a logging library that would work exclusively as an enhancement of the standard library, by reading and parsing the standard log output, in a way that is transparent in your code and that will keep working and making sense if you don’t use it. Meaning that if you are developing libraries or embeddable code you can safely use the CoLog style in your logs to offer CoLog’s goodies to CoLog users while not enforcing any dependency on anyone else. A mixture of Logrus and Hashicorp’s logutils.

Here’s an example:

// src/colog/main.go
package main

import (
	"log"
	"comail.io/go/colog"
)

func main() {
	log.Println("error: something happened colog=no")
	colog.Register()
	colog.ParseFields(true)
	log.Println("error: something happened colog=yes")
}

This will output the following:

When you call colog.Register() a new CoLog instance is created with the same log flags that were previously enabled in the standard logger and sets itself as the output. It will then recognize the prefix ‘error: ‘ as an error message and generate a new entry with that level. Calling colog.ParseFields(true) activates parsing the entire message looking for key=value pairs (or key='some quoted value').

Every entry is a simple struct.

// Entry represents a message being logged and all attached data
type Entry struct {
	Level   Level     // severity: trace, debug, info, warning, error, alert
	Time    time.Time // time of the event
	Host    string    // host origin of the message
	Prefix  string    // prefix set for the logger
	File    string    // file where the log was called
	Line    int       // line in the file where the log was called
	Message []byte    // logged message
	Fields  Fields    // map of key-value data parsed from the message
}

It then gets passed to CoLog’s standard formatter, which prints that nice output (without colors if you are logging to a file). The minimum level to be logged can be set via colog.SetMinLevel, and which level messages without prefix get can be set via colog.SetDefaultLevel.

CoLog entries are very much like the entries in Logrus. You can similarly add hooks to receive entries for specific levels via colog.AddHook. In fact you can even use existing Logrus hooks and formatters by wrapping them with cologrus.

The behavior is quite customizable, not only you can use your own hooks and output formatter, you can also define your own message headers for each level or plug your own function to extract fields. To use CoLog with a custom log.Logger instance, you need to create a new CoLog, set the parameters you want and then use the NewLogger method to get a ready to use instance. You can also use CoLog as output of any log.Logger, but be careful not to pass any prefix or flags to it directly.

cl := colog.NewCoLog(os.Stderr, "myworker ", log.LstdFlags)
cl.SetMinLevel(colog.LWarning)
cl.FixedValue("worker_id", "42")
logger := cl.NewLogger() // same as logger := log.New(cl, "", 0)
logger.Println("info: ready to log!")
// Outputs:
// [  info ] myworker 2015/08/05 16:39:18 ready to log!  worker_id=42

This segregation between CoLog and Logger is a bit quirky, but is necessary to preserve compatibility since unfortunately log.Logger is not an interface that anyone can implement. Adding to the list of quirks, obviously having context values as key-value pairs in text is not as flexible and foolproof as having a function take values directly. Personally I try to make this a bit safer and less cumbersome by always having the Stringer interface defined for all my types with CoLog in mind.

type User struct {
	ID    int
	Name  string
	Birth time.Time
}

func (u User) String() string {
	return fmt.Sprintf("user_id=%d", u.ID)
}

func main() {
    colog.Register()
    colog.ParseFields(true)
	user := User{27, "Bob", time.Date(1970, 10, 1, 0, 0, 0, 0, time.Local)}
	log.Printf("info: user created %s", user)
    // Outputs:
    // [  info ] 2015/08/05 16:39:18 user created  user_id=27
}

You might be wondering how’s the performance with all this parsing, surprisingly not bad I’d say. Yes, it’s obviously slower than using the standard logger directly, but I think the time is still negligible for most applications.

Here is the current (not very optimized) benchmark on my 3 year old laptop:

BenchmarkLoggerNoFlags-4               	   3000000	       404 ns/op
BenchmarkLoggerWithFlags-4             	   1000000	      1314 ns/op
BenchmarkCoLogPlainNoFlags-4           	   1000000	      2023 ns/op
BenchmarkCoLogPlainWithFlags-4         	    300000	      5008 ns/op
BenchmarkCoLogPlainWithFlagsAndFields-4	    100000	     16337 ns/op
BenchmarkCoLogColorNoFlags-4           	    500000	      3447 ns/op
BenchmarkCoLogColorWithFlags-4         	    200000	      6465 ns/op
BenchmarkCoLogColorWithFlagsAndFields-4	    100000	     18200 ns/op

That’s it. To find out more about CoLog, take a look at the source code or the customary godoc.