[Go advanced] how to make your Go Project Log clear and interesting - Zap log Library

This paper first introduces the use of the native log Library of Go language, then introduces the very popular open source zap log Library of Uber in detail, and introduces how to cut and archive logs with Lumberjack.

Use of Zap log Library in Go language project

In many Go language projects, we need a good logger that can provide the following functions:

  • Ability to log events to a file instead of the application console.
  • Log cutting - can cut log files according to file size, time or interval.
  • Different log levels are supported. For example, INFO, DEBUG, ERROR, etc.
  • Be able to print basic information, such as calling file / function name and line number, log time, etc.

Default Go Logger

Before introducing the zap package of Uber Go, let's take a look at the basic logging functions provided by the Go language. The default log package provided by Go language is https://golang.org/pkg/log/.

Implement Go Logger

Implementing a logger in Go language is very simple - create a new log file and set it as the output location of the log.

Set Logger

We can set up the logger like the following code

func SetupLogger() {
	logFileLocation, _ := os.OpenFile("/Users/q1mi/test.log", os.O_CREATE|os.O_APPEND|os.O_RDWR, 0744)
	log.SetOutput(logFileLocation)
}

Using Logger

Let's write some virtual code to use the logger.

In the current example, we will establish an HTTP connection to the URL and record the status code / error to the log file.

func simpleHttpGet(url string) {
	resp, err := http.Get(url)
	if err != nil {
		log.Printf("Error fetching url %s : %s", url, err.Error())
	} else {
		log.Printf("Status Code for %s : %s", url, resp.Status)
		resp.Body.Close()
	}
}

Operation of Logger

Now let's execute the above code and see how the logger works.

func main() {
	SetupLogger()
	simpleHttpGet("www.google.com")
	simpleHttpGet("http://www.google.com")
}

When we execute the above code, we can see a test The log file is created and the following contents will be added to the log file.

2019/05/24 01:14:13 Error fetching url www.google.com : Get www.google.com: unsupported protocol scheme ""
2019/05/24 01:14:14 Status Code for http://www.google.com : 200 OK

Strengths and weaknesses of Go Logger

advantage

Its biggest advantage is that it is very simple to use. We can set any io The writer outputs as a log record and sends it the log to write.

inferiority

  • Basic log level only
    • There is only one Print option. Multiple levels such as INFO/DEBUG are not supported.
  • For the error log, it has Fatal and Panic
    • Fatal logs are logged by calling OS Exit (1) to end the program
    • Panic log throws a panic after the log message is written
    • However, it lacks an ERROR log level, which can record errors without throwing panic or exiting the program
  • Lack of log formatting capabilities -- such as recording the caller's function name and line number, formatting date and time formats. wait.
  • The ability to cut logs is not provided.

Uber-go Zap

Zap It is a very fast, structured, log level Go log library.

Why Uber go zap

  • It provides both structured logging and printf style logging
  • It's very fast

According to Uber go Zap's documentation, its performance is better than similar structured log packages -- and faster than the standard library. The following is the benchmark information released by Zap

Record a message and 10 fields:

PackageTimeTime % to zapObjects Allocated
⚡️ zap862 ns/op+0%5 allocs/op
⚡️ zap (sugared)1250 ns/op+45%11 allocs/op
zerolog4021 ns/op+366%76 allocs/op
go-kit4542 ns/op+427%105 allocs/op
apex/log26785 ns/op+3007%115 allocs/op
logrus29501 ns/op+3322%125 allocs/op
log1529906 ns/op+3369%122 allocs/op

Record a static string without any context or printf style template:

PackageTimeTime % to zapObjects Allocated
⚡️ zap118 ns/op+0%0 allocs/op
⚡️ zap (sugared)191 ns/op+62%2 allocs/op
zerolog93 ns/op-21%0 allocs/op
go-kit280 ns/op+137%11 allocs/op
standard library499 ns/op+323%2 allocs/op
apex/log1990 ns/op+1586%10 allocs/op
logrus3129 ns/op+2552%24 allocs/op
log153887 ns/op+3194%23 allocs/op

