[GNPS] 챕터 13 로깅 & 메트릭s

GNPS (Go Network Programming School)의 내용을 정리한 글입니다.
Go 언어를 활용한 네트워크 프로그래밍 - 책으로 스터디를 진행합니다.

---

---

애플리케이션 모니터링은 안정적인 기능 제공에 필수적이다. 필요한 정보를 로깅하고 필요시 대처할 수 있는 이벤트들에 대한 자세한 정보를 파악할 수 있다. 이를 통해 어느 지점에 병목 현상이 생겼는지 파악할 수 있다.

Logging

로깅은 어렵다. 애플리케이션의 문제를 해결하는데 필요한 정보를 얻기 위한 최소한의 로깅을 할 수 있도록 하는 것은 어려운 일이다. 로깅은 애플리케이션이 사용할 수 있는 CPU와 I/O 시간을 소모한다. 개발하면서 남긴 과한 로깅은 실제 운영 환경에서 엄청난 지연 시간을 더하며 병목 현상이 생길 수 있다.

Go에서는 log 패키지를 사용하여 Logger 인스턴스를 사용할 수 있다. log.New 함수는 매개변수로 io.Writer와 각 로그에 사용할 접두사 그리고 로거의 출력 포맷을 설정하는 플래그를 받는다.

기본 로거는 출력을 표준 에러인 os.Stderr로 쓴다. 이를 표준 출력인 os.Stdout으로 바꿔서 로거를 사용할 수 있다.

func Log() {
	l := log.New(os.Stdout, "example: ", log.Lshortfile)
	l.Print("logging to standard output")
}

기본 로거의 플래그는 log.Ldate와 log.Ltime이며, log.Lshortfile은 log_test.go:12와 같이 파일명과 해당 로그의 라인 넘버를 출력한다.

log.New 함수의 첫 번째 매개변수는 io.Writer 인터페이스 타입이기 때문에 io.MultiWriter 함수를 사용해서 여러 writer로 사용할 수 있다. 다만, 순차적으로 여러 writer에 작성하기 때문에 한 번이라도 에러가 발생하는 경우 Write 함수 호출이 종료되는 문제가 있을 수 있다. 이런 문제를 해결할 수 있는 코드는 다음과 같다.

go get go.uber.org/multierr

여러 에러를 한번에 다루기 위한 go.uber.org/multierr 모듈을 설치한다.

package observe

import (
	"io"

	"go.uber.org/multierr"
)

type sustainedMultiWriter struct {
	writers []io.Writer
}

func (s *sustainedMultiWriter) Write(p []byte) (n int, err error) {
	for _, w := range s.writers {
		i, wErr := w.Write(p)
		n += i
		err = multierr.Append(err, wErr)
	}
	return n, err
}

func SustainedMultiWriter(writers ...io.Writer) io.Writer {
	mw := &sustainedMultiWriter{writers: make([]io.Writer, 0, len(writers))}

	for _, w := range writers {
		if m, ok := w.(*sustainedMultiWriter); ok {
			mw.writers = append(mw.writers, m.writers...)
			continue
		}
		mw.writers = append(mw.writers, w)
	}
	return mw
}

 

위에서 작성한 sustainedMultiWriter를 사용하여 한 번의 로깅으로 여러 writer에 작성하는 로그를 확인해 보자.

package observe

import (
	"bytes"
	"fmt"
	"log"
	"os"
)

func Example_logMultiWriter() {
	logFile := new(bytes.Buffer)
	w := SustainedMultiWriter(os.Stdout, logFile)

	l := log.New(w, "example: ", log.Lshortfile|log.Lmsgprefix)

	fmt.Println("standard output:")
	l.Print("Canada is south of Detroit")

	fmt.Print("\nlog file contents:\n", logFile.String())

	// Output:
	// standard output:
	// log_test.go:17: example: Canada is south of Detroit
	//
	// log file contents:
	// log_test.go:17: example: Canada is south of Detroit
}

 

로그 레벨 설정하기

로그가 너무 많아지면 비효율적이다. 필요한 필수 정보가 아니면 운영 환경에서는 병목 포인트가 될 수 있다. 로그 레벨을 사용하면 우선순위에 따라 로그를 선택적으로 활성화할 수 있다.

Go의 대부분 패키지에서는 여러 로그 레벨을 지원한다. log 패키지는 로그 레벨에 대한 기본적인 지원은 하지 않지만, 필요에 따라 로그 레벨별로 로거를 생성하여 관리할 수 있다.

