Talking about engineering practices for Go application output logging

golang log

Go is a back-end language that is known for developing various services, middleware and system platforms. When learning Go, logging is not indispensable or even unnecessary, but once we get to the real Go engineering practice, output logging is an inevitable problem we must face.

Most of the services developed by Go have the property of continuous and autonomous operation, usually running 7×24 hours, and it is impossible for the development and operation personnel to keep an eye on the running state of the service, which requires recording the running log of the service. The essence of logs is to be checked. Through logs, we can.

Check the running status of the system
Discover anomalies
Audit behavior
Aid in the diagnosis of problems

In today’s cloud-native era, where Observability is all the rage, logs are known as “the three pillars of Observability” (the other two are metrics and tracing), and is an essential part of cloud-native system devops.

the three pillars of Observability

So what is the current state of Go’s support for logging output in Go engineering practice? What are the problems? What are the common problem-solving approaches? And what are the community efforts and expectations? In this article, I’ll talk about these issues.

I. The State of Go Logging

Go is a “bring-your-own-battery” language that works out of the box. This means that there are ready-made log packages in the Go standard library for developers to use.

Go Standard Library log packages

As part of the Go standard library, the Go log package is very easy to use. You can simply import the log package and output logs to standard errors (stderr) without having to do any creation or setup operations, because the log package has a built-in default logger named std:

1
2

// $GOROOT/src/log/log.go
var std = New(os.Stderr, "", LstdFlags)

This pattern of having a default logger instance built in is also emulated by many third-party logging packages. The following is a simple example of using the default logger to output logs.

import "log"

func main() {
    log.Println("hello, go log")
}

Output of the above example program.

`1`	`2022/02/27 14:40:41 hello, go log`

We see: go log provides a printf-like style log API, which means that the code will work just as well if the log in the code is replaced with fmt. go log supports three types of APIs.

1
2
3

Println/Printf
Panicln/Panicf // 相当于PrintX + panic
Fatalln/Fatalf // 相当于PrintX + exit

The go log package allows for some “customization” of the logger through the following three export methods.

1
2
3

func SetFlags(flag int)       // 主要用于设置日志的时间戳格式，也可以设置前缀字符串在log输出中的位置，默认flag为LstdFlags
func SetOutput(w io.Writer)   // 设置日志的输出目的地，比如文件、网络socket、syslog等
func SetPrefix(prefix string) // 设置日志前缀

But go log package does not support setting log level and output by level, and the built-in std logger also does not support log level. If you have a need for log level, you can use the go log package for secondary packaging. The following is a simple wrapping demo.

package main

import (
    "io"
    "log"
    "os"
    "sync/atomic"
)

// log level
const (
    LDEBUG = iota + 1 // 1
    LWARN             // 2
    LINFO             // 3
    LERROR            // 4
    LFATAL            // 5
)

type myLogger struct {
    level       int64
    w           io.Writer
    debugLogger *log.Logger
    warnLogger  *log.Logger
    infoLogger  *log.Logger
    errLogger   *log.Logger
    fatalLogger *log.Logger
}

func New(w io.Writer, level int64, flag int) *myLogger {
    if w == nil {
        w = os.Stderr
    }

    if flag <= 0 {
        flag = log.LstdFlags
    }

    return &myLogger{
        w:           w,
        level:       level,
        debugLogger: log.New(w, "[DEBUG] ", flag|log.Lmsgprefix),
        warnLogger:  log.New(w, "[WARN] ", flag|log.Lmsgprefix),
        infoLogger:  log.New(w, "[INFO] ", flag|log.Lmsgprefix),
        errLogger:   log.New(w, "[ERROR] ", flag|log.Lmsgprefix),
        fatalLogger: log.New(w, "[FATAL] ", flag|log.Lmsgprefix),
    }
}

func (l *myLogger) SetLevel(level int64) {
    if level < LDEBUG || level > LFATAL {
        return
    }

    atomic.StoreInt64(&l.level, level)
}