install

Run the following command to install zap

go get -u go.uber.org/zap

Configure Zap Logger

Zap provides two types of loggers - sugar Logger and Logger.

In a context where performance is good but not critical, use sugarlogger. It is 4-10 times faster than other structured logging packages, and supports structured and printf style logging.

In the context where every microsecond and every memory allocation are important, use the Logger. It is even faster than sugarlogger and has fewer memory allocations, but it only supports strongly typed structured logging.

Logger

  • By calling zap NewProduction()/zap. Newdevelopment () or zap Example() creates a Logger.
  • Each of the above functions will create a logger. The only difference is that it will record different information. For example, production logger records the calling function information, date and time by default.
  • Call Info/Error through Logger.
  • By default, logs are printed to the application's console interface.
var logger *zap.Logger

func main() {
	InitLogger()
  defer logger.Sync()
	simpleHttpGet("www.google.com")
	simpleHttpGet("http://www.google.com")
}

func InitLogger() {
	logger, _ = zap.NewProduction()
}

func simpleHttpGet(url string) {
	resp, err := http.Get(url)
	if err != nil {
		logger.Error(
			"Error fetching url..",
			zap.String("url", url),
			zap.Error(err))
	} else {
		logger.Info("Success..",
			zap.String("statusCode", resp.Status),
			zap.String("url", url))
		resp.Body.Close()
	}
}

In the above code, we first create a Logger, and then use the Logger methods such as Info/ Error to record messages.

The syntax of the logger method is as follows:

func (log *Logger) MethodXXX(msg string, fields ...Field) 

MethodXXX is a variable parameter function, which can be Info / Error/ Debug / Panic, etc. Each method accepts a message string and any number of zapcore Field field parameter.

Each zapcore Field is actually a set of key value pair parameters.

When we execute the above code, we will get the following output results:

{"level":"error","ts":1572159218.912792,"caller":"zap_demo/temp.go:25","msg":"Error fetching url..","url":"www.sogo.com","error":"Get www.sogo.com: unsupported protocol scheme \"\"","stacktrace":"main.simpleHttpGet\n\t/Users/q1mi/zap_demo/temp.go:25\nmain.main\n\t/Users/q1mi/zap_demo/temp.go:14\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:203"}
{"level":"info","ts":1572159219.1227388,"caller":"zap_demo/temp.go:30","msg":"Success..","statusCode":"200 OK","url":"http://www.sogo.com"}

Sugared Logger

Now let's use sugar logger to achieve the same function.

  • Most implementations are basically the same.
  • The only difference is that we call the main logger Sugar() method to get a sugarlogger.
  • Then use sugarlogger to record the statement in printf format

The following is the modified code to use sugarlogger instead of Logger:

var sugarLogger *zap.SugaredLogger

func main() {
	InitLogger()
	defer sugarLogger.Sync()
	simpleHttpGet("www.google.com")
	simpleHttpGet("http://www.google.com")
}

func InitLogger() {
  logger, _ := zap.NewProduction()
	sugarLogger = logger.Sugar()
}

func simpleHttpGet(url string) {
	sugarLogger.Debugf("Trying to hit GET request for %s", url)
	resp, err := http.Get(url)
	if err != nil {
		sugarLogger.Errorf("Error fetching URL %s : Error = %s", url, err)
	} else {
		sugarLogger.Infof("Success! statusCode = %s for URL %s", resp.Status, url)
		resp.Body.Close()
	}
}

When you execute the above code, you will get the following output:

{"level":"error","ts":1572159149.923002,"caller":"logic/temp2.go:27","msg":"Error fetching URL www.sogo.com : Error = Get www.sogo.com: unsupported protocol scheme \"\"","stacktrace":"main.simpleHttpGet\n\t/Users/q1mi/zap_demo/logic/temp2.go:27\nmain.main\n\t/Users/q1mi/zap_demo/logic/temp2.go:14\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:203"}
{"level":"info","ts":1572159150.192585,"caller":"logic/temp2.go:29","msg":"Success! statusCode = 200 OK for URL http://www.sogo.com"}