func Example_logLevels() {
	lDebug := log.New(os.Stdout, "DEBUG: ", log.Lshortfile)
	logFile := new(bytes.Buffer)
	w := SustainedMultiWriter(logFile, lDebug.Writer())
	lError := log.New(w, "ERROR: ", log.Lshortfile)

	fmt.Println("standard output:")
	lError.Print("cannot communicate with the database")
	lDebug.Print("you cannot hum while holding your nose")

	fmt.Print("\nlog file contents:\n", logFile.String())

	// Output:
	// standard output:
	// ERROR: log_test.go:36: cannot communicate with the database
	// DEBUG: log_test.go:37: you cannot hum while holding your nose
	//
	// log file contents:
	// ERROR: log_test.go:36: cannot communicate with the database
}

MultiWriter를 사용하는 에러 로거의 경우 os.Stdout과 log 파일 역할을 흉내 낼 bytes.Buffer에 로그를 쓴다.

Go에서 지원하는 기본 로거인 log 패키지의 Logger는 충분히 강력한 로그 기능을 지원한다. 기본 패키지를 사용하여 여러 레벨의 로깅을 처리할 수도 있으며, 로그 레벨을 내장 지원하는 로거 패키지를 사용할 수도 있다.

 

구조화된 로깅

로깅은 원하는 정보를 빠르게 찾을 수 있을 때 유용하다. 그런 점에서 앞서 남긴 로깅은 구조와 형식이 일관적이지 않다. 필요한 정보를 찾기가 어려워진다.

일반적으로는 로그에 형식을 지정하고 메타 데이터를 추가하는 방식을 사용한다. 이런 종류의 로깅을 structured logging 즉 구조화된 로깅이라고 부른다. 대부분의 구조화된 로그를 지원하는 로거들은 로그 파일에 쓰거나 로그 서버로 전송하기 전에 로그 엔트리를 JSON으로 인코딩한다. JSON으로 인코딩 된 데이터는 로그 서버에서 인덱싱 되고 필요한 로그를 쉽게 조회할 수 있다.

Go의 1.21 버전부터 표준 라이브러리에 정식으로 포함된 구조화된 로깅 패키지인 log/slog가 있지만 이번에는 고성능에 메모리 할당도 최소화하여 성능적 이슈를 최소화한 Zap에 대해 알아본다. 메모리 할당은 적으면서 고성능의 퍼포먼스를 내는 Zap은 설정에 따라 로그 파일 로테이션 기능이 통합되어 있다.

로그 파일 로테이션이란 현재 로그 파일이 특정 시간 이상 존재하거나 특정 사이즈보다 커지는 경우 현재 로그 파일을 닫고 파일의 이름을 변경한 후 새로운 파일을 여는 일련의 프로세스를 의미한다. 이를 사용하면 디스크 공간을 효율적으로 사용할 수 있고 작은 사이즈의 로그 파일에서 내용을 찾는 것이 하나의 큰 로그 파일에서 찾는 것보다 빠르고 효율적이다.

 

Zap 로거 사용해 보기

Zap 로거에서는 로그 엔트리의 출력에 대한 인코딩의 역할을 하는 인코더 컴포넌트가 존재한다. 인코더 구성 정보는 여러 인코더의 옵션으로 사용할 수 있기 때문에 인코더와 독립적으로 존재한다.

package observe

