clean access logging (#996)

examples/helloworld/client/main.go

@@ -2,11 +2,13 @@ package main
 
 import (
 	"context"
-	"log"
+	"fmt"
 
 	pb "github.com/go-kratos/kratos/examples/helloworld/helloworld"
 	"github.com/go-kratos/kratos/v2/errors"
+	"github.com/go-kratos/kratos/v2/log"
 	"github.com/go-kratos/kratos/v2/middleware"
+	"github.com/go-kratos/kratos/v2/middleware/logging"
 	"github.com/go-kratos/kratos/v2/middleware/recovery"
 	transgrpc "github.com/go-kratos/kratos/v2/transport/grpc"
 	transhttp "github.com/go-kratos/kratos/v2/transport/http"
@@ -18,59 +20,63 @@ func main() {
 }
 
 func callHTTP() {
+	logger := log.DefaultLogger
 	conn, err := transhttp.NewClient(
 		context.Background(),
 		transhttp.WithMiddleware(
 			recovery.Recovery(),
+			logging.Client(logger),
 		),
 		transhttp.WithEndpoint("127.0.0.1:8000"),
 	)
 	if err != nil {
-		log.Fatal(err)
+		panic(err)
 	}
 	client := pb.NewGreeterHTTPClient(conn)
 	reply, err := client.SayHello(context.Background(), &pb.HelloRequest{Name: "kratos"})
 	if err != nil {
-		log.Fatal(err)
+		panic(err)
 	}
-	log.Printf("[http] SayHello %s\n", reply.Message)
+	logger.Log(log.LevelInfo, fmt.Sprintf("[http] SayHello %s\n", reply.Message))
 
 	// returns error
 	reply, err = client.SayHello(context.Background(), &pb.HelloRequest{Name: "error"})
 	if err != nil {
-		log.Printf("[http] SayHello error: %v\n", err)
+		logger.Log(log.LevelInfo, fmt.Sprintf("[http] SayHello error: %v\n", err))
 	}
 	if errors.IsBadRequest(err) {
-		log.Printf("[http] SayHello error is invalid argument: %v\n", err)
+		logger.Log(log.LevelInfo, fmt.Sprintf("[http] SayHello error is invalid argument: %v\n", err))
 	}
 }
 
 func callGRPC() {
+	logger := log.DefaultLogger
 	conn, err := transgrpc.DialInsecure(
 		context.Background(),
 		transgrpc.WithEndpoint("127.0.0.1:9000"),
 		transgrpc.WithMiddleware(
 			middleware.Chain(
 				recovery.Recovery(),
+				logging.Client(logger),
 			),
 		),
 	)
 	if err != nil {
-		log.Fatal(err)
+		panic(err)
 	}
 	client := pb.NewGreeterClient(conn)
 	reply, err := client.SayHello(context.Background(), &pb.HelloRequest{Name: "kratos"})
 	if err != nil {
-		log.Fatal(err)
+		panic(err)
 	}
-	log.Printf("[grpc] SayHello %+v\n", reply)
+	logger.Log(log.LevelInfo, fmt.Sprintf("[grpc] SayHello %+v", reply))
 
 	// returns error
 	_, err = client.SayHello(context.Background(), &pb.HelloRequest{Name: "error"})
 	if err != nil {
-		log.Printf("[grpc] SayHello error: %v\n", err)
+		logger.Log(log.LevelInfo, fmt.Sprintf("[grpc] SayHello error: %v", err))
 	}
 	if errors.IsBadRequest(err) {
-		log.Printf("[grpc] SayHello error is invalid argument: %v\n", err)
+		logger.Log(log.LevelInfo, fmt.Sprintf("[grpc] SayHello error is invalid argument: %v", err))
 	}
 }

middleware/logging/grpc.go

@@ -0,0 +1,54 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/go-kratos/kratos/v2/log"
+	"github.com/go-kratos/kratos/v2/transport/grpc"
+)
+
+func grpcServerLog(logger log.Logger, ctx context.Context, args string, err error) {
+	info, ok := grpc.FromServerContext(ctx)
+	if !ok {
+		return
+	}
+	traceID, spanID := extractTrace(ctx)
+	code, errMsg := extractError(err)
+	level := log.LevelInfo
+	if err != nil {
+		level = log.LevelError
+	}
+	logger.Log(level,
+		"kind", "server",
+		"component", "grpc",
+		"trace_id", traceID,
+		"span_id", spanID,
+		"grpc.target", info.FullMethod,
+		"grpc.args", args,
+		"grpc.code", code,
+		"grpc.error", errMsg,
+	)
+}
+
+func grpcClientLog(logger log.Logger, ctx context.Context, args string, err error) {
+	info, ok := grpc.FromClientContext(ctx)
+	if !ok {
+		return
+	}
+	traceID, spanID := extractTrace(ctx)
+	code, errMsg := extractError(err)
+	level := log.LevelInfo
+	if err != nil {
+		level = log.LevelError
+	}
+	logger.Log(level,
+		"kind", "client",
+		"component", "grpc",
+		"trace_id", traceID,
+		"span_id", spanID,
+		"grpc.target", info.FullMethod,
+		"grpc.args", args,
+		"grpc.code", code,
+		"grpc.error", errMsg,
+	)
+}

middleware/logging/http.go

@@ -0,0 +1,56 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/go-kratos/kratos/v2/log"
+	"github.com/go-kratos/kratos/v2/transport/http"
+)
+
+func httpServerLog(logger log.Logger, ctx context.Context, args string, err error) {
+	info, ok := http.FromServerContext(ctx)
+	if !ok {
+		return
+	}
+	traceID, spanID := extractTrace(ctx)
+	code, errMsg := extractError(err)
+	level := log.LevelInfo
+	if err != nil {
+		level = log.LevelError
+	}
+	logger.Log(level,
+		"kind", "server",
+		"component", "http",
+		"trace_id", traceID,
+		"span_id", spanID,
+		"http.target", info.Request.RequestURI,
+		"http.method", info.Request.Method,
+		"http.args", args,
+		"http.code", code,
+		"http.error", errMsg,
+	)
+}
+
+func httpClientLog(logger log.Logger, ctx context.Context, args string, err error) {
+	info, ok := http.FromClientContext(ctx)
+	if !ok {
+		return
+	}
+	traceID, spanID := extractTrace(ctx)
+	code, errMsg := extractError(err)
+	level := log.LevelInfo
+	if err != nil {
+		level = log.LevelError
+	}
+	logger.Log(level,
+		"kind", "client",
+		"component", "http",
+		"trace_id", traceID,
+		"span_id", spanID,
+		"http.target", info.Request.RequestURI,
+		"http.method", info.Request.Method,
+		"http.args", args,
+		"http.code", code,
+		"http.error", errMsg,
+	)
+}

