구조화 로깅 log/slog

이 챕터에서 다루는 것

log/slog로 서비스 로그를 조립한다. 핸들러 구성, 속성과 그룹, 요청 ID 전파, 비밀값 가리기, 실행 중 레벨 변경까지. 12-1에서 LogFunc로 비워 둔 자리에 진짜 로거를 넣는 작업이다.

11-5에서 미뤄 둔 "GORM 느린 쿼리를 slog로"도 여기서 갚는다.

문제 — `log.Printf`로는 검색이 안 된다

파트 9까지 쓰던 표준 log 패키지는 문자열 한 줄을 찍는다.

log.Printf("메모 %d 조회 실패: %v (사용자 %s)", id, err, owner)

로컬에서는 읽기 좋다. 그런데 이 줄이 하루에 수백만 개 쌓인 로그 저장소에 들어가면 질문에 답할 수 없게 된다. "사용자 sohee의 실패한 요청만" 같은 질의를 하려면 정규식으로 문자열을 파싱해야 하고, 메시지 포맷을 누가 한 글자만 바꿔도 그 정규식이 깨진다.

구조화 로깅은 로그를 문장이 아니라 키-값의 집합으로 본다.

{"level":"ERROR","msg":"메모 조회 실패","id":7,"owner":"sohee","error":"..."}

이제 owner:"sohee" AND level:ERROR로 검색된다. 메시지 문구를 바꿔도 필드는 그대로다.

Go는 1.21에서 log/slog를 표준 라이브러리에 넣었다. 그전까지는 zap, zerolog, logrus가 각자의 인터페이스로 갈라져 있었고, 라이브러리가 로그를 남기려면 어느 것에 의존할지 골라야 했다. 이제 표준이 생겼으니 새 코드는 slog로 쓴다.

Logger와 Handler

slog의 구조는 두 층이다.

*slog.Logger — 애플리케이션이 부르는 쪽. Info, Error, With.
slog.Handler — 실제로 형식을 만들고 쓰는 쪽. 인터페이스다.

애플리케이션 코드는 Logger만 알면 되고, "JSON이냐 text냐", "어디에 쓰느냐"는 프로그램 시작 지점에서 한 번 정한다. 그 조립을 한 패키지에 모아 둔다.

examples/12-production/02-slog/applog/applog.go
// New는 핸들러 하나짜리 로거를 만든다.
func New(w io.Writer, opt Options) *slog.Logger {
	return slog.New(NewContextHandler(newHandler(w, opt)))
}

func newHandler(w io.Writer, opt Options) slog.Handler {
	ho := &slog.HandlerOptions{
		Level:     Level,
		AddSource: opt.AddSource,
	}
	if opt.Stable {
		ho.ReplaceAttr = stableAttr
	}
	if opt.JSON {
		return slog.NewJSONHandler(w, ho)
	}
	return slog.NewTextHandler(w, ho)
}

같은 로그가 핸들러에 따라 이렇게 달라진다.

examples/12-production/02-slog/main.go
func handlers() {
	text := applog.New(os.Stdout, applog.Options{Stable: true})
	text.Info("서버 시작", "port", 8080, "env", "dev")

	js := applog.New(os.Stdout, applog.Options{JSON: true, Stable: true})
	js.Info("서버 시작", "port", 8080, "env", "dev")
}

level=INFO msg="서버 시작" port=8080 env=dev
{"level":"INFO","msg":"서버 시작","port":8080,"env":"dev"}

로컬 개발은 text, 운영은 JSON이 보통이다. 환경 변수 하나로 고르게 해 두면 된다.

:::note 출력에 시각이 없는 이유 예제의 모든 로그에는 time 필드가 없다. Options.Stable이 켜져 있어서 매 실행 달라지는 값을 지우기 때문이다. 강의 출력이 결정적이어야 해서 넣은 장치이고, 실제 운영 로그에는 "time":"2026-08-12T14:03:11.482+09:00"이 맨 앞에 붙는다. 뒤에 나오는 duration도 같은 이유로 0.000ms로 고정된 값이다. :::

그 장치는 HandlerOptions.ReplaceAttr로 만든다. 이것 자체가 알아 둘 만한 기능이다.

