diff --git a/appx/context.go b/appx/context.go index cba01e37..9fa90cb4 100644 --- a/appx/context.go +++ b/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,18 +29,14 @@ 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) @@ -49,7 +44,7 @@ func RequestIDMiddleware() func(http.Handler) http.Handler { }) } -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 "" -} diff --git a/appx/context_test.go b/appx/context_test.go index a95093bc..b79be0f2 100644 --- a/appx/context_test.go +++ b/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() diff --git a/appx/gql.go b/appx/gql.go index 685b0687..e0cd70bc 100644 --- a/appx/gql.go +++ b/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) }, diff --git a/log/echo.go b/log/echo.go index 657719fa..449b2bb5 100644 --- a/log/echo.go +++ b/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 "" +}