func (l *myLogger) Debugln(v ...interface{}) {
    if atomic.LoadInt64(&l.level) > LDEBUG {
        return
    }
    l.debugLogger.Println(v...)
}

func (l *myLogger) Debugf(format string, v ...interface{}) {
    if atomic.LoadInt64(&l.level) > LDEBUG {
        return
    }
    l.debugLogger.Printf(format, v...)
}

func (l *myLogger) Infoln(v ...interface{}) {
    if atomic.LoadInt64(&l.level) > LINFO {
        return
    }
    l.infoLogger.Println(v...)
}

func (l *myLogger) Infof(format string, v ...interface{}) {
    if atomic.LoadInt64(&l.level) > LINFO {
        return
    }
    l.infoLogger.Printf(format, v...)
}

func main() {
    logger := New(nil, LWARN, 0)
    logger.Infoln("info level log demo")
    logger.Debugln("debug level log demo")
}

Run this demo, the output log is as follows: (Since the LWARN level is set, only the info level log will be output, the debug level log will be ignored).

`1`	`2022/02/27 15:41:01 [INFO] info level log demo`

glog

A Google internal use, Go version of glog is also available under the golang organization of github.

Note: glog is google’s own internal logging package, and does not accept external PRs for adding features.

glog supports hierarchical logging and provides a dedicated API to output logs by specific log level, such as: InfoXx, WarningXx, ErrorXx, FatalXx, etc. The following is an example of using glog.

package main

import (
    "flag"

    "github.com/golang/glog"
)

func main() {
    flag.Parse()
    glog.Info("Prepare to repel boarders")

    if glog.V(2) {
        glog.Info("Starting transaction...")
    }
    glog.V(2).Infoln("Processed", 5, "elements")
    glog.Flush()
}

glog specifies the log level by flag, so you must call the Parse function of the Go standard library flag package to parse the command line flag before using glog to output the log. executing this example, the output is as follows.

$go run main.go -logtostderr -v=2
I0227 16:14:35.968922   40869 main.go:12] Prepare to repel boarders
I0227 16:14:35.969024   40869 main.go:15] Starting transaction...
I0227 16:14:35.969027   40869 main.go:17] Processed 5 elements

Note: Using -logtostderr makes the log output to the standard error, otherwise the default output is to a temporary file in the system temporary file directory; if you want to output the log to a specific directory, you can remove -logtostderr and specify -log_dir, but we can’t specify the log file name, glog has a set of built-in automatic naming mechanism for log files.

Although there are many differences between glog and the standard library log package, they generally belong to a class of log packages that share a common feature: Developers need to compose an unstructured log by themselves through the class Printf API, such logs are easy for humans to read, but not for machines to read (parse).

Structured logging package

Well, this brings us to another class of log packages, which are the opposite of the standard library log and golang/glog above: Developers don’t need to self-organize the log format when using this class of log packages, they just need to give the fields to be output by key-value, and the log package will automatically organize these fields into a structured log like the following.

1
2
3

// 以zap包输出为例：

{"level":"info","ts":1646256841.204795,"caller":"zap/testzap.go:13","msg":"failed to fetch URL","url":"http://tonybai.com","attempt":3,"backoff":1}

We can easily see that this is a legitimate json data, such log packages mostly use json as the output form of structured logs. And, even if some packages provide a Printf-like API, they actually just use a self-assembled string as the value of a specific key (e.g., the zap package uses msg).

The vast majority of third-party log packages open-sourced by the Go community belong to this type of structured logging package, including the two most highly ranked and widely adopted packages on github, sirupsen/logrus and uber-go/zap.

sirupsen/logrus and uber-go/zap

I use uber/zap in production, and I’ll talk more about how to use the zap package when I get a chance.

The main reason for the popularity of structured logging packages is that they are easy to be “read” by machines, nowadays it is no longer a best practice to “write” logs to a centralized logging platform of class [ELK] for review, but a must.