examples/12-production/02-slog/applog/applog.go
// stableAttr는 실행마다 달라지는 값을 고정한다.
//
// ReplaceAttr는 로그에 실리는 모든 속성마다 불린다. groups는 지금 있는
// 그룹 경로이고, 최상위 속성(time, level, msg, source)에 대해서는 비어 있다.
// 빈 Attr(slog.Attr{})을 돌려주면 그 속성은 출력에서 사라진다.
func stableAttr(groups []string, a slog.Attr) slog.Attr {
	if len(groups) == 0 && a.Key == slog.TimeKey {
		return slog.Attr{}
	}
	// GORM slog 로거가 넣는 trace.duration은 실행마다 다르다.
	if a.Key == "duration" {
		return slog.String("duration", "0.000ms")
	}

ReplaceAttr는 강의용 장치를 넘어서 쓸모가 있다. 로그 필드 이름을 회사 표준에 맞추거나, 특정 키를 통째로 가리거나, 타임스탬프 형식을 바꾸는 자리가 여기다.

속성 붙이는 세 가지 방법

examples/12-production/02-slog/main.go
	// With는 이후 모든 로그에 같은 속성을 붙인 새 로거를 만든다.
	// 요청 단위·컴포넌트 단위로 하나씩 만들어 쓰는 것이 기본 패턴이다.
	svc := l.With("component", "notes")
	svc.Info("메모 생성", "id", 1)

	// LogAttrs는 any가 아니라 slog.Attr을 받는다. 키-값 쌍이 어긋날
	// 여지가 없고, 인터페이스 변환 할당이 없어서 더 빠르다.
	svc.LogAttrs(ctx, slog.LevelInfo, "메모 삭제", slog.Int64("id", 1))

	// Group은 속성을 중첩시킨다. JSON에서는 객체가 된다.
	svc.Info("요청 처리",
		slog.Group("http", slog.String("method", "GET"), slog.Int("status", 200)))

	// GroupAttrs는 Attr만 받는 Group이다. any 슬라이스를 거치지 않으므로
	// 할당이 적다. 미리 만들어 둔 []slog.Attr을 그대로 넘길 때 특히 편하다.
	fields := []slog.Attr{slog.String("method", "POST"), slog.Int("status", 201)}
	svc.LogAttrs(ctx, slog.LevelInfo, "요청 처리", slog.GroupAttrs("http", fields...))

{"level":"INFO","msg":"메모 생성","component":"notes","id":1}
{"level":"INFO","msg":"메모 삭제","component":"notes","id":1}
{"level":"INFO","msg":"요청 처리","component":"notes","http":{"method":"GET","status":200}}
{"level":"INFO","msg":"요청 처리","component":"notes","http":{"method":"POST","status":201}}

세 방식의 차이는 편의성과 비용이다.

방식	인자	비용	언제
`Info("msg", "k", v, ...)`	`...any`	값마다 인터페이스 변환	대부분의 경우
`LogAttrs(ctx, lvl, "msg", attrs...)`	`...slog.Attr`	변환 없음	뜨거운 경로
`Group` / `GroupAttrs`	중첩	—	필드 묶기

...any 방식의 진짜 위험은 성능이 아니라 짝이 어긋나는 것이다.

// 값 하나를 빠뜨렸다. 컴파일은 통과한다.
l.Info("메모 생성", "id", 1, "owner")

slog는 짝이 안 맞는 마지막 인자를 !BADKEY로 처리한다. 죽지는 않지만 필드가 사라진다. go vet의 slog 분석기가 이런 호출을 잡아 주므로, CI에 go vet이 있으면 대부분 걸린다. 그래도 신경 쓰이는 경로에는 LogAttrs를 쓰는 편이 확실하다.

:::tip Group과 GroupAttrs GroupAttrs는 Group의 ...any를 ...slog.Attr로 바꾼 것이다. 하는 일은 같지만 []slog.Attr을 이미 갖고 있을 때 ...any로 변환하는 루프를 돌지 않아도 된다. 미들웨어처럼 속성을 모아 뒀다가 한 번에 붙이는 코드에서 자연스럽게 쓰인다. :::

비밀값은 타입으로 막는다

로그에 토큰이나 비밀번호가 실리는 사고는 "조심하자"로 막히지 않는다. 타입이 막게 해야 한다. slog.LogValuer를 구현하면 slog가 값을 기록하기 직전에 LogValue()를 부른다.

examples/12-production/02-slog/applog/applog.go
// Secret은 로그에 절대 실려서는 안 되는 문자열이다.
//
// slog.LogValuer를 구현하면 slog가 값을 기록하기 직전에 LogValue()를 부른다.
// 그래서 이 타입은 "실수로 로깅해도 안전한 문자열"이 된다. 12-3에서
// 설정 구조체가 이 타입을 쓴다.
type Secret string

// LogValue는 항상 가려진 값을 돌려준다.
func (Secret) LogValue() slog.Value { return slog.StringValue("REDACTED") }

// String은 사람이 실수로 %v를 써도 새지 않게 한다.
func (Secret) String() string { return "REDACTED" }

// Reveal은 진짜 값이 필요할 때만 쓴다. 이름이 길고 눈에 띄는 것이 의도다.
func (s Secret) Reveal() string { return string(s) }

String()까지 구현한 것이 중요하다. LogValue는 slog 경로만 막는다. 누가 fmt.Printf("%v", token)이나 errors.New("토큰 " + string(token) + " 만료")를 쓰면 그대로 샌다. String()이 있으면 fmt의 %v와 %s도 막힌다. 남는 구멍은 명시적 변환(string(token))뿐이고, 그것은 코드 리뷰에서 눈에 띈다.

{"level":"INFO","msg":"외부 API 호출","endpoint":"/v1/charge","token":"REDACTED"}
  fmt로 찍어도: REDACTED / REDACTED
  진짜 값이 필요하면: sk-live-abcdef123456

LogValuer는 그룹 안이나 구조체 필드 안에 있어도 불린다.

examples/12-production/02-slog/applog/applog_test.go
func TestSecretRedactedInsideStructAndGroup(t *testing.T) {
	// LogValuer는 어디에 들어 있든 불린다. 구조체 필드로 감싸도,
	// 그룹 안에 넣어도 마찬가지인지 확인한다.
	var buf bytes.Buffer
	l := applog.New(&buf, applog.Options{JSON: true, Stable: true})

	l.Info("설정",
		slog.Group("db", slog.Any("password", applog.Secret("hunter2"))))

	if strings.Contains(buf.String(), "hunter2") {
		t.Fatalf("비밀이 그룹 안에서 샜다: %s", buf.String())
	}
}

NewMultiHandler로 여러 곳에 보내기

"전부 stdout으로, 에러만 별도 파일로" 같은 요구는 흔하다. Go 1.26의 slog.NewMultiHandler가 그것을 해 준다.

examples/12-production/02-slog/main.go
func multi() {
	// 첫 번째 핸들러는 전부, 두 번째는 Error 이상만 받는다.
	// MultiHandler는 핸들러마다 Enabled를 물어보고 통과한 쪽에만 넘긴다.
	all := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
		Level:       slog.LevelInfo,
		ReplaceAttr: dropTime,
	})
	errsOnly := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
		Level:       slog.LevelError,
		ReplaceAttr: dropTime,
	})
	l := slog.New(slog.NewMultiHandler(all, errsOnly))

	l.Info("이 줄은 JSON 한 줄만 나온다")
	l.Error("이 줄은 두 번 나온다", "kind", "internal")
}

