golang logging을 위한 zap 사용 방법을 알아보자.

놀고 싶은데, 왜 다들 공부하는거야·2024년 1월 2일

zap

목록 보기

1/1

golang zap 사용

https://www.golinuxcloud.com/golang-zap-logger/#google_vignette

golang에는 여러가지 logging library들이 있는데, 그 중 가장 많이 사용되고 효율이 좋다고 평가받는 것이 zap이다.

zap은 우버에서 만들어졌는데, 기존의 다량의 log들이 시스템 부하를 만들었고 MSA구조에서 구조화된 log를 제공하지 않아 tracing이나 monitoring이 어려웠다고 한다. 이에 우버는 zap을 만들어 system bottleneck이 생기지 않도록 하고, 구조화된 log를 제공하여 tracing, monitoring을 제공하기 쉽도록 하였다.

https://github.com/uber-go/zap

먼저 zap을 설치하는 방법은 다음과 같다.

go get -u go.uber.org/zap

zap.Logger

zap에서는 두가지 logger를 제공한다. 하나는 기본적인 zap.Logger로 강타입 언어를 사용하도록 하여 굉장히 속도가 빠르다.

package main

import (
	"go.uber.org/zap"
)

func main() {
	logger, _ := zap.NewProduction()
	defer logger.Sync()
	logger.Info("Hello world", zap.String("key", "value"))
}

zap.NewProduction을 사용하면 zap.Logger를 만들 수 있으며, logger.Sync()를 통해서 기존에 buffering된 log entry들을 삭제하도록 하는 것이다.

logging결과는 다음과 같다.

{"level":"info","ts":1704179664.2145793,"caller":"ticker_test/main.go:10","msg":"Hello world","key":"value"}

zap.SugaredLogger

두번째는 zap.SugaredLogger로 zap.Logger보다 느리지만, 더 사용하기 편한 방법들을 제공한다. 그래서 sugar라는 것 자체가 synthetic-sugar를 의미하는 것이다.

package main

import (
	"go.uber.org/zap"
)

func main() {
	logger, _ := zap.NewProduction()
	defer logger.Sync()
	sugar := logger.Sugar()
	sugar.Infof("Hello world %s log", "info", "key", "value")
}

zap.Logger에서 Sugar를 호출하면 zap.SugaredLogger가 만들어진다. 사용방법은 Infof등 다양한 방법들이 있는데, zap.Logger에 비해서 훨씬 더 사용자 친화적인 방식을 가진다.

{"level":"info","ts":1704180324.302456,"caller":"ticker_test/main.go:11","msg":"Hello world info log%!(EXTRA string=key, string=value)"}

따라서, logging의 성능이 매우 중요한 경우에는 zap.Logger를 사용하고, 그렇지 않은 경우에는 zap.SugaredLogger를 사용하여 좀 더 개발자 친화적인 로깅을 만드는 것이 좋다.

Configuration

zap에는 크게 두 가지 configuration이 있다고 생각하면 된다. zap.Config는 zap에서 log를 만들 때 사용하는 configuration이고, zapcore.EncoderConfig는 zap.Config에 들어가는 encoder configuration으로 log를 어떤 형식으로 출력할 것인지를 설정하는 것이다.

따라서, log entry를 출력할 때 위에서 time을 ts가 아니라 timestamp로 찍거나 time형식을 다르게 하고싶다면 zapcore.EncoderConfig를 수정하면 되고, log level과 같은 log의 기본 설정을 바꾸고 싶다면 zap.Config를 수정하면 된다.

zap.Config

zap.Logger는 기본적으로 다음의 zap.Config를 통해서 만들어진다.

func NewProductionConfig() Config {
	return Config{
		Level:       NewAtomicLevelAt(InfoLevel),
		Development: false,
		Sampling: &SamplingConfig{
			Initial:    100,
			Thereafter: 100,
		},
		Encoding:         "json",
		EncoderConfig:    NewProductionEncoderConfig(),
		OutputPaths:      []string{"stderr"},
		ErrorOutputPaths: []string{"stderr"},
	}
}

