Devin.KR
통합 검색 Ctrl K

운영 준비 - 구조화 로그와 설정

개발자KR 조회 0

이 장에서 배우는 것

앞 장까지 만든 중계 서비스는 주문을 받고 JSON 으로 답한다. 기능은 동작하지만 운영 환경에 올리면 부족한 점이 나온다. 장애가 났을 때 어떤 요청에서 무슨 일이 있었는지 로그로 추적하기 어렵다. 주소나 로그 수준을 바꾸려면 코드를 고쳐 다시 빌드해야 한다. 지금 떠 있는 바이너리가 어느 버전인지도 알 수 없다. 로드 밸런서나 오케스트레이터가 서버 상태를 물어볼 길도 없다. 이 장은 표준 라이브러리만으로 이 네 가지를 해결한다.

  • log/slog 의 핸들러(handler)·속성(attribute)·레벨(level)을 구분하고, 텍스트와 JSON 로그를 같은 코드로 낼 수 있다.
  • 요청 ID 를 context 에 실어 두고, 로그를 남길 때마다 자동으로 붙도록 핸들러를 감쌀 수 있다.
  • 기본값, 환경 변수, 플래그의 우선순위를 정해 설정을 읽고 잘못된 값을 시작 시점에 거부할 수 있다.
  • debug.ReadBuildInfo 로 바이너리의 빌드 정보를 읽어 헬스 체크 응답에 넣을 수 있다.
  • 살아 있는지 묻는 검사와 요청을 받을 준비가 됐는지 묻는 검사를 나누어 구현할 수 있다.

문제 상황

저녁 피크 시간에 한 가게에서 "주문이 들어갔는데 배달원 배정이 안 된다"는 문의가 온다. 서버 로그에는 주문 조회, 배정 실패 같은 줄이 초당 수십 개 섞여 있다. 어느 줄이 그 가게의 그 요청에 속하는지 가려낼 방법이 없다. 줄마다 fmt.Printf 로 찍은 형식이 달라서 검색 도구로 걸러내기도 어렵다.

배포 쪽에서도 문제가 있다. 테스트 서버는 디버그 로그가 필요하고 운영 서버는 정보 수준이면 충분하다. 그런데 이 차이를 코드 상수로 박아 두었다. 배포 직후에는 새 버전이 올라갔는지 확인하려고 바이너리를 직접 실행해 본다. 로드 밸런서는 서버가 아직 시작 중인데도 트래픽을 보낸다.

모두 서비스 기능이 아니라 운영 준비의 문제다. 한 번 갖춰 두면 이후 어떤 기능을 붙여도 그대로 쓴다.

구조화 로그: log/slog

구조화 로그(structured logging)는 로그 한 줄을 문장이 아니라 키와 값의 모음으로 남기는 방식이다. 검색 도구는 문장을 파싱하는 대신 status=404 같은 키로 바로 걸러낸다. Go 는 이 기능을 log/slog 패키지로 표준 라이브러리에 담고 있다. 세부 사항은 log/slog 문서에서 확인할 수 있다.

로거, 핸들러, 속성, 레벨

slog 는 역할이 네 가지로 나뉜다. 호출하는 쪽은 *slog.Logger 를 쓰고, 실제로 줄을 만들어 내보내는 쪽은 slog.Handler 다. 로거는 메시지와 속성을 모아 레코드(slog.Record)를 만들고 핸들러에 넘긴다. 이 분리 덕분에 호출 코드를 바꾸지 않고 출력 형식만 바꿀 수 있다.

slog 를 이루는 요소와 역할
요소대표 이름역할바꾸는 때
로거slog.LoggerInfo, Warn 같은 호출을 받는다컴포넌트마다 With 로 파생한다
핸들러TextHandler, JSONHandler레코드를 줄로 만들어 쓴다설정의 로그 형식을 따른다
속성slog.String, slog.Group키와 값 한 쌍 또는 묶음이다호출마다 다르다
레벨Debug, Info, Warn, Error출력할 줄을 거른다설정의 로그 수준을 따른다

속성은 logger.Info("주문 조회", "order_id", 1001) 처럼 키와 값을 번갈아 넘겨도 되고, slog.Int 같은 생성 함수로 넘겨도 된다. 앞의 방식은 짧고 뒤의 방식은 타입이 고정된다. 키와 값의 짝이 어긋나면 !BADKEY 라는 키로 출력되므로 go vet 이 이 호출을 검사한다.

관련된 속성은 slog.Group 으로 묶는다. 텍스트 핸들러는 order.id=1001 처럼 점으로 이어 쓰고, JSON 핸들러는 "order":{"id":"1001"} 처럼 중첩 객체로 쓴다.