{"level":"INFO","msg":"이 줄은 JSON 한 줄만 나온다"}
{"level":"ERROR","msg":"이 줄은 두 번 나온다","kind":"internal"}
level=ERROR msg="이 줄은 두 번 나온다" kind=internal

동작 규칙은 표준 라이브러리 소스에 명확히 적혀 있다. Enabled는 하나라도 통과하면 참이고, Handle은 통과한 핸들러에만 r.Clone()을 넘긴다. Clone을 넘기는 이유는 핸들러가 레코드에 속성을 추가할 수 있어서, 앞 핸들러의 수정이 뒤 핸들러에 보이면 안 되기 때문이다.

context에서 요청 ID를 자동으로 붙이기

요청 ID는 로그를 요청 단위로 묶는 열쇠다. 그런데 logger.With("request_id", id)를 호출 사슬 끝까지 손으로 나르는 것은 현실적이지 않다. 요청마다 값이 달라지므로 전역 로거에 붙일 수도 없다.

답은 두 가지를 조합하는 것이다. 로거를 context에 넣어 나르고, 핸들러가 context를 읽게 한다.

examples/12-production/02-slog/applog/applog.go
// From은 context에서 로거를 꺼낸다. 없으면 기본 로거다.
//
// 없을 때 nil이 아니라 기본 로거를 돌려주는 것이 중요하다. 로깅 때문에
// nil 검사를 하게 만들면 아무도 로깅하지 않게 된다.
func From(ctx context.Context) *slog.Logger {
	if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok {
		return l
	}
	return slog.Default()
}

