feat: log context cancelled error as warn instead of errors

Makefile

@@ -17,8 +17,8 @@ GOTEST_ARGS ?= -short
 OPENWRT_DEVICE ?= 192.168.1.1
 
 SIEGE_URLS_FILE ?= misc/siege/urls.txt
-SIEGE_CONCURRENCY ?= 50
-SIEGE_DURATION ?= 1M
+SIEGE_CONCURRENCY ?= 200
+SIEGE_DURATION ?= 5M
 
 data/bootstrap.d/dummy.yml:
 	mkdir -p data/bootstrap.d

internal/admin/server.go

@@ -2,6 +2,7 @@ package admin
 
 import (
 	"context"
+	"expvar"
 	"fmt"
 	"log"
 	"net"
@@ -115,7 +116,9 @@ func (s *Server) run(parentCtx context.Context, addrs chan net.Addr, errs chan e
 		router.Use(middleware.RealIP)
 	}
 
+	router.Use(middleware.RequestID)
 	router.Use(middleware.RequestLogger(bouncerChi.NewLogFormatter()))
+	router.Use(middleware.Recoverer)
 
 	if s.serverConfig.Sentry.DSN != "" {
 		logger.Info(ctx, "enabling sentry http middleware")
@@ -176,6 +179,7 @@ func (s *Server) run(parentCtx context.Context, addrs chan net.Addr, errs chan e
 				r.HandleFunc("/profile", pprof.Profile)
 				r.HandleFunc("/symbol", pprof.Symbol)
 				r.HandleFunc("/trace", pprof.Trace)
+				r.Handle("/vars", expvar.Handler())
 				r.HandleFunc("/{name}", func(w http.ResponseWriter, r *http.Request) {
 					name := chi.URLParam(r, "name")
 					pprof.Handler(name).ServeHTTP(w, r)

internal/chi/log_formatter.go

@@ -2,7 +2,6 @@ package chi
 
 import (
 	"context"
-	"fmt"
 	"net/http"
 	"time"
 
@@ -37,12 +36,19 @@ type LogEntry struct {
 
 // Panic implements middleware.LogEntry
 func (e *LogEntry) Panic(v interface{}, stack []byte) {
-	logger.Error(e.ctx, fmt.Sprintf("%s %s", e.method, e.path), logger.F("stack", string(stack)))
+	logger.Error(
+		e.ctx, "http panic",
+		logger.F("stack", string(stack)),
+		logger.F("host", e.host),
+		logger.F("method", e.method),
+		logger.F("path", e.path),
+	)
 }
 
 // Write implements middleware.LogEntry
 func (e *LogEntry) Write(status int, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
-	logger.Info(e.ctx, fmt.Sprintf("%s %s - %d", e.method, e.path, status),
+	logger.Info(
+		e.ctx, "http request",
 		logger.F("host", e.host),
 		logger.F("status", status),
 		logger.F("bytes", bytes),

internal/config/sentry.go

@@ -28,11 +28,11 @@ func NewDefaultSentryConfig() SentryConfig {
 		Debug:              false,
 		FlushTimeout:       NewInterpolatedDuration(2 * time.Second),
 		AttachStacktrace:   true,
-		SampleRate:         0.2,
-		EnableTracing:      true,
-		TracesSampleRate:   0.2,
-		ProfilesSampleRate: 0.2,
-		IgnoreErrors:       []string{},
+		SampleRate:         1,
+		EnableTracing:      false,
+		TracesSampleRate:   0.1,
+		ProfilesSampleRate: 0.1,
+		IgnoreErrors:       []string{"context canceled"},
 		SendDefaultPII:     false,
 		ServerName:         "",
 		Environment:        "",

internal/proxy/director/director.go

@@ -8,7 +8,6 @@ import (
 	"forge.cadoles.com/Cadoles/go-proxy"
 	"forge.cadoles.com/Cadoles/go-proxy/wildcard"
 	"forge.cadoles.com/cadoles/bouncer/internal/cache"
-	bouncersentry "forge.cadoles.com/cadoles/bouncer/internal/sentry"
 	"forge.cadoles.com/cadoles/bouncer/internal/store"
 	"github.com/pkg/errors"
 	"github.com/prometheus/client_golang/prometheus"
@@ -42,21 +41,11 @@ func (d *Director) rewriteRequest(r *http.Request) (*http.Request, error) {
 
 	for _, p := range proxies {
 		for _, from := range p.From {
-			logger.Debug(
-				ctx, "matching request with proxy's from",
-				logger.F("from", from),
-			)
-
 			if matches := wildcard.Match(url.String(), from); !matches {
 				continue
 			}
 
-			logger.Debug(
-				ctx, "proxy's from matched",
-				logger.F("from", from),
-			)
-
-			ctx = logger.With(ctx,
+			proxyCtx := logger.With(ctx,
 				logger.F("proxy", p.Name),
 				logger.F("host", r.Host),
 				logger.F("remoteAddr", r.RemoteAddr),
@@ -64,7 +53,7 @@ func (d *Director) rewriteRequest(r *http.Request) (*http.Request, error) {
 
 			metricProxyRequestsTotal.With(prometheus.Labels{metricLabelProxy: string(p.Name)}).Add(1)
 
-			proxyLayers, err := d.getLayers(ctx, p.Name)
+			proxyLayers, err := d.getLayers(proxyCtx, p.Name)
 			if err != nil {
 				return r, errors.WithStack(err)
 			}
@@ -84,8 +73,8 @@ func (d *Director) rewriteRequest(r *http.Request) (*http.Request, error) {
 			r.URL.Scheme = toURL.Scheme
 			r.URL.Path = toURL.JoinPath(r.URL.Path).Path
 
-			ctx = withLayers(ctx, layers)
-			r = r.WithContext(ctx)
+			proxyCtx = withLayers(proxyCtx, layers)
+			r = r.WithContext(proxyCtx)
 
 			return r, nil
 		}
@@ -259,7 +248,6 @@ func (d *Director) Middleware() proxy.Middleware {
 			}
 
 			handler := createMiddlewareChain(next, httpMiddlewares)
-			handler = bouncersentry.SpanHandler(handler, "director.proxy")
 
 			handler.ServeHTTP(w, r)
 		}

internal/proxy/server.go

@@ -3,6 +3,7 @@ package proxy
 import (
 	"bytes"
 	"context"
+	"expvar"
 	"fmt"
 	"html/template"
 	"io"
@@ -31,8 +32,6 @@ import (
 	"github.com/pkg/errors"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"gitlab.com/wpetit/goweb/logger"
-
-	bouncersentry "forge.cadoles.com/cadoles/bouncer/internal/sentry"
 )
 
 type Server struct {
@@ -120,7 +119,9 @@ func (s *Server) run(parentCtx context.Context, addrs chan net.Addr, errs chan e
 		router.Use(middleware.RealIP)
 	}
 
+	router.Use(middleware.RequestID)
 	router.Use(middleware.RequestLogger(bouncerChi.NewLogFormatter()))
+	router.Use(middleware.Recoverer)
 
 	if s.serverConfig.Sentry.DSN != "" {
 		logger.Info(ctx, "enabling sentry http middleware")
@@ -171,6 +172,7 @@ func (s *Server) run(parentCtx context.Context, addrs chan net.Addr, errs chan e
 				r.HandleFunc("/profile", pprof.Profile)
 				r.HandleFunc("/symbol", pprof.Symbol)
 				r.HandleFunc("/trace", pprof.Trace)
+				r.Handle("/vars", expvar.Handler())
 				r.HandleFunc("/{name}", func(w http.ResponseWriter, r *http.Request) {
 					name := chi.URLParam(r, "name")
 					pprof.Handler(name).ServeHTTP(w, r)
@@ -193,7 +195,7 @@ func (s *Server) run(parentCtx context.Context, addrs chan net.Addr, errs chan e
 			proxy.WithDefaultHandler(http.HandlerFunc(s.handleDefault)),
 		)
 
-		r.Handle("/*", bouncersentry.SpanHandler(handler, "http.proxy"))
+		r.Handle("/*", handler)
 	})
 
 	if err := http.Serve(listener, router); err != nil && !errors.Is(err, net.ErrClosed) {
@@ -230,7 +232,12 @@ func (s *Server) handleDefault(w http.ResponseWriter, r *http.Request) {
 
 func (s *Server) handleError(w http.ResponseWriter, r *http.Request, status int, err error) {
 	err = errors.WithStack(err)
-	logger.Error(r.Context(), err.Error(), logger.CapturedE(err))
+
+	if errors.Is(err, context.Canceled) {
+		logger.Warn(r.Context(), err.Error(), logger.CapturedE(err))
+	} else {
+		logger.Error(r.Context(), err.Error(), logger.CapturedE(err))
+	}
 
 	s.renderErrorPage(w, r, err, status, http.StatusText(status))
 }

internal/sentry/sentry.go

@@ -1,37 +0,0 @@
-package sentry
-
-import (
-	"net/http"
-
-	"github.com/getsentry/sentry-go"
-)
-
-func SpanHandler(handler http.Handler, name string) http.Handler {
-	fn := func(w http.ResponseWriter, r *http.Request) {
-		ctx := r.Context()
-
-		hub := sentry.GetHubFromContext(ctx)
-		if hub == nil {
-			hub = sentry.CurrentHub().Clone()
-			ctx = sentry.SetHubOnContext(ctx, hub)
-		}
-
-		options := []sentry.SpanOption{
-			sentry.WithOpName(name),
-			sentry.ContinueFromRequest(r),
-			sentry.WithTransactionSource(sentry.SourceURL),
-		}
-
-		span := sentry.StartSpan(ctx,
-			name,
-			options...,
-		)
-		defer span.Finish()
-
-		r = r.WithContext(span.Context())
-
-		handler.ServeHTTP(w, r)
-	}
-
-	return http.HandlerFunc(fn)
-}