레벨은 실행 중에 바꿀 수 있다

핸들러 옵션의 Level 에는 고정값 대신 *slog.LevelVar 를 줄 수 있다. 이 값은 동시 접근에 안전해서, 서비스를 재시작하지 않고 디버그 로그를 켰다 끌 수 있다. 이 장의 예제는 시작할 때 설정에서 읽은 수준을 넣고, 중간에 한 번 Debug 로 바꿨다가 되돌린다. 실제 서비스라면 관리용 엔드포인트나 신호로 이 값을 바꾸게 된다.

값을 로그에 맞게 바꾸기: LogValuer

고객 전화번호를 로그에 그대로 남기면 안 된다. 호출하는 곳마다 마스킹 함수를 부르면 하나만 빠져도 새어 나간다. 대신 타입 자체가 로그에 어떻게 보일지 정하게 한다. LogValue() slog.Value 메서드를 가진 타입은 핸들러가 값을 쓰기 직전에 이 메서드를 호출한다. 전화번호 타입에 이 메서드를 달아 두면 어디서 로그에 넘기든 마스킹된 값만 나간다.

요청 ID 를 로그에 싣기

한 요청에서 나온 로그 줄을 묶으려면 모든 줄에 같은 요청 ID 가 있어야 한다. 줄마다 "request_id", id 를 직접 쓰는 방식은 함수 깊숙이 ID 를 계속 넘겨야 하고, 한 번 빠뜨리면 추적이 끊긴다. 이미 모든 요청 처리 경로에는 context.Context 가 흐르므로 ID 를 거기에 싣는다. 로깅 쪽에서는 InfoContext 처럼 ctx 를 받는 메서드를 쓰고, 핸들러가 ctx 에서 ID 를 꺼내 속성으로 붙인다.

요청 ID 는 미들웨어가 ctx 에 넣고 핸들러가 로그 줄에 붙이므로 호출 코드는 ID 를 다루지 않는다.

구현은 세 부분이다. 첫째, 미들웨어가 요청 헤더 X-Request-ID 를 읽고 없으면 새로 만든다. 헤더 값은 바깥에서 오는 입력이므로 길이를 제한하고, 조건에 맞지 않으면 새로 발급한다. 둘째, ID 를 context.WithValue 로 요청 ctx 에 넣고 응답 헤더에도 같은 값을 돌려준다. 클라이언트가 문의할 때 이 값을 알려 주면 서버 로그에서 바로 찾을 수 있다. 셋째, 기존 핸들러를 감싸는 ctxHandler 가 Handle 에서 ctx 를 보고 request_id 속성을 레코드에 더한다.

핸들러를 감쌀 때는 WithAttrs 와 WithGroup 도 감싸서 돌려줘야 한다. 이 두 메서드는 새 핸들러를 반환하므로, 안쪽 핸들러를 그대로 반환하면 logger.With(...) 를 거치는 순간 우리 래퍼가 사라지고 요청 ID 가 빠진다. 구조체에 slog.Handler 를 임베딩하면 Enabled 는 그대로 위임되고, 위 두 메서드만 다시 정의하면 된다.

접근 로그(access log)도 같은 미들웨어 체인에서 남긴다. 응답 상태 코드를 알아야 하므로 http.ResponseWriter 를 감싸 WriteHeader 에 넘어온 값을 기억한다. 이 장의 예제는 처리 시간을 로그에 넣지 않는다. 실서비스에서는 처리 시간을 남기는 편이 좋지만, 값이 실행마다 달라지므로 출력을 고정해야 하는 예제에서는 뺐다. 상태 코드에 따라 4xx 는 Warn, 5xx 는 Error 로 남기고, 로드 밸런서가 몇 초마다 부르는 헬스 체크는 Debug 로 낮춘다. 이렇게 하지 않으면 로그 대부분이 헬스 체크로 채워진다.

설정: 환경 변수와 플래그

설정은 세 단계로 정한다. 코드에 둔 기본값이 가장 낮고, 환경 변수가 그 위, 명령줄 플래그가 가장 위다. 컨테이너 배포는 환경 변수로 값을 주는 일이 많고, 사람이 로컬에서 실행할 때는 플래그로 잠깐 덮어쓰는 일이 많다. 둘을 모두 받으면 두 상황을 한 바이너리가 처리한다.

설정은 기본값, 환경 변수, 플래그 순으로 덮어써서 가장 나중 단계의 값이 최종값이 된다.