Handler 인터페이스는 메서드가 넷뿐이라 직접 구현하기 어렵지 않다.

examples/12-production/02-slog/applog/applog.go
// Handle은 context에서 요청 ID를 꺼내 최상위 속성으로 붙인다.
func (h *ContextHandler) Handle(ctx context.Context, r slog.Record) error {
	id, ok := ctx.Value(requestIDKey).(string)
	if !ok {
		// 붙일 것이 없으면 미리 조립해 둔 경로가 없더라도 손해가 없다.
		return h.build(nil).Handle(ctx, r)
	}
	return h.build([]slog.Attr{slog.String("request_id", id)}).Handle(ctx, r)
}

여기서 실제로 걸린 버그

처음 쓴 구현은 훨씬 단순했다. Handle에서 r.AddAttrs(slog.String("request_id", id))를 하고, WithAttrs/WithGroup은 감싼 핸들러에 위임한 뒤 다시 감싸는 것이 전부였다. 테스트를 돌리자 이렇게 실패했다.

--- FAIL: TestContextHandlerSurvivesWith (0.00s)
    applog_test.go:89: With/WithGroup 이후 request_id가 사라졌다: map[component:notes level:INFO msg:작업 op:map[name:rename request_id:req-7]]

request_id가 사라진 게 아니라 op 그룹 안으로 들어가 있었다. 이유는 이렇다. WithGroup("op")를 하면 그 뒤로 레코드에 실린 모든 속성이 그 그룹 안에 담긴다. Handle에서 r.AddAttrs로 붙인 요청 ID도 예외가 아니다. 요청 ID가 op.request_id가 되면 request_id:"req-7" 검색에 걸리지 않는다.

고친 방법은 그룹 적용을 Handle 시점까지 미루는 것이다.

examples/12-production/02-slog/applog/applog.go
// WithGroup도 연산을 기록만 해 둔다.
//
// 여기서 바로 root.WithGroup(name)을 해 버리면, Handle에서 붙이는
// request_id가 그 그룹 안으로 들어간다. logger.WithGroup("op")를 한
// 로거로 찍은 로그가 {"op":{"name":"rename","request_id":"..."}}가 되는
// 것이다. 요청 ID는 최상위에 있어야 검색이 되므로 이것은 버그다.
//
// 그래서 그룹 적용을 Handle 시점까지 미루고, 그때 request_id를 먼저 붙인
// 뒤에 그룹을 연다. 대가는 로그 한 줄마다 핸들러 사슬을 다시 만드는
// 비용이다. 초당 수만 줄을 찍는다면 이 비용이 문제가 되고, 그때는
// 요청 ID를 슬롯 하나짜리 전용 필드로 다루는 핸들러를 직접 써야 한다.
func (h *ContextHandler) WithGroup(name string) slog.Handler {
	if name == "" {
		return h
	}
	return h.with(func(in slog.Handler) slog.Handler { return in.WithGroup(name) })
}

with가 슬라이스를 매번 새로 만드는 것도 우연이 아니다.

examples/12-production/02-slog/applog/applog.go
func (h *ContextHandler) with(op func(slog.Handler) slog.Handler) slog.Handler {
	// 슬라이스를 공유하면 형제 로거끼리 서로의 연산을 덮어쓴다.
	// 파트 3에서 본 append의 배열 공유 문제가 그대로 재현되는 자리다.
	ops := make([]func(slog.Handler) slog.Handler, len(h.ops)+1)
	copy(ops, h.ops)
	ops[len(h.ops)] = op
	return &ContextHandler{root: h.root, ops: ops}
}

