Let's write our own logging package

In the previous videos, we introduced some open source log packages of golang, including: standard library log package, glog, logrus, zap. We also discussed how to record logs, and the modules and functions that a log package should have. Now let’s write a log package with basic functions to master the core design ideas of the log package.

Open Table of contents

Youtube Video
Included Features
Define log levels and log options
Create Logger and log printing methods at different levels
Output logs to supported output
Custom log output format
Test log package

Youtube Video

Included Features

Supports custom configuration.
Supports file name and line number.
Supports log levels Debug, Info, Warn, Error, Panic, Fatal.
Supports output to local files and standard output.
Supports log output in JSON and TEXT formats,
Supports custom log format.
Supports option mode.

The name of the log package is catlog, and the complete code of the sample project is stored in catlog.

The specific implementation is divided into the following four steps:

Define: define the log level and log options.
Create: create Logger and log printing methods of each level.
Write: output logs to supported outputs.
Customize: customize log output format.

Define log levels and log options

A basic log package first needs to define the log level and log options

type Level uint8

const (
    DebugLevel Level = iota
    InfoLevel
    WarnLevel
    ErrorLevel
    PanicLevel
    FatalLevel
)

var LevelNameMapping = map[Level]string{
    DebugLevel: "DEBUG",
    InfoLevel:  "INFO",
    WarnLevel:  "WARN",
    ErrorLevel: "ERROR",
    PanicLevel: "PANIC",
    FatalLevel: "FATAL",
}

When outputting logs, the switch level and the output level must be compared to decide whether to output, so the log level Level must be defined as a numerical type that is easy to compare. Almost all log packages use the constant counter iota to define the log level.

In addition, because you need to output a readable log level in the log output (for example, output INFO instead of 1), you need a mapping from Level to Level Name LevelNameMapping, which will be used during formatting.

Next, let’s define the log options. The log needs to be configurable so that developers can set different log behaviors according to different environments. The more common configuration options are:

Log level.
Output location, such as standard output or file.
Output format, such as JSON or Text.
Whether to enable file name and line number.

type options struct {
    output        io.Writer
    level         Level
    stdLevel      Level
    formatter     Formatter
    disableCaller bool
}

In order to flexibly set the log options, you can set the log options through the option pattern.

type Option func(*options)

func initOptions(opts ...Option) (o *options) {
    o = &options{}
    for _, opt := range opts {
        opt(o)
    }

    if o.output == nil {
        o.output = os.Stderr
    }

    if o.formatter == nil {
        o.formatter = &TextFormatter{}
    }

    return
}

For log packages with option mode, you can dynamically modify log options in the following ways:

catlog.SetOptions(catlog.WithLevel(catlog.DebugLevel))

You can create a setting function WithXXXX for each log option as needed.

Next, let’s create the following option setting function:

WithOutput (output io.Writer): Set the output location.
WithLevel (level Level): Set the output level.
WithFormatter (formatter Formatter): Set the output format.
WithDisableCaller (caller bool): Set whether to print the file name and line number.

func WithOutput(output io.Writer) Option {
	return func(o *options) {
		o.output = output
	}
}

func WithLevel(level Level) Option {
	return func(o *options) {
		o.level = level
	}
}

func WithStdLevel(level Level) Option {
	return func(o *options) {
		o.stdLevel = level
	}
}

func WithFormatter(formatter Formatter) Option {
	return func(o *options) {
		o.formatter = formatter
	}
}

func WithDisableCaller(caller bool) Option {
	return func(o *options) {
		o.disableCaller = caller
	}
}

Create Logger and log printing methods at different levels

In order to print logs, we need to create a Logger according to the log configuration, and then complete the output of logs at various levels by calling the logger’s log printing method.

type logger struct {
	opt       *options
	mu        sync.Mutex
	entryPool *sync.Pool
}

func New(opts ...Option) *logger {
	logger := &logger{opt: initOptions(opts...)}
	logger.entryPool = &sync.Pool{New: func() interface{} { return entry(logger) }}
	return logger
}
var std = New()

First, define a Logger, and the New function for creating a Logger. The log package will have a default global Logger. This example creates a global default Logger through var std = New(). Functions such as catlog.Debug, catlog.Info, and catlog.Warnf print logs by calling the methods provided by std Logger.

After defining a Logger, you also need to add the most core log printing method to the Logger, and provide log printing methods for all supported levels.

If the log level is Xyz, you usually need to provide two types of methods, namely the non-formatted method Xyz(args ...interface{}) and the formatted method Xyzf(format string, args ...interface{}).

Let’s implement the Debug,Debugf, Info, Infof, Warn, Warnf, Error, Errorf, Panic, Panicf, Fatal, Fatalf method for instance and function for the std global logger.