구현 요령은 간단하다. 기본값에 환경 변수를 먼저 적용하고, 그 결과를 flag 의 기본값으로 등록한 뒤 파싱한다. 플래그가 주어지면 환경 변수 값을 덮어쓰고, 주어지지 않으면 환경 변수 값이 남는다. 순서를 반대로 해서 파싱 뒤에 환경 변수를 적용하면 플래그가 무시된다.

설정 입력 방식의 비교
방식주로 쓰는 곳장점주의할 점
코드 기본값모든 환경설정이 없어도 시작한다운영 값을 박아 두지 않는다
환경 변수컨테이너, 배포 환경이미지를 바꾸지 않고 값을 준다빈 문자열과 미설정을 구분한다
플래그로컬 실행, 일회성 덮어쓰기--help 로 목록이 나온다비밀 값은 프로세스 목록에 보인다

값은 읽는 즉시 검증한다. 로그 수준 문자열은 slog.Level 의 UnmarshalText 로 해석하고, 로그 형식은 두 값 중 하나인지 확인한다. 잘못된 값이 들어오면 서버를 띄우기 전에 오류로 끝내야 한다. 운영 중에 처음 그 값을 쓰는 순간 실패하는 것보다 훨씬 낫다. 테스트하기 쉽게 os.Args 와 os.Getenv 를 함수 안에서 직접 부르지 않고, 인자 목록과 조회 함수를 매개변수로 받는다.

빌드 정보와 헬스 체크

빌드 정보

Go 로 빌드한 바이너리에는 모듈 정보가 들어 있다. runtime/debug.ReadBuildInfo 는 이 정보를 읽어 *debug.BuildInfo 로 돌려준다. 주 모듈의 버전은 info.Main.Version 이고, info.Settings 에는 vcs.revision, vcs.modified 같은 키가 들어 있다. 버전 관리 저장소 안에서 go build 로 빌드하면 커밋 해시와 수정 여부가 기록된다. 저장소 밖에서 빌드하거나 go run 으로 실행하면 버전이 비어 있거나 (devel) 로 나온다. 이 장은 이런 값을 devel 하나로 정리한다. 커밋 해시는 다음과 같이 꺼낸다.

for _, s := range info.Settings {
	if s.Key == "vcs.revision" {
		revision = s.Value
	}
}

릴리스 번호를 직접 정하고 싶으면 go build -ldflags "-X main.version=1.4.0" 로 패키지 변수에 값을 주입하는 방법도 있다. 어느 쪽이든 그 값을 시작 로그와 헬스 체크 응답에 넣어 두면 "지금 떠 있는 것이 어느 빌드인가"에 바로 답할 수 있다. 자세한 필드는 debug.BuildInfo 문서에 있다.

살아 있음과 준비됨은 다르다

헬스 체크 엔드포인트는 보통 둘로 나눈다. /healthz 는 프로세스가 살아 있는지 묻는다. 응답이 없으면 오케스트레이터가 프로세스를 재시작한다. /readyz 는 지금 요청을 받을 준비가 됐는지 묻는다. 시작 중이거나 종료 중이면 503 으로 답해서 로드 밸런서가 트래픽을 잠시 빼게 한다. 두 검사를 하나로 합치면, 외부 의존성이 잠깐 흔들릴 때 멀쩡한 프로세스까지 재시작되는 문제가 생긴다.

두 헬스 체크 엔드포인트의 차이
엔드포인트묻는 것실패 시 조치검사 내용
/healthz프로세스가 살아 있는가재시작응답만 하면 통과한다
/readyz요청을 받을 준비가 됐는가트래픽에서 제외준비 플래그, 필요하면 의존성

준비 상태는 atomic.Bool 로 둔다. 초기값은 false 이고, 시작 작업이 끝나면 true 로 바꾼다. 여러 고루틴이 동시에 읽어도 안전하다.

완성 코드

아래 파일 하나가 설정 읽기, 로거 구성, 요청 ID, 접근 로그, 헬스 체크, 빌드 정보를 모두 담는다. 포트는 열지 않고 httptest 로 핸들러에 요청을 직접 보낸다.

package main

import (
	"context"
	"encoding/json"
	"errors"
	"flag"
	"fmt"
	"io"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"os"
	"runtime/debug"
	"strings"
	"sync/atomic"
)

type config struct {
	Addr      string
	LogLevel  slog.Level
	LogFormat string
}

