Published on

API Service with Go: Logging

Authors

Logging

ในภาษา Go เมื่อเราต้องการ log ข้อมูลออกมาเพื่อดูข้อมูล สามารถใช้ fmt.Println() หรือ log.Println() เพื่อแสดงข้อมูลออกมาได้ แต่ข้อมูลที่ได้ออกมานั้นนำเอาไปใช้งานต่อลำบาก เพราะไม่มีรูปแบบที่เป็นมาตราฐาน ดังนั้นเราควรมีการจัดการ log ที่ดี เช่น การ log ข้อมูลออกมาในรูปแบบของ JSON เพื่อนำไปใช้งานต่อได้สะดวก หรือถ้ามี microservices เรียกซ้อนๆ กันหลายๆ ตัว ก็ควรมี uniquie id อะไรบางอย่าง เพื่อใช้อย่างอิงว่าไป log ของ request เดียวกัน ก็จะสะดวกต่อการค้นหา

ค้นหาด้วย Unique ID

ในกรณีที่ระบบของเราเป็น microservices แล้วมีการเรียก service กันภายใน การแสดง log แค่ข้อความออกมานั้น เราไม่สามารถรู้ได้เลยว่า log แต่ละตัวนั้นเป็นข้อมูลชุดเดียวกันหรือไม่

ดังนั้น เราควรมีรหัสอะไรบางอย่างที่เอามาใช้เพื่อบอกว่าเป็นข้อมูลของ request ครั้งเดียวกัน เช่น Request ID หรือ Transaction ID หรือถ้าใช้การ Tracing ก็ควรที่จะแสดง TraceID และ SpanID ออกมาด้วย ซึ่งเราจะใช้ค่าเหล่านั้นมาตัวบอกว่าบอกเป็น request ครั้งเดียวกัน ก็จะทำให้เราค้นหา log ได้ง่ายขึ้น

ตัวอย่าง Transaction ID

เราจะให้ Client ที่เรียกเข้ามาส่งค่า unique id มาให้ด้วยทุกครั้ง ผ่านมาทาง Request Header ที่ชื่อ X-Trasaction-Id แล้วฝั่ง Server เอาค่าที่ส่งมานั้นมาแสดงใน log ด้วย เช่น

pkg/handlers/todo.go
func CreateTodoHandler(w http.ResponseWriter, r *http.Request) {
	// ...
  tx := database.DB.Create(&todo)
  if err := tx.Error; err != nil {
		appErr := errs.NewUnexpectedError(err.Error())
		if errors.Is(err, gorm.ErrRecordNotFound) {
			appErr = errs.NewNotFoundError("todo with given id not found")
		}
	  // กำหนดให้ส่ง X-Trasaction-Id เป็น uuid มาใน request header
		txId := r.Header.Get("X-Transaction-Id")
		log.Println(txId, appErr.Message)
		w.Header().Add("Content-Type", "application/json")
		w.WriteHeader(appErr.Code)
		json.NewEncoder(w).Encode(appErr)
		return
	}
  // ...
}

// 2022/02/01 11:07:10 833d57ef-afb9-45c1-8450-9eff6559043e todo with given id not found

กำหนดรูปแบบของการแสดง Log

ถ้าเราแสดง log ออกมาเป็นข้อความธรรมดานั้น เวลาที่ส่งต่อไปยังโปรแกรมอื่น เช่น ELK เราก็เอาไปใช้งานต่อลำบาก ค้นหาก็ยาก ดังนั้นเรามีการกำหนดรูปแบบการแสดง log ของเรา เช่น ให้แสดงออกมาเป็น JSON แทน เช่น

2022/02/01 11:07:10 833d57ef-afb9-45c1-8450-9eff6559043e todo with given id not found

เปลี่ยนเป็น

{
  "timestamp": "2022/02/01 11:07:10",
  "transactionId": "833d57ef-afb9-45c1-8450-9eff6559043e",
  "message": "todo with given id not found"
}

จะเห็นว่าเราสามารถค้นหาได้จากชื่อ key ได้เลย โดยจะมี package ที่นิยมใช้งานอยู่ 2 ตัว คือ zap กับ logrus ซึ่งในบทความนี้จะเลือกใช้ zap

go get -u go.uber.org/zap

Logger Module

การใช้งาน เริ่มจากสร้าง logger module ของเราขึ้นมา แบบนี้

pkg/common/logger/logger.go
package logger

import (
	"fmt"

	"go.uber.org/zap"
)

var zlog *zap.Logger

func init() {
	var err error

	zlog, err = zap.NewProduction()

	if err != nil {
		panic(err)
	}
}

func Info(message string, fileds ...zap.Field) {
	zlog.Info(message, fileds...)
}