You should notice that so far, both logger s print out JSON structure format.

Later in this blog, we will discuss sugarlogger in more detail and learn how to further configure it.

Custom logger

Write log to file instead of terminal

The first change we need to make is to write the log to a file instead of printing to the application console.

  • We will use zap New (...) method to manually pass all configurations instead of using a method like zap A preset method such as newproduction () to create a logger.
func New(core zapcore.Core, options ...Option) *Logger

zapcore. The core requires three configurations - Encoder, writesynchronizer, and LogLevel.

1.Encoder: encoder (how to write log). We'll use NewJSONEncoder() out of the box and the preset productionencoder config ().

   zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())

2.WriterSyncer: specifies where the log will be written. We use zapcore Addsync() function and pass in the open file handle.

   file, _ := os.Create("./test.log")
   writeSyncer := zapcore.AddSync(file)

3.Log Level: which level of logs will be written.

We will modify the Logger code in the above section and override the InitLogger() method. The remaining methods - main() /SimpleHttpGet() remain unchanged.

func InitLogger() {
	writeSyncer := getLogWriter()
	encoder := getEncoder()
	core := zapcore.NewCore(encoder, writeSyncer, zapcore.DebugLevel)

	logger := zap.New(core)
	sugarLogger = logger.Sugar()
}

func getEncoder() zapcore.Encoder {
	return zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
}

func getLogWriter() zapcore.WriteSyncer {
	file, _ := os.Create("./test.log")
	return zapcore.AddSync(file)
}

When the main() function of the above section is called with these modified logger configurations, the following output will be printed in the file - test Log.

{"level":"debug","ts":1572160754.994731,"msg":"Trying to hit GET request for www.sogo.com"}
{"level":"error","ts":1572160754.994982,"msg":"Error fetching URL www.sogo.com : Error = Get www.sogo.com: unsupported protocol scheme \"\""}
{"level":"debug","ts":1572160754.994996,"msg":"Trying to hit GET request for http://www.sogo.com"}
{"level":"info","ts":1572160757.3755069,"msg":"Success! statusCode = 200 OK for URL http://www.sogo.com"}

Change JSON Encoder to normal Log Encoder

Now, we want to change the Encoder from JSON Encoder to normal Encoder. To do this, we need to change newjsoneencoder () to NewConsoleEncoder().

return zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig())

When the main() function of the above section is called with these modified logger configurations, the following output will be printed in the file - test Log.

1.572161051846623e+09	debug	Trying to hit GET request for www.sogo.com
1.572161051846828e+09	error	Error fetching URL www.sogo.com : Error = Get www.sogo.com: unsupported protocol scheme ""
1.5721610518468401e+09	debug	Trying to hit GET request for http://www.sogo.com
1.572161052068744e+09	info	Success! statusCode = 200 OK for URL http://www.sogo.com

Change the time code and add caller details

In view of the changes we made to the configuration, there are two problems:

  • Time is displayed in a non-human readable manner, such as 1.572161051846623e+09
  • The details of the caller function are not displayed in the log

The first thing we need to do is override the default ProductionConfig() and make the following changes:

  • Modify time encoder
  • Use uppercase letters to record the log level in the log file
func getEncoder() zapcore.Encoder {
	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
	encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder
	return zapcore.NewConsoleEncoder(encoderConfig)
}

Next, we will modify the zap logger code to add the function of logging the calling function information. To this end, we will be in zap New(..) Add an Option to the function.

logger := zap.New(core, zap.AddCaller())

When the main() function of the above section is called with these modified logger configurations, the following output will be printed in the file - test Log.