다음의 내용을 수정하여 custom한 zap.Config를 만들 수 있다.

package main

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	config := zap.Config{
		Level:            zap.NewAtomicLevelAt(zapcore.DebugLevel),
		Development:      true,
		Encoding:         "json",
		EncoderConfig:    zap.NewProductionEncoderConfig(),
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stderr"},
	}

	logger, _ := config.Build()
	defer logger.Sync()

	// Example logs
	logger.Debug("This is a debug message.")
	logger.Info("This is an info message.")
	logger.Warn("This is a warning message.")
	logger.Error("This is an error message.")
}

zap.Config를 통해서 EncoderConfig를 받는 것을 볼 수 있다. 이 부분이 앞서 말한 각 log entry에 적용되는 encoder를 설정하는 부분이다.

zap.Config의 Build를 통해서 zap.Logger를 만들 수 있는 것을 볼 수 있다. custom zap.Config를 적용한 logger를 통해서 찍힌 log의 결과는 다음과 같다.

{"level":"debug","ts":1704180938.1026042,"caller":"ticker_test/main.go:22","msg":"This is a debug message."}
{"level":"info","ts":1704180938.1026251,"caller":"ticker_test/main.go:23","msg":"This is an info message."}
{"level":"warn","ts":1704180938.1026285,"caller":"ticker_test/main.go:24","msg":"This is a warning message.","stacktrace":"main.main\n\t/p4ws/golang/ticker_test/main.go:24\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
{"level":"error","ts":1704180938.1026332,"caller":"ticker_test/main.go:25","msg":"This is an error message.","stacktrace":"main.main\n\t/p4ws/golang/ticker_test/main.go:25\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}

zap.Config의 zap.NewAtomicLevelAt(zapcore.DebugLevel)부분을 수정하여 log level을 수정할 수도 있다.

zap에서 제공하는 log level은 다음과 같다.

type Level int8

const (
	// DebugLevel logs are typically voluminous, and are usually disabled in
	// production.
	DebugLevel Level = iota - 1
	// InfoLevel is the default logging priority.
	InfoLevel
	// WarnLevel logs are more important than Info, but don't need individual
	// human review.
	WarnLevel
	// ErrorLevel logs are high-priority. If an application is running smoothly,
	// it shouldn't generate any error-level logs.
	ErrorLevel
	// DPanicLevel logs are particularly important errors. In development the
	// logger panics after writing the message.
	DPanicLevel
	// PanicLevel logs a message, then panics.
	PanicLevel
	// FatalLevel logs a message, then calls os.Exit(1).
	FatalLevel

	_minLevel = DebugLevel
	_maxLevel = FatalLevel

	// InvalidLevel is an invalid value for Level.
	//
	// Core implementations may panic if they see messages of this level.
	InvalidLevel = _maxLevel + 1
)

zap.NewAtomicLevelAt에 위의 log level을 적용시키면 된다. 가령 Info level로 변경해보도록 하자.

package main

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	config := zap.Config{
		Level:            zap.NewAtomicLevelAt(zapcore.InfoLevel),
		Development:      true,
		Encoding:         "json",
		EncoderConfig:    zap.NewProductionEncoderConfig(),
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stderr"},
	}

	logger, _ := config.Build()
	defer logger.Sync()

	// Example logs
	logger.Debug("This is a debug message.")
	logger.Info("This is an info message.")
}

zap.NewAtomicLevelAt을 zapcore.InfoLevel로 변경한 것이다.

{"level":"info","ts":1704181260.9538274,"caller":"ticker_test/main.go:23","msg":"This is an info message."}

Debug log가 발생하지 않고 Info만 찍힌 것을 볼 수 있다.

zap에서는 log level을 application이 동작하는 중에도 변경할 수 있다. 즉, log level을 동적으로 변경이 가능하다는 것이다. log level을 만들 때 zap.NewAtomicLevelAt으로 쓰여져 있는데, atomic이라는 말이 의미하는 것은 application이 동작 중에, 여러 goroutine과 상관없이 atomic하게 log level을 변경할 수 있다는 것이다.

package main

import (
	"go.uber.org/zap"
)

func main() {
	atomicLevel := zap.NewAtomicLevelAt(zap.InfoLevel)
	config := zap.Config{
		Level:            atomicLevel,
		Development:      true,
		Encoding:         "json",
		EncoderConfig:    zap.NewProductionEncoderConfig(),
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stderr"},
	}

	logger, _ := config.Build()
	defer logger.Sync()

	// Example logs
	logger.Debug("This is a debug message.")
	logger.Info("This is an info message.")

	atomicLevel.SetLevel(zap.DebugLevel)

	logger.Debug("This is a debug message.")
	logger.Info("This is an info message.")
}

zap.NewAtomicLevelAt를 통해서 atomicLevel을 만들고 이를 zap.Config에 적용시키도록 한다. zap.Config의 Build를 통해서 zap.Logger를 만들어도 atomicLevel.SetLevel을 이용하면 zap.Logger의 log level을 바꿀 수 있다.

결과는 다음과 같다.

{"level":"info","ts":1704181818.3115754,"caller":"ticker_test/main.go:23","msg":"This is an info message."}
{"level":"debug","ts":1704181818.311598,"caller":"ticker_test/main.go:27","msg":"This is a debug message."}
{"level":"info","ts":1704181818.311602,"caller":"ticker_test/main.go:28","msg":"This is an info message."}

log level이 info에서 debug로 바뀌어서 이전에는 안찍힌 debug log가 찍힌 것을 볼 수 있다.

이와 같은 동작이 가능한 것은 log level을 결정하는 zap.AtomicLevel구조체가 다음과 같이 포인터로 log level값을 가지고 있기 때문이다.

type AtomicLevel struct {
	l *atomic.Int32
}

따라서 값이 바뀌어도, zap.Logger인스턴스가 log level을 가져올 수 있다.

이 밖에 zap.Config에서 output log에 대한 encoding을 설정할 수 있는데, 다음과 같다.
1. Encoding: zap에서는 output log에 대해서 두 가지 주요 encoding 타입을 지원한다.
- JSON: json 형식으로 output log를 만들도록 한다.
- Console: 인간이 읽기 쉬운 형식으로 output log를 만들어 system보다는 개발자가 직접 로그를 읽고 분석할 때 좋다.

zapcore.EncoderConfig

다음은 각 log entry의 formatting을 담당하는 zapcore.EncoderConfig이다.

zap에서 encoding formatting customization할 수 있는 부분들은 다음과 같다.
1. TimeKey, LevelKey, NameKey, CallerKey: log output에서의 key값을 결정한다.
2. FunctionKey: 특정 function을 logging한다면 key를 지정할 수 있다.
3. MessageKey: log message의 key를 지정할 수 있다.
4. StacktraceKey: stacktrace의 key를 지정할 수 있다.
5. LineEncoding: log message의 line encoding을 적용할 수 있는데, 기본적으로 \n이다.
6. EncodeLevel: log level을 encoding하는 방식을 지정할 수 있다. 기본적으로 zapcore.CapitalLevelEncoder를 사용하여 info가 아니라 INFO로 출력된다.
7. EncodeTime: timestamp를 어떻게 encoding할 지 결정한다. 기본적으로 1704181818.3115754와 같은 형식으로 출력 가능한데, zapcore.ISO8601TimeEncoder를 사용하여 2024-01-02T15:27:57.341+0900와 같은 형식으로 출력이 가능하다.
8. EncodeDuration: 어떻게 duration을 encoding할지 결정한다. 가령 duration을 인간이 읽을 수 있는 string으로 변환하는 것이 있다. 가령 1704181818.3115754와 같은 형식으로 출력 가능한데, zapcore.StringDurationEncoder를 사용하여 1s 234ms 578µs 1.234ms와 같은 형식으로 출력이 가능하다.
9. EncodeCaller: log entry의 caller부분을 어떻게 encoding할지 결정한다. 가령 main.main과 같이 출력하는 것이 아니라, ticker_test/main.go:23과 같이 출력하는 것이다.

이를 이용하여 다음과 같은 zapcore.EncoderConfig를 만들 수 있다.

package main

import (
	"os"
	"time"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	// Define custom encoder configuration
	encoderConfig := zapcore.EncoderConfig{
		TimeKey:        "timestamp",
		LevelKey:       "level",
		NameKey:        "logger",
		CallerKey:      "caller",
		MessageKey:     "message",
		StacktraceKey:  "stacktrace",
		LineEnding:     zapcore.DefaultLineEnding,
		EncodeLevel:    zapcore.CapitalLevelEncoder,    // Capitalize the log level names
		EncodeTime:     zapcore.ISO8601TimeEncoder,     // ISO8601 UTC timestamp format
		EncodeDuration: zapcore.SecondsDurationEncoder, // Duration in seconds
		EncodeCaller:   zapcore.ShortCallerEncoder,     // Short caller (file and line)
	}

	// Create a core logger with JSON encoding
	core := zapcore.NewCore(
		zapcore.NewJSONEncoder(encoderConfig), // Using JSON encoder
		zapcore.NewMultiWriteSyncer(zapcore.AddSync(os.Stdout)),
		zap.InfoLevel,
	)

	logger := zap.New(core)
	defer logger.Sync() // Sync writes logs to the writers (in this case, stdout)

	// Basic structured logging with Logger
	logger.Info("Structured logging with Logger",
		zap.String("stringField", "stringValue"),
		zap.Int("intField", 42),
		zap.Duration("durationField", time.Second*3), // This will use the SecondsDurationEncoder format
	)

	// Using SugaredLogger for printf-style logging
	sugar := logger.Sugar()
	sugar.Infof("Printf-style logging with SugaredLogger: %s = %d", "intField", 42)

	// SugaredLogger supports adding structured context
	sugar.With(
		zap.String("contextField", "contextValue"),
	).Infof("Printf-style logging with context: %s", "additional info")

	// Demonstrating other field types with Logger
	logger.Info("Demonstrating other field types",
		zap.Bool("boolField", true),
		zap.Float64("floatField", 3.14),
		zap.Time("timeField", time.Now()),
		zap.Any("anyField", map[string]int{"key": 1}), // Use zap.Any for any supported type
	)
}

zapcore.EncoderConfig는 하나의 configuration이기 때문에 zapcore.NewJSONEncoder를 통해서 Encoder로 만들어주어야 한다.

zapcore.EncoderConfig를 만들고 이를 zapcore.NewCore에 제공해주어 zapcore.Core인스턴스를 만들 수 있다. 이 core를 기반으로 logger를 만들어 낼 수 있다.

사실 zap.Config의 Build 역시도 내부를 보면 configuration값을 이용하여 zapcore.NewCore를 만든다음 zap.New를 호출하여 zap.Logger인스턴스를 만들어낸다. 따라서, zap.New함수와 zapcore.Core인스턴스는 별로 새로울 것이 없다.

zap.Config.Build

func (cfg Config) Build(opts ...Option) (*Logger, error) {
	enc, err := cfg.buildEncoder()
	if err != nil {
		return nil, err
	}

	sink, errSink, err := cfg.openSinks()
	if err != nil {
		return nil, err
	}

	if cfg.Level == (AtomicLevel{}) {
		return nil, errors.New("missing Level")
	}

	log := New(
		zapcore.NewCore(enc, sink, cfg.Level),
		cfg.buildOptions(errSink)...,
	)
	if len(opts) > 0 {
		log = log.WithOptions(opts...)
	}
	return log, nil
}

zapcore.NewCore에 configuration의 level을 주고 encoder configuration을 설정해주어 zapcore.Core를 만들어내고 zap.New를 통해서 zap.Logger를 만들어내는 것을 볼 수 있다.

이제 custom encoder를 적용한 출력된 결과를 확인해보도록 하자.

{"level":"INFO","timestamp":"2024-01-02T17:36:18.589+0900","message":"Structured logging with Logger","stringField":"stringValue","intField":42,"durationField":3}
{"level":"INFO","timestamp":"2024-01-02T17:36:18.589+0900","message":"Printf-style logging with SugaredLogger: intField = 42"}
{"level":"INFO","timestamp":"2024-01-02T17:36:18.589+0900","message":"Printf-style logging with context: additional info","contextField":"contextValue"}
{"level":"INFO","timestamp":"2024-01-02T17:36:18.589+0900","message":"Demonstrating other field types","boolField":true,"floatField":3.14,"timeField":"2024-01-02T17:36:18.589+0900","anyField":{"key":1}}

우리가 만든 custom encoder의 configuration을 보면 다음과 같다.

encoderConfig := zapcore.EncoderConfig{
		TimeKey:        "timestamp",
		LevelKey:       "level",
		NameKey:        "logger",
		CallerKey:      "caller",
		MessageKey:     "message",
		StacktraceKey:  "stacktrace",
		LineEnding:     zapcore.DefaultLineEnding,
		EncodeLevel:    zapcore.CapitalLevelEncoder,    // Capitalize the log level names
		EncodeTime:     zapcore.ISO8601TimeEncoder,     // ISO8601 UTC timestamp format
		EncodeDuration: zapcore.SecondsDurationEncoder, // Duration in seconds
		EncodeCaller:   zapcore.ShortCallerEncoder,     // Short caller (file and line)
	}

TimeKey를 timestamp로 했기 때문에 ts가 아니라 timestamp로 찍히는 것을 볼 수 있다. MessageKey를 message로 섰기 때문에 msg가 아니라 message로 찍힌 것 또한 볼 수 있다.

timestamp의 값 또한 1704181818.311602이 아니라 2024-01-02T17:36:18.589+0900형식으로 찍힌 것을 볼 수 있다. 이는 zapcore.ISO8601TimeEncoder를 사용하여 zapcore.EncoderConfig에서 EncodeTime을 지정했기 때문이다.

만약 custom time format을 적용하고 싶다면 다음과 같이 함수를 만들어 지정할 수 있다.

encoderConfig.EncodeTime = func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
	enc.AppendString(t.Format("2006-01-02 15:04:05"))
}

