Building package-level, runtime configurable logging ala log4j in Go

September 13, 2024

15 min read

Introduction

We're using Go to write Dolt, the world's first version-controlled SQL database. Before I joined DoltHub, I had been a backend Java developer for over a decade. I love Go, and I vastly prefer it to Java. I'm on record as saying I'll never write Java again if I have the option to write Go instead.

But there is one Java tool I find myself missing more and more as time goes on: log4j.

What's so good about log4j?

log4j was one of the first widely deployed logging frameworks in the Java ecosystem, and it has decades of development time under its belt. It's powerful, flexible, and performant, with tons of built-in features. It's so popular that a security exploit discovered in 2021 affected hundreds of millions of devices.

But the feature that I miss most is package-level logging configuration. It's easiest to explain with an example. We'll crib this one from a Digital Ocean tutorial.

Let's say we have a Java class that looks like this:

package com.journaldev.log4j.main;

import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

import com.journaldev.log4j.logic.MathUtils;

public class Log4jExample {

	static{
        PropertyConfigurator.configure("log4j.properties");
	}
	
	private final static Logger logger = Logger.getLogger(Log4jExample.class);
	
	public static void main(String[] args) {
		logger.debug("My Debug Log");
		logger.info("My Info Log");
		logger.warn("My Warn Log");
		logger.error("My error log");
		logger.fatal("My fatal log");
				
	}
}

Pay attention to this line:

PropertyConfigurator.configure("log4j.properties");

Unlike existing popular Go logging frameworks, log4j was designed from the beginning to use file-driven configuration. So the logging behavior you get changes based on the contents of the configuration file provided, no need to re-compile or re-release the software.

Suppose we use the following as our log4j.properties file:

#Define root logger options
log4j.rootLogger=DEBUG, file, console

#Define console appender
log4j.appender.console=org.apache.log4j.ConsoleAppender
logrj.appender.console.Target=System.out

#Define rolling file appender
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=logs/main.log

#Define loggers
log4j.logger.com.journaldev.log4j=ERROR, file, console

With this configuration file, when we run the program above we see this output:

ERROR Log4jExample - My error log
FATAL Log4jExample - My fatal log

We have a rootLogger level of DEBUG, but the DEBUG and INFO log messages from our class don't get printed, because of this line in the configuration:

log4j.logger.com.journaldev.log4j=ERROR, file, console

If we change that line of the config to WARN instead and run the program again, we see this:

WARN  Log4jExample - My Warn Log
ERROR Log4jExample - My error log
FATAL Log4jExample - My fatal log

Get all that? Think about what this does:

We can get more or less detailed logging from one particular part of the code by changing a config file.
We didn't have to re-compile anything to do it.

That's package-based logging configuration. While it might not seem too important at first glance, it's a big deal. But why?

Logging is a powerful tool for understanding what's going on in your program, especially in the context of a long-running server. Let's say you're investigating a bug in your server, and you have a hunch that the bug is in a specific part of the database access layer. With popular existing Go logging frameworks, if you want to log more detail from that part of the code, you generally have to log more detail in the entire program by turning up the global logging level to DEBUG or similar.

Hopefully your program accepts command line arguments or file-based configuration to adjust this global log level -- if not, you'll need to recompile, which is an even bigger pain when the error is being experienced by one of your users you're trying to support. But assuming you can change the log level, this does work. The problem is that for large programs, your log will be cluttered with many thousands of irrelevant messages before you get to the ones you're trying to investigate.

Package-level logging configuration solves this problem: you see more detailed messages from where you want to see it and nowhere else, with no recompile. We had this technology in the early 2000s, but as far as I can tell, to date no Go logging library has implemented it as a standard feature.

Let's fix that.

Building our own

We don't want to re-invent the wheel, so we'll build our prototypes on the backs of two popular and mature Go logging frameworks: Zap and logrus. We use both at DoltHub: Zap powers logging in our backend web services, while we use logrus for logging in the Dolt SQL server.

We want the prototypes we build to have these features:

Change logging behavior per-package by changing a config file, no re-compiling necessary.
Easy to write the code to get per-package logging behavior.
No major performance penalties relative to changing the global logging level.

With that in mind, let's write a fake package hierarchy we can use to test our solutions. It looks like this:

.
├── a
│   ├── a.go
│   └── c
│       ├── c.go
│       └── e
│           └── e.go
├── b
│   ├── b.go
│   └── d
│       └── d.go
├── main.go

