Write a golang log processing package from 0

Time:2021-10-20

WHY

Log overview

Log is essential for almost every actual software project from development to final actual operation. It is very important to view the code running process, record what happened and so on.

A good log system should be able to accurately record the information to be recorded and have good performance. Next, this paper will write a golang log processing package from 0.

Generally, go applications are mostly concurrent model applications, and it is impossible to avoid calling log methods concurrently in the process of concurrent processing.

Generally speaking, unless the method is declared to be co process safe in go, it is best to regard it as co process unsafe. The default log method in go is log, which is co process safe but has limited functions.

Third party go log packages such as zap and logrus are good log libraries and provide more configuration options. However, some logs with high customization requirements are not applicable. It is more applicable to write one from 0.

Design Overview

  • Output to file in JSON mode
  • Log types support rich
  • There are log classification settings
  • Separate log files by day
  • Abnormal exit can finish writing the log that has not been written

HOW

Overall process

How to fill in the log content

To output to files in JSON mode and support rich types, the first thing you can think of is the powerful interface in golang

Two types are designed to receive map and string logs respectively, and then expose the external interfaces according to the log classification settings:

func Debug(msg map[string]interface{}) {
	writeLog("DEBUG", msg)
}
func DebugMsg(msg interface{}) {
	writeLog("DEBUG", map[string]interface{}{"msg": msg})
}
func Info(msg map[string]interface{}) {
	writeLog("INFO", msg)
}
func InfoMsg(msg interface{}) {
	writeLog("INFO", map[string]interface{}{"msg": msg})
}
func Warn(msg map[string]interface{}) {
	writeLog("WARN", msg)
}
func WarnMsg(msg interface{}) {
	writeLog("WARN", map[string]interface{}{"msg": msg})
}
func Error(msg map[string]interface{}) {
	writeLog("ERROR", msg)
}
func ErrorMsg(msg interface{}) {
	writeLog("ERROR", map[string]interface{}{"msg": msg})
}

Finally, writelog is used for log processing. The writelog method is defined as follows:

func writeLog(level string, msg map[string]interface{})

How do I write to the file

Golang writes files in a variety of ways. Generally speaking, it uses the disk IO method of the operating system to write data to files

In terms of model selection, bufio is used to build this module. The default 4096 length is used. If the length of the collected log exceeds the buffer length, the content will be automatically written to the file. At the same time, a group of timers will be added to write the buffer content to the file every second, which is good in integrity

Handle the preemption problem of cooperative process

To solve the problem of multi process preemption, golang provides two standard solutions: using channel or locking

Here, the read-write lock is used to process bufio. The writestring method of bufio needs serial processing, otherwise it will cause errors, and the flush method can operate multiple processes at the same time

Based on these characteristics, we use write lock when using writestring method and read lock when using flush method:

fileWriter.Mu.Lock()
	fileWriter.Writer.WriteString(a)
	fileWriter.Mu.Unlock()
fileWriter.Mu.RLock()
	err = fileWriter.Writer.Flush()
	if err != nil {
		log.Println("flush log file err", err)
	}
	fileWriter.Mu.RUnlock()

Log file processing across days

First, clarify a problem. A new log file will be opened at the end of each day and the beginning of the next day. How to deal with the data that is still in the buffer that has not been refreshed?

Bufio provides a reset method, but the annotation of this method indicates that the unrefreshed data will be discarded and directly re pointed to the new IO writer. Therefore, we cannot use this method directly, otherwise the data near this time node will be lost

The actual test proves that if we close the original IO first, and then recreate the new file descriptor, and finally call the Reset method to point to the new descriptor, we will lose about 20ms data in this period.

Based on this, we use secondary pointers:

1. Judge whether the current date is today. If yes, wait for the next judgment cycle. If not, start preparing pointer redirection

2. Judge which file descriptor is empty. If it is empty, create a new descriptor and specify the paired filebuffer. If it is not empty, it means that it is the file currently being operated