func loadConfig(args []string, getenv func(string) string) (config, error) {
	addr, levelText, format := ":8080", "info", "text"
	if v := getenv("RELAY_ADDR"); v != "" {
		addr = v
	}
	if v := getenv("RELAY_LOG_LEVEL"); v != "" {
		levelText = v
	}
	if v := getenv("RELAY_LOG_FORMAT"); v != "" {
		format = v
	}

	fs := flag.NewFlagSet("relay", flag.ContinueOnError)
	fs.SetOutput(io.Discard)
	fs.StringVar(&addr, "addr", addr, "수신 주소")
	fs.StringVar(&levelText, "log-level", levelText, "로그 수준")
	fs.StringVar(&format, "log-format", format, "text 또는 json")
	if err := fs.Parse(args); err != nil {
		return config{}, err
	}

	var level slog.Level
	if err := level.UnmarshalText([]byte(levelText)); err != nil {
		return config{}, fmt.Errorf("로그 수준 %q 를 해석할 수 없다", levelText)
	}
	if format != "text" && format != "json" {
		return config{}, fmt.Errorf("로그 형식 %q 는 text 또는 json 이어야 한다", format)
	}
	return config{Addr: addr, LogLevel: level, LogFormat: format}, nil
}

type requestIDKey struct{}

type ctxHandler struct {
	slog.Handler
}

func (h ctxHandler) Handle(ctx context.Context, r slog.Record) error {
	if id, ok := ctx.Value(requestIDKey{}).(string); ok {
		r.AddAttrs(slog.String("request_id", id))
	}
	return h.Handler.Handle(ctx, r)
}

func (h ctxHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return ctxHandler{h.Handler.WithAttrs(attrs)}
}

func (h ctxHandler) WithGroup(name string) slog.Handler {
	return ctxHandler{h.Handler.WithGroup(name)}
}

// 예제 출력을 고정하려고 시각 속성을 뺀다. 실서비스에서는 빼지 않는다.
func dropTime(groups []string, a slog.Attr) slog.Attr {
	if len(groups) == 0 && a.Key == slog.TimeKey {
		return slog.Attr{}
	}
	return a
}

func newLogger(w io.Writer, format string, lvl slog.Leveler) *slog.Logger {
	opts := &slog.HandlerOptions{Level: lvl, ReplaceAttr: dropTime}
	var h slog.Handler
	if format == "json" {
		h = slog.NewJSONHandler(w, opts)
	} else {
		h = slog.NewTextHandler(w, opts)
	}
	return slog.New(ctxHandler{h})
}

type buildInfo struct {
	Version string
}

func readBuild() buildInfo {
	info, ok := debug.ReadBuildInfo()
	if !ok {
		return buildInfo{Version: "unknown"}
	}
	v := info.Main.Version
	if v == "" || v == "(devel)" {
		v = "devel"
	}
	return buildInfo{Version: v}
}

type phone string

func (p phone) LogValue() slog.Value {
	s := string(p)
	if len(s) < 8 {
		return slog.StringValue("****")
	}
	return slog.StringValue(s[:4] + "****" + s[len(s)-5:])
}

type order struct {
	Shop  string
	Phone phone
}

func sampleOrders() map[string]order {
	return map[string]order{
		"1001": {Shop: "한강분식", Phone: "010-1234-5678"},
		"1002": {Shop: "골목치킨", Phone: "010-9876-5432"},
	}
}

type server struct {
	logger *slog.Logger
	build  buildInfo
	orders map[string]order
	ready  atomic.Bool
	seq    atomic.Int64
}

func (s *server) routes() http.Handler {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /healthz", s.healthz)
	mux.HandleFunc("GET /readyz", s.readyz)
	mux.HandleFunc("GET /orders/{id}", s.getOrder)
	return s.withRequestID(s.accessLog(mux))
}

func writeJSON(w http.ResponseWriter, code int, v any) {
	w.Header().Set("Content-Type", "application/json; charset=utf-8")
	w.WriteHeader(code)
	_ = json.NewEncoder(w).Encode(v)
}

func (s *server) healthz(w http.ResponseWriter, r *http.Request) {
	writeJSON(w, http.StatusOK, map[string]string{"status": "ok", "version": s.build.Version})
}

func (s *server) readyz(w http.ResponseWriter, r *http.Request) {
	if !s.ready.Load() {
		writeJSON(w, http.StatusServiceUnavailable, map[string]string{"status": "starting"})
		return
	}
	writeJSON(w, http.StatusOK, map[string]string{"status": "ready"})
}