또한, custom log field를 추가할 수 있는데, zap.Logger는 다음과 같이 사용할 수 있다.

logger.Info("Demonstrating other field types",
	zap.Bool("boolField", true),
	zap.Float64("floatField", 3.14),
	zap.Time("timeField", time.Now()),
	zap.Any("anyField", map[string]int{"key": 1}), // Use zap.Any for any supported type
)

boolField, floatField, timeField, anyField 등이 추가된 것을 볼 수 있을 것이다.

해당 로그의 결과는 다음과 같았다.

{"level":"INFO","timestamp":"2024-01-02T18:36:32.076+0900","message":"Demonstrating other field types","boolField":true,"floatField":3.14,"timeField":"2024-01-02T18:36:32.076+0900","anyField":{"key":1}}

zap.SugaredLogger의 경우는 다음과 같이 custom field를 추가할 수 있다.

sugar.With(
    zap.String("key1", "value1"),
).Infof("A log message with key2=%d", 42)

마지막으로 zapcore.EncoderConfig를 zap.Config에 넣어서 logger를 만들 수 있다고 했는데, 위의 예제를 수정하면 다음과 같다.

func main() {
	// Define custom encoder configuration
	encoderConfig := zapcore.EncoderConfig{
		TimeKey:        "timestamp",
		LevelKey:       "level",
		NameKey:        "logger",
		CallerKey:      "caller",
		MessageKey:     "message",
		StacktraceKey:  "stacktrace",
		LineEnding:     zapcore.DefaultLineEnding,
		EncodeLevel:    zapcore.CapitalLevelEncoder,    // Capitalize the log level names
		EncodeTime:     zapcore.ISO8601TimeEncoder,     // ISO8601 UTC timestamp format
		EncodeDuration: zapcore.SecondsDurationEncoder, // Duration in seconds
		EncodeCaller:   zapcore.ShortCallerEncoder,     // Short caller (file and line)
	}

	logLevel := zap.NewAtomicLevelAt(zap.InfoLevel)
	config := zap.Config{
		Level:            logLevel,
		Development:      true,
		Encoding:         "json",
		EncoderConfig:    encoderConfig,
		OutputPaths:      []string{"stdout"},
		ErrorOutputPaths: []string{"stderr"},
	}

	logger, _ := config.Build()
	defer logger.Sync() // 
	...
}

