從0寫一個Golang日誌處理包
阿新 • • 發佈：2020-08-11
## WHY
### 日誌概述
日誌幾乎是每個實際的軟體專案從開發到最後實際執行過程中都必不可少的東西。它對於檢視程式碼執行流程，記錄發生的事情等方面都是很重要的。
一個好的日誌系統應當能準確地記錄需要記錄的資訊，同時兼具良好的效能，接下來本文將從0寫一個Golang日誌處理包。
通常Go應用程式多為併發模型應用，在併發處理實際應用的過程中也無法避免併發地呼叫日誌方法。
通常來說，Go中除非宣告方法是協程安全的，否則最好都視為協程不安全，Go中預設的日誌方法為log,該方法協程安全，但是功能有限。
第三方Go日誌包如ZAP、logrus等均為較為不錯的日誌庫，也提供了較多的配置選項，但是對於高度定製需求的日誌則有些不適用，從0開始自己寫一個就較為適用。
### 設計概述
* 按json方式輸出到檔案
* 日誌型別支援豐富
* 有日誌分級設定
* 按天分隔日誌檔案
* 異常退出能把未寫入的日誌寫完
## HOW
### 整體流程
### 怎麼填充日誌內容
要做到按json方式輸出到檔案，並且支援豐富的型別，第一個能想到的則是Golang中強大的interface
設計兩種型別分別用於接收map型和string型日誌，再根據日誌分級設定分別暴露出對外介面：
```go
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})
}
```
最終都是使用writeLog進行日誌的處理，writeLog方法定義如下：
```go
func writeLog(level string, msg map[string]interface{})
```
### 用哪種方式寫入檔案
Golang對於檔案的寫入方式多種多樣，通常來講最後都是使用作業系統的磁碟IO方法把資料寫入檔案
在選型上這塊使用bufio方式來構建，使用預設的4096長度，如果收集的日誌長度超過了緩衝區長度則自動將內容寫入到檔案，同時增加一組定時器，每秒將緩衝區內容寫入到檔案中，這樣在整體效能上較為不錯
### 處理協程搶佔問題
針對多協程搶佔的問題，Golang提供有兩個比較標準的應對方式：使用channel或者加鎖
在這裡採用讀寫鎖的方式來進行處理bufio，bufio的WriteString方法需序列處理，要不然會導致錯誤，而Flush方法可以多協程同時操作
基於這些特性，我們在使用WriteString方法的時候使用寫鎖，使用Flush方法時採用讀鎖：
```go
fileWriter.Mu.Lock()
fileWriter.Writer.WriteString(a)
fileWriter.Mu.Unlock()
```
```go
fileWriter.Mu.RLock()
err = fileWriter.Writer.Flush()
if err != nil {
log.Println("flush log file err", err)
}
fileWriter.Mu.RUnlock()
```
### 跨天的日誌檔案處理
首先明確一個問題，在每日結束次日開始時將開啟一個新的日誌檔案，那麼還在緩衝區未完成重新整理的資料怎麼處理呢？
bufio提供了Reset方法，但是該方法註釋說明將丟棄未重新整理的資料而直接重新指向新的io writer，因此我們不能直接使用該方法，否則這個時間節點附近的資料將會丟掉
實際測試證明如果先關閉原IO，再重新建立新的檔案描述符，最後呼叫Reset方法指向新的描述符過後這段時間將會丟掉達約20ms的資料
基於此，我們使用了二級指標：
1.判斷當前日期是否就是今天，如果是則等待下個判斷週期，如果不是則開始準備指標重定向操作
2.判斷哪一個檔案描述符為空，如果為空則為其建立新的描述符，並指定配對的filebuffer，如果不為空則說明它就是當前正在操作的檔案
3.將filewriter指向新的filebuffer
4.對老的filebuffer進行Flush操作，之後將filebuffer和file都置為空
經過這樣的操作過後，跨天的日誌檔案處理就不會有資料丟失的情況了
```go
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
}
}
```
### 異常退出的處理
一個基本的概念就是程式在作業系統退出的時候通常都會得到系統訊號，比如linux的kill操作就是給應用程式傳送系統訊號
訊號分很多種，比如常見的ctrl+c對應的訊號則是Interrupt訊號，這塊去搜索“posix訊號”也有詳細的解釋說明
基於此，常規的異常處理我們可以捕獲系統訊號然後做一些結束前的處理操作，這樣的訊號可以在多個包同時使用，均會收到訊號，不用擔心訊號強佔的問題
比如這個包在接收到退出訊號時則重新整理所有快取資料並關閉所有檔案描述符：
```go
func exitHandle() {
<-exitChan
if file != nil {
if fileWriter.Writer.Buffered() > 0 {
fileWriter.Writer.Flush()
}
//及時關閉file控制代碼
if file[0] != nil {
file[0].Close()
}
if file[1] != nil {
file[1].Close()
}
}
os.Exit(1) //使用os.Exit強行關掉
}
```
## 完整原始碼
```go
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處可以直接換成自己的config甚至直接寫死
_, 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() {
<-exitChan
if file != nil {
if fileWriter.Writer.Buffered() > 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
}
//buffer滿了會自動flush
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")