Some say that performance is also a consideration. That’s true, or at least I would focus on a high-performing logging package in my selection. For example: zap beats std log in concurrent benchmark.

goos: linux
goarch: amd64
pkg: demo
cpu: Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz
BenchmarkGolog-4         4126830        290.7 ns/op    24 B/op      1 allocs/op
BenchmarkGooglelog-4     711428    1427 ns/op      216 B/op     2 allocs/op
BenchmarkZap-4      11572719        97.08 ns/op     0 B/op      0 allocs/op
PASS

What you may not know is that zap performance is actually inferior to std log under a single goroutine.

goos: linux
goarch: amd64
pkg: demo
cpu: Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz
BenchmarkGolog-4         4470559        273.4 ns/op    24 B/op      1 allocs/op
BenchmarkGooglelog-4     789846    1363 ns/op      216 B/op     2 allocs/op
BenchmarkZap-4       2934202        400.4 ns/op     0 B/op      0 allocs/op
PASS

However, which Go application as a backend service today does not start several goroutines? Concurrency is the main scenario for log applications.

Whether you choose the unstructured std log package or the structured, high-performance zap log package, you will still encounter some problems during the application. Next, let’s take a look at the main problems that exist in the engineering practice of logging.

II. The main problems in engineering practice

In engineering practice, you will encounter many problems in dealing with logs, such as: how to log selection, how to evaluate log performance, how to set log output (including: setting the purpose of log output io.Writer, log format, log rotation (rotate) and archive (archive), etc.).

But these are not the main problems, log selection can refer to the most widely used community log package; log performance can be judged by a simple benchmark; log settings, look at the doc and example provided by each package can mostly be handled.

So what is the main problem? Actually, it is log adaptation. Why is there a log adaptation problem? Let me give you an example to understand.

Now I have a Go project P1, P1 relies on uber/zap package to output log. through the previous understanding of zap, we know that zap output log style is like this.

`1`	`{"level":"warn","logtime":"2022-02-27T15:24:57+08:00","caller":"xx/log.go:19","msg":"[f:1,l:33372,t:4,c:33372,a:33372] [00103:00001] t24 cast vote from n00003 index 33373 term 24, log term: 5"}`

Now P1 wants to implement distributed and strongly consistent data synchronization based on the dragonboat package, but dragonboat uses a custom logger, whose internal module outputs logs in the style of

`1`	`2022-02-27 16:25:40.259479 I \| raft: [f:1,l:33375,t:26,c:33374,a:33374] [00101:00001] t26 became leader`

We see: the problem arises: P1 outputs some logs in zap log format and some in dragonboat’s custom format, which is not only difficult for human to read, but also impossible for the machine to parse.

The good thing is that the dragonboat package is kind enough to provide an external export function SetLoggerFactory to set its internal logger, but only if the type of the logger instance set should satisfy the following interface type.

// dragonboat包中的logger/logger.go
type ILogger interface {
    SetLevel(LogLevel)
    Debugf(format string, args ...interface{})
    Infof(format string, args ...interface{})
    Warningf(format string, args ...interface{})
    Errorf(format string, args ...interface{})
    Panicf(format string, args ...interface{})
}

The good thing is that the zap package provides a “Sugar” style Printf-like API that can be used to adapt the above ILogger interface, we take the dragonboat-example as an example to adapt the project to the zap-style log, we provide a log.go file for the helloworld project with the following source code.

//helloworld/log.go

package main

import (
    "github.com/lni/dragonboat/v3/logger"
    "go.uber.org/zap"
)

type LogLevel = logger.LogLevel

type Mylogger struct {
    *zap.Logger
}

func (l *Mylogger) SetLevel(level LogLevel) {
}

func (l *Mylogger) Warningf(format string, args ...interface{}) {
    l.Logger.Sugar().Warnf(format, args...)
}

func (l *Mylogger) Debugf(format string, args ...interface{}) {
    l.Logger.Sugar().Debugf(format, args...)
}

func (l *Mylogger) Errorf(format string, args ...interface{}) {
    l.Logger.Sugar().Errorf(format, args...)
}