func (s *server) getOrder(w http.ResponseWriter, r *http.Request) {
	id := r.PathValue("id")
	o, ok := s.orders[id]
	if !ok {
		s.logger.WarnContext(r.Context(), "주문 없음", "order_id", id)
		writeJSON(w, http.StatusNotFound, map[string]string{"error": "주문 없음"})
		return
	}
	s.logger.InfoContext(r.Context(), "주문 조회",
		slog.Group("order", "id", id, "shop", o.Shop),
		"phone", o.Phone)
	writeJSON(w, http.StatusOK, map[string]string{"id": id, "shop": o.Shop})
}

func (s *server) withRequestID(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		id := r.Header.Get("X-Request-ID")
		if id == "" || len(id) > 64 {
			id = fmt.Sprintf("req-%04d", s.seq.Add(1))
		}
		w.Header().Set("X-Request-ID", id)
		ctx := context.WithValue(r.Context(), requestIDKey{}, id)
		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

type statusWriter struct {
	http.ResponseWriter
	status int
}

func (w *statusWriter) WriteHeader(code int) {
	w.status = code
	w.ResponseWriter.WriteHeader(code)
}

func (s *server) accessLog(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		sw := &statusWriter{ResponseWriter: w, status: http.StatusOK}
		next.ServeHTTP(sw, r)

		level := slog.LevelInfo
		probe := r.URL.Path == "/healthz" || r.URL.Path == "/readyz"
		switch {
		case probe:
			level = slog.LevelDebug
		case sw.status >= 500:
			level = slog.LevelError
		case sw.status >= 400:
			level = slog.LevelWarn
		}
		s.logger.LogAttrs(r.Context(), level, "요청 완료",
			slog.String("method", r.Method),
			slog.String("path", r.URL.Path),
			slog.Int("status", sw.status))
	})
}

func call(h http.Handler, path, reqID string) {
	req := httptest.NewRequest(http.MethodGet, path, nil)
	if reqID != "" {
		req.Header.Set("X-Request-ID", reqID)
	}
	rec := httptest.NewRecorder()
	h.ServeHTTP(rec, req)
	fmt.Printf("GET %s -> %d %s [%s]\n", path, rec.Code,
		strings.TrimSpace(rec.Body.String()), rec.Header().Get("X-Request-ID"))
}

func main() {
	env := map[string]string{"RELAY_ADDR": ":9090", "RELAY_LOG_LEVEL": "info"}
	getenv := func(k string) string { return env[k] }

	fmt.Println("== 설정 ==")
	cfg, err := loadConfig([]string{"-addr", ":7070"}, getenv)
	if err != nil {
		fmt.Fprintln(os.Stderr, err)
		os.Exit(1)
	}
	fmt.Printf("addr=%s level=%s format=%s\n", cfg.Addr, cfg.LogLevel, cfg.LogFormat)
	env["RELAY_LOG_LEVEL"] = "verbose"
	if _, err := loadConfig(nil, getenv); err != nil {
		fmt.Println("잘못된 설정:", err)
	}

	fmt.Println("== 로그 수준 ==")
	var lvl slog.LevelVar
	lvl.Set(cfg.LogLevel)
	logger := newLogger(os.Stdout, cfg.LogFormat, &lvl).With("service", "relay")
	bi := readBuild()
	logger.Info("서비스 시작", "addr", cfg.Addr, "version", bi.Version)
	logger.Debug("보이지 않는 줄")
	lvl.Set(slog.LevelDebug)
	logger.Debug("디버그 켜짐", "cache_hits", 3)
	lvl.Set(cfg.LogLevel)

	fmt.Println("== 요청 ==")
	s := &server{logger: logger, build: bi, orders: sampleOrders()}
	h := s.routes()
	call(h, "/healthz", "")
	call(h, "/readyz", "")
	s.ready.Store(true)
	call(h, "/readyz", "")
	call(h, "/orders/1001", "mobile-7f3a")
	call(h, "/orders/9999", "")

	fmt.Println("== JSON 로그 ==")
	ctx := context.WithValue(context.Background(), requestIDKey{}, "req-demo")
	jl := newLogger(os.Stdout, "json", &lvl).With("service", "relay")
	jl.InfoContext(ctx, "배달원 배정",
		slog.Group("order", slog.String("id", "1001"), slog.Int("fee", 3000)),
		slog.String("courier", "민준"))
	jl.ErrorContext(ctx, "배정 실패", "order_id", 1002,
		"err", errors.New("가능한 배달원 없음"))
}

줄별 해설