zapcore.EncoderConfig 인스턴스를 zap.Config의 EncoderConfig부분에 넣어주고 zap.Config의 Build()로 zap.Logger를 만들어주면 된다.

이전 예제에서는 zapcore.NewCore를 사용했는데, 어차피 zap.Config의 Build부분에서 zapcore.NewCore를 사용하므로 사실상 같은 로직의 코드인 것이다.

Logging to file and console

zap에서는 file에만 log를 쓸 수도 있고, console에만 log를 쓸 수도 있으며 file, console 둘 다 쓸 수도 있다.

먼저 file에 log를 기록하기 위해서는 먼저 file을 하나 열어두고, zapcore.AddSync를 통해서 zapcore.writerWrapper 인스턴스를 만든다음, 이를 zapcore.NewCore에 넣어주어 만들어주면 된다.

zapcore.NewCore함수를 보면 다음과 같다.

func NewCore(enc Encoder, ws WriteSyncer, enab LevelEnabler) Core {
	return &ioCore{
		LevelEnabler: enab,
		enc:          enc,
		out:          ws,
	}
}

WriteSyncer 타입이 out에 ws로 할당되는 것을 볼 수 있다. 이를 통해 output을 지정할 곳을 WriteSyncer로 넘겨주면 된다는 것을 알 수 있다.