base.With("a", 1)과 base.With("b", 2)를 각각 만들었을 때 둘이 서로의 속성을 덮어쓰면 안 된다. append(h.ops, op)를 그냥 쓰면 용량이 남아 있을 때 정확히 그 일이 일어난다. 파트 3-3에서 다룬 백킹 배열 공유 문제이고, 표준 라이브러리의 commonHandler도 같은 이유로 슬라이스를 복사한다.

:::warning Handler를 직접 쓸 때의 계약 Handler 인터페이스에는 문서로만 적힌 규칙이 몇 개 있다.

WithAttrs/WithGroup은 새 핸들러를 돌려준다. 자기 자신을 수정하면 안 된다.
빈 이름의 WithGroup("")은 아무것도 하지 않아야 한다.
속성이 없는 WithAttrs(nil)도 마찬가지다.
Handle은 Record를 다른 고루틴에 넘겨 보관하면 안 된다. 필요하면 Clone한다.

컴파일러가 잡아 주지 않는 규칙이라 테스트로 확인하는 수밖에 없다. 표준 라이브러리에 testing/slogtest 패키지가 있고, 핸들러를 넘기면 이 계약을 자동으로 검사해 준다. :::

미들웨어와 합치기

examples/12-production/02-slog/applog/applog.go
			rw := &statusWriter{ResponseWriter: w, status: http.StatusOK}
			start := time.Now()
			next.ServeHTTP(rw, r.WithContext(ctx))

			// 요청 하나에 접근 로그 한 줄. 여러 줄로 쪼개면 집계할 때
			// 다시 이어 붙여야 한다.
			base.LogAttrs(ctx, slog.LevelInfo, "http request",
				slog.String("method", r.Method),
				slog.String("path", r.URL.Path),
				slog.Int("status", rw.status),
				slog.Int("bytes", rw.bytes),
				slog.Duration("duration", time.Since(start)),
			)

{"level":"INFO","msg":"메모 조회","request_id":"req-1","id":"7"}
{"level":"INFO","msg":"http request","request_id":"req-1","method":"GET","path":"/notes/7","status":200,"bytes":3,"duration":"0.000ms"}
  응답 헤더 X-Request-Id = req-1
{"level":"INFO","msg":"메모 조회","request_id":"req-2","id":"7"}
{"level":"INFO","msg":"http request","request_id":"req-2","method":"GET","path":"/notes/7","status":200,"bytes":3,"duration":"0.000ms"}
  응답 헤더 X-Request-Id = req-2

핸들러 안의 applog.From(ctx).InfoContext(ctx, ...)는 요청 ID를 한 글자도 언급하지 않는데 로그에는 붙어 있다. ResponseWriter를 감싸 상태 코드를 엿보는 statusWriter는 파트 10에서 미들웨어를 만들 때 이미 본 패턴이다.

들어온 X-Request-Id를 그대로 쓰는 것도 의도다. 앞단 프록시나 다른 서비스가 붙인 ID를 이어받아야 여러 서비스의 로그가 하나의 요청으로 묶인다.

실행 중 레벨 바꾸기

slog.LevelVar는 원자적으로 읽고 쓰는 레벨 홀더다. 핸들러에 *LevelVar를 넘겨 두면 프로세스를 재시작하지 않고 레벨을 바꿀 수 있다.

examples/12-production/02-slog/applog/applog.go
// Level은 실행 중에 바꿀 수 있는 로그 레벨이다.
//
// slog.LevelVar는 원자적으로 읽고 쓴다. 핸들러에 *LevelVar를 넘겨 두면
// 프로세스를 재시작하지 않고 레벨을 바꿀 수 있다.
var Level = new(slog.LevelVar)

  레벨 = INFO
{"level":"INFO","msg":"이 줄은 나온다"}
  레벨 = DEBUG
{"level":"DEBUG","msg":"이제 나온다"}

운영 가치가 큰 기능이다. 장애가 났을 때 디버그 로그를 켜기 위해 재배포를 하면, 재시작 과정에서 문제 상황이 사라져 버리는 일이 흔하다. 관리 엔드포인트를 하나 열어 두면 살아 있는 프로세스의 레벨을 바로 올릴 수 있다. 다만 그 엔드포인트는 반드시 내부망에만 노출한다. 12-4에서 pprof 엔드포인트에 대해 같은 이야기를 한다.

GORM 느린 쿼리를 slog로 (11-5의 숙제)