func Debug(message string, fileds ...zap.Field) {
	zlog.Debug(message, fileds...)
}

func Error(message string, fileds ...zap.Field) {
	zlog.Error(message, fileds...)
}

func Warn(message string, fileds ...zap.Field) {
	zlog.Warn(message, fileds...)
}

func Fatal(message string, fileds ...zap.Field) {
	zlog.Fatal(message, fileds...)
}

func Panic(message string, fileds ...zap.Field) {
	zlog.Panic(message, fileds...)
}

และเปลี่ยนการ log.Println() มาเป็น logger.Info() แทน

cmd/main.go
func main() {
  // ...
  logger.Info("Starting server at port 8080")
	log.Fatal(http.ListenAndServe(":8080", handler))
}

// {"level":"info","ts":1643702027.675124,"caller":"logger/logger.go:20","msg":"Starting server at port 8080"}
pkg/common/logger/logger.go
func init() {
	var err error

- log, err = zap.NewProduction()
+	log, err = zap.NewProduction(zap.AddCallerSkip(1))

	if err != nil {
		panic(err)
	}
}

การตั้งค่าอื่นๆ

  • เปลี่ยนชื่อ field เช่น ถ้าต้องการเปลี่ยนชื่อ field เช่น ts เป็น timestamp และปลี่ยน format ใหม่ทำได้ โดย key = "NewKeyName"
pkg/common/logger/logger.go
func init() {
	var err error

	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.TimeKey = "timestamp"
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder

	config := zap.NewProductionConfig()
	config.EncoderConfig = encoderConfig

	log, err = config.Build(zap.AddCallerSkip(1))

	if err != nil {
		panic(err)
	}
}
// {"level":"info","timestamp":"2022-02-01T15:04:40.736+0700","caller":"goapi/main.go:39","msg":"Starting server at port 8080"}
  • ปิดการแสดงข้อมูล ถ้าไม่ต้องการให้แสดง key ไหนออกมาให้ใส่ key = "" เช่น encoderConfig.StacktraceKey = "" ก็จะไม่แสดงข้อมูล StacktraceKey ออกมาแล้ว
  • Dev mode ในขณะที่กำลังพัฒนาอยู่ การแสดง log แบบ json อาจทำให้อ่านไม่สะดวก เราสามารถใช้แบบ Development Config แทนได้
pkg/common/logger/logger.go
func init() {
	var err error

  encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.TimeKey = "timestamp"
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder

+	mode := os.Getenv("APP_MODE")
+	var config zap.Config
+	if mode == "production" {
+		config = zap.NewProductionConfig()
+	} else {
+		config = zap.NewDevelopmentConfig()
+	}

	config.EncoderConfig = encoderConfig

	log, err = config.Build(zap.AddCallerSkip(1))

	if err != nil {
		panic(err)
	}
}

ถ้าหาก log ของเราต้องส่งออกไปยัง Elastic Search ก็จำเป็นที่จะต้องกำหนดรูปแบบของ JSON ตาม Elastic Common Schema (ECS) ซึ่งมี plugin ที่ชื่อว่า ecszap มาให้แล้ว เมื่อเรียกใช้งานก็จะได้ format ที่ถูกต้องเลย

pkg/common/logger/logger.go
// go get go.elastic.co/ecszap

func init() {
	var err error

  mode := os.Getenv("APP_MODE")
	var config zap.Config
	if mode == "production" {
		config = zap.NewProductionConfig()
	} else {
		config = zap.NewDevelopmentConfig()
	}

	config.EncoderConfig = ecszap.ECSCompatibleEncoderConfig(config.EncoderConfig)
	log, err = config.Build(ecszap.WrapCoreOption(), zap.AddCallerSkip(1))

	if err != nil {
		panic(err)
	}
}

การแสดงข้อมูลเพิ่มเติม

เมื่อเราใช้งาน plugin ecszap แล้วนั้น ก็จะได้ format ตาม ECS เลย แต่หากเราต้องการให้แสดงข้อมูลเพิ่มเติม เช่น เพิ่มการแสดง Transaction ID ออกมาด้วย เราจะต้องสร้าง zap.Field ใหม่ขึ้นมา แล้วส่งไปพร้อมข้อความที่ต้องการแสดง

  • สร้าง filed ใหม่ เพื่อแสดง transactionId ทำได้โดยใช้ zap.String("transactionId", txId)
  • ส่งไปพร้อม message
