はじめに
Go の net/http で web server を立てた際に、手前に nginx などのプロキシを置くパターンと置かないパターンがあると思います。
rails などでは c10k やバッファリングの問題から nginx とセットで構築することが多いように思いますが、go の場合 goroutine がうまいことやってくれるので nginx などのプロキシを置かないケースがあります。
置かない時に nginx が出してくれる相当のアクセスログを go で出したいな、となったので http と gRPC それぞれで実装したサンプルです。
http server
アクセスロギングのような共通処理は middleware パターンが適しているので、独自 middleware を作って、http server に差し込みます。
以下はその middleware の実装例。
package middleware
import (...) // 省略
// サンプルの都合上ここでロガー作ってますが、実際はアプリ用のロガーを使います
var logger, _ = zap.NewProduction()
func AccessLogger(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
startTime := time.Now()
reqBodyBuf, _ := io.ReadAll(r.Body)
r.Body = io.NopCloser(bytes.NewBuffer(reqBodyBuf)) // 一度読み切るとそれ以降読めなくなるため、再度詰め直す
lrw := middleware.NewWrapResponseWriter(w, 1) // レスポンスボディが取得できるようにラップする
resBodyBuf := &bytes.Buffer{}
lrw.Tee(resBodyBuf)
// ServeHTTP で実際の処理を行なった後に実行される
defer func() {
logger.Sugar().Infow("access log",
"http_method", r.Method,
"path", r.URL,
"remote_addr", r.RemoteAddr,
"user_agent", r.UserAgent(),
"request", string(reqBodyBuf),
"status", lrw.Status(),
"response", resBodyBuf.String(),
"response_duration_second", fmt.Sprintf("%.3f", time.Since(startTime).Seconds()),
)
}()
next.ServeHTTP(lrw, r)
})
}
ロガーは zap を使ってますが、なんでも良いです。
アウトプットはこんな感じになります（zap が勝手に付加する項目は省略してます）。
{
"msg":"access log",
"http_method":"GET",
"path":"/healthcheck",
"remote_addr":"",
"user_agent":"curl/7.86.0",
"request":"{\"value\":\"hoge\"}",
"status":0,
"response":"fuga",
"response_duration_second":"0.004"
}
リクエストボディは io.ReadCloser の仕様上、io.ReadAll で一度読み切ってしまうと、以降の（ハンドラーでの）処理で読めなくなってしまうため、読んだ後に再度詰め直しています。
また、レスポンスボディを出力するのは工夫が必要で、元の ResponseWriter をラップする必要があり、ちょっと手間だったので chi が用意してくれているラッパーを借用しています。レスポンスステータスは指定していないとデフォが200ではなく0になってしまうので、ここはちょっと読み替えたほうが良さそうです（chi のラッパーの作りの問題）。
ちなみに chi が用意してくれているロギング middleware があるんですが、欲しい項目が出せる IF になっていなかったり、リクエストとレスポンスで別々に出力しないとダメだったりで、使うのをやめました。
参考
gRPC server
gRPC の場合はインターセプターとして実装するのが定石なので、以下のようなインターセプターを作って、server に差し込みます。
以下はそのインターセプターの実装例。
package grpc
import (...) // 省略
// ここのキーストリングは構成によって変わるので参考値
const (
realIPKey = "X-Forwarded-For"
userAgentKey = "User-Agent"
)
// サンプルの都合上ここでロガー作ってますが、実際はアプリ用のロガーを使います
var logger, _ = zap.NewProduction()
func accessLoggingInterceptor() grpc.UnaryServerInterceptor {
return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
startTime := time.Now()
// 実際の処理を実行
resp, err := handler(ctx, req)
c, ok := status.FromError(err)
if !ok {
panic(fmt.Sprintf("error is not gRPC status error: %s", err.Error()))
}
var realIP string
var userAgent string
if md, ok := metadata.FromIncomingContext(ctx); ok {
if v := md.Get(realIPKey); len(v) > 0 {
realIP = v[0]
}
if v := md.Get(userAgentKey); len(v) > 0 {
userAgent = v[0]
}
}
logger.Sugar().Infow("access log",
"method", info.FullMethod,
"remote_addr", realIP,
"user_agent", userAgent,
"request", req,
"status", c.Code(),
"response", resp,
"response_time_second", fmt.Sprintf("%.3f", time.Since(startTime).Seconds()),
)
return resp, err
}
}
アウトプットは http の方とそう変わらないので割愛。
普通に差し込むと、protocl buffer でシリアライズされる前のデータを扱えるので、リクエストとレスポンスをそのままログに吐けます。
リクエスト元 IP や UA などのメタ情報は基本的にメタデータから取得できます（gRPC では http ヘッダー/トレイラーの情報はメタデータで管理されます）。
ちなみに zap か logrus 限定にはなりますが、grpc が用意してくれているロギングインターセプターがあるので、それで事足りる場合はわざわざ自前で実装する必要はなさそうです。