GORM v1.31.2는 logger.NewSlogLogger(*slog.Logger, logger.Config)를 제공한다. 어댑터를 직접 쓸 필요가 없다.

examples/12-production/02-slog/gormlog/gormlog.go
// New는 GORM 로거를 만든다.
//
// slow는 이 시간을 넘는 쿼리를 Warn으로 올리는 기준이다. 운영에서는
// 200ms 정도를 쓰고, LogLevel을 logger.Warn으로 두어 정상 쿼리는
// 아예 찍지 않는다. 쿼리마다 한 줄씩 남기면 로그량이 요청 수의
// 몇 배가 되고, 정작 봐야 할 줄이 묻힌다.
func New(l *slog.Logger, slow time.Duration) logger.Interface {
	return logger.NewSlogLogger(l, logger.Config{
		SlowThreshold: slow,
		LogLevel:      logger.Warn,
		// ParameterizedQueries를 켜면 SQL에 값이 끼워지지 않고
		// 플레이스홀더로 남는다. 로그에 개인정보가 실리는 것을 막는
		// 가장 값싼 방법이고, 운영에서는 켜는 편이 맞다.
		ParameterizedQueries: true,
		// 레코드 없음은 애플리케이션이 처리하는 정상 흐름이다.
		// 로그로 올리면 노이즈가 된다.
		IgnoreRecordNotFoundError: true,
	})
}

데모에서는 임계값을 1ns로 두어 모든 쿼리가 느린 쿼리가 되게 했다. 그래야 출력이 결정적이다.

{"level":"WARN","msg":"SQL executed","trace":{"duration":"0.000ms","sql":"SELECT count(*) FROM sqlite_master WHERE type='table' AND name=?"}}
{"level":"WARN","msg":"SQL executed","trace":{"duration":"0.000ms","sql":"CREATE TABLE `notes` (`id` integer PRIMARY KEY AUTOINCREMENT,`title` text)","rows":0}}
{"level":"WARN","msg":"SQL executed","trace":{"duration":"0.000ms","sql":"INSERT INTO `notes` (`title`) VALUES (?) RETURNING `id`","rows":1}}
{"level":"WARN","msg":"SQL executed","trace":{"duration":"0.000ms","sql":"SELECT * FROM `notes` WHERE title = ? ORDER BY `notes`.`id` LIMIT 1","rows":1}}

GORM은 trace라는 그룹 안에 duration, sql, rows를 넣는다. duration은 실제로는 "1.284ms" 같은 값이고 예제에서만 고정돼 있다.

ParameterizedQueries: true의 효과가 SQL에 보인다. VALUES (?)이지 VALUES ("장보기")가 아니다. 11-5에서 로그에 찍히는 SQL은 GORM이 값을 끼워 넣어 읽기 좋게 만든 것이라고 했는데, 이 옵션이 그 동작을 끈다. 값이 개인정보라면 로그 저장소에 그것이 영구히 남는다는 뜻이므로, 운영에서는 켜는 편이 맞다. 테스트로 못 박아 둔다.

examples/12-production/02-slog/gormlog/gormlog_test.go
	// ParameterizedQueries가 켜져 있으면 값이 SQL에 박히지 않는다.
	if strings.Contains(sql, "장보기") {
		t.Fatalf("값이 SQL 로그에 실렸다: %q", sql)
	}

구 `log` 패키지와의 관계

log는 없어지지 않았고, 두 방향으로 연결돼 있다.

slog → log. slog.SetDefault(logger)를 부르면 slog.Default()뿐 아니라 표준 log 패키지의 기본 출력까지 그 로거로 넘어간다. 남의 라이브러리가 log.Printf를 쓰고 있어도 그 줄이 JSON 로그로 나온다는 뜻이다. 프로그램 시작 지점에서 한 번 부른다.

log → slog. slog.NewLogLogger(handler, level)은 *log.Logger를 돌려준다. http.Server.ErrorLog처럼 *log.Logger를 요구하는 API에 구조화 로거를 꽂는 자리다. 12-8에서 실제로 쓴다.

srv := &http.Server{
    Addr:     ":8080",
    Handler:  h,
    ErrorLog: slog.NewLogLogger(logger.Handler(), slog.LevelError),
}

흔한 실수

