Golang Logrus Hook을 이용한 mutisink 로깅

Logrus?

golang에서 사용하는 대표적인 logging 패키지인 logrus는 stdout, stderr등 다양한 output 및 커스터마이징이 가능한 formatter등 구조화된 로깅을 지원한다.

구조화된(structured) 로깅?

로그를 단순한 텍스트의 연속이 아닌 특정 데이터 세트(날짜, 사용자, 각종 필드)로 처리할 수 있도록 특정한 메시지 포맷을 구현하는 방식이다.

기본 사용법

간단하게 콘솔창에 로그를 찍는 예제는 다음과 같다

package main

import (
	"os"
	"time"

	log "github.com/sirupsen/logrus"
)

func main() {
	log.SetOutput(os.Stdout)

	log.SetFormatter(&log.TextFormatter{
		FullTimestamp:   true,
		TimestampFormat: time.RFC822,
	})

	log.SetLevel(log.InfoLevel)
	log.Info("Info message")
	log.WithFields(log.Fields{
		"name": "Neymar",
		"age":  32,
		"club": "PSG",
	}).Info("Info message with fields")
	log.Debug("Debug message")

	log.SetLevel(log.DebugLevel)
	log.Info("Info message")
	log.Debug("Debug message")
}

INFO[07 Jun 22 23:08 KST] Info message     
INFO[07 Jun 22 23:54 KST] Info message with fields                      age=32 club=PSG name=Neymar                            
INFO[07 Jun 22 23:08 KST] Info message                                 
DEBU[07 Jun 22 23:08 KST] Debug message

이외에 다양한 사용방법에 대해서는 logrus 공식레포에서 확인하도록 하자

Multisink 로깅

개발을 하다보면 단순히 콘솔창뿐만 아니라 파일에 로그를 남겨야 할 경우가 있다. 당연하게도 logrus 패키지에서는 io.Writer를 파라미터로 받는 logrus.SetOutput를 사용하여 콘솔, 파일 둘 다 동시에 로깅을 할 수 있다.

