Published on

API Service with Go: Logger Middleware

Authors

Logger Middleware

จากบทความที่ผ่านๆ มามีการใช้ logger middleware ของ fiber เพื่อแสดงข้อมูลของ request และ response แต่ปัญหาอย่างหนึ่ง คือ มันแสดงออกมาเป็นข้อความธรรมดา ซึ่งจากบทความความเรื่อง logger module การแสดง log ของเราควรมีรูปแบบเป็น JSON เพื่อให้นำเอาไปใช้งานต่อได้

ดังนั้นในบทความนี้จะมาสร้าง logger middleware ขึ้นมาเอง เพื่อให้แสดง request log ได้ถูกต้อง

Logger Middleware ของ Fiber

มาดูกันก่อนว่า logger middleware ของ fiber ใช้งานยังไง ซึ่งตัวมันเองสามารถปรับเปลี่ยนรูปแบบของข้อมูลที่ต้องการแสดงได้ เช่น เพิ่มให้แสดง ip, port และ request id ออกมา

cmd/api/main.go
func main() {
	app := fiber.New()

	app.Use(requestid.New())

	app.Use(logger.New(logger.Config{
		Format: "[${ip}]:${port} ${locals:requestid} ${status} - ${method} ${path}\n",
	}))

	app.Get("/", func(c *fiber.Ctx) error {
		return c.SendString("Hello, World!")
	})

	app.Listen(":3000")
}

เมื่อมี request เรียกเข้ามา จะแสดง log แบบนี้

[127.0.0.1]:50462 d69ecd6d-7de4-46bc-845f-ad5f4fc4043c  200  -  GET      /

ซึ่งก็ยังเป็นข้อความธรรมดา ไม่ใช้ format ตามที่เราต้องการ

เปลี่ยนเป็น JSON Format

การที่จะเปลี่ยนการแสดงข้อมูลให้เป็น JSON Format เราจะต้องสร้าง logger middleware ของเราขึ้นมาเอง ซึ่ง fiber มีวิธีการสร้าง แบบนี้

cmd/api/main.go
func main() {
	app := fiber.New()

	app.Use(requestid.New())
	app.Use(logMiddleware)

	app.Get("/", func(c *fiber.Ctx) error {
		return c.SendString("Hello, World!")
	})

	logger.Default.Info("start on port 3000")

	app.Listen(":3000")
}

func logMiddleware(c *fiber.Ctx) error {
	c.Next()
}

ส่วนข้อความของ log เช่น "[ip]:port status - method path (latency)" แทนที่จะแสดงออกมาทาง message ก็เปลี่ยนให้แสดงเป็น field แทน

cmd/api/main.go
func logMiddleware(c *fiber.Ctx) error {
	start := time.Now()

	err := c.Next()

	fileds := map[string]interface{}{
    "requestId": c.GetRespHeader("X-Request-ID"),
		"ip":        c.IP(),
		"method":    c.Method(),
		"uri":       c.Path(),
		"status":    c.Response().StatusCode(),
		"latency":   time.Since(start),
	}

	logger.Default.Info("", logger.ToFields(fileds)...)

	return err
}

เมื่อมี request เรียกเข้ามาก็จะได้ log ในรูปแบบของ JSON แล้ว

{
  "log.level": "info",
  "@timestamp": "2022-08-15T14:17:08.397+0700",
  "log.origin": {
    "file.name": "api/main.go",
    "file.line": 42
  },
  "message": "",
  "status": 200,
  "latency": 0,
  "requestId": "b867ca47-422c-4e1b-a1bf-93ec638c53be",
  "ip": "127.0.0.1",
  "method": "GET",
  "uri": "/",
  "ecs.version": "1.6.0"
}

สร้าง Logger ส่งไปให้ Handler

ปัญหาอีกอย่างหนึ่ง เมื่อเรากำหนดรูปแบบของ log ให้แสดง ip, method, path และ request id ออกมาด้วยทุกครั้ง ทำให้ต้องมีการสร้าง fields เหล่านี้ ในทุกๆ handler

fileds := map[string]interface{}{
  "requestId": c.GetRespHeader("X-Request-ID"),
	"ip":        c.IP(),
	"method":    c.Method(),
	"uri":       c.Path(),
}

ซึ่งมีโอกาศผิดพลาดตกหล่นได้ หรือถ้าในอนาคตมีการเพิ่ม หรือลดข้อมูลที่จะแสดงก็ต้องเข้าไปแก้ในทุกๆ handlers

เพื่อแก้ปัญหาดังกล่าว เราจะใช้ logger middleware ของเรา สร้าง fields ทุกอย่างที่ต้องใช้จาก Request แล้วเอาไปสร้าง logger ตัวใหม่ แยกไปกับ request แต่ละตัวไปเลย แล้วใน handler ก็แค่เอา logger ตัวนี้มาใช้งานแสดง message ก็จะได้ fields ทุกอย่างตามที่ส่งมาเลย มีขั้นตอนดังนี้

  • เริ่มจากแก้ไข logger middleware ให้ดึงทุกค่าจาก request ที่จะเอาไปแสดงใน log ออกมา แล้วเอามาใส่ไว้ใน map[string]interface{} เช่น จากโค้ดด้านบนให้ย้าย fields มาอยู่ก่อน c.Next()