요청마다 새 핸들러를 만든다. slog.NewJSONHandler는 시작 시 한 번만 부른다. 요청 단위로 필요한 것은 logger.With(...)이고, 이것은 핸들러를 새로 만들지 않는다.

로그 안에 로그를 만든다. 커스텀 핸들러의 Handle 안에서 로깅하면 무한 재귀다. 핸들러가 에러를 만나면 error를 돌려주는 것이 계약이다.

Error 레벨을 남발한다. 사용자 입력이 잘못된 것은 Error가 아니다. Error는 "사람이 봐야 한다"는 신호로 남겨 두어야 알림이 의미를 갖는다. 12-1의 Kind를 그대로 레벨에 매핑하면 편하다 — KindInternal만 Error, 나머지는 Warn이나 Info.

메시지에 값을 끼워 넣는다. l.Info(fmt.Sprintf("메모 %d 생성", id))는 구조화 로깅을 쓰면서 얻는 것을 전부 버린다. l.Info("메모 생성", "id", id)다.

Debug에서 비싼 값을 계산한다. l.Debug("상태", "dump", expensiveDump())는 레벨이 Info여도 expensiveDump()를 부른다. 인자는 호출 전에 평가되기 때문이다. 파트 4에서 본 defer의 인자 평가 시점과 같은 함정이다. slog.LogValuer로 감싸면 실제로 기록될 때만 계산된다. l.Enabled(ctx, slog.LevelDebug)로 감싸는 방법도 있다.

요청 ID를 그룹 안에 넣는다. 이 챕터에서 실제로 걸린 그 버그다.

정리

slog는 Logger와 Handler로 나뉜다. 형식과 목적지는 시작 지점에서 한 번 정한다.
HandlerOptions.ReplaceAttr로 필드를 지우거나 바꾼다. 필드 이름 표준화, 마스킹, 시각 형식.
LogAttrs는 키-값 짝이 어긋날 수 없고 더 빠르다. GroupAttrs는 []slog.Attr을 그대로 받는 Group이다.
비밀값은 slog.LogValuer와 String()을 함께 구현한 타입으로 막는다.
NewMultiHandler는 Enabled를 통과한 핸들러에만 Clone한 레코드를 넘긴다.
요청 ID는 커스텀 핸들러가 context에서 읽어 붙인다. WithGroup 때문에 그룹 안에 들어가지 않도록 그룹 적용을 미룬다.
LevelVar로 재시작 없이 레벨을 바꾼다. 관리 엔드포인트는 내부망에만.
GORM은 logger.NewSlogLogger로 붙이고, ParameterizedQueries를 켠다.

연습문제

applog.Level을 바꾸는 HTTP 엔드포인트 PUT /admin/log-level을 만들어 보자. 본문은 {"level":"debug"}. slog.Level은 UnmarshalText를 구현하고 있으니 직접 파싱할 필요가 없다. 다 만든 뒤, 이 엔드포인트를 공개 라우터에 붙이면 어떤 공격이 가능한지 생각해 보자. (힌트: 로그량과 디스크)
12-1의 web.LogFunc 자리에 *slog.Logger를 넣어 보자. apperr.Kind에 따라 로그 레벨을 다르게 하고(KindInternal만 Error), apperr.Ops(err)를 속성으로 붙인다. 500과 400의 로그 레벨이 달라진 뒤 "에러 로그가 급증했다"는 알림이 실제로 의미를 갖게 되는지 확인해 보자.
testing/slogtest로 ContextHandler를 검증해 보자. slogtest.Run(t, newHandler, result) 형태이고, 두 번째 인자는 핸들러를 만드는 함수, 세 번째는 기록된 로그를 map[string]any로 파싱해 돌려주는 함수다. 계약 위반이 하나라도 나오는가?

이 챕터에서 다루는 것​

문제 — log.Printf로는 검색이 안 된다​

Logger와 Handler​

속성 붙이는 세 가지 방법​

비밀값은 타입으로 막는다​

NewMultiHandler로 여러 곳에 보내기​

context에서 요청 ID를 자동으로 붙이기​

여기서 실제로 걸린 버그​

미들웨어와 합치기​

실행 중 레벨 바꾸기​

GORM 느린 쿼리를 slog로 (11-5의 숙제)​

구 log 패키지와의 관계​

흔한 실수​

정리​

연습문제​