What is Log in backend

Log顧名思義就是紀錄，通常在Backend當中會將可預期或非預期的錯誤記錄在此，除此之外也會記錄些測試用資料以及警訊資料用以幫忙我們除錯/紀錄/開發。

那Backend Log的產生都是發生在Server端，目前大部分的Backend設計也都透過API, Application，並採用Client/Broswer與Server的架構完成，也因此可將Backend Log分為三大種類

• Event Log
• Application Log
• Request Log

Event Log

定義使用者在介面上的操作，像是新增資料、上傳檔案、發送訊息等。，通常表示一個業務邏輯的執行與實現，那裡頭每次的動作可能會包含多次的API呼叫，而每次的呼叫都屬於一項操作。Event Log的目的就是紀錄使用者的操作記錄，以此可以用來檢測、除錯與統計資料等。

Application Log

由Server執行過程中所產生的Log，用來追蹤系統實際運行狀況，與資料的流動情形。而且在Exception發生時就是紀錄在此，好讓後續可以追蹤分析與解決。

Request Log

人如其名，就是Request在傳遞時所記錄的訊息，但由於Requests繁多導致紀錄成本龐大，因此大部分情況只會紀錄HTTP Header甚至是不紀錄Request，只有在發生Error時才會紀錄完整Request資料。

Log level

TRACE < DEBUG < INFO < WARN < ERROR < FATAL < PANIC

Log除了類型以外也有優先序的差別，當log訊息等級高於你所設定的日誌等級，
則該訊息不會紀錄輸出。

當你設定越高的層級，你的紀錄成本也會越大，那通常在production environment只會預設為ERROR或是WARN而已。那下面就依照不同的Level依序介紹

TRACE

最高等級的log，主要用來追蹤某些小事。

DEBUG

紀錄有用的debug資訊。

INFO

當有些有用的事件發生時，會紀錄的資訊。

WARN

警示訊息，雖然不會對系統有重大影響，但需要注意一下該訊息。

ERROR

發生了錯誤，但系統依舊在運作。

FATAL

最緊急的錯誤，一但發生需要立即hotflix。

PANIC

最低等級的log，當調用Panic時發生。

Logrus

這邊我們選用github.com/sirupsen/logrus 這個相當多人使用的log package將Log實作在Gin Backend Server當中。那logrus也有著以下的幾個優點:

1. 完全兼容於Golang的官方Log Module，logrus有著DEBUG、INFO、WARN、ERROR、FATAL與PANIC這六個級別，與Go的官方Modul相同。假使有些第三方套件或是其他專案是用官方的Log，之後可以無痛地遷移至logrus上。
2. 可以拓展的Hook機制，允許使用者能將log放到任意地方，像是本地儲存空間、LogStash、ElasticSearch與Message Queue等。
3. 可選的Formatter，logrus內建兩種輸出格式，JSON與Text，如果還需要其他格式，則可以自己手動實現Interface Formatter來定義自己格式。

Installation

go get -u github.com/sirupsen/logrus

GIn with logrus

/app/middleware/log.go

package middleware

import (
	"fmt"
	"github.com/gin-gonic/gin"
	"github.com/sirupsen/logrus"
	"os"
	"path"
	"time"
)

func Logger() *logrus.Logger {
	now := time.Now()
	logFilePath := ""
	if dir, err := os.Getwd(); err == nil {
		logFilePath = dir + "/logs/"
	}
	if err := os.MkdirAll(logFilePath, 0777); err != nil {
		fmt.Println(err.Error())
	}
	logFileName := now.Format("2006-01-02") + ".log"

	fileName := path.Join(logFilePath, logFileName)
	if _, err := os.Stat(fileName); err != nil {
		if _, err := os.Create(fileName); err != nil {
			fmt.Println(err.Error())
		}
	}

	src, err := os.OpenFile(fileName, os.O_APPEND|os.O_WRONLY, os.ModeAppend)
	if err != nil {
		fmt.Println("err", err)
	}

	logger := logrus.New()
	logger.Out = src
	logger.SetLevel(logrus.DebugLevel)
	logger.SetFormatter(&logrus.TextFormatter{
		TimestampFormat: "2021-01-01 11:11:11",
	})
	return logger
}

func LoggerToFile() gin.HandlerFunc {
	logger := Logger()
	return func(c *gin.Context) {
		startTime := time.Now()
		c.Next()

		endTime := time.Now()
		latencyTime := endTime.Sub(startTime)
		reqMethod := c.Request.Method
		reqUri := c.Request.RequestURI
		statusCode := c.Writer.Status()
		clientIP := c.ClientIP()
		logger.Infof("| %3d | %13v | %15s | %s | %s |",
			statusCode,
			latencyTime,
			clientIP,
			reqMethod,
			reqUri,
		)
	}
}

• Logger(): 主要是設定輸出檔案的位置、輸出格式、檔案命名等設定，在init好LogFile之後藉由

logrus.New() 實體化一個logrus物件，並設定所需的log level與TIme Format，並將log寫入LogFile之中。

• LoggerToFile(): Gin的log middleware，我們會將時間相關資訊與gin.Context中的Request Method, URL, StatusCode與IP等資訊也一併寫入log之中。

main.go

	server := gin.Default()
	server.Use(middleware.LoggerToFile())
	server.Use(middleware.CORSMiddleware())
	server.GET("/hc", func(c *gin.Context) {
		c.String(http.StatusOK, fmt.Sprintf("Health Check"))
		middleware.Logger().WithFields(logrus.Fields{
			"name": "Flynn Sun",
		}).Info("Health Check", "Info")
	})
	

我們讓Gin使用LoggerToFile()這個Middleware，並在health check endpoint當中寫入INFO Level的log加以測試。

docker-compose.yaml

ironman-2021:
    container_name: ironman-2021
    ports:
      - "8080:8080"
    build:
      context: ./
      dockerfile: Dockerfile
    command: ./main
    restart: always
    networks:
      - backend-bridge
    depends_on:
      - postgresql
      - redis
    volumes:
    - ./logs/:/usr/local/go/src/ironman-2021/logs

我們在Gin的Container中將logs folder的log file都mount出來，讓我們比較容易去觀察與紀錄log。

最後我們則是來啟動docker-compose —build 並 GET http://localhost:8080/hc 進行測試。

然後會在/logs/2021-10-09.log當中得到以下內容

time="90910-10-10 1010:1010:1010" level=info msg="Health CheckInfo" name="Flynn Sun"
time="90910-10-10 1010:1010:1010" level=info msg="| 200 |      6.7669ms |   192.168.160.1 | GET | /hc |"

這也證實我們的logger實裝完成！

Summary

Logger在Backend Server當中是必不可缺的一環，因為再怎麼完美的系統也一定會有著漏洞，如果屆時沒有logger的話，會相當難找到問題所在！

這次的程式碼我也會放在下方連結，歡迎大家享用。

https://github.com/Neskem/Ironman-2021/tree/Day-26