pkg/handlers/todo.go
func CreateTodoHandler(w http.ResponseWriter, r *http.Request) {
	// ...
  tx := database.DB.Create(&todo)
  if err := tx.Error; err != nil {
		appErr := errs.NewUnexpectedError(err.Error())
		if errors.Is(err, gorm.ErrRecordNotFound) {
			appErr = errs.NewNotFoundError("todo with given id not found")
		}
	  // กำหนดให้ส่ง X-Trasaction-Id เป็น uuid มาใน request header
		txId := r.Header.Get("X-Transaction-Id")
		// สร้าง field ใหม่
    txField := zap.String("transactionId", txId)
    // ส่งไปพร้อมข้อความ
		logger.Error(appErr.Message, txField)

		w.Header().Add("Content-Type", "application/json")
		w.WriteHeader(appErr.Code)
		json.NewEncoder(w).Encode(appErr)
		return
	}
  // ...
}

Final logger module

ปรับโค้ด logger module ใหม่ ให้รองรับ dev mode และส่งออกไป Elastic Search จะกำหนดฟังก์ชันใช้ผ่าน interface จะได้ออกมาแบบนี้

  • สร้าง Logger interface และใช้งานผ่านตัวแปรชื่อ Default แทน
pkg/common/logger/logger.go
package logger

import (
	"os"

	"go.elastic.co/ecszap"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

type Field = zapcore.Field

type Interface interface {
	Info(msg string, fileds ...Field)
	Debug(msg string, fileds ...Field)
	Error(msg string, fileds ...Field)
	Warn(msg string, fileds ...Field)
	Fatal(msg string, fileds ...Field)
	Panic(msg string, fileds ...Field)
}

var zlog *zap.Logger
var Default Interface

func init() {
	var err error

	mode := os.Getenv("APP_MODE")

	var config zap.Config
	if mode == "production" {
		config = zap.NewProductionConfig()
	} else {
		config = zap.NewDevelopmentConfig()
	}

	config.EncoderConfig = ecszap.ECSCompatibleEncoderConfig(config.EncoderConfig)

	zlog, err = config.Build(ecszap.WrapCoreOption(), zap.AddCallerSkip(1))

	if err != nil {
		panic(err)
	}

	Default = newZapLogger(zlog)
}

func New(fileds ...Field) Interface {
	nlog := zlog.With(fileds...)
	return newZapLogger(nlog)
}

func ToFields(source map[string]interface{}) []Field {
	fields := []Field{}
	for k, v := range source {
		fields = append(fields, zap.Any(k, v))
	}
	return fields
}
  • สร้าง Logger โดยใช้ zap logger
pkg/common/logger/zap.go
package logger

import "go.uber.org/zap"

type zapLogger struct {
	*zap.Logger
}

func newZapLogger(logger *zap.Logger) Interface {
	return &zapLogger{logger}
}

func (l *zapLogger) Info(msg string, fileds ...Field) {
	l.Logger.Info(msg, fileds...)
}

func (l *zapLogger) Debug(msg string, fileds ...Field) {
	l.Logger.Debug(msg, fileds...)
}

func (l *zapLogger) Error(msg string, fileds ...Field) {
	l.Logger.Error(msg, fileds...)
}

func (l *zapLogger) Warn(msg string, fileds ...Field) {
	l.Logger.Warn(msg, fileds...)
}

func (l *zapLogger) Fatal(msg string, fileds ...Field) {
	l.Logger.Fatal(msg, fileds...)
}

func (l *zapLogger) Panic(msg string, fileds ...Field) {
	l.Logger.Panic(msg, fileds...)
}
  • เมื่อใช้งาน logger module ให้เรียกผ่าน logger.Default เช่น
cmd/main.go
func main() {
  // ...
  logger.Default.Info("Starting server at port 8080")
	log.Fatal(http.ListenAndServe(":8080", handler))
}
  • ถ้าต้องการเพิ่ม fields เช่น transactionId ส่งเป็น map[string]interface{} ไปแทน
pkg/handlers/todo.go
func CreateTodoHandler(w http.ResponseWriter, r *http.Request) {
	// ...
  tx := database.DB.Create(&todo)
  if err := tx.Error; err != nil {
		appErr := errs.NewUnexpectedError(err.Error())
		if errors.Is(err, gorm.ErrRecordNotFound) {
			appErr = errs.NewNotFoundError("todo with given id not found")
		}
	  // กำหนดให้ส่ง X-Trasaction-Id เป็น uuid มาใน request header
		txId := r.Header.Get("X-Transaction-Id")
		// สร้าง field ใหม่
    fields := map[string]interface{}{}
		fields["transactionId"] = txId
    // ส่งไปพร้อมข้อความ
		logger.Default.Error(appErr.Message, logger.ToFields(fields)...)

		w.Header().Add("Content-Type", "application/json")
		w.WriteHeader(appErr.Code)
		json.NewEncoder(w).Encode(appErr)
		return
	}
  // ...
}
Discuss on Twitter • View on GitHub