Go 백엔드 7: 로깅

개요

RequestID, Logger 미들웨어를 고도화하여 요청, 응답에 대한 로깅을 구조적으로 남겨서 추적, 모니터링에 유용하게 만들어보자.

링크

• GitHub 브랜치: https://github.com/nicewook/gocore/tree/6_logging
• 블로그 링크
  • Go 백엔드 1: 클린 아키텍처 기본
  • Go 백엔드 2: 설정
  • Go 백엔드 3: 데이터베이스 연결
  • Go 백엔드 4: 유닛 테스트
  • Go 백엔드 5: 의존성 주입
  • Go 백엔드 6: 미들웨어
  • Go 백엔드 7: 로깅

RequestID 미들웨어

// AS-IS
e.Use(middleware.RequestID())

// TO-BE
e.Use(middleware.RequestIDWithConfig(middleware.RequestIDConfig{
	RequestIDHandler: func(c echo.Context, requestID string) {
		// RequestID를 request header 및 context 에 추가하기
		// 이렇게 하면 다른 미들웨어나 handler, usecase, repository 등에서 RequestID를 가져다 쓸 수 있다
		req := c.Request()
		req.Header.Set(echo.HeaderXRequestID, requestID) // 요청 헤더에 추가

		ctx := contextutil.WithRequestID(req.Context(), requestID)
		c.SetRequest(req.WithContext(ctx))
	},
}))

middleware.RequestID 로 기본 설정만을 사용하던 것을, middleware.RequestIDWithConfig 를 사용하여 세부 설정을 추가하였다.

먼저, 미들웨어 내부에서 찾아내거나 생성한 requestID를 request의 헤더에 추가하였는데 이는 요청이 다시 외부로 요청을 하도록 하는 경우에도 requestID를 추적하기 위함이다. 컨텍스트에도 넣어주었는데 handler, usecase, repository 등에서 필요할 때에 빠르게 requestID를 가져올 수 있도록 하였다. 참고로 RequestIDWithConfig 함수의 구현을 찾아 들어가보면 이해에 도움이 될 것이다.

requestID를 컨텍스트에 넣어주거나 꺼내주는 헬퍼함수를 만들어두었다.

// pkg/contextutil/contextutil.go
func WithRequestID(ctx context.Context, requestID string) context.Context {
	return context.WithValue(ctx, echo.HeaderXRequestID, requestID)
}

func GetRequestID(ctx context.Context) string {
	if requestID, ok := ctx.Value(echo.HeaderXRequestID).(string); ok {
		return requestID
	}
	return "no-request-id-in-context"
}

Logger 미들웨어

// internal/middlewares/logger.go
func LoggerMiddleware(logger *slog.Logger) echo.MiddlewareFunc {

	return middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{

		BeforeNextFunc: func(c echo.Context) {
			// 요청이 시작될 때 실행되는 함수.
			// - 요청 컨텍스트에 `request_id`가 포함된 로거를 추가하여 이후 handler, usecase, repository 등에서 로깅할 때 사용.
			req := c.Request()
			requestID := contextutil.GetRequestID(c.Request().Context())
			ctxLogger := logger.With(slog.String("request_id", requestID))
			ctx := contextutil.WithLogger(req.Context(), ctxLogger)
			c.SetRequest(req.WithContext(ctx))
		},

		// 요청 및 응답에서 로깅할 값들
		LogRequestID: true, // 요청 ID 로깅
		LogStatus:    true, // HTTP 응답 상태 코드 로깅
		LogMethod:    true, // HTTP 메서드 (GET, POST 등) 로깅
		LogURIPath:   true, // 요청된 URI 경로 로깅
		LogRemoteIP:  true, // 클라이언트 IP 주소 로깅
		LogUserAgent: true, // 요청한 클라이언트의 User-Agent 로깅
		LogReferer:   true, // Referer 헤더(어디서 요청이 왔는지) 로깅
		LogLatency:   true, // 요청 완료까지 걸린 시간 로깅
		LogError:     true, // 에러 발생 시 로깅
		HandleError:  true, // 에러 발생 시 글로벌 에러 핸들러로 전달하여 적절한 응답을 반환

		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
			// 공통 로깅 필드 설정 (모든 요청에서 공통적으로 기록할 항목)
			baseLogger := logger.With(
				slog.String("request_id", v.RequestID),
				slog.Int("status", v.Status),
				slog.String("method", v.Method),
				slog.String("path", v.URIPath),
				slog.String("remote_ip", v.RemoteIP),
				slog.String("user_agent", v.UserAgent),
				slog.String("referer", v.Referer),
				slog.String("latency", v.Latency.String()),
			)
			if v.Error != nil {
				baseLogger.With(slog.String("err", v.Error.Error())).Error("REQUEST_ERROR")
			} else {
				baseLogger.Info("REQUEST_SUCCESS")
			}
			return nil
		},
	})
}

echo가 제공하는 미들웨어를 최대한 활용하여 만들어보았다.

• BeforeNextFunc: 앞의 RequestID 미들웨어에서 만들어둔 requestID를 추출하여 request_id 필드를 기본으로 가지는 ctxLogger를 만들어서 컨텍스트에 넣어주었다. 이후 컨텍스트에서 logger를 꺼내어 로깅을 하는 경우에는 기본적으로 requestID 정보를 담게 된다.
• 요청 및 응답에서 로깅할 값들: 로깅에 사용할 값들을 true로 설정해두면 LogValuesFunc 에서 사용할 수 있다.
• LogValuesFunc: 요청이 에러가 발생하는 지 여부에 따라 로깅할 내용을 정의해준다.

