feat: improve logging, rework ctx

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,15 +40,15 @@ 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
 	github.com/prometheus/client_model v0.6.1 // indirect
 	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

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=

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)
-		})
-	}
-}

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 {

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
 						}

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
 }