file, err := os.OpenFile("test.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0755)
if err != nil {
	panic(err)
}
log.SetOutput(io.MultiWriter(os.Stdout, file))

위 코드를 실행하게 되면 아래와 같은 출력과 로그파일을 볼수있다.

time="07 Jun 22 23:21 KST" level=info msg="Info message"
time="07 Jun 22 23:21 KST" level=info msg="Info message"
time="07 Jun 22 23:21 KST" level=debug msg="Debug message"

로깅 형식이 바뀐 이유

단순히 output을 바꿔주기만 했을뿐인데 로깅 포맷이 바뀌었다. 그 이유가 너무 궁금해서 패키지 내부 코드를 살펴보았다

func (entry *Entry) write() {
	serialized, err := entry.Logger.Formatter.Format(entry)
	if err != nil {
		fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
		return
	}
	entry.Logger.mu.Lock()
	defer entry.Logger.mu.Unlock()
	if _, err := entry.Logger.Out.Write(serialized); err != nil {
		fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
	}
}

logrus 내부에서 실질적으로 로깅을 하는 부분을 봤더니 formatting된 byte slice를 받아서 logger에 등록된 io.Writer을 통해 write를 하는부분을 볼수 있었다.

	f.terminalInitOnce.Do(func() { f.init(entry) })

	timestampFormat := f.TimestampFormat
	if timestampFormat == "" {
		timestampFormat = defaultTimestampFormat
	}
	if f.isColored() {
		f.printColored(b, entry, keys, data, timestampFormat)
	} else {
    // ...

출력 형식이 바뀐 이유가 된 핵심 부분이다. logrus내부에서 각 formatter에 맞게 형식을 변환시키는데 기본 TextFormatter의 경우, isTerminal이라는 변수로 터미널 여부를 판단한다. f.isColored 의 조건에 맞으면 원했던 로깅 포맷을 출력하게 되어있다.

isColored := f.ForceColors || (f.isTerminal && (runtime.GOOS != "windows"))

isColored의 조건은 위와 같다. 따라서 Formatter의 옵션중 하나인 ForceColors를 true로 설정해주면 이 문제는 해결된다.

아래에서 서술할 내용이지만, 터미널 출력이 아닐경우 color code값이 로그파일에 남게되어 지저분해지니까 위와 같은 처리를 한 것같다.

ForceColor 옵션의 문제점

[36mINFO[0m[08 Jun 22 00:35 KST] Info message                                 
[36mINFO[0m[08 Jun 22 00:35 KST] Info message with fields                      [36mage[0m=32 [36mclub[0m=PSG [36mname[0m=Neymar
[36mINFO[0m[08 Jun 22 00:35 KST] Info message                                 
[37mDEBU[0m[08 Jun 22 00:35 KST] Debug message

ForceColors옵션을 주어 강제로 색상을 주고 로그파일을 보면 위와같이 콘솔에서 색상을 출력해주기위한 color code값이 그대로 적혀있다.

로깅 자체에는 문제가 없지만 파일을 열어서 봤을때 보기도 힘들고 아무래도 뭔가 찝찝하다… 그렇다고 DisableColors값을 false로 주어 위 color code값을 없애자니 콘솔창에서 색상 highlight가 되지 않는다.

사실 로그파일을 읽을때 grep 으로 level keyword를 highlight를 하는 등의 특정 키워드를 highlight하는 방법은 여러가지가 있다.

그래도 이렇게 마무리하면 아쉬울 것 같아서

같은 로깅 포맷을 사용
콘솔에서는 highlight를 그대로 사용
파일 로깅시에는 color code값을 제거

위를 모두 만족하는 방법은 없을까 해서 열심히 구글링을 해보다가. 비슷한 문제로 issue가 올라온걸 보았다.

답변을 요약하면 SetOutput(os.Stdout)은 그대로 적용해 coloring을 하고, 별도의 formatter를 갖는 Hook을 추가하는 방법으로 문제를 해결하는 방법을 말하고 있다.

File Hooking

logrus는 hook기능을 제공하는데 hook을 이용해 지정된 곳에 한번에 로그를 남길 수 있다.

우선 color code가 없는 형태의 custom formatter 인터페이스를 구현한다

type PlainFormatter struct {
	log.TextFormatter
	TimestampFormat string
	LevelDesc       []string
}

func NewPlainFormatter() *PlainFormatter {
	return &PlainFormatter{
		TimestampFormat: time.RFC3339,
		LevelDesc:       []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG"},
	}
}

func (f *PlainFormatter) Format(entry *log.Entry) ([]byte, error) {
	timestamp := fmt.Sprintf("%v", entry.Time.Format(f.TimestampFormat))
	return []byte(fmt.Sprintf("[%s] [%s] %s\n", f.LevelDesc[entry.Level], timestamp, entry.Message)), nil
}

다음으로 file을 생성하는 Hook 인터페이스를 구현한다

type FileHook struct {
	Formatter logrus.Formatter
	Level     []logrus.Level
	Writer    io.Writer
}

func NewFileHook() log.Hook {
	file, err := os.OpenFile("test.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0755)
	if err != nil {
		panic(err)
	}

	return &FileHook{
		Formatter: NewPlainFormatter(),
		Level: []log.Level{
			log.InfoLevel,
		},
		Writer: file,
	}
}

func (h *FileHook) Fire(entry *log.Entry) error {
	bytes, err := h.Formatter.Format(entry)
	if err != nil {
		return err
	}
	h.Writer.Write(bytes)

	return nil
}

func (h *FileHook) Levels() []logrus.Level {
	return h.Level
}

중요한 부분은 FileHook 구조체에 별도의 Formatter와 Writer를 설정하는것이다.

built-in formatter인 TextFormatter를 사용하지 않는 이유는 color code값을 제거하기 위해서다.

위 설정을 모두 추가한 후, 실제 사용부분에서 log.AddHook(NewFileHook) 만 추가해주면 완성이다.

실제 쓰여진 파일로그를 보면, WithFields를 사용한 로그는 적용되지 않는데, 그 부분은 PlainFormatter의 interface method인 Format()에서 별도로 처리해야 한다.

Reference

https://github.com/sirupsen/logrus/issues/784

Logrus?#

구조화된(structured) 로깅?#

기본 사용법#

Multisink 로깅#

로깅 형식이 바뀐 이유#

ForceColor 옵션의 문제점#

File Hooking#

Reference#