feat(log): add incoming access logs and update outcoming log format

appx/context.go

@@ -3,7 +3,6 @@ package appx
 import (
 	"context"
 	"net/http"
-	"strings"
 
 	"github.com/google/uuid"
 	"github.com/reearth/reearthx/log"
@@ -12,15 +11,15 @@ import (
 type requestIDKey struct{}
 
 func ContextMiddleware(key, value any) func(http.Handler) http.Handler {
-	return ContextMiddlewareBy(func(r *http.Request) context.Context {
+	return ContextMiddlewareBy(func(w http.ResponseWriter, r *http.Request) context.Context {
 		return context.WithValue(r.Context(), key, value)
 	})
 }
 
-func ContextMiddlewareBy(c func(*http.Request) context.Context) func(http.Handler) http.Handler {
+func ContextMiddlewareBy(c func(http.ResponseWriter, *http.Request) context.Context) func(http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			if ctx := c(r); ctx == nil {
+			if ctx := c(w, r); ctx == nil {
 				next.ServeHTTP(w, r)
 			} else {
 				next.ServeHTTP(w, r.WithContext(ctx))
@@ -30,26 +29,22 @@ func ContextMiddlewareBy(c func(*http.Request) context.Context) func(http.Handle
 }
 
 func RequestIDMiddleware() func(http.Handler) http.Handler {
-	return ContextMiddlewareBy(func(r *http.Request) context.Context {
+	return ContextMiddlewareBy(func(w http.ResponseWriter, r *http.Request) context.Context {
 		ctx := r.Context()
-		reqid := getHeader(r,
-			"X-Request-ID",
-			"X-Amzn-Trace-Id",       // AWS
-			"X-Cloud-Trace-Context", // GCP
-			"X-ARR-LOG-ID",          // Azure
-		)
+		reqid := log.GetReqestID(w, r)
 		if reqid == "" {
 			reqid = uuid.NewString()
 		}
 		ctx = context.WithValue(ctx, requestIDKey{}, reqid)
+		w.Header().Set("X-Request-ID", reqid)
 
 		logger := log.GetLoggerFromContextOrDefault(ctx).SetPrefix(reqid)
 		ctx = log.AttachLoggerToContext(ctx, logger)
 		return ctx
 	})
 }
 
-func GetRequestID(ctx context.Context) string {
+func GetRequestIDFromContext(ctx context.Context) string {
 	if ctx == nil {
 		return ""
 	}
@@ -58,15 +53,3 @@ func GetRequestID(ctx context.Context) string {
 	}
 	return ""
 }
-
-func getHeader(r *http.Request, keys ...string) string {
-	for _, k := range keys {
-		if v := r.Header.Get(k); v != "" {
-			return v
-		}
-		if v := r.Header.Get(strings.ToLower(k)); v != "" {
-			return v
-		}
-	}
-	return ""
-}

appx/context_test.go

@@ -25,8 +25,9 @@ func TestContextMiddleware(t *testing.T) {
 }
 
 func TestContextMiddlewareBy(t *testing.T) {
-	key := struct{}{}
-	ts := httptest.NewServer(ContextMiddlewareBy(func(r *http.Request) context.Context {
+	type keys struct{}
+	key := keys{}
+	ts := httptest.NewServer(ContextMiddlewareBy(func(w http.ResponseWriter, r *http.Request) context.Context {
 		if r.Method == http.MethodPost {
 			return context.WithValue(r.Context(), key, "aaa")
 		}
@@ -49,7 +50,7 @@ func TestContextMiddlewareBy(t *testing.T) {
 
 func TestRequestIDMiddleware(t *testing.T) {
 	ts := httptest.NewServer(RequestIDMiddleware()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		_, _ = w.Write([]byte(GetRequestID(r.Context())))
+		_, _ = w.Write([]byte(GetRequestIDFromContext(r.Context())))
 	})))
 	defer ts.Close()
 

appx/gql.go

@@ -8,6 +8,7 @@ import (
 	"github.com/99designs/gqlgen/graphql/handler"
 	"github.com/99designs/gqlgen/graphql/handler/extension"
 	"github.com/ravilushqa/otelgqlgen"
+	"github.com/reearth/reearthx/log"
 	"github.com/vektah/gqlparser/v2/gqlerror"
 )
 
@@ -33,8 +34,10 @@ func GraphQLHandler(c GraphQLHandlerConfig) http.Handler {
 	srv.SetErrorPresenter(
 		// show more detailed error messgage in debug mode
 		func(ctx context.Context, e error) *gqlerror.Error {
+			path := graphql.GetFieldContext(ctx).Path()
+			log.Debugfc(ctx, "gql error: %v: %v", path, e)
 			if c.Dev {
-				return gqlerror.ErrorPathf(graphql.GetFieldContext(ctx).Path(), e.Error())
+				return gqlerror.ErrorPathf(path, "%v", e)
 			}
 			return graphql.DefaultErrorPresenter(ctx, e)
 		},

log/echo.go

@@ -1,7 +1,10 @@
 package log
 
 import (
+	"fmt"
 	"io"
+	"net/http"
+	"strings"
 	"time"
 
 	"github.com/labstack/echo/v4"
@@ -203,29 +206,54 @@ func (l *Echo) AccessLogger() echo.MiddlewareFunc {
 			req := c.Request()
 			res := c.Response()
 			start := time.Now()
-			if err := next(c); err != nil {
-				c.Error(err)
-			}
-			stop := time.Now()
 
-			logger := GetLoggerFromContext(c.Request().Context())
-			if logger == nil {
-				logger = l.logger
-			}
-			logger.Infow(
-				"Handled request",
+			reqid := GetReqestID(res, req)
+			args := []any{
+				"time_unix", start.Unix(),
 				"remote_ip", c.RealIP(),
 				"host", req.Host,
+				"origin", req.Header.Get("Origin"),
 				"uri", req.RequestURI,
 				"method", req.Method,
 				"path", req.URL.Path,
+				"protocol", req.Proto,
 				"referer", req.Referer(),
 				"user_agent", req.UserAgent(),
-				"status", res.Status,
-				"latency", stop.Sub(start).Microseconds(),
-				"latency_human", stop.Sub(start).String(),
 				"bytes_in", req.ContentLength,
+				"request_id", reqid,
+				"route", c.Path(),
+			}
+
+			logger := GetLoggerFromContext(c.Request().Context())
+			if logger == nil {
+				logger = l.logger
+			}
+
+			// incoming log
+			logger.Infow(
+				fmt.Sprintf("<-- %s %s %s", req.Method, req.URL.Path, reqid),
+				args...,
+			)
+
+			if err := next(c); err != nil {
+				c.Error(err)
+			}
+
+			res = c.Response()
+			stop := time.Now()
+			latency := stop.Sub(start)
+			latencyHuman := latency.String()
+			args = append(args,
+				"status", res.Status,
 				"bytes_out", res.Size,
+				"letency", latency.Microseconds(),
+				"latency_human", latencyHuman,
+			)
+
+			// outcoming log
+			logger.Infow(
+				fmt.Sprintf("--> %s %s %s %d %s", req.Method, req.URL.Path, reqid, res.Status, latencyHuman),
+				args...,
 			)
 			return nil
 		}
@@ -240,3 +268,32 @@ func fromMap(m map[string]any) (res []any) {
 	}
 	return
 }
+
+func GetReqestID(w http.ResponseWriter, r *http.Request) string {
+	if reqid := getHeader(r,
+		"X-Request-ID",
+		"X-Cloud-Trace-Context", // Google Cloud
+		"X-Amzn-Trace-Id",       // AWS
+		"X-ARR-LOG-ID",          // Azure
+	); reqid != "" {
+		return reqid
+	}
+
+	if reqid := w.Header().Get("X-Request-ID"); reqid != "" {
+		return reqid
+	}
+
+	return ""
+}
+
+func getHeader(r *http.Request, keys ...string) string {
+	for _, k := range keys {
+		if v := r.Header.Get(k); v != "" {
+			return v
+		}
+		if v := r.Header.Get(strings.ToLower(k)); v != "" {
+			return v
+		}
+	}
+	return ""
+}