import (
	"os"
	"runtime"

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

var encoderCfg = zapcore.EncoderConfig{
	MessageKey:   "msg",
	NameKey:      "name",
	LevelKey:     "level",
	EncodeLevel:  zapcore.LowercaseLevelEncoder,
	CallerKey:    "caller",
	EncodeCaller: zapcore.ShortCallerEncoder,
}

func Example_zapJSON() {
	zl := zap.New(
		zapcore.NewCore(
			zapcore.NewJSONEncoder(encoderCfg),
			zapcore.Lock(os.Stdout),
			zapcore.DebugLevel,
		),
		zap.AddCaller(),
		zap.Fields(
			zap.String("version", runtime.Version()),
		),
	)

	defer func() {
		_ = zl.Sync()
	}()

	example := zl.Named("example")
	example.Debug("test debug message")
	example.Info("test info message")

	// Output:
	// {"level":"debug","name":"example","caller":"observe/zap_test.go:38","msg":"test debug message","version":"go1.25.3"}
	// {"level":"info","name":"example","caller":"observe/zap_test.go:39","msg":"test info message","version":"go1.25.3"}
}

zap.New 함수는 zap.Core 구조체와 하나 이상의 zap.Options 구조체를 받는다. AddCaller 옵션과 런타임 버전을 포함하는 버전 필드를 추가한다.

인코더 구성을 사용하는 JSON Encoder와 zapcore.Lock을 사용한 동시성 사용에도 안전한 io.Writer 그리고 로깅의 경곗값을 나타내는 zapcore.DebugLevel을 설정하였다.

로거 사용 종료 전 defer 키워드에서 Sync 메서드를 호출하여 버퍼링 된 데이터를 출력할 수 있도록 한다.

 

로그 엔트리 샘플링

CPU와 I/O의 관점에서 로그를 보자면, 로깅 때문에 애플리케이션의 병목이 생기면 안 된다. 복잡한 반복작업이나 중복된 로그 엔트리를 출력하는 경우 모든 엔트리를 로깅하지 않고 샘플링한 로그 엔트리만 로깅하도록 설정할 수 있다.

func Example_zapSampling() {
	zl := zap.New(
		zapcore.NewSamplerWithOptions(
			zapcore.NewCore(
				zapcore.NewJSONEncoder(encoderCfg),
				zapcore.Lock(os.Stdout),
				zapcore.DebugLevel,
			),
			time.Second, 1, 3,
		),
	)

	defer func() {
		_ = zl.Sync()
	}()

	for i := 0; i < 10; i++ {
		if i == 5 {
			time.Sleep(time.Second)
		}
		zl.Debug(fmt.Sprintf("%d", i))
		zl.Debug("debug message")
	}

	// Output:
	// {"level":"debug","msg":"0"}
	// {"level":"debug","msg":"debug message"}
	// {"level":"debug","msg":"1"}
	// {"level":"debug","msg":"2"}
	// {"level":"debug","msg":"3"}
	// {"level":"debug","msg":"debug message"}
	// {"level":"debug","msg":"4"}
	// {"level":"debug","msg":"5"}
	// {"level":"debug","msg":"debug message"}
	// {"level":"debug","msg":"6"}
	// {"level":"debug","msg":"7"}
	// {"level":"debug","msg":"8"}
	// {"level":"debug","msg":"debug message"}
	// {"level":"debug","msg":"9"}
}

zapcore.NewSamplerWithOptions 함수는 샘플링 간격, 초기 중복 로그 엔트리수, 그리고 n번째마다 로깅할 정수 n, 총 3개의 매개변수를 받는다. 첫 번째 로깅 엔트리 로깅 후 1초 간격 이내에 중복 발생하는 로그에 대해 3번째 로그 엔트리를 로깅한다. 예를 들어 0과 debug message를 로깅했다면 1초 안에 중복해서 발생하는 로깅 중 3번째 로깅 엔트리를 로깅한다. 1, 4, 7, 10번째에 로깅되는 debug message만 샘플링된 것을 확인할 수 있다.

 

 

동적 로그 레벨 변경

애플리케이션 로그 레벨을 동적으로 변경하는 방법은 다양하다. 그중 한 가지 방법은 세마포어 파일을 사용하여 로거의 동작을 변경하는 신호 역할을 하는 파일을 사용하는 방법이다. 세마포어란 여러 프로세스나 스레드가 공유 자원에 접근할 때 동기화를 위해 사용하는 신호체계로 원자적으로 사용 가능한 자원의 개수를 사용하여 나타내는 방식이다.

여기서는 0과 1을 나타내는 세마포어 파일로 파일이 존재하면 로거가 디버그 레벨을 출력하고 파일이 없는 경우 이전 로그 레벨로 출력하도록 한다.

zap 로거는 경쟁 상태를 유발하지 않고 동적으로 로거 레벨을 수정할 수 있도록 제공하기 때문에 경쟁 상태로 인한 데드락 등의 문제가 발생하지 않아 안정적으로 사용 가능하다.

 

func Example_zapDynamicDebugging() {
	tempDir, err := os.MkdirTemp("", "")
	if err != nil {
		log.Fatal(err)
	}
	defer func() {
		_ = os.RemoveAll(tempDir)
	}()

	debugLevelFile := filepath.Join(tempDir, "level.debug")
	atomicLevel := zap.NewAtomicLevel()

	zl := zap.New(
		zapcore.NewCore(
			zapcore.NewJSONEncoder(encoderCfg),
			zapcore.Lock(os.Stdout),
			atomicLevel,
		),
	)

	defer func() {
		_ = zl.Sync()
	}()

임시 디렉터리에 존재하는 level.debug 파일을 세마포어 파일로 사용하는 코드 샘플이다. 파일이 존재하는 경우 동적으로 로거의 레벨을 디버그 수준으로 변경한다.

 

 

	// 위에서 이어서 작성
	watcher, err := fsnotify.NewWatcher()

	if err != nil {
		log.Fatal(err)
	}

	defer func() {
		_ = watcher.Close()
	}()

	err = watcher.Add(tempDir)
	if err != nil {
		log.Fatal(err)
	}

	ready := make(chan struct{})

fsnotify 패키지를 사용해서 특정 경로의 파일의 이벤트에 대해서 watch 한다. 이를 위해 fsnotify 패키지는 다음 명령어로 설치한다.

 

go get -u github.com/fsnotify/fsnotify

 

	// 앞선 코드에 이어서 작성
	go func() {
		defer close(ready)
		originalLevel := atomicLevel.Level()

		for {
			select {
			case event, ok := <-watcher.Events:
				if !ok {
					return
				}
				if event.Name == debugLevelFile {
					switch {
					case event.Op&fsnotify.Create == fsnotify.Create:
						atomicLevel.SetLevel(zapcore.DebugLevel)
						ready <- struct{}{}
					case event.Op&fsnotify.Remove == fsnotify.Remove:
						atomicLevel.SetLevel(originalLevel)
						ready <- struct{}{}
					}
				}
			case err, ok := <-watcher.Errors:
				if !ok {
					return
				}
				zl.Error(err.Error())
			}
		}
	}()

파일 시스템을 감시하는 watcher를 생성하여 임시 디렉터리를 감시한다. 감시 중인 디렉터리의 변화를 감지하여 이벤트를 발생시킨다. 이때 세마포어 파일로 사용할 파일에 대한 이벤트만 감지하도록 조건 설정을 한다. 파일의 존재 여부에 따라서 atomic 레벨의 로그 레벨을 디버그로 바꾸거나 원래의 로그 레벨인 인포 레벨로 설정한다.

 

 

	// 앞선 코드에 이어서 작성
	zl.Debug("debug log 는 찍히지 않습니다.")
	df, err := os.Create(debugLevelFile)
	if err != nil {
		log.Fatal(err)
	}

	err = df.Close()
	if err != nil {
		log.Fatal(err)
	}
	<-ready

	zl.Debug("debug log 가 찍힙니다.")

	err = os.Remove(debugLevelFile)
	if err != nil {
		log.Fatal(err)
	}
	<-ready

	zl.Debug("debug log 는 찍히지 않습니다.")
	zl.Info("info log 가 찍힙니다.")

	// Output:
	// {"level":"debug","msg":"debug log 가 찍힙니다."}
	// {"level":"info","msg":"info log 가 찍힙니다."}

}

세마포어 파일에 따른 로그 레벨 설정을 테스트한다. 세마포어 파일이 있으면 debug 레벨로 로거의 레벨이 설정되어 로그가 출력되며, 세마포어 파일이 삭제되는 경우 원래의 로그 레벨로 로그가 출력된다.

 

---

코드 계측하기 (Code Instrumentation)

서비스의 현재 상태를 추론하기 위한 목적으로 Metrics를 수집하는 프로세스를 코드 계측이라 한다. 코드 계측은 로깅과는 반대로 간단하고 쉽기 때문에 모든 것을 계측하는 것이 좋다. 핵심적인 Metrics 정보로 서비스나 시스템이 잘못되기 전에 미리 알아차릴 수 있다.

OpenTelemetry(OTel)를 사용하여 Prometheus로 메트릭을 보내는 방식은 표준화된 계측(Instrumentation)과 유연한 백엔드 선택이라는 장점이 있다. OTel SDK가 데이터를 수집하고 OTel Prometheus Exporter가 이 데이터를 Prometheus가 이해할 수 있는 포맷으로 변환하여 /metrics 엔드포인트에 노출하는 샘플 코드를 작성한다.

필요한 패키지들을 설치한다.

# OTel 코어 및 SDK
go get go.opentelemetry.io/otel
go get go.opentelemetry.io/otel/sdk
go get go.opentelemetry.io/otel/metric

# Prometheus Exporter
go get go.opentelemetry.io/otel/exporters/prometheus

# Prometheus HTTP 핸들러 (엔드포인트 서빙용)
go get github.com/prometheus/client_golang/prometheus/promhttp

 

package main

import (
	"context"
	"io"
	"net/http"
	"net/http/httptest"
	"strings"
	"testing"

	"github.com/prometheus/client_golang/prometheus/promhttp"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/exporters/prometheus"
	"go.opentelemetry.io/otel/metric"
	sdkmetric "go.opentelemetry.io/otel/sdk/metric"
)

func setupTestHandler(t *testing.T) http.Handler {
	ctx := context.Background()

	exporter, err := prometheus.New()
	if err != nil {
		t.Fatalf("failed to create exporter: %v", err)
	}

	provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(exporter))
	meter := provider.Meter("hippo-an")

	counter, _ := meter.Int64Counter("demo_api_requests_total")
	histogram, _ := meter.Float64Histogram("demo_api_duration_seconds")

	mux := http.NewServeMux()

	mux.HandleFunc("/hello", func(w http.ResponseWriter, r *http.Request) {
		w.Write([]byte("Hello, OpenTelemetry!"))

		attrs := metric.WithAttributes(
			attribute.String("method", r.Method),
			attribute.String("route", "/hello"),
		)
		counter.Add(ctx, 1, attrs)
		histogram.Record(ctx, 0.05, attrs)
	})

	mux.Handle("/metrics", promhttp.Handler())

	return mux
}