loadConfig. 인자 목록과 환경 변수 조회 함수를 매개변수로 받으므로 테스트에서 어떤 조합이든 넣어 볼 수 있다. 환경 변수가 비어 있지 않을 때만 변수 addr, levelText, format 을 덮어쓴다. 그 값이 곧 flag 의 기본값이 되므로, 플래그가 있으면 플래그가 이기고 없으면 환경 변수가 남는다. flag.ContinueOnError 와 io.Discard 는 파싱 실패 시 프로세스를 끝내지 않고 오류만 돌려받으려는 설정이다. 해석할 수 없는 로그 수준은 slog 의 오류 문구를 그대로 쓰지 않고 우리 문장으로 바꿔 돌려준다.

ctxHandler. Handle 은 ctx 에서 requestIDKey{} 로 ID 를 꺼내 레코드 끝에 request_id 를 붙인다. ctx 키를 빈 구조체 타입으로 정한 것은 다른 패키지의 키와 충돌하지 않게 하려는 관례다. WithAttrs 와 WithGroup 은 안쪽 핸들러의 결과를 다시 ctxHandler 로 감싼다. logger.With("service", "relay") 를 거쳐도 래퍼가 유지되는 이유다.

dropTime 과 newLogger. ReplaceAttr 는 속성이 출력되기 직전에 호출된다. 최상위(그룹 이름이 없는) 시각 키에 빈 slog.Attr 를 돌려주면 그 속성이 사라진다. 이 코드는 출력을 고정하기 위한 것일 뿐이고, 실서비스에서는 시각이 로그의 가장 중요한 필드다. Level 에 넘긴 slog.Leveler 인터페이스는 slog.Level 과 *slog.LevelVar 가 모두 구현한다.

phone.LogValue. 길이가 짧으면 전부 가리고, 아니면 앞 네 글자와 뒤 다섯 글자만 남긴다. "phone", o.Phone 처럼 일반 속성으로 넘기기만 하면 핸들러가 이 메서드를 호출한다.

server 와 routes. atomic.Bool 과 atomic.Int64 는 영값으로 쓸 수 있고 복사하면 안 되므로 서버는 포인터로 다룬다. 경로 패턴 GET /orders/{id} 는 메서드와 경로 변수를 한 문자열에 쓰는 표준 라우터 문법이다. 반환값은 withRequestID(accessLog(mux)) 로, 요청은 바깥쪽 미들웨어부터 들어오고 응답은 안쪽부터 나간다. 접근 로그가 요청 ID 를 쓸 수 있는 것은 ID 미들웨어가 더 바깥에 있기 때문이다.

getOrder. 로그 호출에 r.Context() 를 넘기는 것이 핵심이다. Warn 대신 WarnContext 를 쓴 이유가 이것이고, 이렇게 해야 ctxHandler 가 ID 를 찾는다. slog.Group("order", "id", id, "shop", o.Shop) 은 속성 두 개를 order 아래에 묶는다.

withRequestID. 헤더 값이 비었거나 64바이트를 넘으면 req-0001 형식의 ID 를 새로 만든다. 카운터는 원자적으로 증가시키므로 동시 요청에서도 겹치지 않는다. 실서비스에서는 난수 기반 ID 를 쓰는 경우가 많지만, 여기서는 출력을 고정하려고 순번을 썼다.

accessLog. statusWriter 는 WriteHeader 만 가로채서 상태 코드를 저장한다. 핸들러가 WriteHeader 를 부르지 않고 바로 쓰면 200 으로 간주되므로 초기값을 200 으로 둔다. switch 의 첫 case 가 헬스 체크를 Debug 로 낮추고, 이어서 5xx 와 4xx 를 각각 Error 와 Warn 으로 올린다. 레벨이 동적이므로 LogAttrs 로 레벨을 변수로 넘긴다.

main. 환경 변수를 맵으로 흉내 내어 설정 우선순위를 보인 뒤, 같은 맵의 값을 잘못된 수준으로 바꿔 검증이 실패하는 경로를 보인다. 이어서 LevelVar 로 Debug 를 켰다 끄고, 서버에는 준비 플래그를 켜기 전과 후에 /readyz 를 한 번씩 부른다. 마지막은 같은 로거 구성을 JSON 형식으로 바꿔 요청 ID 가 붙는 모습을 보인다.

실행 결과

버전 관리 저장소가 아닌 빈 디렉터리에서 실행한다. 저장소 안이면 빌드 정보의 버전이 달라질 수 있다.

