Logging is indispensable in any code that we need its support both in debugging and in statistics. However, a package that filled withfmt.Println/fmt.Printf printing various messages can never be considered a read-to-be-adopted package, which can be optimized by a simple change, using Golang’s native log package to print information to standard output or to a file.

Then, how to apply the log package? Are there any limitations? If so, can we seek open-source packages? Let’s find the answers together.

Golang log

package main

import "log"

func main() {
   log.Println("Log println") // Fatalln, Panicln
   log.Print("Log print")     // Fatal, Panic
   str := "Log Printf"
   log.Printf("%s", str) // Fatalf, Panicf
}

This code basically covers all the log printing usages, which correspond to the fmt usage pattern, including the 9 methods of Print/Fatal/Panic, Printf/Fatalf/Panicf, and Println/Fatalln/Panicln.

Group Fatal and Panic are different upon they finish printing.

• Fatal calls os.Exist(1) to exit.
• Panic calls the panic method to exit.

So the core difference is whether the defer function is called: Panic will return layer by layer, calling the defer function at each level; While, os.Exist exits directly.

package main

import (
	"log"
	"time"
)

func main() {
	defer log.Println("defer main")

	logPanic()
	//        logFatal()
	time.Sleep(100)

	log.Println("End")
}

func logPanic() {
	defer log.Println("defer logPanic")
	go func() {
		defer log.Println("defer gorountine1")
		log.Panic("log panic")
	}()
}

func logFatal() {
	go func() {
		defer log.Println("defer goroutine2")
		log.Fatal("log fatal")
	}()
}

log.Panic will trigger the call of the defer function in the above case.

But only one line of log is displayed without stack trace when using the logFatal method. Test here.

Customization

• Set Prefix.

func (l *Logger) SetPrefix(prefix string)

SetPrefix sets the output prefix for the logger.

It’s a common way of adding some general information needed when starting a method, such as adding the method name, parameters, etc.

• SetFlags

func (l *Logger) SetFlags(flag int)

SetFlags sets the output flags for the logger. The flag bits are Ldate, Ltime, and so on.

log package offers the following configurable flags.

And the common applications are:

log.SetFlags(log.Ldate|log.Lshortfile), output date + line number;

log.SetFlags(log.Ldate|log.Ltime |log.LUTC), output date + UTC time;

log.SetFlags(log.LstdFlags), output date + time, which is equal to the log.Ldate and log.Ltime combined.

• SetOutput

func SetOutput(w io.Writer)

SetOutput sets the output destination for the standard logger.

It can be used to redirect logs to files.

file, err := os.OpenFile("logs.txt", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0666)
if err != nil {
  log.Fatal(err)
}
log.SetOutput(file)

Inside log

Now to the log implementation. The log library defines a default Logger std, the standard log, whose corresponding methods are called internally when we call the methods of the log library directly.

And the Output function lies in the kernel of Logger.

As is seen, the log is thread-safe since it is under the protection of a mutex lock in the whole process except for the releasing of the lock when obtaining the Caller information.

The part of thebuf is something we can learn from, which reduces io by assembling the log via the []byte defined in the log, and then writing it to the writer.

Drawbacks

We don’t like to talk about drawbacks, but we have to.

• Not leveled-logs supportive. Let’s talk about logging | Dave Cheney indicated it as thelog package’s biggest cons.

That is, information on the leveled-logs like Info, Error, and Debug cannot be printed, causing all logs to be output to the same place, not conducive to subsequent log analysis and monitoring.

• Insufficient support for formatting. It is not friendly in scenarios where we need both logs in text format and JSON logs in key=value format for future log analysis and statistics.

Open-source log packages

log package is enough in most cases though, its limitation can be seen in those complex systems. So we should turn to various open-source log packages, some of which I want to walk you through.

glog

glog was originally the go log framework used internally by Google. Its biggest feature is leveled-logs supportive, and the four levels are Info, Warning, Error and Fatal.

func main() {
   flag.Parse()
   defer glog.Flush()
   glog.Info("This is a log,", "level", "info")
   glog.Warning("This is a log,", "level", "warning")
   glog.Error("This is a log,", "level", "error")
   glog.Fatal("This is a log,", "level", "fatal")
}

Meanwhile, glog also supports formatted output like Infof, and newline output like Infoln.

glog is unique for its implementation that V sets and filters the debug-level log, which largely facilitates the development of large-scale systems. Before it, I see no similar implementations.

glog.V(1).Infoln("level 1")glog.V(2).Infoln("level 2")

// -v=0 // Enable V-leveled logging at the specified level, and the default value of V is 0.

By adding these two lines to the above example, we can see the following output.

If -v =1 is passed in, then the line level 2 will not be displayed.

Moreover, glog supports writing logs into multi-levels based on the level as well. Run go run main.go -log_dir=. to generate multiple log files locally.

The log content is upward-compatible: main.INFO contains logs of the ERROR, WARNING and FATAL levels, while main.FATAL only has logs of the FATAL level.

Besides, glog will automatically create a new log file once the log file size is beyond Maxsize.

func (sb *syncBuffer) Write(p []byte) (n int, err error) {
   if sb.nbytes+uint64(len(p)) >= MaxSize {
      if err := sb.rotateFile(time.Now()); err != nil {
         sb.logger.exit(err)
      }
   }
   //...
}

// rotateFile closes the syncBuffer's file and starts a new one.
func (sb *syncBuffer) rotateFile(now time.Time) error {
   // ...
   sb.file, _, err = create(severityName[sb.sev], now)
   sb.nbytes = 0
   if err != nil {
      return err
   }
   // ...
}