프로그램이 시작되면 먼저 Prometheus 익스포터를 생성한다. 이 익스포터는 OpenTelemetry에서 수집한 메트릭 데이터를 Prometheus가 읽을 수 있는 형식으로 변환해 주는 역할을 한다. 해당 익스포터를 사용하는 MeterProvider를 만들고, 이를 통해 "hippo-an"이라는 이름의 미터를 생성한다.

MeterProvider는 OpenTelemetry에서 메트릭 수집 시스템을 관리하는 중앙 객체이다. 애플리케이션 전체의 메트릭 수집 설정을 담당하며, Meter라는 측정 도구를 생성하는 팩토리 역할을 한다. MeterProvider를 생성할 때 어떤 익스포터를 사용할지, 메트릭을 어떻게 처리하고 어디로 내보낼지 등의 설정을 지정하면, 이후 이 Provider에서 만들어진 모든 Meter와 메트릭 측정 도구들이 해당 설정을 따르게 된다.

생성된 미터를 사용해서 두 가지 측정 도구를 만든다. 첫 번째는 "demo_api_requests_total"이라는 이름의 카운터로, API 요청이 총 몇 번 들어왔는지 세는 용도의 메트릭이고, 두 번째는 "demo_api_duration_seconds"라는 히스토그램으로, 각 API 요청이 처리되는 데 걸린 시간을 초 단위로 기록한다.