$ go run main.go
== 설정 ==
addr=:7070 level=INFO format=text
잘못된 설정: 로그 수준 "verbose" 를 해석할 수 없다
== 로그 수준 ==
level=INFO msg="서비스 시작" service=relay addr=:7070 version=devel
level=DEBUG msg="디버그 켜짐" service=relay cache_hits=3
== 요청 ==
GET /healthz -> 200 {"status":"ok","version":"devel"} [req-0001]
GET /readyz -> 503 {"status":"starting"} [req-0002]
GET /readyz -> 200 {"status":"ready"} [req-0003]
level=INFO msg="주문 조회" service=relay order.id=1001 order.shop=한강분식 phone=010-****-5678 request_id=mobile-7f3a
level=INFO msg="요청 완료" service=relay method=GET path=/orders/1001 status=200 request_id=mobile-7f3a
GET /orders/1001 -> 200 {"id":"1001","shop":"한강분식"} [mobile-7f3a]
level=WARN msg="주문 없음" service=relay order_id=9999 request_id=req-0004
level=WARN msg="요청 완료" service=relay method=GET path=/orders/9999 status=404 request_id=req-0004
GET /orders/9999 -> 404 {"error":"주문 없음"} [req-0004]
== JSON 로그 ==
{"level":"INFO","msg":"배달원 배정","service":"relay","order":{"id":"1001","fee":3000},"courier":"민준","request_id":"req-demo"}
{"level":"ERROR","msg":"배정 실패","service":"relay","order_id":1002,"err":"가능한 배달원 없음","request_id":"req-demo"}

세 가지를 확인한다. 첫째, 정보 수준에서는 보이지 않는 줄 과 헬스 체크의 접근 로그가 나오지 않는다. 둘째, 같은 요청에서 나온 두 줄이 같은 request_id 를 가진다. 셋째, 전화번호는 마스킹된 채로 출력된다.

실무에서 자주 틀리는 것

ctx 를 받지 않는 메서드로 로그를 남긴다

요청 ID 를 ctx 에 넣었는데 일부 로그에만 ID 가 없다면 대부분 이 문제다. Info, Warn 은 ctx 를 받지 않으므로 핸들러가 ID 를 찾을 수 없다.

// 틀림: request_id 가 붙지 않는다
s.logger.Warn("주문 없음", "order_id", id)

// 고침: ctx 를 넘긴다
s.logger.WarnContext(r.Context(), "주문 없음", "order_id", id)

민감한 값을 그대로 속성에 넘긴다

전화번호, 주소, 토큰은 호출하는 사람이 기억해서 가리는 방식으로는 지켜지지 않는다. 값의 타입이 스스로 로그 표현을 정하게 한다.

// 틀림: 원문이 로그 저장소에 남는다
logger.Info("주문 조회", "phone", "010-1234-5678")

// 고침: phone 타입의 LogValue 가 마스킹한다
logger.Info("주문 조회", "phone", phone("010-1234-5678"))

환경 변수를 플래그 파싱 뒤에 적용한다

우선순위를 "플래그가 이긴다"로 정했다면 환경 변수는 파싱 전에 반영해야 한다. 파싱 뒤에 덮어쓰면 사용자가 준 플래그가 조용히 무시된다.

// 틀림: -addr 로 준 값이 환경 변수에 덮어쓰인다
fs.StringVar(&addr, "addr", ":8080", "수신 주소")
fs.Parse(args)
if v := getenv("RELAY_ADDR"); v != "" {
	addr = v
}

// 고침: 환경 변수를 먼저 반영하고 그 값을 플래그의 기본값으로 쓴다
if v := getenv("RELAY_ADDR"); v != "" {
	addr = v
}
fs.StringVar(&addr, "addr", addr, "수신 주소")
fs.Parse(args)

살아 있음 검사에 외부 의존성을 넣는다

데이터베이스나 배달원 연동 서버가 잠깐 응답하지 않을 때 /healthz 가 실패하면, 오케스트레이터가 멀쩡한 프로세스를 줄줄이 재시작한다. 재시작은 문제를 풀지 못하고 연결 부하만 늘린다.

// 틀림: 외부 장애가 프로세스 재시작으로 번진다
func (s *server) healthz(w http.ResponseWriter, r *http.Request) {
	if err := s.db.PingContext(r.Context()); err != nil {
		w.WriteHeader(http.StatusServiceUnavailable)
		return
	}
	w.WriteHeader(http.StatusOK)
}

// 고침: healthz 는 응답만 확인하고, 의존성은 readyz 에서 본다
func (s *server) healthz(w http.ResponseWriter, r *http.Request) {
	w.WriteHeader(http.StatusOK)
}

한눈에 보기