Please note that Panic and Panicf must call the panic() function, and Fatal and Fatalf functions must call the os.Exit(1) function.

func (l *logger) Debug(args ...interface{}) {
	l.entry().write(DebugLevel, FmtEmptySeparate, args...)
}

func (l *logger) Info(args ...interface{}) {
	l.entry().write(InfoLevel, FmtEmptySeparate, args...)
}

func (l *logger) Warn(args ...interface{}) {
	l.entry().write(WarnLevel, FmtEmptySeparate, args...)
}

func (l *logger) Error(args ...interface{}) {
	l.entry().write(ErrorLevel, FmtEmptySeparate, args...)
}

func (l *logger) Panic(args ...interface{}) {
	l.entry().write(PanicLevel, FmtEmptySeparate, args...)
	panic(fmt.Sprint(args...))
}

func (l *logger) Fatal(args ...interface{}) {
	l.entry().write(FatalLevel, FmtEmptySeparate, args...)
	os.Exit(1)
}

func (l *logger) Debugf(format string, args ...interface{}) {
	l.entry().write(DebugLevel, format, args...)
}

func (l *logger) Infof(format string, args ...interface{}) {
	l.entry().write(InfoLevel, format, args...)
}

func (l *logger) Warnf(format string, args ...interface{}) {
	l.entry().write(WarnLevel, format, args...)
}

func (l *logger) Errorf(format string, args ...interface{}) {
	l.entry().write(ErrorLevel, format, args...)
}

func (l *logger) Panicf(format string, args ...interface{}) {
	l.entry().write(PanicLevel, format, args...)
	panic(fmt.Sprintf(format, args...))
}

func (l *logger) Fatalf(format string, args ...interface{}) {
	l.entry().write(FatalLevel, format, args...)
	os.Exit(1)
}

// std logger
func Debug(args ...interface{}) {
	std.entry().write(DebugLevel, FmtEmptySeparate, args...)
}

func Info(args ...interface{}) {
	std.entry().write(InfoLevel, FmtEmptySeparate, args...)
}

func Warn(args ...interface{}) {
	std.entry().write(WarnLevel, FmtEmptySeparate, args...)
}

func Error(args ...interface{}) {
	std.entry().write(ErrorLevel, FmtEmptySeparate, args...)
}

func Panic(args ...interface{}) {
	std.entry().write(PanicLevel, FmtEmptySeparate, args...)
	panic(fmt.Sprint(args...))
}

func Fatal(args ...interface{}) {
	std.entry().write(FatalLevel, FmtEmptySeparate, args...)
	os.Exit(1)
}

func Debugf(format string, args ...interface{}) {
	std.entry().write(DebugLevel, format, args...)
}

func Infof(format string, args ...interface{}) {
	std.entry().write(InfoLevel, format, args...)
}

func Warnf(format string, args ...interface{}) {
	std.entry().write(WarnLevel, format, args...)
}

func Errorf(format string, args ...interface{}) {
	std.entry().write(ErrorLevel, format, args...)
}

func Panicf(format string, args ...interface{}) {
	std.entry().write(PanicLevel, format, args...)
	panic(fmt.Sprintf(format, args...))
}

func Fatalf(format string, args ...interface{}) {
	std.entry().write(FatalLevel, format, args...)
	os.Exit(1)
}

Output logs to supported output

After calling the log printing function, you also need to output these logs to the supported output, so you need to implement the write function

type Entry struct {
    logger *logger
    Buffer *bytes.Buffer
    Map    map[string]interface{}
    Level  Level
    Time   time.Time
    File   string
    Line   int
    Func   string
    Format string
    Args   []interface{}
}

func (e *Entry) write(level Level, format string, args ...interface{}) {
    if e.logger.opt.level > level {
        return
    }
    e.Time = time.Now()
    e.Level = level
    e.Format = format
    e.Args = args
    if !e.logger.opt.disableCaller {
        if pc, file, line, ok := runtime.Caller(2); !ok {
            e.File = "???"
            e.Func = "???"
        } else {
            e.File, e.Line, e.Func = file, line, runtime.FuncForPC(pc).Name()
            e.Func = e.Func[strings.LastIndex(e.Func, "/")+1:]
        }
    }
    e.format()
    e.writer()
    e.release()
}

func (e *Entry) format() {
    _ = e.logger.opt.formatter.Format(e)
}

func (e *Entry) writer() {
    e.logger.mu.Lock()
    _, _ = e.logger.opt.output.Write(e.Buffer.Bytes())
    e.logger.mu.Unlock()
}

