From 9cf826075fe7b46f15175d89ede3cb8771d64d72 Mon Sep 17 00:00:00 2001 From: Amy Gale Ruth Bowersox Date: Sat, 7 Nov 2026 23:59:27 -0700 Subject: [PATCH] added logging updates and context naming to get more information about mysterious context cancellation error --- conference.go | 8 +++++++- go.mod | 12 ++++++------ go.sum | 20 ++++++++++---------- logging.go | 46 ++++++++++++++++++++++++++++++++++++++-------- main.go | 3 ++- 5 files changed, 63 insertions(+), 26 deletions(-) diff --git a/conference.go b/conference.go index b6a3c3e..33b9ed5 100644 --- a/conference.go +++ b/conference.go @@ -14,6 +14,7 @@ package main import ( "context" + "errors" "fmt" "net/http" "reflect" @@ -375,7 +376,12 @@ func templatePostText(args jet.Arguments) reflect.Value { ctxt := args.Get(1).Convert(reflect.TypeFor[ui.AmContext]()).Interface().(ui.AmContext) rc, err := post.Text(ctxt.Ctx()) if err != nil { - log.Errorf("templatePostText could not get post text from post #%d: %v", post.PostId, err) + if errors.Is(err, context.Canceled) { + log.Errorf("templatePostText could not get post text from post #%d: context %s canceled: %v", post.PostId, + ctxt.Ctx().Value(CONTEXTVAL_NAME), ctxt.Ctx().Err()) + } else { + log.Errorf("templatePostText could not get post text from post #%d: %v", post.PostId, err) + } rc = "" } return reflect.ValueOf(rc) diff --git a/go.mod b/go.mod index 7bd2e06..ec9f4b1 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,6 @@ module git.erbosoft.com/amy/amsterdam -go 1.26 +go 1.27 require ( github.com/CloudyKit/jet/v6 v6.3.2 @@ -14,12 +14,12 @@ require ( github.com/hashicorp/golang-lru v1.0.2 github.com/jmoiron/sqlx v1.4.0 github.com/klauspost/lctime v0.1.0 - github.com/labstack/echo/v5 v5.1.1 + github.com/labstack/echo/v5 v5.4.4 github.com/labstack/gommon v0.5.0 github.com/sirupsen/logrus v1.9.4 github.com/tkuchiki/go-timezone v0.2.3 - golang.org/x/net v0.53.0 - golang.org/x/text v0.36.0 + golang.org/x/net v0.62.0 + golang.org/x/text v0.43.0 gopkg.in/yaml.v3 v3.0.1 ) @@ -31,7 +31,7 @@ require ( github.com/mattn/go-isatty v0.0.22 // indirect github.com/valyala/bytebufferpool v1.0.0 // indirect github.com/valyala/fasttemplate v1.2.2 // indirect - golang.org/x/image v0.37.0 // indirect - golang.org/x/sys v0.43.0 // indirect + golang.org/x/image v0.45.0 // indirect + golang.org/x/sys v0.49.0 // indirect golang.org/x/time v0.15.0 // indirect ) diff --git a/go.sum b/go.sum index 1559793..a038443 100644 --- a/go.sum +++ b/go.sum @@ -31,8 +31,8 @@ github.com/jmoiron/sqlx v1.4.0 h1:1PLqN7S1UYp5t4SrVVnt4nUVNemrDAtxlulVe+Qgm3o= github.com/jmoiron/sqlx v1.4.0/go.mod h1:ZrZ7UsYB/weZdl2Bxg6jCRO9c3YHl8r3ahlKmRT4JLY= github.com/klauspost/lctime v0.1.0 h1:nINsuFc860M9cyYhT6vfg6U1USh7kiVBj/s/2b04U70= github.com/klauspost/lctime v0.1.0/go.mod h1:OwdMhr8tbQvusAsnilqkkgDQqivWlqyg0w5cfXkLiDk= -github.com/labstack/echo/v5 v5.1.1 h1:4QkvKoS8ps5ch49t8b72QS9Z581ytgxhTzxuB/CBA2I= -github.com/labstack/echo/v5 v5.1.1/go.mod h1:SyvlSdObGjRXeQfCCXW/sybkZdOOQZBmpKF0bvALaeo= +github.com/labstack/echo/v5 v5.4.4 h1:Nag9Mee0M9sOcKjProYuDNiw60QisysgfbIgz5US5Cw= +github.com/labstack/echo/v5 v5.4.4/go.mod h1:4iEGNQiPPZnkfYpNR/L6fINd3NLiGWUD5+eBotFALas= github.com/labstack/gommon v0.5.0 h1:6VSQ2NOzsnEJ5W6+84E0RbcaDDmgB6NIAzWCczTEe6c= github.com/labstack/gommon v0.5.0/go.mod h1:Rzlg7HHy1maLfzBYGg9NZcVuz1sA68HHhLjhcEllYE0= github.com/lib/pq v1.10.9 h1:YXG7RB+JIjhP29X+OtkiDnYaXQwpS4JEWq7dtCCRUEw= @@ -57,15 +57,15 @@ github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyC github.com/valyala/fasttemplate v1.2.2 h1:lxLXG0uE3Qnshl9QyaK6XJxMXlQZELvChBOCmQD0Loo= github.com/valyala/fasttemplate v1.2.2/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+qRAEEKiv+SiQ= golang.org/x/image v0.0.0-20191009234506-e7c1f5e7dbb8/go.mod h1:FeLwcggjj3mMvU+oOTbSwawSJRM1uh48EjtB4UJZlP0= -golang.org/x/image v0.37.0 h1:ZiRjArKI8GwxZOoEtUfhrBtaCN+4b/7709dlT6SSnQA= -golang.org/x/image v0.37.0/go.mod h1:/3f6vaXC+6CEanU4KJxbcUZyEePbyKbaLoDOe4ehFYY= -golang.org/x/net v0.53.0 h1:d+qAbo5L0orcWAr0a9JweQpjXF19LMXJE8Ey7hwOdUA= -golang.org/x/net v0.53.0/go.mod h1:JvMuJH7rrdiCfbeHoo3fCQU24Lf5JJwT9W3sJFulfgs= -golang.org/x/sys v0.43.0 h1:Rlag2XtaFTxp19wS8MXlJwTvoh8ArU6ezoyFsMyCTNI= -golang.org/x/sys v0.43.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= +golang.org/x/image v0.45.0 h1:FMb1nTbH5H9vF55SriQHgFw5GnNL9Jg6L25BwXKzhB0= +golang.org/x/image v0.45.0/go.mod h1:n62x/7RqlwXDvGsSU4u6IUTUf6KghUZ9Bt7cG/T9Fx4= +golang.org/x/net v0.62.0 h1:18ELalfM5+XNRwzM2nYqXsZQ9ByS1uhj2O/U7+5jqRY= +golang.org/x/net v0.62.0/go.mod h1:WgDCOTH8iwtB66T4/GfI94AHo/hhdb7Hah9NDseQfiI= +golang.org/x/sys v0.49.0 h1:XbzkgYJHdqh/8m2Uu0W/dQv8nktxx4BFHp1M0gROTXA= +golang.org/x/sys v0.49.0/go.mod h1:hNLxWAXmnKAxqDtdwIYC4bM9oQPEecfsnNMuSxOs3og= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= -golang.org/x/text v0.36.0 h1:JfKh3XmcRPqZPKevfXVpI1wXPTqbkE5f7JA92a55Yxg= -golang.org/x/text v0.36.0/go.mod h1:NIdBknypM8iqVmPiuco0Dh6P5Jcdk8lJL0CUebqK164= +golang.org/x/text v0.43.0 h1:1QivrlhwAsnMOcqgOdl9my7s9OyZl8O5/UGUTJVXoWc= +golang.org/x/text v0.43.0/go.mod h1:hbSIYA/amXcRXTFSZqh8tWHEoqRvvbKPJ2uz/KU+a+s= golang.org/x/time v0.15.0 h1:bbrp8t3bGUeFOx08pvsMYRTCVSMk89u4tKbNOZbp88U= golang.org/x/time v0.15.0/go.mod h1:Y4YMaQmXwGQZoFaVFk4YpCt4FLQMYKZe9oeV/f4MSno= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= diff --git a/logging.go b/logging.go index ae8c058..fbebb10 100644 --- a/logging.go +++ b/logging.go @@ -24,6 +24,7 @@ import ( "path/filepath" "sync" "time" + "uuid" "git.erbosoft.com/amy/amsterdam/config" "github.com/dustin/go-humanize" @@ -37,6 +38,15 @@ const DEFAULT_MAXLOG = 16 * 1024 * 1024 // LOG_ROTATE_INTERVAL is the interval, in seconds, at which we try to rotate the logfile. const LOG_ROTATE_INTERVAL = 10 +// ContextValKey is the type Amsterdam uses for context keys. +type ContextValKey struct{} + +// CONTEXTVAL_NAME is the context key used to store the context name. +var CONTEXTVAL_NAME = ContextValKey{} + +// CONTEXTVAL_REQUESTID is the context key used to store the request id +var CONTEXTVAL_REQUESTID = ContextValKey{} + /*---------------------------------------------------------------------------- * slog handler that outputs to Logrus *---------------------------------------------------------------------------- @@ -103,24 +113,44 @@ func (h *SlogLogrusHandler) WithGroup(name string) slog.Handler { *---------------------------------------------------------------------------- */ -// LogrusMiddleware installs Logrus logging into the Echo middleware chain. -func LogrusMiddleware(next echo.HandlerFunc) echo.HandlerFunc { +// LoggingMiddleware installs Logrus logging into the Echo middleware chain. +func LoggingMiddleware(next echo.HandlerFunc) echo.HandlerFunc { return func(c *echo.Context) error { + req := c.Request() + orgReq := req + + // Set up the request ID and the context. + requestId := uuid.New() + ctx := context.WithValue(req.Context(), CONTEXTVAL_REQUESTID, requestId) + ctx = context.WithValue(ctx, CONTEXTVAL_NAME, fmt.Sprintf("rq:%s", requestId.String())) + req = req.WithContext(ctx) + c.SetRequest(req) + defer c.SetRequest(orgReq) + + // Log the start-request line. + log.WithFields(log.Fields{ + "id": requestId.String(), + "remote_ip": c.RealIP(), + "host": req.Host, + "method": req.Method, + "uri": req.RequestURI, + }).Info("start request") + + // Execute the actual request. start := time.Now() err := next(c) stop := time.Now() - req := c.Request() + // Set the response and the request-ID header. res := c.Response().(*echo.Response) + res.Header().Set(echo.HeaderXRequestID, requestId.String()) + // Log the end-request line. log.WithFields(log.Fields{ - "remote_ip": c.RealIP(), - "host": req.Host, - "method": req.Method, - "uri": req.RequestURI, + "id": requestId.String(), "status": res.Status, "latency_ms": stop.Sub(start).Milliseconds(), - }).Info("handled request") + }).Info("end request") return err } } diff --git a/main.go b/main.go index d036b55..fa0adc7 100644 --- a/main.go +++ b/main.go @@ -71,7 +71,7 @@ func setupEcho() *echo.Echo { } else { log.Warn("WARNING: --debug-panic in effect - DO NOT use this in production!") } - e.Use(LogrusMiddleware) + e.Use(LoggingMiddleware) // set up the rate limiter from the configuration rateLimiter := AmSetupRateLimiter() @@ -262,6 +262,7 @@ func main() { // Set up to trap SIGINT/SIGTERM and shut down gracefully ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM) defer stop() + ctx = context.WithValue(ctx, CONTEXTVAL_NAME, "main") // Set up ampool. ampool = util.AmNewPool(ctx, config.GlobalConfig.Tuning.WorkerTasks, config.GlobalConfig.Tuning.Queues.WorkerTasks)