cmd/api/main.go
func logMiddleware(c *fiber.Ctx) error {
	start := time.Now()

  appName := os.Getenv("APP_NAME")

	if len(appName) == 0 {
		appName = "goapi"
	}

	fileds := map[string]interface{}{
		"app":       appName,
		"domain":    c.Hostname(),
		"requestId": c.GetRespHeader("X-Request-ID"),
		"userAgent": c.Get("User-Agent"),
		"ip":        c.IP(),
		"method":    c.Method(),
		"traceId":   c.Get("X-B3-Traceid"),
		"spanId":    c.Get("X-B3-Spanid"),
		"uri":       c.Path(),
	}

	err := c.Next()

  fileds["status"] = c.Response().StatusCode()
	fileds["latency"] = time.Since(start)

	logger.Default.Info("", logger.ToFields(fileds)...)

  return err
}
  • สร้าง Logger ใหม่พร้อม fields ทั้งหมด สำหรับ request แต่ละครั้งขึ้นมา
cmd/api/main.go
func logMiddleware(c *fiber.Ctx) error {
	start := time.Now()

  fileds := map[string]interface{}{}
	fileds["ip"] = c.IP()
	fileds["port"] = c.Port()
	fileds["requestid"] = c.GetRespHeaders()["X-Request-Id"]

+ log := logger.New(logger.ToFields(fileds)...)

	err := c.Next()

  fileds["status"] = c.Response().StatusCode()
	fileds["latency"] = time.Since(start)

	logger.Default.Info("", logger.ToFields(fileds)...)

  return err
}
  • ส่ง logger ที่สร้างไปกลับ request
cmd/api/main.go
func logMiddleware(c *fiber.Ctx) error {
	start := time.Now()

	fileds := map[string]interface{}{}
	fileds["ip"] = c.IP()
	fileds["port"] = c.Port()
	fileds["requestid"] = c.GetRespHeaders()["X-Request-Id"]

  log := logger.NewWithFields(fileds)

+ c.Locals("log", log)

	err := c.Next()

	fileds["status"] = c.Response().StatusCode()
	fileds["latency"] = time.Since(start)

	logger.Default.Info("", logger.ToFields(fileds)...)

  return err
}
  • เมื่อจะใช้งาน log ใน handler ทำได้โดย
cmd/api/main.go
app.Get("/", func(c *fiber.Ctx) error {
  // ดึงออกมาจาก c.Locals
	log := c.Locals("log").(logger.Logger)

	log.Info("log in handler")

	return c.SendString("Hello, World!")
})
  • เมื่อมี request เข้ามา ก็จะได้ log ที่มีข้อมูล fields ทุกอย่างๆ แยกตาม request นั้นๆ เลย
{
	"log.level":"info",
	"@timestamp":"2022-08-15T14:28:02.925+0700",
	"log.origin":{
		"file.name":"api/main.go",
		"file.line":20
	},
	"message":"log in handler",
	"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36",
	"traceId":"",
	"app":"goapi",
	"domain":"127.0.0.1:3000",
	"requestId":"71a494ca-41ea-43b7-a75a-569c2498c910",
	"uri":"/",
	"ip":"127.0.0.1",
	"method":"GET",
	"spanId":"",
	"ecs.version":"1.6.0"
}
{
	"log.level":"info",
	"@timestamp":"2022-08-15T14:28:02.926+0700",
	"log.origin":{
		"file.name":"api/main.go",
		"file.line":59
	},
	"message":"",
	"ip":"127.0.0.1",
	"method":"GET",
	"spanId":"",
	"uri":"/",
	"status":200,
	"latency":0.0009283,
	"app":"goapi",
	"domain":"127.0.0.1:3000",
	"requestId":"71a494ca-41ea-43b7-a75a-569c2498c910",
	"userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36",
	"traceId":"",
	"ecs.version":"1.6.0"
}

สรุป

การสร้าง logger module ขึ้นมาเองเนื่องจาก เพื่อต้องการเปลี่ยนรูปแบบของ request, response log ให้เป็น JSON Format แล้วยังสามารถใช้สร้าง logger แยกตาม request พร้อมกำหนด fields ต่างๆ ที่ต้องดึงอ่านออกมาจาก request ให่เรียบร้อย ทำให้ไม่ต้องไปดึงค่าใน handler เพื่อลดความผิดพลาด และสะดวกในการแก้ในอนาคตด้วย

ดูโค้ดทั้งหมดได้ที่นี่

Discuss on Twitter • View on GitHub