So we have one file in each package. Each package exports a method that matches its name and emits logs at each level, like this:

func A() {
	logrus.Debug("debug message from package a")
	logrus.Info("info message from package a")
	logrus.Warn("warn message from package a")
	logrus.Error("error message from package a")
}

Then in main(), we'll call them all after configuring logging, like this:

func main() {
	a.A()
	b.B()
	c.C()
	d.D()
	e.E()
}

Then we'll play with different logging configuration files to make sure we get the right log lines for each package.

Let's start with Zap.

Package-level logging configuration with Zap

Zap supports a plug-in architecture via the ability to implement custom Cores, and we already have the building blocks for what we want with the zapfilter package. This repository doesn't seem to have gotten much attention despite being mentioned by the main Zap docs. But it does something pretty close to what we want. From the README:

	core := zap.NewExample().Core()
	// *=myns             => any level, myns namespace
    // info,warn:myns.*   => info or warn level, any namespace matching myns.*
	// error=*            => everything with error level
	logger := zap.New(zapfilter.NewFilteringCore(core, zapfilter.MustParseRules("*:myns info,warn:myns.* error:*")))
	defer logger.Sync()

	logger.Debug("top debug")                                 // no match
	logger.Named("myns").Debug("myns debug")                  // matches *:myns
	logger.Named("bar").Debug("bar debug")                    // no match
	logger.Named("myns").Named("foo").Debug("myns.foo debug") // no match

	logger.Info("top info")                                 // no match
	logger.Named("myns").Info("myns info")                  // matches *:myns
	logger.Named("bar").Info("bar info")                    // no match
	logger.Named("myns").Named("foo").Info("myns.foo info") // matches info,warn:myns.*

Basically: the plugin lets you declare a set of rules to control which messages get logged. Rules match based on the level of the logged message and the Name property on a given logger. If we provide one logger per package, and name it the same as the package name, we can write rules that we load at program initialization to control the log level per package.

We'll put the package initialization code in a special pkglog_init.go file in each package. Here's a sample for zap-pkg-filter/example/a/c/e package:

var logger *zap.Logger

func getLogger() *zap.Logger {
	if logger != nil {
		return logger
	}
	logger = pkglog.NewProductionLogger("zap-pkg-filter/example/a/c/e")
	return logger
}

We use the package-level logger like this:

func E() {
	logger := getLogger()
	logger.Debug("debug message from package a/c/e")
	logger.Info("info message from package a/c/e")
	logger.Warn("warn message from package a/c/e")
	logger.Error("error message from package a/c/e")
}

Now we just need to initialize it with a config file at startup. Here's the code to do so:

package pkglog

import (
	"os"

	"go.uber.org/zap"
	"moul.io/zapfilter"
)

var filterRules zapfilter.FilterFunc

func Init(config string) {
	filterRules = zapfilter.MustParseRules(config)
}

func InitFromFile(configFile string) {
	file, err := os.ReadFile(configFile)
	if err != nil {
		panic(err)
	}
	filterRules = zapfilter.MustParseRules(string(file))
}

func NewProductionLogger(namespace string) *zap.Logger {
	config := zap.NewProductionConfig()
	config.OutputPaths = []string{"output.log"}
	config.Sampling = nil
	config.Level = zap.NewAtomicLevelAt(zap.DebugLevel)

	underlying, err := config.Build()
	if err != nil {
		panic(err)
	}

	return zap.New(zapfilter.NewFilteringCore(underlying.Core(), filterRules)).Named(namespace)
}

Note that we need to set the base logging level to DEBUG, the lowest level supported by Zap, so that our filter has a chance to examine every possible log entry and decide to log it or not.

Now we can provide a config file using the configuration language zapfilter supports.

info,warn,error:zap-pkg-filter/example/a
warn,error:zap-pkg-filter/example/b*
info,warn,error:zap-pkg-filter/example/a/c
debug,info,warn,error:zap-pkg-filter/example/a/c/e
*:zap-pkg-filter/example/b/d

When we run main() with this config file, we get the following output:

{"level":"info","ts":1726272873.8489308,"logger":"zap-pkg-filter/example/a","msg":"info message from package a"}
{"level":"warn","ts":1726272873.8494518,"logger":"zap-pkg-filter/example/a","msg":"warn message from package a"}
{"level":"error","ts":1726272873.8494518,"logger":"zap-pkg-filter/example/a","msg":"error message from package a"}
{"level":"warn","ts":1726272873.8515682,"logger":"zap-pkg-filter/example/b","msg":"warn message from package b"}
{"level":"error","ts":1726272873.8515682,"logger":"zap-pkg-filter/example/b","msg":"error message from package b"}
{"level":"info","ts":1726272873.8521004,"logger":"zap-pkg-filter/example/a/c","msg":"info message from package a/c"}
{"level":"warn","ts":1726272873.8521004,"logger":"zap-pkg-filter/example/a/c","msg":"warn message from package a/c"}
{"level":"error","ts":1726272873.8526373,"logger":"zap-pkg-filter/example/a/c","msg":"error message from package a/c"}
{"level":"debug","ts":1726272873.8531635,"logger":"zap-pkg-filter/example/b/d","msg":"debug message from package b/d"}
{"level":"info","ts":1726272873.8531775,"logger":"zap-pkg-filter/example/b/d","msg":"info message from package b/d"}
{"level":"warn","ts":1726272873.8531775,"logger":"zap-pkg-filter/example/b/d","msg":"warn message from package b/d"}
{"level":"error","ts":1726272873.8531775,"logger":"zap-pkg-filter/example/b/d","msg":"error message from package b/d"}
{"level":"debug","ts":1726272873.8537083,"logger":"zap-pkg-filter/example/a/c/e","msg":"debug message from package a/c/e"}
{"level":"info","ts":1726272873.8537083,"logger":"zap-pkg-filter/example/a/c/e","msg":"info message from package a/c/e"}
{"level":"warn","ts":1726272873.8537083,"logger":"zap-pkg-filter/example/a/c/e","msg":"warn message from package a/c/e"}
{"level":"error","ts":1726272873.8537083,"logger":"zap-pkg-filter/example/a/c/e","msg":"error message from package a/c/e"}

Let's make the logging more sparse. Here's a config file that does that:

error:*
debug,info,warn,error:zap-pkg-filter/example/a/c/e

And its accompanying output:

{"level":"error","ts":1726276964.83549,"logger":"zap-pkg-filter/example/a","msg":"error message from package a"}
{"level":"error","ts":1726276964.837593,"logger":"zap-pkg-filter/example/b","msg":"error message from package b"}
{"level":"error","ts":1726276964.838627,"logger":"zap-pkg-filter/example/a/c","msg":"error message from package a/c"}
{"level":"error","ts":1726276964.8396807,"logger":"zap-pkg-filter/example/b/d","msg":"error message from package b/d"}
{"level":"debug","ts":1726276964.8402045,"logger":"zap-pkg-filter/example/a/c/e","msg":"debug message from package a/c/e"}
{"level":"info","ts":1726276964.8402045,"logger":"zap-pkg-filter/example/a/c/e","msg":"info message from package a/c/e"}
{"level":"warn","ts":1726276964.8402045,"logger":"zap-pkg-filter/example/a/c/e","msg":"warn message from package a/c/e"}
{"level":"error","ts":1726276964.8402045,"logger":"zap-pkg-filter/example/a/c/e","msg":"error message from package a/c/e"}

So it all works! We can get more or less detail from different Go packages just by changing a config file. Beautiful.

Let's evaluate this prototype:

Pros:

Fast.
Pretty ergonomic: a single logger var for each package, used for all logging.

Cons:

Needs an init file for every package. I wrote them by hand, but they could easily be generated with a simple script. But still, more stuff to maintain, and if you forget to do it for a new package this solution doesn't work.
Rule syntax requires you to list every log level you want to include, e.g. DEBUG doesn't include ERROR as you might expect. Could be fixed with a patch or fork of zapfilter.
Relatively tricky to configure and use correctly relative to other logging solutions. This is mostly a criticism of Zap as opposed to our additions to it, but we made things worse.

You can find the full prototype on GitHub here.

Package-level logging configuration with Logrus

Logrus is in maintenance mode, but is basically complete. Its main extensibility comes in the form of Hooks, which are arbitrary triggers that run whenever a logging event occurs. We'll install a hook that implements message filtering based on the runtime stack of the code logging the message. It looks like this:

type Hook struct {
	props *properties.Properties
	level logrus.Level
	wr    io.Writer
}

