HTTP request ID association with logs

Introduction

Hertz is an ultra-large-scale enterprise-level microservice HTTP framework, featuring high ease of use, easy expansion, and low latency etc.

Hertz uses the self-developed high-performance network library Netpoll by default. In some special scenarios, Hertz has certain advantages in QPS and latency compared to go net. For performance data, please refer to the echo data below.

In internal practice, for some typical services, such as services with a high proportion of frameworks, gateways and other services, after migrating Hertz, compared to the Gin framework, the resource usage is significantly reduced. For more information, see hertz-benchmark.

Hertz provides requestid middleware、built-in hlog log library and some hlog log component extensions, this article focuses on how to associate request IDs with logs to make it easier for users to find logs.

Hands-on

Introduction to the Request ID middleware

The requestid middleware for Hertz is based on the Gin framework's requestid and adapted to Hertz. Its main purpose is to add rquestid to the HTTP response and context of a request to uniquely identify a HTTP request.

It is used in the following way:

package main

import (
    "context"

    "github.com/cloudwego/hertz/pkg/app"
    "github.com/cloudwego/hertz/pkg/app/server"
    "github.com/cloudwego/hertz/pkg/common/utils"
    "github.com/cloudwego/hertz/pkg/protocol/consts"
    "github.com/hertz-contrib/requestid"
)

func main() {
    h := server.Default()

    h.Use(requestid.New())

    // Example ping request.
    h.GET("/ping", func(ctx context.Context, c *app.RequestContext) {
        c.JSON(consts.StatusOK, utils.H{"ping": "pong"})
    })

    h.Spin()
}

Accessing 127.0.0.1:8888/ping, we will see an extra X-request-ID field in the HTTP response header.

Hlog extensions

Hertz also provides hlog for printing the framework's internal logs. Users can use this in simple log printing scenarios.

The default hlog is based on the log package implementation and has normal performance, while Hertz provides the logger extension, which provides zap and logrus implementations.

The logrus extension is used in the following way:

package main

import (
    "context"

    "github.com/cloudwego/hertz/pkg/common/hlog"
    hertzlogrus "github.com/hertz-contrib/logger/logrus"
)

func main() {
    logger := hertzlogrus.NewLogger()
    hlog.SetLogger(logger)
    hlog.CtxInfof(context.Background(), "hello %s", "hertz")
}

Practical code

Associate the log of a request by using the requestid middleware with the logger extension.

Custom Hooks

Logrus supports a user-defined Hook that can print requestid in the log by implementing a custom Hook.

// Custom Hook
type RequestIdHook struct{}

func (h *RequestIdHook) Levels() []logrus.Level {
    return logrus.AllLevels
}

func (h *RequestIdHook) Fire(e *logrus.Entry) error {
    ctx := e.Context
    if ctx == nil {
        return nil
    }
    value := ctx.Value("X-Request-ID")
    if value != nil {
        e.Data["log_id"] = value
    }
    return nil
}

Full code

package main

import (
    "context"

    "github.com/cloudwego/hertz/pkg/app"
    "github.com/cloudwego/hertz/pkg/app/server"
    "github.com/cloudwego/hertz/pkg/common/hlog"
    "github.com/cloudwego/hertz/pkg/common/utils"
    "github.com/cloudwego/hertz/pkg/protocol/consts"
    hertzlogrus "github.com/hertz-contrib/logger/logrus"
    "github.com/hertz-contrib/requestid"
    "github.com/sirupsen/logrus"
)

type RequestIdHook struct{}

func (h *RequestIdHook) Levels() []logrus.Level {
    return logrus.AllLevels
}

func (h *RequestIdHook) Fire(e *logrus.Entry) error {
    ctx := e.Context
    if ctx == nil {
        return nil
    }
    value := ctx.Value("X-Request-ID")
    if value != nil {
        e.Data["log_id"] = value
    }
    return nil
}

func main() {
    h := server.Default()
    logger := hertzlogrus.NewLogger(hertzlogrus.WithHook(&RequestIdHook{}))
    hlog.SetLogger(logger)

    h.Use(requestid.New())

    // Example ping request.
    h.GET("/ping", func(ctx context.Context, c *app.RequestContext) {
        hlog.CtxInfof(ctx, "test log")
        c.JSON(consts.StatusOK, utils.H{"ping": "pong"})
    })
    h.Spin()
}

Effect

{"level":"info","msg":"HERTZ: Using network library=netpoll","time":"2022-11-04T13:58:51+08:00"}
{"level":"info","msg":"HERTZ: HTTP server listening on address=[::]:8888","time":"2022-11-04T13:58:51+08:00"}
{"level":"info","log_id":"8f0012a3-f97b-49ca-b13b-1f009585b5d9","msg":"test log","time":"2022-11-04T13:59:11+08:00"}

In this way we associate the log of an HTTP request with requstid. In fact Hertz provides more powerful capabilities, which we will cover in the next article. You can check out obs-opentelemetry in advance if you are interested.

Reference

• https://github.com/cloudwego/hertz/
• https://github.com/hertz-contrib/requestid/issues/6
• https://github.com/hertz-contrib/logger

Comments

[bxio]

How would you pass the log_id to other functions that are called deeper in the stack? Would you need to pass the ctx to every function that wants to log that log_id?

[li-jin-ou]

It's a good question.we need to pass ctx to each function if we need the log_id,but I've seen some people implement a simple thread_local , which avoids passing context.

[li-jin-ou]

Why do you need to pass the ctx, which contains the log_id

refer to github.com/hertz-contrib/requestid...