WriteSyncer를 만들기 위해서는 zapcore.AddSync를 사용하면되는데, 정의 부분이 다음과 같다.

func AddSync(w io.Writer) WriteSyncer {
	switch w := w.(type) {
	case WriteSyncer:
		return w
	default:
		return writerWrapper{w}
	}
}

io.Writer를 받아서 zapcore.WriteSyncer를 만족하는 writerWrapper 구조체로 변환하는 것이다. 따라서, io.Writer interface를 만족하는 file 인스턴스를 하나 만들어주어 넘겨주면, io.Writer의 Write연산을 통해 log를 file인스턴스에 작성하는 것이다.

package main

import (
	"os"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	filename := "logs.log"
	logger := fileLogger(filename)

	logger.Info("INFO log level message")
	logger.Warn("Warn log level message")
	logger.Error("Error log level message")

}

func fileLogger(filename string) *zap.Logger {
	config := zap.NewProductionEncoderConfig()
	config.EncodeTime = zapcore.ISO8601TimeEncoder
	fileEncoder := zapcore.NewJSONEncoder(config)
	logFile, _ := os.OpenFile(filename, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
	writer := zapcore.AddSync(logFile)
	defaultLogLevel := zapcore.DebugLevel
	core := zapcore.NewTee(
		zapcore.NewCore(fileEncoder, writer, defaultLogLevel),
	)

	logger := zap.New(core, zap.AddCaller(), zap.AddStacktrace(zapcore.ErrorLevel))

	return logger
}

logs.log라는 logging file을 하나만들고 file pointer를 zapcore.AddSync에 넣어 zapcore.WriteSyncer interface를 만족하는 zapcore.writerWrapper로 만든다. 그리고 이 writer를 zapcore.NewCore에 넣어서 zapcore.Core를 만드는 것이다. 참고로 zapcore.NewTee는 여러 zapcore.Core를 엮어서 하나의 zapcore.Core처럼 쓸 수 있도록 만드는 것이다.

zap.New에 zapcore.NewTee로 엮어낸 zapcore.Core 인스턴스인 core와 여러 옵션들을 주면 logger를 만들어낼 수 있다.

이제 코드를 실행해보면 logs.log가 나올 것이고 다음의 logging이 적혀있을 것이다.

{"level":"info","ts":"2024-01-02T18:53:41.874+0900","caller":"ticker_test/main.go:14","msg":"INFO log level message"}
{"level":"warn","ts":"2024-01-02T18:53:41.874+0900","caller":"ticker_test/main.go:15","msg":"Warn log level message"}
{"level":"error","ts":"2024-01-02T18:53:41.874+0900","caller":"ticker_test/main.go:16","msg":"Error log level message","stacktrace":"main.main\n\t/p4ws/golang/ticker_test/main.go:16\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}

zapcore.NewTee는 여러 zapcore.Core를 엮어낸다는 특징이 있다. 그렇다면 하나는 file을 io.Writer로 하는 zapcore.Core를 만들고, 하나는 console을 io.Writer로 하는 zapcore.Core를 만들어 zapcore.NewTee로 엮어낼 수 있다. 이를 통해 file logging과 console logging 둘 다 제공하는 것이 가능한 것이다.

더불어 io.Writer 인터페이스를 구현한 모든 인스턴스에 대해서 logging이 가능하다.

package main

import (
	"fmt"
	"os"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	filename := "logs.log"
	logger, err := fileLogger(filename)
	if err != nil {
		fmt.Printf("Failed to initialize logger: %v\n", err)
		return
	}
	defer logger.Sync() // Ensure logs are flushed

	logger.Info("INFO log level message")
	logger.Warn("Warn log level message")
	logger.Error("Error log level message")
}

// fileLogger initializes a zap.Logger that writes to both the console and a specified file.
func fileLogger(filename string) (*zap.Logger, error) {
	// Configure the time format
	config := zap.NewProductionEncoderConfig()
	config.EncodeTime = zapcore.ISO8601TimeEncoder

	// Create file and console encoders
	fileEncoder := zapcore.NewJSONEncoder(config)
	consoleEncoder := zapcore.NewConsoleEncoder(config)

	// Open the log file
	logFile, err := os.OpenFile(filename, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
	if err != nil {
		return nil, fmt.Errorf("failed to open log file: %v", err)
	}

	// Create writers for file and console
	fileWriter := zapcore.AddSync(logFile)
	consoleWriter := zapcore.AddSync(os.Stdout)

	// Set the log level
	defaultLogLevel := zapcore.DebugLevel

	// Create cores for writing to the file and console
	fileCore := zapcore.NewCore(fileEncoder, fileWriter, defaultLogLevel)
	consoleCore := zapcore.NewCore(consoleEncoder, consoleWriter, defaultLogLevel)

	// Combine cores
	core := zapcore.NewTee(fileCore, consoleCore)

	// Create the logger with additional context information (caller, stack trace)
	logger := zap.New(core, zap.AddCaller(), zap.AddStacktrace(zapcore.ErrorLevel))

	return logger, nil
}

코드가 길어서 어려워 보이지만, logFile과 os.Stdout을 io.Writer로하는 두 zapcore.Core를 만들고 zapcore.NewTee로 이들을 엮어낸 것이 전부이다.

실행해보면 console로도 log가 찍히고, 파일에도 log가 기록될 것이다.

2024-01-02T19:19:06.100+0900    info    ticker_test/main.go:20  INFO log level message
2024-01-02T19:19:06.100+0900    warn    ticker_test/main.go:21  Warn log level message
2024-01-02T19:19:06.100+0900    error   ticker_test/main.go:22  Error log level message
main.main
        /p4ws/golang/ticker_test/main.go:22
runtime.main
        /usr/local/go/src/runtime/proc.go:250

console의 경우 인간이 읽기 쉬운 console log가 만들어진다는 것을 알 수 있다.

반면에 file log의 경우는 json encoder를 사용하였으므로 다음과 같다.

{"level":"info","ts":"2024-01-02T19:19:06.100+0900","caller":"ticker_test/main.go:20","msg":"INFO log level message"}
{"level":"warn","ts":"2024-01-02T19:19:06.100+0900","caller":"ticker_test/main.go:21","msg":"Warn log level message"}
{"level":"error","ts":"2024-01-02T19:19:06.100+0900","caller":"ticker_test/main.go:22","msg":"Error log level message","stacktrace":"main.main\n\t/p4ws/golang/ticker_test/main.go:22\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}

log retention and rotation (rolling)

실제 구동환경에서 log file이 너무 많아지면 실행 환경에 큰 문제를 야기할 수 있다. 이를 위해서 log 파일을 주기적으로 삭제하거나, 특정 용량이 넘어가면 새로 만들고 이전 log들을 백업하도록 해야한다.

zap에서는 자체적으로 이를 제공하지 않지만 lumberjack을 함께 이용하면 가능하다.

go get -u gopkg.in/natefinch/lumberjack.v2

lumberjack또한 하나의 logging library이지만 zap과 같이 사용하여 retention 기능을 제공할 수 있다.

이는 lumberjack의 lumberjack.Logger 구조체가 io.Writer를 만족하기 때문인데, zapcore.AddSync를 통해서 io.Writer interface를 만족하는 lumberjack.Logger 구조체를 입력하면 lumberjack.Logger구조체에서 logging하는 방식대로 log를 작성하기 때문이다. 때문에 file을 통해서 logging할 때는 lumberjack.Logger를 통해서 logging하는 것이 좋다.

애시당초 lumberjack github를 보면 logging보다는 plugin으로서 logger를 rolling하기위해 사용하기를 원해한다.

Lumberjack is intended to be one part of a logging infrastructure. It is not an all-in-one solution, but instead is a pluggable component at the bottom of the logging stack that simply controls the files to which logs are written.

package main

import (
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"gopkg.in/natefinch/lumberjack.v2"
)

func main() {
	// Set up lumberjack as a logger:
	logger := &lumberjack.Logger{
		Filename:   "./myapp.log", // Or any other path
		MaxSize:    500,                  // MB; after this size, a new log file is created
		MaxBackups: 3,                    // Number of backups to keep
		MaxAge:     28,                   // Days
		Compress:   true,                 // Compress the backups using gzip
	}

	writeSyncer := zapcore.AddSync(logger)

	// Set up zap logger configuration:
	core := zapcore.NewCore(
		zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), // Using JSON encoder, but you can choose another
		writeSyncer,
		zapcore.InfoLevel,
	)

	loggerZap := zap.New(core)
	defer loggerZap.Sync()

	// Log messages:
	loggerZap.Info("This is a test message for our logger!")
}

lumberjack.Logger의 옵션들을 설명하면 다음과 같다.
1. MaxSize: 해당 사이즈(MB)를 넘으면 새로 log file을 만든다.
2. MaxBackups: 유지할 log file갯수를 지정한다.
3. MaxAge: log file을 몇일동안 유지할 것인지 지정한다. 일정이 지나면 삭제한다.
4. Compress: true이면 gzip을 통해서 log파일을 압축하여 저장한다.

lumberjack.Logger에 원하는 옵션들과 file 경로를 적어주면 해당 file에 log를 적어준다. zapcore.AddSync를 통해서 lumberjack.Logger를 넣어주면 lumberjack.Logger가 io.Writer를 만족하므로 zapcore.WriteSyncer 인터페이스를 만족하는 zapcore.writerWrapper로 wrapping해준다.

lumberjack.Logger를 wrapping하고 있는 zapcore.writerWrapper를 NewCore에 넘겨주면 된다.

이것이 가능한 이유는 log를 쓰는 부분과 log를 어떻게 encoding하고 쓸 지에 대한 configuration인 zapcore.EncoderConfig를 분리하였기 때문이다.

이를 실행해보면 다음의 결과가 나올 것이다.

./myapp.log

{"level":"info","ts":1704191967.7121196,"msg":"This is a test message for our logger!"}

놀고 싶은데, 왜 다들 공부하는거야

R3의 망령