var _ logrus.Hook = (*Hook)(nil)

func (p Hook) Levels() []logrus.Level {
	return logrus.AllLevels
}

var formatter = &logrus.JSONFormatter{
	FieldMap: logrus.FieldMap{
		logrus.FieldKeyTime:  "ts",
		logrus.FieldKeyLevel: "level",
		logrus.FieldKeyMsg:   "msg",
		logrus.FieldKeyFile:  "",
	},
	CallerPrettyfier: func(frame *runtime.Frame) (function string, file string) {
		return frame.Function, ""
	},
}

func (p Hook) Fire(entry *logrus.Entry) error {
	f := entry.Caller.Function
	f = f[:strings.LastIndex(f, ".")]
	loglevel, ok := p.props.Get("pkglog." + f)
	if !ok {
		if entry.Level <= p.level {
			format, _ := formatter.Format(entry)
			p.wr.Write(format)
		}
	} else {
		if level, err := logrus.ParseLevel(loglevel); err == nil {
			if entry.Level <= level {
				format, _ := formatter.Format(entry)
				p.wr.Write(format)
			}
		}
	}
	return nil
}

This hook logs messages to a file or not depending based on the configured log level of the call site. We install it like this:

func InitFromFile(configFile string) {
	file, err := os.ReadFile(configFile)
	if err != nil {
		panic(err)
	}

	props, err := properties.Load(file, properties.UTF8)
	if err != nil {
		return
	}

	logrus.SetReportCaller(true)
	rootLogLevel, ok := props.Get("pkglog.rootLogger")
	var level logrus.Level
	if ok {
		level, err = logrus.ParseLevel(rootLogLevel)
		if err != nil {
			panic(err)
		}
	} else {
		level = logrus.InfoLevel
	}

	// We need the lowest level possible or our hook won't be invoked on all log messages
	logrus.SetLevel(logrus.TraceLevel)
	logrus.SetOutput(io.Discard)

	// clear hooks before adding ours, we only want one
	logrus.StandardLogger().Hooks = make(logrus.LevelHooks)
	logWriter, err := os.Create("output.log")
	if err != nil {
		panic(err)
	}

	logrus.AddHook(Hook{props: props, level: level, wr: logWriter})
}

Note where we set the main logger output to io.Discard, which means that the only logging that will happen is whatever our hook does. Unlike our Zap solution, we don't need to augment any of our packages with any additional configuration code. We can just call logrus.Debug or whatever level we want anywhere it's needed. (Zap can use a global logger too, but unlike logrus they very actively discourage doing so).

Now we need a config file. I opted to use the same format used by log4j:

pkglog.rootLogger=INFO

pkglog.logrusprops/example/b=WARN
pkglog.logrusprops/example/b/d=TRACE
pkglog.logrusprops/example/a/c/e=DEBUG
pkglog.logrusprops/example/a/c=INFO

When we run this our program with this config, we get this output logged:

{"func":"logrusprops/example/a.A","level":"info","msg":"info message from package a","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a.A","level":"warning","msg":"warn message from package a","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a.A","level":"error","msg":"error message from package a","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b.B","level":"warning","msg":"warn message from package b","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b.B","level":"error","msg":"error message from package b","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c.C","level":"info","msg":"info message from package a/c","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c.C","level":"warning","msg":"warn message from package a/c","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c.C","level":"error","msg":"error message from package a/c","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b/d.D","level":"debug","msg":"debug message from package b/d","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b/d.D","level":"info","msg":"info message from package b/d","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b/d.D","level":"warning","msg":"warn message from package b/d","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/b/d.D","level":"error","msg":"error message from package b/d","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c/e.E","level":"debug","msg":"debug message from package a/c/e","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c/e.E","level":"info","msg":"info message from package a/c/e","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c/e.E","level":"warning","msg":"warn message from package a/c/e","ts":"2024-09-13T17:46:05-07:00"}
{"func":"logrusprops/example/a/c/e.E","level":"error","msg":"error message from package a/c/e","ts":"2024-09-13T17:46:05-07:00"}

So this works as well. Let's evaluate this solution.

Pros:

Very simple to configure and use, no code gen or other setup needed.
Configured log levels include all lower levels (so DEBUG includes WARN e.g.).
You get a TRACE logging level, for when DEBUG is not low level enough (although this is just a feature of logrus relative to Zap).