middleware/logging/logging.go

@@ -9,175 +9,67 @@ import (
 	"github.com/go-kratos/kratos/v2/errors"
 	"github.com/go-kratos/kratos/v2/log"
 	"github.com/go-kratos/kratos/v2/middleware"
-	"github.com/go-kratos/kratos/v2/transport/grpc"
-	"github.com/go-kratos/kratos/v2/transport/http"
+	"github.com/go-kratos/kratos/v2/transport"
 )
 
 // Server is an server logging middleware.
-func Server(l log.Logger) middleware.Middleware {
-	logger := log.NewHelper(l)
+func Server(logger log.Logger) middleware.Middleware {
 	return func(handler middleware.Handler) middleware.Handler {
-		return func(ctx context.Context, req interface{}) (interface{}, error) {
-			var (
-				path      string
-				method    string
-				args      string
-				component string
-				query     string
-				traceID   string
-			)
-			if tid := trace.SpanContextFromContext(ctx).TraceID(); tid.IsValid() {
-				traceID = tid.String()
-			}
-			if stringer, ok := req.(fmt.Stringer); ok {
-				args = stringer.String()
-			} else {
-				args = fmt.Sprintf("%+v", req)
-			}
-			if info, ok := http.FromServerContext(ctx); ok {
-				component = "HTTP"
-				path = info.Request.URL.Path
-				method = info.Request.Method
-				query = info.Request.URL.RawQuery
-			} else if info, ok := grpc.FromServerContext(ctx); ok {
-				component = "gRPC"
-				path = info.FullMethod
-				method = "POST"
-			}
-			reply, err := handler(ctx, req)
-			if component == "HTTP" {
-				if err != nil {
-					logger.Errorw(
-						"kind", "server",
-						"component", component,
-						"traceID", traceID,
-						"path", path,
-						"method", method,
-						"args", args,
-						"query", query,
-						"code", uint32(errors.Code(err)),
-						"error", err.Error(),
-					)
-					return nil, err
+		return func(ctx context.Context, req interface{}) (reply interface{}, err error) {
+			reply, err = handler(ctx, req)
+			if tr, ok := transport.FromContext(ctx); ok {
+				switch tr.Kind {
+				case transport.KindHTTP:
+					httpServerLog(logger, ctx, extractArgs(req), err)
+				case transport.KindGRPC:
+					grpcServerLog(logger, ctx, extractArgs(req), err)
 				}
-				logger.Infow(
-					"kind", "server",
-					"component", component,
-					"traceID", traceID,
-					"path", path,
-					"method", method,
-					"args", args,
-					"query", query,
-					"code", 0,
-				)
-			} else {
-				if err != nil {
-					logger.Errorw(
-						"kind", "server",
-						"component", component,
-						"traceID", traceID,
-						"path", path,
-						"method", method,
-						"args", args,
-						"code", uint32(errors.Code(err)),
-						"error", err.Error(),
-					)
-					return nil, err
-				}
-				logger.Infow(
-					"kind", "server",
-					"component", component,
-					"traceID", traceID,
-					"path", path,
-					"method", method,
-					"args", args,
-					"code", 0,
-				)
 			}
-			return reply, nil
+			return
 		}
 	}
 }
 
 // Client is an client logging middleware.
-func Client(l log.Logger) middleware.Middleware {
-	logger := log.NewHelper(l)
+func Client(logger log.Logger) middleware.Middleware {
 	return func(handler middleware.Handler) middleware.Handler {
-		return func(ctx context.Context, req interface{}) (interface{}, error) {
-			var (
-				path      string
-				method    string
-				args      string
-				component string
-				query     string
-				traceID   string
-			)
-			if tid := trace.SpanContextFromContext(ctx).TraceID(); tid.IsValid() {
-				traceID = tid.String()
-			}
-			if info, ok := http.FromClientContext(ctx); ok {
-				component = "HTTP"
-				path = info.Request.URL.Path
-				method = info.Request.Method
-				args = req.(fmt.Stringer).String()
-				query = info.Request.URL.RawQuery
-			} else if info, ok := grpc.FromClientContext(ctx); ok {
-				path = info.FullMethod
-				method = "POST"
-				component = "gRPC"
-				args = req.(fmt.Stringer).String()
-			}
-			reply, err := handler(ctx, req)
-			if component == "HTTP" {
-				if err != nil {
-					logger.Errorw(
-						"kind", "client",
-						"component", component,
-						"traceID", traceID,
-						"path", path,
-						"method", method,
-						"args", args,
-						"query", query,
-						"code", uint32(errors.Code(err)),
-						"error", err.Error(),
-					)
-					return nil, err
-				}
-				logger.Infow(
-					"kind", "client",
-					"component", component,
-					"traceID", traceID,
-					"path", path,
-					"method", method,
-					"args", args,
-					"query", query,
-					"code", 0,
-				)
-			} else {
-				if err != nil {
-					logger.Errorw(
-						"kind", "client",
-						"component", component,
-						"traceID", traceID,
-						"path", path,
-						"method", method,
-						"args", args,
-						"code", uint32(errors.Code(err)),
-						"error", err.Error(),
-					)
-					return nil, err
+		return func(ctx context.Context, req interface{}) (reply interface{}, err error) {
+			reply, err = handler(ctx, req)
+			if tr, ok := transport.FromContext(ctx); ok {
+				switch tr.Kind {
+				case transport.KindHTTP:
+					httpClientLog(logger, ctx, extractArgs(req), err)
+				case transport.KindGRPC:
+					grpcClientLog(logger, ctx, extractArgs(req), err)
 				}
-				logger.Infow(
-					"kind", "client",
-					"component", component,
-					"traceID", traceID,
-					"path", path,
-					"method", method,
-					"args", args,
-					"code", 0,
-				)
 			}
-			return reply, nil
+			return
 		}
 	}
 }
+
+func extractArgs(req interface{}) string {
+	if stringer, ok := req.(fmt.Stringer); ok {
+		return stringer.String()
+	}
+	return fmt.Sprintf("%+v", req)
+}
+
+func extractTrace(ctx context.Context) (traceID, spanID string) {
+	span := trace.SpanContextFromContext(ctx)
+	if span.HasTraceID() {
+		traceID = span.TraceID().String()
+	}
+	if span.HasSpanID() {
+		spanID = span.SpanID().String()
+	}
+	return
+}
+
+func extractError(err error) (code int, errMsg string) {
+	if err != nil {
+		code = errors.Code(err)
+		errMsg = fmt.Sprintf("%+v", err)
+	}
+	return
+}