2019-10-27T15:33:29.855+0800	DEBUG	logic/temp2.go:47	Trying to hit GET request for www.sogo.com
2019-10-27T15:33:29.855+0800	ERROR	logic/temp2.go:50	Error fetching URL www.sogo.com : Error = Get www.sogo.com: unsupported protocol scheme ""
2019-10-27T15:33:29.856+0800	DEBUG	logic/temp2.go:47	Trying to hit GET request for http://www.sogo.com
2019-10-27T15:33:30.125+0800	INFO	logic/temp2.go:52	Success! statusCode = 200 OK for URL http://www.sogo.com

Log cutting and archiving using Lumberjack

The only thing missing in this log program is the log cutting and archiving function.

Zap itself does not support cutting archive log files

In order to add log cutting and archiving, we will use a third-party library Lumberjack To achieve.

install

Execute the following command to install Lumberjack

go get -u github.com/natefinch/lumberjack

Add Lumberjack to zap logger

To add Lumberjack support to zap, we need to modify the WriteSyncer code. We will modify the getLogWriter() function according to the following code:

func getLogWriter() zapcore.WriteSyncer {
	lumberJackLogger := &lumberjack.Logger{
		Filename:   "./test.log",
		MaxSize:    10,
		MaxBackups: 5,
		MaxAge:     30,
		Compress:   false,
	}
	return zapcore.AddSync(lumberJackLogger)
}

Lumberjack Logger takes the following attributes as input:

  • Filename: location of log file
  • MaxSize: the maximum size (in MB) of the log file before cutting
  • MaxBackups: the maximum number of old files to keep
  • MaxAges: maximum number of days to keep old files
  • Compress: compress / archive old files

Test all functions

Finally, the complete example code of Zap/Lumberjack logger is as follows:

package main

import (
	"net/http"

	"github.com/natefinch/lumberjack"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

var sugarLogger *zap.SugaredLogger

func main() {
	InitLogger()
	defer sugarLogger.Sync()
	simpleHttpGet("www.sogo.com")
	simpleHttpGet("http://www.sogo.com")
}

func InitLogger() {
	writeSyncer := getLogWriter()
	encoder := getEncoder()
	core := zapcore.NewCore(encoder, writeSyncer, zapcore.DebugLevel)

	logger := zap.New(core, zap.AddCaller())
	sugarLogger = logger.Sugar()
}

func getEncoder() zapcore.Encoder {
	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
	encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder
	return zapcore.NewConsoleEncoder(encoderConfig)
}

func getLogWriter() zapcore.WriteSyncer {
	lumberJackLogger := &lumberjack.Logger{
		Filename:   "./test.log",
		MaxSize:    1,
		MaxBackups: 5,
		MaxAge:     30,
		Compress:   false,
	}
	return zapcore.AddSync(lumberJackLogger)
}

func simpleHttpGet(url string) {
	sugarLogger.Debugf("Trying to hit GET request for %s", url)
	resp, err := http.Get(url)
	if err != nil {
		sugarLogger.Errorf("Error fetching URL %s : Error = %s", url, err)
	} else {
		sugarLogger.Infof("Success! statusCode = %s for URL %s", resp.Status, url)
		resp.Body.Close()
	}
}

Execute the above code, and the following content will be output to the file - test Log.

2019-10-27T15:50:32.944+0800	DEBUG	logic/temp2.go:48	Trying to hit GET request for www.sogo.com
2019-10-27T15:50:32.944+0800	ERROR	logic/temp2.go:51	Error fetching URL www.sogo.com : Error = Get www.sogo.com: unsupported protocol scheme ""
2019-10-27T15:50:32.944+0800	DEBUG	logic/temp2.go:48	Trying to hit GET request for http://www.sogo.com
2019-10-27T15:50:33.165+0800	INFO	logic/temp2.go:53	Success! statusCode = 200 OK for URL http://www.sogo.com

At the same time, you can record the log circularly in the main function to test whether the log file will be automatically cut and archived (the log file will be cut every 1MB and save up to 5 backups in the current directory).

So far, we have summarized how to integrate the Zap logger into the Go application project.

Keywords: Go log

Added by ShootingBlanks on Mon, 20 Dec 2021 23:22:48 +0200