3. Point the filewriter to the new filebuffer

4. Flush the old filebuffer, and then set both filebuffer and file to null

After this operation, there will be no data loss in cross day log file processing

if today != time.Now().Day() {
				today = time.Now().Day()
				if file[0] == nil {
					file[0], err = os.OpenFile(filePath+"/"+config.Get("app", "name")+"_"+time.Now().Format("2006-01-02")+".log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
					if err != nil {
						log.Fatal("open log file err: ", err)
					}
					fileBuffer[0] = bufio.NewWriterSize(file[0], 4096)
					fileWriter.Writer = fileBuffer[0]
					if fileBuffer[1].Buffered() > 0 {
						fileBuffer[1].Flush()
					}
					fileBuffer[1] = nil
					file[1].Close()
					file[1] = nil
				} else if file[1] == nil {
					file[1], err = os.OpenFile(filePath+"/"+config.Get("app", "name")+"_"+time.Now().Format("2006-01-02")+".log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
					if err != nil {
						log.Fatal("open log file err: ", err)
					}
					fileBuffer[1] = bufio.NewWriterSize(file[1], 4096)
					fileWriter.Writer = fileBuffer[1]
					if fileBuffer[0].Buffered() > 0 {
						fileBuffer[0].Flush()
					}
					fileBuffer[0] = nil
					file[0].Close()
					file[0] = nil
				}

			}

Handling of abnormal exit

A basic concept is that programs usually get system signals when the operating system exits. For example, the kill operation of Linux is to send system signals to applications

There are many kinds of signals. For example, the common signal corresponding to Ctrl + C is the interrupt signal. There is also a detailed explanation to search for “POSIX signal”

Based on this, in the conventional exception handling, we can capture the system signal and then do some processing operations before the end. Such a signal can be used in multiple packets at the same time and will receive the signal. We don’t have to worry about the problem of signal occupation

For example, when the package receives the exit signal, it will refresh all cached data and close all file descriptors:

func exitHandle() {

	 0 {
			fileWriter.Writer.Flush()
		}
		//Close the file handle in time
		if file[0] != nil {
			file[0].Close()
		}
		if file[1] != nil {
			file[1].Close()
		}

	}
	OS. Exit (1) // use OS. Exit to forcibly turn it off
}

Complete source code

package logger

import (
	"bufio"
	"bytes"
	"encoding/json"
	"fmt"
	"log"
	"os"
	"os/signal"
	"xxx/config"
	"sync"
	"syscall"
	"time"
)

var file []*os.File
var err error
var fileBuffer []*bufio.Writer
var exitChan chan os.Signal

type fileWriterS struct {
	Writer *bufio.Writer
	Mu     sync.RWMutex
}

var fileWriter fileWriterS
var today int

func LoggerInit() {

	Filepath: = config. Get ("app", "log_path") // config can be directly replaced with your own config or even written to death
	_, err := os.Stat(filePath)
	if err != nil {
		if os.IsNotExist(err) {
			os.MkdirAll(filePath, os.ModePerm)
		} else {
			log.Fatal("log path err:", err)
		}
	}

	file = make([]*os.File, 2)
	file[0] = nil
	file[1] = nil
	fileBuffer = make([]*bufio.Writer, 2)
	fileBuffer[0] = nil
	fileBuffer[1] = nil
	today = time.Now().Day()
	file[0], err = os.OpenFile(filePath+"/"+config.Get("app", "name")+"_"+time.Now().Format("2006-01-02")+".log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
	if err != nil {
		log.Fatal("open log file err: ", err)
	}
	fileBuffer[0] = bufio.NewWriterSize(file[0], 4096)
	fileWriter.Writer = fileBuffer[0]
	exitChan = make(chan os.Signal)
	signal.Notify(exitChan, os.Interrupt, os.Kill, syscall.SIGTERM)
	go exitHandle()
	go func() {
		time.Sleep(1 * time.Second)
		for {
			if fileWriter.Writer.Buffered() > 0 {
				fileWriter.Mu.RLock()
				err = fileWriter.Writer.Flush()
				if err != nil {
					log.Println("flush log file err", err)
				}
				fileWriter.Mu.RUnlock()
			}
			time.Sleep(1 * time.Second)

			if today != time.Now().Day() {
				today = time.Now().Day()
				if file[0] == nil {
					file[0], err = os.OpenFile(filePath+"/"+config.Get("app", "name")+"_"+time.Now().Format("2006-01-02")+".log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
					if err != nil {
						log.Fatal("open log file err: ", err)
					}
					fileBuffer[0] = bufio.NewWriterSize(file[0], 4096)
					fileWriter.Writer = fileBuffer[0]
					if fileBuffer[1].Buffered() > 0 {
						fileBuffer[1].Flush()
					}
					fileBuffer[1] = nil
					file[1].Close()
					file[1] = nil
				} else if file[1] == nil {
					file[1], err = os.OpenFile(filePath+"/"+config.Get("app", "name")+"_"+time.Now().Format("2006-01-02")+".log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
					if err != nil {
						log.Fatal("open log file err: ", err)
					}
					fileBuffer[1] = bufio.NewWriterSize(file[1], 4096)
					fileWriter.Writer = fileBuffer[1]
					if fileBuffer[0].Buffered() > 0 {
						fileBuffer[0].Flush()
					}
					fileBuffer[0] = nil
					file[0].Close()
					file[0] = nil
				}

			}

		}
	}()

}

func exitHandle() {

	 0 {
			fileWriter.Writer.Flush()
		}

		if file[0] != nil {
			file[0].Close()
		}
		if file[1] != nil {
			file[1].Close()
		}

	}
	os.Exit(1)
}

func Debug(msg map[string]interface{}) {
	writeLog("DEBUG", msg)
}
func DebugMsg(msg interface{}) {
	writeLog("DEBUG", map[string]interface{}{"msg": msg})
}
func Info(msg map[string]interface{}) {
	writeLog("INFO", msg)
}
func InfoMsg(msg interface{}) {
	writeLog("INFO", map[string]interface{}{"msg": msg})
}
func Warn(msg map[string]interface{}) {
	writeLog("WARN", msg)
}
func WarnMsg(msg interface{}) {
	writeLog("WARN", map[string]interface{}{"msg": msg})
}
func Error(msg map[string]interface{}) {
	writeLog("ERROR", msg)
}
func ErrorMsg(msg interface{}) {
	writeLog("ERROR", map[string]interface{}{"msg": msg})
}

func writeLog(level string, msg map[string]interface{}) {

	will_write_map := make(map[string]interface{})
	t := time.Now()
	will_write_map["@timestamp"] = fmt.Sprintf("%d-%02d-%02dT%02d:%02d:%02d.%03d", t.Year(), t.Month(), t.Day(), t.Hour(), t.Minute(), t.Second(), t.Nanosecond()/1e6)
	will_write_map["level"] = level

	for p, v := range msg {
		will_write_map[p] = v
	}

	//When the buffer is full, it will flush automatically
	bf := bytes.NewBuffer([]byte{})
	jsonEncoder := json.NewEncoder(bf)
	jsonEncoder.SetEscapeHTML(false)
	jsonEncoder.Encode(will_write_map)
	a := bf.String()

	//	fmt.Println(a)
	fileWriter.Mu.Lock()
	fileWriter.Writer.WriteString(a)
	fileWriter.Mu.Unlock()
	//	fileWriter.WriteString("\n")

}

Recommended Today

SQL exercise 20 – Modeling & Reporting

This blog is used to review and sort out the common topic modeling architecture, analysis oriented architecture and integration topic reports in data warehouse. I have uploaded these reports to GitHub. If you are interested, you can have a lookAddress:https://github.com/nino-laiqiu/TiTanI recorded a relatively complete development process in my hexo blog deployed on GitHub. You can […]