이 장에서 다룬 도구와 쓰임
주제도구핵심 규칙확인 방법
구조화 로그slog.NewTextHandler, NewJSONHandler호출 코드는 그대로, 핸들러만 바꾼다설정의 형식을 바꿔 실행한다
레벨slog.LevelVar실행 중에 안전하게 바꾼다Debug 줄이 켜졌을 때만 나온다
요청 IDcontext.WithValue, ctxHandlerctx 를 받는 메서드를 쓴다같은 요청의 줄이 같은 ID 를 가진다
민감한 값slog.LogValuer타입이 로그 표현을 정한다출력에 원문이 없다
설정os 환경 변수, flag.FlagSet기본값, 환경 변수, 플래그 순으로 덮어쓴다잘못된 값은 시작 시 실패한다
빌드 정보debug.ReadBuildInfo시작 로그와 헬스 응답에 넣는다/healthz 의 version 을 본다
헬스 체크/healthz, /readyz, atomic.Bool살아 있음과 준비됨을 나눈다준비 전에 503 이 나온다

연습 문제

  1. 완성 코드에서 loadConfig 에 인자 -log-format json 을 주고, 그 설정으로 만든 로거가 JSON 줄을 내는지 확인하려면 main 을 어떻게 고치는가.
  2. 외부에서 들어온 X-Request-ID 에 영숫자, 하이픈, 밑줄 이외의 문자가 있으면 새로 발급하도록 withRequestID 를 고쳐라. 로그 줄을 위조하는 입력을 막으려는 조치다.
  3. /readyz 가 준비 플래그뿐 아니라 검사 함수 목록 []func(context.Context) error 도 통과해야 200 을 돌려주도록 확장하라. 실패하면 503 과 함께 어떤 검사가 실패했는지 로그로 남긴다.
  4. logger.WithGroup("http") 로 만든 로거에 ctxHandler 가 적용돼 있다. InfoContext(ctx, "처리", "status", 200) 을 부르면 request_id 는 텍스트 출력에서 어디에 나타나는가.

정답과 해설

1. 설정을 읽는 호출의 인자를 []string{"-addr", ":7070", "-log-format", "json"} 로 바꾼다. newLogger(os.Stdout, cfg.LogFormat, &lvl) 는 이미 cfg.LogFormat 을 쓰고 있으므로 다른 곳은 고칠 필요가 없다. 이후 시작 로그가 {"level":"INFO","msg":"서비스 시작",...} 형태로 나온다. 환경 변수 RELAY_LOG_FORMAT=json 으로 줘도 같다. 호출 코드와 출력 형식이 분리돼 있다는 점이 요점이다.

2. 검증 함수를 하나 두고 조건에 합친다.

func validID(id string) bool {
	if id == "" || len(id) > 64 {
		return false
	}
	for _, c := range id {
		ok := c >= 'a' && c <= 'z' || c >= 'A' && c <= 'Z' ||
			c >= '0' && c <= '9' || c == '-' || c == '_'
		if !ok {
			return false
		}
	}
	return true
}

withRequestID 에서는 if !validID(id) { id = fmt.Sprintf(...) } 로 바꾼다. 텍스트 핸들러는 공백이나 따옴표가 든 값을 따옴표로 감싸 주지만, ID 를 로그 검색 키로 쓰는 쪽에서도 형식이 고정돼 있는 편이 안전하다.

3. 서버에 checks map[string]func(context.Context) error 를 두면 이름이 있어 로그에 남기기 쉽다. readyz 는 먼저 플래그를 보고, 이어서 이름을 정렬한 순서로 검사를 돌린다. 하나라도 오류를 돌려주면 s.logger.WarnContext(r.Context(), "준비 검사 실패", "check", name, "err", err) 를 남기고 503 으로 답한다. 맵을 그대로 순회하면 실패 로그의 순서가 실행마다 달라지므로 키를 정렬한다. 검사 함수에는 r.Context() 를 넘겨, 요청이 취소되면 검사도 멈추게 한다. 의존성 검사는 이 엔드포인트에만 넣고 /healthz 에는 넣지 않는다.

4. request_id 는 http.status=200 http.request_id=... 처럼 그룹 안에 들어간다. ctxHandler 는 레코드에 속성을 더할 뿐이고, 어디에 놓일지는 안쪽 핸들러가 정한다. WithGroup 이후에 추가된 속성은 모두 열려 있는 그룹 아래에 놓인다. 최상위에 두고 싶으면 그룹 없는 로거를 따로 두거나, 핸들러에서 ID 를 미리 WithAttrs 로 심는 방식을 쓴다. 이 점 때문에 요청 ID 는 그룹을 열기 전의 로거에서 붙이는 구성이 다루기 쉽다.

댓글 0

아직 댓글이 없습니다. 첫 댓글을 남겨 보세요.

댓글을 남기려면 로그인이 필요합니다.