Global logger logging context value, even tough a key does not exist in the event map.

[vkosev]

I've implemented an RequestID middleware, so that I can log an UUID for each Request in my logs.

The problem is that when I don't use the logger in the context, and use the global zerolog Logger a %!s(<nil>) string is printed. I expected it to not log anything for the UUID part, since it's not set in the context of the global logger.

package logger

var once sync.Once

var logger zerolog.Logger

func NewLogger() zerolog.Logger {
	once.Do(func() {

		consoleWriter := zerolog.ConsoleWriter{
			Out:        os.Stderr,
			TimeFormat: time.RFC3339,
			PartsOrder: []string{
				zerolog.TimestampFieldName,
				zerolog.LevelFieldName,
				zerolog.CallerFieldName,
				"request_id",
				zerolog.MessageFieldName,
			},
			FieldsExclude: []string{"request_id"},
			FormatCaller: func(i interface{}) string {
				return colorize(i, colorBold)
			},
			FormatMessage: func(i interface{}) string {
				return colorize("> ", colorCyan) + colorize(i, colorBold)
			},
			FormatFieldName: func(i interface{}) string {
				fmt.Println(i)
				return fmt.Sprintf("%s:", i)
			},
			FormatPrepare: func(evt map[string]interface{}) error {
				msg, ok := evt["request_id"]

				if ok {
					if msg == nil || msg == "" {
						delete(evt, "request_id")
					} else {
						evt["request_id"] = fmt.Sprintf(colorize(msg, colorBlue))
					}
				}

				return nil
			},
			FormatExtra: func(evt map[string]interface{}, buffer *bytes.Buffer) error {
				msg, ok := evt["request_id"]
				if ok {
					if msg == nil || msg == "" {
						delete(evt, "request_id")
					}
				}

				return nil
			},
		}

		logger = zerolog.New(consoleWriter).With().Timestamp().Caller().Logger()

	})

	return logger
}

These are my middleware funcs

func RequestIDMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		reqID := uuid.New().String()

		ctx := context.WithValue(r.Context(), service.RequestIDKey, reqID)

		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

func LoggerMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		reqId, ok := r.Context().Value(service.RequestIDKey).(string)
		if !ok {
			reqId = uuid.New().String()
		}

		l := log.Logger.With().Str("request_id", reqId).Logger()

		r = r.WithContext(l.WithContext(r.Context()))

		next.ServeHTTP(w, r)

	})
}

func main() {
	l := logger.NewLogger()
	log.Logger = l
	zerolog.DefaultContextLogger = &l

	s := service.NewService()
	h := handler.NewHandler(s)

	router := mux.NewRouter()

	router.Handle("/context-logger-message", RequestIDMiddleware(LoggerMiddleware(
		http.HandlerFunc(h.MessageWithLoggerInContext)))).Methods("GET")

	log.Info().Msg("Starting server")
	if err := http.ListenAndServe(":8080", router); err != nil {
		log.Fatal().Err(err).Msg("Server failed")
	}
}

When I start the application I receive the following log message:

2025-02-23T00:39:35+02:00 INF D:/dev/git/trainings/golang/request_id_logging/main.go:26 %!s(<nil>) > Starting server

From what I understand, the global logger should not contain the context data, for the request ID and not print the %!s(<nil>) string.

Hitting the HTTP Request, works, and logs a proper log with an UUID part.