In the previous post, we explored how to output logs as JSON in Go, and this time we will look at how to log Request IDs in an API server.
While striving for monitoring, we inevitably end up using logging extensively. However, when viewing logs, it can sometimes be challenging to find logs related to a specific request. Especially when there is a high volume of requests, it becomes difficult to find logs for a specific request even with time-based filtering.
func SomeAPIHandler(w http.ResponseWriter, r *http.Request) {
slog.Info("A")
slog.Info("B")
slog.Info("C")
//...
}
For example, if we have the above code and the logs come in as follows:
{"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"}
When the logs come in like this, would it be possible to distinguish which is the first request and which is the second? It would be difficult.
Of course, if there are issues, we could just look at the error logs, but concurrency-related problems may arise that cannot be resolved simply by looking at errors, and situations may occur where the values are strange even though there are no errors.
To address these issues, a commonly used method is to employ Request IDs.
A Request ID can be seen as an ID value that identifies a request, as the name suggests.
For example, let’s assume that the following requestID field has been added to the previous logs:
{"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"}
In this case, it becomes very easy to understand that logs with the same requestID are connected to the same request.
Additionally, on platforms that handle logs, command syntax like requestID:1234 could be used to filter specific logs.
Thus, Request IDs help identify requests, facilitating debugging and related tasks in the future.
Adding Request ID to the Logger
In fact, adding fields to a logger is relatively straightforward. You can use the With function.
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger = logger.With("requestID", "1234")
This way, you can easily add the requestID field to the logger.
However, since different APIs require different Request IDs, adding a Request ID at the start of each handler would result in repetitive code, diminishing readability and increasing the probability of human errors.
To mitigate this, a common approach is to use Middleware.
flowchart LR
subgraph RequestIDMiddleware
requestIdGenerate --> SomeAPIHandler
end
user1[User] -->|GET /some/api| RequestIDMiddleware
RequestIDMiddleware -->|Response| user2[User]
Middleware wraps the handler method, allowing specific operations to be executed before and after the actual API handler.
As illustrated in the above diagram, when a request is made, the RequestIDMiddleware first captures the request, generates a Request ID, and then passes it to the API handler.
This way, the API handler does not need to concern itself with the Request ID, while the Middleware only needs to handle the logic for generating the Request ID.
In Spring, this approach is provided as Filters, and in Go, you can use it by implementing the following interface:
type MiddlewareFunc func(next http.Handler) http.Handler
In simple terms, the definition of a Middleware function is one that takes http.Handler as input and returns http.Handler as output.
While this may seem daunting, implementing it alongside will make it easier to grasp.
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))
})
}
First, we received the value of Client-Request-ID. While it’s not necessary, if the client is using that Client-Request-ID value for monitoring, it is useful for examining user interactions from the client to the server.
However, the requestID always generates a new UUID to prevent malicious users from altering the header value and sending requests.
The Middleware does not have much to do other than inserting requestID and clientRequestID values into the Context.
To actually include the requestID in the logging, we need to implement the slog.Handler interface.
Implementing the 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)}
}
The requestIDHandler is implemented within the logging package. The key method to note is the Handle method.
This method is executed when the actual logging methods like Info or InfoContext are called, allowing for the slog.Record to be handled by utilizing the received ctx to include fields.
In the NewRequestIDHandler() function, it’s evident that the decorator pattern has been applied, meaning it accepts a struct that implements the slog.Handler interface and returns a struct that implements requestIDHandler.
This implies that should a need arise for further custom functionality of slog.Handler, it can infinitely be implemented like log.NewRequestIDHandler(slog.NewJSONHandler(os.Stdout)).
Now that all preparations are complete, let’s proceed to use it.
Usage
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)
}
}
We initialized a handler and created a logger, setting it as the default Logger.
The mux is set to log the message when there’s a request to GET /hello, responding with Hello, World!.
Now, upon executing that section, you can observe that a Request ID is generated and logged each time a request is made:
{"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"}
If the context is the same, it will indicate that these logs are related to the same request.