이전 포스팅에서는 Go에서 로그를 JSON으로 출력하는 방법을 알아보았는데 이번에는 API 서버에서 Request ID를 로깅하는 방법을 알아보려 한다.
모니터링에 힘쓰다보면 필연적으로 로깅을 많이 사용하게 된다. 그런데 로그를 보다보면, 특정 요청에 대한 로그를 찾기가 어려울 때가 있다. 특히 요청이 많이 오다보면, 시간대로 필터링하더라도 특정 요청에 대한 로그를 찾기가 어렵다.
func SomeAPIHandler(w http.ResponseWriter, r *http.Request) {
slog.Info("A")
slog.Info("B")
slog.Info("C")
//...
}
예를 들어 위와 같은 코드가 같은 코드가 있을 때 다음과 같이 로그가 들어왔다고 해보자
{"time":"2025-03-07T16:27:52.268722+09:00","level":"INFO","msg":"A"}
{"time":"2025-03-07T16:27:52.268723+09:00","level":"INFO","msg":"B"}
{"time":"2025-03-07T16:27:52.268724+09:00","level":"INFO","msg":"A"}
{"time":"2025-03-07T16:27:52.268725+09:00","level":"INFO","msg":"B"}
{"time":"2025-03-07T16:27:52.268726+09:00","level":"INFO","msg":"C"}
{"time":"2025-03-07T16:27:52.268727+09:00","level":"INFO","msg":"C"}
이렇게 로그가 들어왔을때 어떤게 첫번째 요청인지, 어떤게 두번째 요청인지 구분할 수 있을까? 어려울 것이다.
물론 문제가 있다면 에러로그만 봐도 되겠지만, 에러만 봐서 해결이 안되는 동시성 관련한 문제도 언제든지 생길 수 있으며, 에러는 없지만 값이 이상하다던가 하는 상황이 언제든 발생할 수 있다.
그래서 이런 문제를 해결하기 위해 예전부터 많이 써왔던 방식은 Request ID를 사용하는 것이다.
Request ID란 이름과 같이 요청을 식별하는 ID값이라고 보면 된다.
예를 들어 아까의 로그에 다음과 같이 requestID 필드가 추가되었다고 가정해보자
{"time":"2025-03-07T16:27:52.268722+09:00","level":"INFO","msg":"A", "requestID": "1234"}
{"time":"2025-03-07T16:27:52.268723+09:00","level":"INFO","msg":"B", "requestID": "1234"}
{"time":"2025-03-07T16:27:52.268724+09:00","level":"INFO","msg":"A", "requestID": "5678"}
{"time":"2025-03-07T16:27:52.268725+09:00","level":"INFO","msg":"B", "requestID": "5678"}
{"time":"2025-03-07T16:27:52.268726+09:00","level":"INFO","msg":"C", "requestID": "5678"}
{"time":"2025-03-07T16:27:52.268727+09:00","level":"INFO","msg":"C", "requestID": "1234"}
이렇게 되면, 아주 쉽게 requestID가 같은 것들은 같은 요청에 대한 로그라는 것을 알 수 있다.
그리고 로그를 다루는 플랫폼에서는 requestID:1234와 같은 명령어를 통해 특정 로그만 필터링할 수도 있을 것이다.
이처럼 RequestID는 요청을 식별하여, 추후 생길 디버깅 등에 매우 용이하게 대처할 수 있도록 돕는다.
RequestID를 Logger에 추가하는 방법
사실 logger에 필드를 추가하는 방법 자체는 쉬운 편이다. With함수를 사용하면 된다.
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger = logger.With("requestID", "1234")
이렇게 하면 logger에 requestID라는 필드에 쉽게 추가할 수 있다.
그런데 API마다 RequestID를 다르게 주어야 하는데, 핸들러의 시작마다 RequestID를 추가하는 코드를 넣는다면, 코드가 너무 반복적이고, 가독성이 떨어질 것이다. 그리고 휴먼 에러 확률도 높아진다.
이를 방지하기 위해 일반적으로 사용하는 방법은 Middleware를 사용하는 것이다.
flowchart LR
subgraph RequestIDMiddleware
requestIdGenerate --> SomeAPIHandler
end
user1[User] -->|GET /some/api| RequestIDMiddleware
RequestIDMiddleware -->|Response| user2[User]
Middleware는 Handler 메서드를 감싸서, 실제 API 핸들러 전, 후의 작업을 수행할 수 있게 돕는다.
그래서 위 다이어그램과 같이 요청 시 RequestIDMiddleware가 먼저 요청을 받아 Request ID를 생성한 후 API 핸들러에게 전달해주는 방식으로 사용할 수 있다.
이렇게 하면 API 핸들러에서는 Request ID를 신경쓰지 않아도 되고, Middleware에서는 Request ID를 생성하는 로직만 신경쓰면 된다.
Spring 에서는 이런 방식을 Filter로 제공하고 있고, Go에서는 다음 인터페이스를 구현하면 Middleware로 사용할 수 있다.
type MiddlewareFunc func(next http.Handler) http.Handler
쉽게 말해, Middleware 함수의 정의는 http.Handler를 인자로 받아서 http.Handler를 반환하는 함수이다.
이렇게 보면 어려울 수 있는데, 구현을 함께 해보면 쉽게 이해할 수 있을 것이다.
package middleware
import (
"context"
"net/http"
"github.com/google/uuid"
)
func RequestIDMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
ctx := r.Context()
if clientRequestID := r.Header.Get("Client-Request-ID"); clientRequestID != "" {
ctx = context.WithValue(ctx, "clientRequestID", clientRequestID)
}
ctx = context.WithValue(ctx, "requestID", uuid.New().String())
next.ServeHTTP(w, r.WithContext(ctx))
})
}
먼저 Client-Request-ID 값을 받았다. 사실 받지 않아도 되지만, 클라이언트에서 해당 Client-Request-ID 값을 가지고 모니터링에 이용하고 있다면, 클라이언트에서 서버에 이르기까지의 사용자 상호작용을 살펴볼 수도 있다.
다만 requestID는 항상 UUID를 새로 생성하도록 하고 있는데 이는 악의적인 사용자가 헤더값을 변경하여 요청을 보낼 수 있기 때문이다.
미들웨어에서 하는 것이라곤, Context에 requestID와 clientRequestID 값을 넣어주는 것 외엔 크게 없다.
실제로 로깅에 requestID를 포함시키는 것은 slog.Handler 라는 인터페이스를 구현하면 된다.
RequestID Handler 구현하기
package logging
import (
"context"
"log/slog"
)
type requestIDHandler struct {
handler slog.Handler
}
func NewRequestIDHandler(handler slog.Handler) slog.Handler {
return &requestIDHandler{handler: handler}
}
func (c *requestIDHandler) Enabled(ctx context.Context, level slog.Level) bool {
return c.handler.Enabled(ctx, level)
}
func (c *requestIDHandler) Handle(ctx context.Context, r slog.Record) error {
if requestID, ok := ctx.Value("requestID").(string); ok {
r.AddAttrs(slog.String("requestID", requestID))
}
if clientRequestID, ok := ctx.Value("clientRequestID").(string); ok {
r.AddAttrs(slog.String("clientRequestID", clientRequestID))
}
return c.handler.Handle(ctx, r)
}
func (c *requestIDHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return &requestIDHandler{handler: c.handler.WithAttrs(attrs)}
}
func (c *requestIDHandler) WithGroup(name string) slog.Handler {
return &requestIDHandler{handler: c.handler.WithGroup(name)}
}
logging이라는 패키지에 requestIDHandler를 구현하였다. 주목해야할 메서드는 Handle 메서드이다.
해당 메서드는 Info, InfoContext등 실제 로깅을 하는 메서드가 호출되었을 때 실행되는 메서드로 InfoContext()의 경우 인자인 ctx을 이용해 필드를 담는 slog.Record를 핸들링 할 수 있다.
NewRequestIDHandler()함수를 보면 데코레이터 패턴이 적용되었음을 알수 있는데 이는 slog.Handler 인터페이스를 구현한 구조체를 받아서 requestIDHandler이를 구현한 구조체를 반환하고 있다.
이 말인 즉슨 추후 또 다른 커스텀 slog.Handler의 기능이 필요하더라도 log.NewRequestIDHandler(slog.NewJSONHandler(os.Stdout))와 같이 무한히 구현할 수 있다는 것이다.
자 이제 모든 준비가 끝났다.
사용하기
package main
import (
"log"
"log-json-demo/logging"
"log-json-demo/middleware"
"log/slog"
"net/http"
"os"
)
//TIP <p>To run your code, right-click the code and select <b>Run</b>.</p> <p>Alternatively, click
// the <icon src="AllIcons.Actions.Execute"/> icon in the gutter and select the <b>Run</b> menu item from here.</p>
func main() {
handler := logging.NewRequestIDHandler(slog.NewJSONHandler(os.Stdout, nil))
logger := slog.New(handler)
slog.SetDefault(logger)
mux := http.NewServeMux()
mux.Handle("GET /hello", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
slog.InfoContext(r.Context(), "Hello, World!")
w.Write([]byte("Hello, World!"))
}))
slog.Info("listen", "port", ":8080")
if err := http.ListenAndServe(":8080", middleware.RequestIDMiddleware(mux)); err != nil {
log.Fatal("ListenAndServe", err)
}
}
핸들러를 초기화해주고, logger를 생성해서 디폴트 Logger로 설정해주었다.
mux에는 GET /hello로 요청이 들어왔을 때 Hello, World!를 출력하고, 로깅을 하도록 하였다.
이제 해당 부분을 실행하면 아래처럼 요청할때마다 RequestID가 생성되어 로깅되는 것을 확인할 수 있다.
{"time":"2025-03-07T18:40:32.761218+09:00","level":"INFO","msg":"listen","port":":8080"}
{"time":"2025-03-07T18:40:33.951091+09:00","level":"INFO","msg":"Hello, World!","requestID":"7d497009-4fa0-4b9b-a2be-3bab6423e0f5"}
{"time":"2025-03-07T18:40:34.946194+09:00","level":"INFO","msg":"Hello, World!","requestID":"57d77ed6-dec5-4f60-9331-91677fa4316c"}
{"time":"2025-03-07T18:40:38.224631+09:00","level":"INFO","msg":"Hello, World!","requestID":"e135d626-8669-451b-b2df-481b12acda87"}
context만 같다면, 같은 요청에 대한 로그라는 것을 알 수 있을 것이다.