func (e *Entry) release() {
    e.Args, e.Line, e.File, e.Format, e.Func = nil, 0, "", "", ""
    e.Buffer.Reset()
    e.logger.entryPool.Put(e)
}

First, define an Entry structure type, which is used to save all log information, namely log configuration and log content.

Use the write method of Entry to complete the writing of the log. In the write method, the output level and switch level of the log will be determined first. If the output level is less than the switch level, it will return directly without making any records.

In write method, it will also determine whether the file name and line number need to be recorded. If necessary, runtime.Caller() is called to obtain the file name and line number. When calling runtime.Caller(), pay attention to passing in the correct stack depth.

In the write function, e.format is called to format the log, and e.writer is called to write the log. In the log configuration passed in when creating the Logger, the output location output io.Writer is specified, and the output type is io.Writer.

e.Writer implements the Write method for writing, so you only need to call e.logger.opt.output.Write(e.Buffer.Bytes()) to write the log to the specified location.

Finally, the release() method will be called to clear the cache and object pool. At this point, we have completed the logging and writing.

Custom log output format

The catlog package supports custom output formats and has built-in JSON and Text format Formatters. First, define The Formatter interface:

type Formatter interface {
    Format(entry *Entry) error
}

next, create the JSON format Formatters.

package catlog

import (
	"fmt"
	"strconv"
	"time"

	jsoniter "github.com/json-iterator/go"
)

type JsonFormatter struct {
	IgnoreBasicFields bool
}

func (f *JsonFormatter) Format(e *Entry) error {
	if !f.IgnoreBasicFields {
		e.Map["level"] = LevelNameMapping[e.Level]
		e.Map["time"] = e.Time.Format(time.RFC3339)
		if e.File != "" {
			e.Map["file"] = e.File + ":" + strconv.Itoa(e.Line)
			e.Map["func"] = e.Func
		}
	}

	switch e.Format {
	case FmtEmptySeparate:
		e.Map["message"] = fmt.Sprint(e.Args...)

	default:
		e.Map["message"] = fmt.Sprintf(e.Format, e.Args...)

	}
	return jsoniter.NewEncoder(e.Buffer).Encode(e.Map)
}

and Text format Formatters

package catlog

import (
	"fmt"
	"time"
)

type TextFormatter struct {
	IgnoreBasicFields bool
}

func (f *TextFormatter) Format(e *Entry) error {
	if !f.IgnoreBasicFields {
		e.Buffer.WriteString(fmt.Sprintf("%s %s", e.Time.Format(time.RFC3339), LevelNameMapping[e.Level])) // allocs
		if e.File != "" {
			short := e.File
			for i := len(e.File) - 1; i > 0; i-- {
				if e.File[i] == '/' {
					short = e.File[i+1:]
					break
				}
			}
			e.Buffer.WriteString(fmt.Sprintf(" %s:%d", short, e.Line))
		}
		e.Buffer.WriteString(" ")
	}

	switch e.Format {
	case FmtEmptySeparate:
		e.Buffer.WriteString(fmt.Sprint(e.Args...))
	default:
		e.Buffer.WriteString(fmt.Sprintf(e.Format, e.Args...))
	}
	e.Buffer.WriteString("\n")
	return nil
}

Test log package

package main

import (
	"log"
	"os"

	"github.com/zerotone.ae/catlog"
)

func main() {
	catlog.Info("std log")
	catlog.SetOptions(catlog.WithLevel(catlog.DebugLevel))
	catlog.Debug("change std log to debug level")
	catlog.SetOptions(catlog.WithFormatter(&catlog.JsonFormatter{IgnoreBasicFields: false}))
	catlog.Debug("log in json format")
	catlog.Info("another log in json format")

	// output to file
	fd, err := os.OpenFile("test.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
	if err != nil {
		log.Fatalln("create file test.log failed")
	}
	defer fd.Close()

	l := catlog.New(catlog.WithLevel(catlog.InfoLevel), catlog.WithOutput(fd), catlog.WithFormatter(&catlog.JsonFormatter{IgnoreBasicFields: false}))
	l.Info("custom log with json formatter")
}

run below command in the terminal,

go run example/main.go

and get the result:

2024-08-14T22:10:16+08:00 INFO main.go:11 std log
2024-08-14T22:10:16+08:00 DEBUG main.go:13 change std log to debug level
{"level":"DEBUG","time":"2024-08-14T22:10:16+08:00","file":"/Users/andying/github/maloong-zhang/catlog/example/main.go:15","func":"main.main","message":"log in json format"}
{"level":"INFO","time":"2024-08-14T22:10:16+08:00","file":"/Users/andying/github/maloong-zhang/catlog/example/main.go:16","func":"main.main","message":"another log in json format"}

Congratulations, you have completed a golang log package.