Cons:

Getting call stack makes logging slower (and logrus is already much slower than Zap).
Global logger instance is no longer considered best practice in the Go community.
No wildcard support for package names, although that could be fixed.

You can find the full prototype on GitHub here.

Performance comparison

Zap is a lot faster than logrus. And that remains the case with our package-level configuration changes. I benchmarked the main method for both packages to compare.

First, logrus. It can run the main method in about 416 µs.

goos: linux
goarch: amd64
pkg: logrusprops/example
cpu: AMD EPYC 7571
                 │ benchmark.txt │
                 │    sec/op     │
Logging-16           416.4µ ± 0%
SparseLogging-16     334.0µ ± 0%
geomean              372.9µ

Now Zap. It clocks in at a little over 4 times as fast as logrus for similar sized messages.

goos: linux
goarch: amd64
pkg: zap-pkg-filter/example
cpu: AMD EPYC 7571
                 │ benchmark-no-sync.txt │
                 │        sec/op         │
Logging-16                   105.2µ ± 0%
SparseLogging-16             49.40µ ± 0%
geomean                      72.09µ

I ran two different benchmarks corresponding to the two different logging configurations above in order to understand how the volume of messages logged impacted performance. Zap scales down quite nicely: many fewer messages logged means much faster runtime. logrus was disappointing in this respect, with much smaller savings from logging many fewer messages. It's likely that my prototype could do much better on this axis, but given the huge baseline performance difference between Zap and logrus it's not clear it's worth optimizing much.

To put the performance numbers in different terms, Zap logged about 8 times as many log lines in the same time interval for the sparse logging scenario.

$ wc -l logrusprops/example/output.log zap-pkg-filter/example/output.log
   26520 logrusprops/example/output.log
  193664 zap-pkg-filter/example/output.log

One important caveat is that the standard practice recommended in many Zap tutorials, of calling Sync() on loggers after logging operations to flush output to disk, absolutely destroys Zap's performance. I ended up adding code to optionally disable the Sync() behavior:

var _, skipSync = os.LookupEnv("SKIP_SYNC")

func A() {
	logger := getLogger()
	if !skipSync {
		defer logger.Sync()
	}

	logger.Debug("debug message from package a")
	logger.Info("info message from package a")
	logger.Warn("warn message from package a")
	logger.Error("error message from package a")
}

Without this environment variable set, Zap's performance falls through the floor, coming in about 4x slower than logrus.

goos: linux
goarch: amd64
pkg: zap-pkg-filter/example
cpu: AMD EPYC 7571
                 │ benchmark.txt │
                 │    sec/op     │
Logging-16           13.30m ± 0%
SparseLogging-16     13.10m ± 1%
geomean              13.20m

Future work

I built these two prototypes because I was frustrated by the apparent lack of package-level logging configuration in the Go ecosystem, and wanted to see what was possible in an afternoon's worth of work. And because we use both logging packages internally, I wanted to see how solutions using off-the-shelf extensions for each of them would compare.

Given Zap's overwhelming advantage in performance, I think the next step would be to try to get the better ergonomics of the logrus solution working in Zap, combining the best of both worlds.

zapfilter only has the capability to filter messages based on the name of a given logger, so we have to name every logger based on the package it's being used to take advantage of the library. But there's an obvious alternative to this approach.

Here's how Zap defines a LogEntry:

type Entry struct {
	Level      Level
	Time       time.Time
	LoggerName string
	Message    string
	Caller     EntryCaller
	Stack      string
}

// EntryCaller represents the caller of a logging function.
type EntryCaller struct {
	Defined  bool
	PC       uintptr
	File     string
	Line     int
	Function string
}

So we already have all the information necessary to filter log output based on the file name or function of the logged message. It should be a relatively simple matter to extend zapfilter to enable this desired behavior. If we decide to pursue this work, that would be my next move. It's unclear how much of a performance penalty enabling caller information would be, but given the massive performance advantage of Zap to begin with, it's very likely it would still come out far ahead of the logrus implementation.

Conclusion

Once again, you can find the full source of the Zap prototype here and the logrus prototype here. Comments welcome.

What do you think? Is package-level logging configuration a good idea for Go? Should we pursue this strategy and make it available for public consumption? Join us on Discord to let us know. Or maybe you are curious about the world's first version-controlled SQL database? We hope to hear from you in either case.

Blog