func (l *Mylogger) Infof(format string, args ...interface{}) {
    l.Logger.Sugar().Infof(format, args...)
}

func (l *Mylogger) Panicf(format string, args ...interface{}) {
    l.Logger.Sugar().Panicf(format, args...)
}

var _ logger.ILogger = (*Mylogger)(nil)

var factory = func(pkgName string) logger.ILogger {
    logger, _ := zap.NewProduction()
    return &Mylogger{
        Logger: logger,
    }
}

Then use the SetLoggerFactory provided by dragonboat to reset the logger instance used internally by dragonboat in the main.go of helloworld.

func main() {
    ... ...
    logger.SetLoggerFactory(logger.Factory(factory))

    // change the log verbosity
    logger.GetLogger("raft").SetLevel(logger.ERROR)
    logger.GetLogger("rsm").SetLevel(logger.WARNING)
    logger.GetLogger("transport").SetLevel(logger.WARNING)
    logger.GetLogger("grpc").SetLevel(logger.WARNING)
    ... ...
}

When we run the helloworld example after this change, we can see that its output log style has changed to zap style.

1
2

{"level":"warn","ts":1646300185.9349403,"caller":"helloworld/log.go:18","msg":"[f:1,l:4,t:2,c:4,a:4] [00128:00001] t3 received 2 votes and 0 rejections, quorum is 2"}
{"level":"info","ts":1646300185.9352179,"caller":"helloworld/log.go:30","msg":"[f:1,l:5,t:3,c:4,a:4] [00128:00001] t3 became leader"}

Here, some people may say: Adapting a logging package seems to be okay! In fact, if you come across a package like dragonboat, it means we are lucky that it provides a logger interface for you to adapt, but what if it doesn’t provide such an interface? What if zap didn’t provide a Printf-like API? We can’t even blend zap with dragonboat like above.

Furthermore, I’d say the seriousness of the problem lies in the uncertainty that comes from the unpredictability of future logging interface format compatibility with some newly introduced third-party package, and the root of the problem lies in the fact that there is no official Go logging interface for all projects to follow.

As we said earlier in the state of logging, the Go standard library Logger is a structure, a concrete implementation, and not decoupled.

III. Interim solutions, community efforts and expectations

So what do we do when we encounter such engineering problems? In the absence of a unified log interface provided by Go, we may encounter the following two scenarios (Project P, Dependency D).

If D provides a log interface for adaptation like dragonboat above, and the style of the log interface is compatible with the style of P’s own log package (e.g., both support the Printf-like API), then we need to provide a logger implementation in project P for adaptation to D, as in the above example.
If D does not provide a logging interface for adaptation, and its output logging style is not consistent with P’s own logging style or D’s logging API style is not compatible with P’s own logging package API, in this case, either raise an issue or pr with the author of the D library (which may be rejected in most cases), or be more practical and fork the D project yourself and develop it twice, replacing the logger or add an interface for adaptation.

To solve the log engineering problem once and for all, or the need to Go official definition of a unified log interface, the community in this regard can not say no effort, in 2017 a group of Go community gods on the establishment of a unified log interface committee, and discussion came up with a proposal to try to add a unified log interface to the Go standard library, but the proposal was not accepted by the Go core team. After that, the topic gradually fell silent, forming the current status quo.

The Go community can only take the peripheral route, so there are many Go community version of java-like SLF4J(Simple Logging Facade for Java) projects, such as logr, slf4go, etc. The more active log API at the moment is the logr project, which provides adapted implementations of most major log packages. If you don’t have a better solution, you can think about adopting logr’s API specification.

IV. Summary

The problem of log in engineering practice is not singled out in the Go Annual User Survey, but it does exist, and I think it should be part of the “Missing or immature I think it should be part of the “Missing or immature libraries” survey, and the sooner this problem is solved, the better, it will bring great convenience to developers and save a lot of time spent on implementing log adaptations.

Table of Contents