logger 를 컨텍스트에 넣어주거나 꺼내주는 헬퍼함수 역시 만들어두었다.

// pkg/contextutil/contextutil.go
type contextKey string

var loggerContextKey contextKey = "logger_context_key"

func WithLogger(ctx context.Context, logger *slog.Logger) context.Context {
	return context.WithValue(ctx, loggerContextKey, logger)
}

func GetLogger(ctx context.Context) *slog.Logger {
	if logger, ok := ctx.Value(loggerContextKey).(*slog.Logger); ok {
		return logger
	}

	logger := slog.Default()
	logger.Error("Default logger used",
		slog.String("reason", "no logger found in context"),
	)
	return logger
}

로그 예시

테스트를 위해 user handler의 GetAll 핸들러에 로깅을 하도록 해두었다.

func (h *UserHandler) GetAll(c echo.Context) error {
	logger := contextutil.GetLogger(c.Request().Context())
	logger.Info("UserHandler:GetAll")
	
	// (후략)
}

로그 내용은 다음과 같다. 핸들러쪽의 로그를 보면 UserHandler:GetAll 라는 메시지가 보이고, request_id가 기본으로 찍힌 것을 볼 수 있다. 요청이 처리되고 나면 그 결과에 대하여 지정해둔 항목이 출력된 것을 볼 수 있다.

{"time":"2025-02-21T19:53:58.509+09:00","level":"INFO","msg":"UserHandler:GetAll","request_id":"yFKFbBckBBPvzHtgydIFHvYSngtTfBxX"}
{"time":"2025-02-21T19:53:58.514+09:00","level":"INFO","msg":"REQUEST_SUCCESS","request_id":"yFKFbBckBBPvzHtgydIFHvYSngtTfBxX","status":200,"method":"GET","path":"/users","remote_ip":"127.0.0.1","user_agent":"IntelliJ HTTP Client/GoLand 2024.3.2.1","referer":"","latency":"5.02925ms"}

로거의 생성과 주입

로거의 생성 코드는 다음과 같다. Go에서 제공해주는 slog를 사용하였다. slog.Logger 는 slog.Handler 인터페이스를 가지고 있는 구조체이기에 만약 성능이 매우 중요하다면 이를 만족하도록 zerolog와 같은 더욱 빠른 라이브러리를 사용할 수 도 있다.

설정에 로그레벨 항목을 추가하였는데 이를 참고하여 로그레벨을 설정하고, 타임포맷을 설정하여 slog.Logger 를 생성하였다.

설정관련 추가한 부분은 다음 두 파일을 참고하기 바란다.

• config/config.dev.yaml
• internal/config/config.go

func NewLogger(cfg *config.Config) *slog.Logger {
	// 로그 레벨 설정
	logLevel := slog.LevelInfo
	switch strings.ToLower(cfg.App.LogLevel) {
	case "debug":
		logLevel = slog.LevelDebug
	case "info":
		logLevel = slog.LevelInfo
	case "warn":
		logLevel = slog.LevelWarn
	case "error":
		logLevel = slog.LevelError
	default:
		logLevel = slog.LevelInfo
	}

	logHandler := slog.NewJSONHandler(
		os.Stdout,
		&slog.HandlerOptions{
			Level: logLevel,
			ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
				if a.Key == slog.TimeKey {
					return slog.String(a.Key, time.Now().Format("2006-01-02T15:04:05.000Z07:00"))
				}
				return a
			},
		},
	)
	return slog.New(logHandler)
}

의존선 주입 부분은 다음과 같이 변경되었다.

• NewConfig 생성자에서 생성된 *config.Config가 NewLogger에 주입된다.
• RegisterMiddlewares 역시 *slog.Logger 를 파라미터로 받도록 변경되어, 자동으로 주입이 된다.

func main() {
	app := fx.New(
		fx.Provide(
			NewConfig,
			NewLogger,
			NewDB,
			echo.New,
		),
		fx.Provide(
			repository.NewUserRepository,
			repository.NewProductRepository,
			repository.NewOrderRepository,
		),
		fx.Provide(
			usecase.NewUserUseCase,
			usecase.NewProductUseCase,
			usecase.NewOrderUseCase,
		),
		fx.Invoke(
			middlewares.RegisterMiddlewares,
			handler.NewUserHandler,
			handler.NewProductHandler,
			handler.NewOrderHandler,
		),
		fx.Invoke(StartServer),
	)

	app.Run()
}

생각해 볼 것들

로그레벨과 로깅 빈도

너무 많은 로깅은 성능을 저하시키거나 민감한 정보를 노출시킬 수 있는 부분에 주의도 필요하다. 가능한 최소한의 로깅을 하도록 노력하고 개발시에 필요한 로그는 디버그 레벨로 작성한다. 성능이 민감한 서비스라면 zerolog와 같이 빠른 라이브러리를 slog.Handler 인터페이스에 맞춰 구현해줘도 된다.

모니터링

현재는 표준 출력으로 로그를 내보내고 있다. 이를 Loki, Grafana 등의 로그저장, 모니터링 서비스로 전달하는 방법을 고민해보는 것도 좋겠다. 여기까지 구현했다면 Cursor, ChatGPT 등의 도움을 받으면 어렵지 않게 구성해보고 이해해볼 수 있을 것이다.

혹은 OpenTelemetry와 같은 분산 트레이싱, Kafka로 전송하는 방법도 있다.

마무리

다음 주제는 아직 정하지 않았지만 DB migration과 sqlc, sqlx, squirrel 등의 라이브러리나 인증/인가 쪽을 염두에 두고 있다. 둘 다 들여다볼 것이 많은 주제라 시간이 걸릴것으로 예상한다.