出现的问题

最近在使用 kratos 开发 api 的时候, 由于通过 proto 生成的 server handler 不符合业务的需求, 需要通过自定义 handlerFunc 来定义接口。 在开发中为了程序的可观测性，我使用了 kratos 提供的 logging 中间件。

在使用的过程中, 我发现自定义的 HandlerFunc 的请求日志没有显示, 而 proto 生成的请求正确显示了。

问题的原因

为了找到出现这种情况的原因, 我在官方的 Github 仓库提了个 issue(#1566), 得到了维护人员的解答。

出现这种情况的原因是 自己定义的 handlerFunc 不走 middleware 中间件, 需要自定义 http filter 才能解决。

解决

经过对 http filter 例子的简单研究, 参考了官方的 logging 中间件, 我自己实现了 logging filter.

代码:

package middleware

import (
	"fmt"
	"net/http"
	"time"

	"github.com/go-kratos/kratos/v2/errors"
	"github.com/go-kratos/kratos/v2/log"
	"github.com/go-kratos/kratos/v2/transport"
)

func Server(logger log.Logger) func(next http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			var (
				code      int32
				reason    string
				kind      string
				operation string
			)
			ctx := r.Context()
			startTime := time.Now()
			if info, ok := transport.FromServerContext(ctx); ok {
				kind = info.Kind().String()
				operation = info.Operation()
			}
			next.ServeHTTP(w, r)

			if se := errors.FromError(nil); se != nil {
				code = se.Code
				reason = se.Reason
			}
			level, stack := extractError(nil)
			_ = log.WithContext(ctx, logger).Log(level,
				"kind", "server",
				"component", kind,
				"operation", operation,
				"args", extractArgs(r),
				"code", code,
				"reason", reason,
				"stack", stack,
				"latency", time.Since(startTime).Seconds(),
			)
		})
	}
}

// extractArgs returns the string of the req
func extractArgs(req interface{}) string {
	if stringer, ok := req.(fmt.Stringer); ok {
		return stringer.String()
	}
	return fmt.Sprintf("%+v", req)
}

// extractError returns the string of the error
func extractError(err error) (log.Level, string) {
	if err != nil {
		return log.LevelError, fmt.Sprintf("%+v", err)
	}
	return log.LevelInfo, ""
}

顺利的显示了请求的日志:

INFO ts=2021-10-22T21:21:23+08:00 caller=logging.go:34 service.id=DESKTOP-DE38CMV service.name= service.version= trace_id= span_id= kind=server component=http op
eration=/test args=&{Method:GET URL:/test Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[Accept:[text/html,application/xhtml+xml,application/xml;q=0.9,image
/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9] Accept-Encoding:[gzip, deflate, br] Accept-Language:[zh,zh-CN;q=0.9] Cache-Control:
[max-age=0] Connection:[keep-alive] Cookie:[Pycharm-c725b11f=c83c5d07-f28a-4c41-8b0f-c4c1664b7990; _ga=GA1.1.862586244.1625668431] Sec-Ch-Ua:["Chromium";v="94",
"Google Chrome";v="94", ";Not A Brand";v="99"] Sec-Ch-Ua-Mobile:[?0] Sec-Ch-Ua-Platform:["Windows"] Sec-Fetch-Dest:[document] Sec-Fetch-Mode:[navigate] Sec-Fetch
-Site:[none] Sec-Fetch-User:[?1] Upgrade-Insecure-Requests:[1] User-Agent:[Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrom
e/94.0.4606.81 Safari/537.36]] Body:{} GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:localhost:8000 Form:map[] PostForm:map[] MultipartForm:
<nil> Trailer:map[] RemoteAddr:[::1]:8787 RequestURI:/test TLS:<nil> Cancel:<nil> Response:<nil> ctx:0xc0000f4c90} code=0 reason= stack= latency=0

参考