서버는 두 개의 HTTP 엔드포인트를 제공한다. 첫 번째는 "/hello" 경로인데, 이 엔드포인트에 요청이 들어오면 "Hello, OpenTelemetry!"라는 메시지를 응답으로 보낸다. 응답을 보낸 후에 카운터를 1 증가시키고 처리 시간을 히스토그램에 기록한다. 이 메트릭들에는 HTTP 메서드와 라우트 정보가 속성으로 함께 저장된다.

두 번째 엔드포인트인 "/metrics"는 Prometheus가 메트릭을 수집해갈 수 있는 경로이다. Prometheus 서버가 이 경로에 주기적으로 접속하면 지금까지 수집된 모든 메트릭 데이터를 Prometheus 형식으로 제공받을 수 있다.

 

// 위 코드에 이어서 작성


func TestMetricsEndpoint(t *testing.T) {
	handler := setupTestHandler(t)

	req := httptest.NewRequest("GET", "/hello", nil)
	w := httptest.NewRecorder()
	handler.ServeHTTP(w, req)

	req = httptest.NewRequest("GET", "/metrics", nil)
	w = httptest.NewRecorder()
	handler.ServeHTTP(w, req)

	if w.Code != http.StatusOK {
		t.Errorf("expected status 200, got %d", w.Code)
	}

	body, _ := io.ReadAll(w.Body)
	metricsOutput := string(body)

	if !strings.Contains(metricsOutput, "demo_api_requests_total") {
		t.Error("metrics should contain demo_api_requests_total")
	}

	if !strings.Contains(metricsOutput, "demo_api_duration_seconds") {
		t.Error("metrics should contain demo_api_duration_seconds")
	}

	lines := strings.Split(metricsOutput, "\n")
	for _, line := range lines {
		if strings.HasPrefix(line, "demo_api_requests_total") && strings.Contains(line, `method="GET"`) {
			t.Logf("%s\n", line)
		}
		if strings.HasPrefix(line, "demo_api_duration_seconds") && strings.Contains(line, `method="GET"`) {
			t.Logf("%s\n", line)
		}
	}
}

해당 테스트 코드는 /hello 엔드포인트로 요청을 보낸 후 /metrics 엔드포인트에 요청을 보내 수집된 메트릭을 가져온다. 커스텀으로 작성한 메트릭의 값이 포함되어 있는지 확인하고 히스토그램과 카운터 메트릭을 확인할 수 있다.