From f5a081a4a260143187dfb8edd66e7c014ced8479 Mon Sep 17 00:00:00 2001 From: Aleksandr Razumov Date: Mon, 3 Feb 2025 09:45:00 +0300 Subject: [PATCH] feat: improve logging, rework ctx --- go.mod | 8 ++++---- go.sum | 12 ++++++++++-- internal/app/middleware.go | 16 ---------------- internal/cmd/client.go | 4 ++++ internal/cmd/server.go | 25 ++++++++++++++++--------- internal/server/server.go | 22 +++++++++++++++++++++- 6 files changed, 55 insertions(+), 32 deletions(-) diff --git a/go.mod b/go.mod index e01ed89..d0d7a25 100644 --- a/go.mod +++ b/go.mod @@ -7,7 +7,7 @@ toolchain go1.22.10 require ( github.com/go-faster/errors v0.7.1 github.com/go-faster/jx v1.1.0 - github.com/go-faster/sdk v0.23.0 + github.com/go-faster/sdk v0.25.0 github.com/ogen-go/ogen v1.9.0 github.com/rs/cors v1.11.1 github.com/spf13/cobra v1.8.1 @@ -40,7 +40,7 @@ require ( github.com/grpc-ecosystem/grpc-gateway/v2 v2.25.1 // indirect github.com/inconshreveable/mousetrap v1.1.0 // indirect github.com/klauspost/compress v1.17.11 // indirect - github.com/mattn/go-colorable v0.1.13 // indirect + github.com/mattn/go-colorable v0.1.14 // indirect github.com/mattn/go-isatty v0.0.20 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/prometheus/client_golang v1.20.5 // indirect @@ -48,7 +48,7 @@ require ( github.com/prometheus/common v0.61.0 // indirect github.com/prometheus/procfs v0.15.1 // indirect github.com/segmentio/asm v1.2.0 // indirect - github.com/spf13/pflag v1.0.5 // indirect + github.com/spf13/pflag v1.0.6 // indirect go.opentelemetry.io/auto/sdk v1.1.0 // indirect go.opentelemetry.io/contrib/bridges/otelzap v0.9.0 // indirect go.opentelemetry.io/contrib/instrumentation/runtime v0.59.0 // indirect @@ -74,7 +74,7 @@ require ( go.opentelemetry.io/otel/sdk/metric v1.34.0 // indirect go.opentelemetry.io/proto/otlp v1.5.0 // indirect go.uber.org/automaxprocs v1.6.0 // indirect - golang.org/x/exp v0.0.0-20230725093048-515e97ebf090 // indirect + golang.org/x/exp v0.0.0-20250128182459-e0ece0dbea4c // indirect golang.org/x/net v0.34.0 // indirect golang.org/x/sys v0.29.0 // indirect golang.org/x/text v0.21.0 // indirect diff --git a/go.sum b/go.sum index 8eca977..cef1104 100644 --- a/go.sum +++ b/go.sum @@ -20,8 +20,10 @@ github.com/go-faster/errors v0.7.1 h1:MkJTnDoEdi9pDabt1dpWf7AA8/BaSYZqibYyhZ20AY github.com/go-faster/errors v0.7.1/go.mod h1:5ySTjWFiphBs07IKuiL69nxdfd5+fzh1u7FPGZP2quo= github.com/go-faster/jx v1.1.0 h1:ZsW3wD+snOdmTDy9eIVgQdjUpXRRV4rqW8NS3t+20bg= github.com/go-faster/jx v1.1.0/go.mod h1:vKDNikrKoyUmpzaJ0OkIkRQClNHFX/nF3dnTJZb3skg= -github.com/go-faster/sdk v0.23.0 h1:A7+DHEUau3N8uzqh8GY2l3p0YuhdIGYxLF2p4EmYcWw= -github.com/go-faster/sdk v0.23.0/go.mod h1:UJWFlbuRJHmXJwl4JxStMbbIZtMAz4fxrD4CnuDXCIc= +github.com/go-faster/sdk v0.24.0 h1:vH8lomFHZSjgWr1cyDg+57YNfh25JwoHgmTrUa1XpPs= +github.com/go-faster/sdk v0.24.0/go.mod h1:UJWFlbuRJHmXJwl4JxStMbbIZtMAz4fxrD4CnuDXCIc= +github.com/go-faster/sdk v0.25.0 h1:2vqmeLzN1QwSpnEdbUfDgl5ceiIz2zB5YoqQCtt7LpI= +github.com/go-faster/sdk v0.25.0/go.mod h1:UJWFlbuRJHmXJwl4JxStMbbIZtMAz4fxrD4CnuDXCIc= github.com/go-faster/yaml v0.4.6 h1:lOK/EhI04gCpPgPhgt0bChS6bvw7G3WwI8xxVe0sw9I= github.com/go-faster/yaml v0.4.6/go.mod h1:390dRIvV4zbnO7qC9FGo6YYutc+wyyUSHBgbXL52eXk= github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= @@ -58,6 +60,8 @@ github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0 github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= +github.com/mattn/go-colorable v0.1.14 h1:9A9LHSqF/7dyVVX6g0U9cwm9pG3kP9gSzcuIPHPsaIE= +github.com/mattn/go-colorable v0.1.14/go.mod h1:6LmQG8QLFO4G5z1gPvYEzlUgJ2wF+stgPZH1UqBm1s8= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= @@ -88,6 +92,8 @@ github.com/spf13/cobra v1.8.1 h1:e5/vxKd/rZsfSJMUX1agtjeTDf+qv1/JdBF8gg5k9ZM= github.com/spf13/cobra v1.8.1/go.mod h1:wHxEcudfqmLYa8iTfL+OuZPbBZkmvliBWKIezN3kD9Y= github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA= github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= +github.com/spf13/pflag v1.0.6 h1:jFzHGLGAlb3ruxLB8MhbI6A8+AQX/2eW4qeyNZXNp2o= +github.com/spf13/pflag v1.0.6/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= @@ -168,6 +174,8 @@ go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8= go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E= golang.org/x/exp v0.0.0-20230725093048-515e97ebf090 h1:Di6/M8l0O2lCLc6VVRWhgCiApHV8MnQurBnFSHsQtNY= golang.org/x/exp v0.0.0-20230725093048-515e97ebf090/go.mod h1:FXUEEKJgO7OQYeo8N01OfiKP8RXMtf6e8aTskBGqWdc= +golang.org/x/exp v0.0.0-20250128182459-e0ece0dbea4c h1:KL/ZBHXgKGVmuZBZ01Lt57yE5ws8ZPSkkihmEyq7FXc= +golang.org/x/exp v0.0.0-20250128182459-e0ece0dbea4c/go.mod h1:tujkw807nyEEAamNbDrEGzRav+ilXA7PCRAd6xsmwiU= golang.org/x/mod v0.22.0 h1:D4nJWe9zXqHOmWqj4VMOJhvzj7bEZg4wEYa759z1pH4= golang.org/x/mod v0.22.0/go.mod h1:6SkKJ3Xj0I0BrPOZoBy3bdMptDDU9oJrpohJ3eWZ1fY= golang.org/x/net v0.34.0 h1:Mb7Mrk043xzHgnRM88suvJFwzVrRfHEHJEl5/71CKw0= diff --git a/internal/app/middleware.go b/internal/app/middleware.go index 2dfc11e..4e56192 100644 --- a/internal/app/middleware.go +++ b/internal/app/middleware.go @@ -3,10 +3,6 @@ package app import ( "net/http" - "github.com/go-faster/sdk/zctx" - "go.uber.org/zap" - - "github.com/go-faster/simon/internal/middleware" "github.com/go-faster/simon/internal/oas" ) @@ -23,15 +19,3 @@ func NewSpanNameFormatter(h Router) func(operation string, r *http.Request) stri return route.OperationID() } } - -// LogMiddleware adds logger via zctx.With to request context. -func LogMiddleware(lg *zap.Logger) middleware.Middleware { - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - reqCtx := r.Context() - reqCtx = zctx.WithOpenTelemetryZap(reqCtx) - req := r.WithContext(zctx.Base(reqCtx, lg)) - next.ServeHTTP(w, req) - }) - } -} diff --git a/internal/cmd/client.go b/internal/cmd/client.go index ea1ea5c..8a4523e 100644 --- a/internal/cmd/client.go +++ b/internal/cmd/client.go @@ -82,6 +82,8 @@ func cmdClient() *cobra.Command { for { select { case <-t.ShutdownContext().Done(): + return nil + case <-ctx.Done(): return ctx.Err() case <-ticker.C: tick() @@ -158,6 +160,8 @@ func cmdClient() *cobra.Command { for { select { case <-t.ShutdownContext().Done(): + return nil + case <-ctx.Done(): return ctx.Err() default: if err := tick(); err != nil { diff --git a/internal/cmd/server.go b/internal/cmd/server.go index ccbf12e..8cec0af 100644 --- a/internal/cmd/server.go +++ b/internal/cmd/server.go @@ -2,6 +2,7 @@ package cmd import ( "context" + "net" "net/http" "os" "strconv" @@ -18,7 +19,6 @@ import ( "golang.org/x/sync/errgroup" "github.com/go-faster/simon/internal/app" - "github.com/go-faster/simon/internal/middleware" "github.com/go-faster/simon/internal/oas" "github.com/go-faster/simon/internal/server" ) @@ -48,7 +48,10 @@ func cmdServer() *cobra.Command { addr = "localhost:8080" } lg.Info("Listening on", zap.String("addr", addr)) - h, err := oas.NewServer(server.Server{}, + srv := server.NewServer( + t.TracerProvider(), + ) + h, err := oas.NewServer(srv, oas.WithMeterProvider(t.MeterProvider()), oas.WithTracerProvider(t.TracerProvider()), ) @@ -81,22 +84,26 @@ func cmdServer() *cobra.Command { ReadHeaderTimeout: time.Second, WriteTimeout: time.Second, ReadTimeout: time.Second, - Handler: middleware.Wrap(instrumentedHandler, app.LogMiddleware(lg)), + Handler: instrumentedHandler, + BaseContext: func(listener net.Listener) context.Context { + return t.BaseContext() + }, } lg.Info("Starting HTTP server", zap.String("addr", addr)) - parentCtx := ctx g, ctx := errgroup.WithContext(ctx) g.Go(func() error { - <-ctx.Done() - ctx, cancel := context.WithTimeout(context.Background(), time.Second) - defer cancel() - return s.Shutdown(ctx) + select { + case <-ctx.Done(): + return ctx.Err() + case <-t.ShutdownContext().Done(): + return s.Shutdown(t.BaseContext()) + } }) g.Go(func() error { if err := s.ListenAndServe(); err != nil { - if errors.Is(err, http.ErrServerClosed) && parentCtx.Err() != nil { + if errors.Is(err, http.ErrServerClosed) { lg.Info("HTTP server closed gracefully") return nil } diff --git a/internal/server/server.go b/internal/server/server.go index 4b279da..3d840d9 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -10,20 +10,38 @@ import ( "github.com/go-faster/errors" "github.com/go-faster/sdk/zctx" + "go.opentelemetry.io/otel/trace" + "go.uber.org/zap" "github.com/go-faster/simon/internal/oas" ) +func NewServer(tracerProvider trace.TracerProvider) *Server { + return &Server{ + trace: tracerProvider.Tracer("simon.server"), + } +} + // Server implements oas.Handler. -type Server struct{} +type Server struct { + trace trace.Tracer +} func (s Server) UploadFile(ctx context.Context, req *oas.UploadFileReq) (*oas.UploadResponse, error) { + ctx, span := s.trace.Start(ctx, "Server.UploadFile") + defer span.End() + iterations := req.Iterations.Or(1) buf := new(bytes.Buffer) if _, err := io.Copy(buf, req.File.File); err != nil { return nil, errors.Wrap(err, "copy") } + zctx.From(ctx).Info("UploadFile", + zap.Int("iterations", iterations), + zap.Int("size", buf.Len()), + ) + h := sha256.New() for i := 0; i < iterations; i++ { if _, err := h.Write(buf.Bytes()); err != nil { @@ -39,6 +57,8 @@ func (s Server) UploadFile(ctx context.Context, req *oas.UploadFileReq) (*oas.Up var _ oas.Handler = (*Server)(nil) func (s Server) Status(ctx context.Context) (*oas.Status, error) { + ctx, span := s.trace.Start(ctx, "Server.Status") + defer span.End() zctx.From(ctx).Info("Status") return &oas.Status{Message: "ok"}, nil }