glog can be regarded as the upgraded version of the native log, and they share the same feature: Developers are required to pass each field into APIs likePrintf/Errorf/Fatalf to form an unstructured log, which is helpful for searching and analyzing but not for machine sorting and collecting metrics.

logrus

logrus is another hottest log framework with 20.5k stars and 90k users on its github page. Its capability of directly outputting JSON logs in key=value format sets it apart from glog. And of course, it is text-format supportive as well.

package main

import (
	"github.com/sirupsen/logrus"
)

func main() {
	logrus.SetLevel(logrus.TraceLevel)
	//logrus.SetFormatter(&logrus.JSONFormatter{})

	logrus.Trace("print trace msg")
	logrus.WithFields(logrus.Fields{"name": "abc", "age": 11}).Debug("print debug msg")
	logrus.Infof("print info msg %d", 2)
	logrus.WarnFn(func() []interface{} {
		s := make([]interface{}, 4)
		s = append(s, "a")
		s = append(s, "3")
		s = append(s, "b")
		s = append(s, "4")
		return s
	})
	logrus.Error("print error msg")
	logrus.Fatal("print fatal msg")
	logrus.Panic("print panic msg")
}

// output
TRAC[0000] print trace msg                              
DEBU[0000] print debug msg                               age=11 name=abc
INFO[0000] print info msg 2                             
WARN[0000]    a3b4                  
ERRO[0000] print error msg                              
FATA[0000] print fatal msg                              
exit status 1

logrus supports the 7 levels of Trace, Debug, Info, Warn, Error, Fatal, and Panic, but not V- leveled debug log.

And for logs printing, logrus supports not only the conventional three types of methods, Info, Infof, and Infoln, but also the LogFunction func() []interface{}, improving efficiency. For the big messages, it only generates logs when the levels match; Otherwise, skips.

The WithFields function can pass in the parameters that log prints as the separate key and value, better for further analysis.

logrus.SetFormatter(&logrus.JSONFormatter{}) enables the print of JSON format log.

Uncomment the above code and re-run it, you’ll get the following JSON log

In addition to the default TextFormatter and JSONFormatter, Formatters that can be inserted into the third-party are also supported, such as nested-logrus-formatter provides an additional set of flags to control the output format.

With TimestampFormat: time.RFC3339, you can print logs in the 2022–05–26T15:40:07+02:00 format.

With the log hook, we can set the hook to respond to the log level of our interest, manipulate the log content, add and modify the specific key-value parameter of the log, etc. You can try those third-party implementations of Loghook, such as using logrus-redis-hook to forward logs to Redis.

Obviously, logrus is more scalable with all the functions listed above. But its log level setting is not as concise as glog’s V log that Dave Cheney even thinks “Nobody needs a warning log level.”

zap

zap was first introduced for Uber’s internal use before it was contributed to the community. Its biggest aim is “being faster” compared with glog and logrus when providing structured and leveled logs.

It provides two different types of loggers, Logger and SugaredLogger.

• Use Logger in scenarios with high-performance requirements and memory constraints. It is faster in performance with fewer memory allocations than SugaredLogger, but it only supports strong-typed structured logging.
• Use SugaredLogger when performance requirements are lower. It supports structured and printf-style logging while still beating other log packages in memory overhead and speed.

The following shows its advantage over other frameworks on Github.

package main

import (
	"go.uber.org/zap"
)

func main() {
	log := zap.NewExample() // Or zap.NewProduction(), zap.NewDevelopment()
	// sugarLog := log.Sugar()  // Create sugarLogger
	log.Debug("print debug log")
	log.Info("print info log with fileds",
		zap.String("name", "abc"), zap.Int("age", 11))
	log.Warn("print warn log")
	log.Error("print error log")
	log.Panic("print panic log")
}
// Output
{"level":"debug","msg":"print debug log"}
{"level":"info","msg":"print info log with fileds","name":"abc","age":11}
{"level":"warn","msg":"print warn log"}
{"level":"error","msg":"print error log"}
{"level":"panic","msg":"print panic log"}
panic: print panic log

goroutine 1 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc000164000, {0x0, 0x0, 0x0})

zap logger supports three creation methods, NewProduction, NewDevelopment, and NewExample, which corresponds to different output formats respectively.

• NewProduction and NewExample support JSON output.
• NewDevelopment supports text.
• NewExample can print logs at all levels, but shows no date, file, line number, etc.
• NewDevelopment prints logs of warn level and above, and the result includes date, timestamp, file, line number, and a parameter list(if it exists) in JSON format at the end of the line.
• NewProduction prints logs of info level and above, showing date, timestamp, and also the trace stack information for panic and error logs.

zap also supports “write to files”, but not log rotation, which can only be achieved with third-party loggers like lumberjack. And the zap FAQ offers an answer.

Wrap up

Log plays a significant role in development. When to log and which framework to follow is a big deal, which is a conviction further reinforced by the recent Java log4j.

The Go native log package offers most of the functions needed, but with those third-party log frameworks like logrus, glog, and zap, we can achieve more with a better log experience.

This article is just a tiny sip of the log packages, and many more with various functions are out there. If you are interested, you can try to explore more, such as studying the Kubernetes controller-runtime log package or customizing your own Logger.

Thanks for reading!

Note: The post is authorized by original author to republish on our site. Original author is Stefanie Lai who is currently a Spotify engineer and lives in Stockholm, original post is published here.