From 68e6d08c768b789987a753d42f66caf73ce10ee1 Mon Sep 17 00:00:00 2001 From: Daenney Date: Fri, 17 Feb 2023 12:02:29 +0100 Subject: [PATCH] [feature] Add a request ID and include it in logs (#1476) This adds a lightweight form of tracing to GTS. Each incoming request is assigned a Request ID which we then pass on and log in all our log lines. Any function that gets called downstream from an HTTP handler should now emit a requestID=value pair whenever it logs something. Co-authored-by: kim --- .golangci.yml | 6 +- .../action/admin/media/prune/orphaned.go | 4 +- .../action/admin/media/prune/remote.go | 4 +- cmd/gotosocial/action/server/server.go | 9 +- cmd/gotosocial/action/testrig/testrig.go | 4 +- docs/configuration/observability.md | 16 +++ example/config.yaml | 9 ++ internal/api/client/media/mediacreate_test.go | 2 +- internal/api/client/media/mediaupdate_test.go | 2 +- internal/api/client/streaming/stream.go | 11 +- internal/api/fileserver/fileserver_test.go | 2 +- internal/api/fileserver/servefile.go | 23 ++-- internal/api/util/errorhandling.go | 32 +++-- internal/cache/util.go | 2 +- internal/concurrency/workers.go | 10 +- internal/config/config.go | 2 + internal/config/defaults.go | 2 + internal/config/flags.go | 2 + internal/config/helpers.gen.go | 25 ++++ internal/config/testdata/test.yaml | 11 +- internal/config/validate.go | 2 +- internal/db/bundb/account.go | 10 +- internal/db/bundb/admin.go | 14 +-- internal/db/bundb/basic.go | 2 +- internal/db/bundb/bundb.go | 12 +- internal/db/bundb/emoji.go | 4 +- internal/db/bundb/hook.go | 11 +- internal/db/bundb/media.go | 2 +- internal/db/bundb/mention.go | 2 +- .../20220916122701_emojis_in_accounts.go | 2 +- internal/db/bundb/notification.go | 2 +- internal/db/bundb/report.go | 2 +- internal/db/bundb/status.go | 10 +- internal/db/bundb/timeline.go | 6 +- internal/email/confirm.go | 2 +- internal/email/noopsender.go | 4 +- internal/federation/authenticate.go | 54 ++++----- internal/federation/dereferencing/account.go | 10 +- internal/federation/dereferencing/emoji.go | 22 ++-- internal/federation/dereferencing/status.go | 16 +-- internal/federation/dereferencing/thread.go | 27 +++-- internal/federation/federatingactor.go | 2 +- internal/federation/federatingdb/create.go | 14 ++- internal/federation/federatingdb/delete.go | 7 +- internal/federation/federatingdb/exists.go | 9 +- internal/federation/federatingdb/followers.go | 7 +- internal/federation/federatingdb/following.go | 7 +- internal/federation/federatingdb/get.go | 3 +- internal/federation/federatingdb/owns.go | 7 +- internal/federation/federatingdb/util.go | 4 +- internal/federation/federatingprotocol.go | 26 ++-- internal/httpclient/client.go | 13 +- internal/log/entry.go | 53 +++++---- internal/log/log.go | 92 +++++++++------ internal/log/syslog_test.go | 6 +- internal/media/manager.go | 4 +- internal/media/processingemoji.go | 16 +-- internal/media/processingmedia.go | 12 +- internal/media/prune.go | 12 +- internal/media/refetch.go | 16 +-- internal/media/video.go | 2 +- internal/middleware/requestid.go | 111 ++++++++++++++++++ internal/middleware/session.go | 2 +- internal/middleware/signaturecheck.go | 13 +- internal/middleware/tokencheck.go | 27 +++-- internal/oauth/server.go | 8 +- internal/oauth/tokenstore.go | 6 +- internal/oidc/handlecallback.go | 10 +- internal/processing/account/create.go | 4 +- internal/processing/account/delete.go | 2 +- internal/processing/account/update.go | 4 +- .../processing/admin/createdomainblock.go | 7 +- internal/processing/admin/mediarefetch.go | 6 +- internal/processing/fromclientapi.go | 2 +- internal/processing/fromfederator.go | 2 +- internal/processing/media/getemoji.go | 2 +- internal/processing/notification.go | 2 +- internal/processing/search.go | 3 +- internal/processing/statustimeline.go | 14 +-- internal/processing/streaming/openstream.go | 10 +- internal/router/router.go | 14 +-- internal/router/template.go | 6 +- internal/storage/storage.go | 3 +- internal/text/emojionly.go | 7 +- internal/text/goldmark_extension.go | 31 +++-- internal/text/markdown.go | 7 +- internal/text/minify.go | 29 ++--- internal/text/plain.go | 7 +- internal/text/replace.go | 13 +- internal/timeline/get.go | 28 +++-- internal/timeline/index.go | 53 +-------- internal/timeline/manager.go | 30 +++-- internal/timeline/prepare.go | 16 +-- internal/timeline/remove.go | 18 +-- internal/trans/import.go | 18 +-- internal/transport/controller.go | 4 +- internal/transport/derefinstance.go | 14 +-- internal/transport/transport.go | 11 +- internal/typeutils/astointernal.go | 8 +- internal/typeutils/defaulticons.go | 4 +- internal/typeutils/internaltoas.go | 4 +- internal/typeutils/internaltofrontend.go | 16 +-- internal/typeutils/internaltorss.go | 6 +- internal/visibility/statusboostable.go | 8 +- internal/visibility/statushometimelineable.go | 3 +- .../visibility/statuspublictimelineable.go | 3 +- internal/visibility/statusvisible.go | 3 +- internal/web/assets.go | 5 +- internal/web/etag.go | 2 +- internal/web/rss.go | 12 +- internal/web/web.go | 2 +- mkdocs.yml | 1 + test/envparsing.sh | 3 +- testrig/db.go | 62 +++++----- testrig/log.go | 4 +- testrig/transportcontroller.go | 4 +- web/template/404.tmpl | 3 +- web/template/error.tmpl | 1 + 118 files changed, 813 insertions(+), 591 deletions(-) create mode 100644 docs/configuration/observability.md create mode 100644 internal/middleware/requestid.go diff --git a/.golangci.yml b/.golangci.yml index e4f777334..fcfbdee76 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -14,7 +14,6 @@ run: linters: # enable some extra linters, see here for the list: https://golangci-lint.run/usage/linters/ enable: - - contextcheck - forcetypeassert - goconst - gocritic @@ -27,3 +26,8 @@ linters-settings: govet: disable: - composites + staticcheck: + # Enable all checks + # Disable: + # - SA1012: nil context passing + checks: ["all", "-SA1012"] diff --git a/cmd/gotosocial/action/admin/media/prune/orphaned.go b/cmd/gotosocial/action/admin/media/prune/orphaned.go index d8dcec9a4..31196531b 100644 --- a/cmd/gotosocial/action/admin/media/prune/orphaned.go +++ b/cmd/gotosocial/action/admin/media/prune/orphaned.go @@ -42,9 +42,9 @@ } if dry /* dick heyyoooooo */ { - log.Infof("DRY RUN: %d items are orphaned and eligible to be pruned", pruned) + log.Infof(ctx, "DRY RUN: %d items are orphaned and eligible to be pruned", pruned) } else { - log.Infof("%d orphaned items were pruned", pruned) + log.Infof(ctx, "%d orphaned items were pruned", pruned) } return prune.shutdown(ctx) diff --git a/cmd/gotosocial/action/admin/media/prune/remote.go b/cmd/gotosocial/action/admin/media/prune/remote.go index 473c1d3e4..329f04a94 100644 --- a/cmd/gotosocial/action/admin/media/prune/remote.go +++ b/cmd/gotosocial/action/admin/media/prune/remote.go @@ -49,9 +49,9 @@ total := pruned + uncached if dry /* dick heyyoooooo */ { - log.Infof("DRY RUN: %d remote items are unused/stale and eligible to be pruned", total) + log.Infof(ctx, "DRY RUN: %d remote items are unused/stale and eligible to be pruned", total) } else { - log.Infof("%d unused/stale remote items were pruned", pruned) + log.Infof(ctx, "%d unused/stale remote items were pruned", pruned) } return prune.shutdown(ctx) diff --git a/cmd/gotosocial/action/server/server.go b/cmd/gotosocial/action/server/server.go index 89486a5dc..388a88533 100644 --- a/cmd/gotosocial/action/server/server.go +++ b/cmd/gotosocial/action/server/server.go @@ -62,7 +62,7 @@ // Start creates and starts a gotosocial server var Start action.GTSAction = func(ctx context.Context) error { - _, err := maxprocs.Set(maxprocs.Logger(log.Debugf)) + _, err := maxprocs.Set(nil) if err != nil { return fmt.Errorf("failed to set CPU limits from cgroup: %s", err) } @@ -156,6 +156,9 @@ // attach global middlewares which are used for every request router.AttachGlobalMiddleware( + middleware.AddRequestID(config.GetRequestIDHeader()), + // note: hooks adding ctx fields must be ABOVE + // the logger, otherwise won't be accessible. middleware.Logger(), middleware.UserAgent(), middleware.CORS(), @@ -237,13 +240,13 @@ sigs := make(chan os.Signal, 1) signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM) sig := <-sigs // block until signal received - log.Infof("received signal %s, shutting down", sig) + log.Infof(ctx, "received signal %s, shutting down", sig) // close down all running services in order if err := gts.Stop(ctx); err != nil { return fmt.Errorf("error closing gotosocial service: %s", err) } - log.Info("done! exiting...") + log.Info(ctx, "done! exiting...") return nil } diff --git a/cmd/gotosocial/action/testrig/testrig.go b/cmd/gotosocial/action/testrig/testrig.go index baf63a78a..3be7907fe 100644 --- a/cmd/gotosocial/action/testrig/testrig.go +++ b/cmd/gotosocial/action/testrig/testrig.go @@ -155,7 +155,7 @@ sigs := make(chan os.Signal, 1) signal.Notify(sigs, os.Interrupt, syscall.SIGTERM) sig := <-sigs - log.Infof("received signal %s, shutting down", sig) + log.Infof(ctx, "received signal %s, shutting down", sig) testrig.StandardDBTeardown(dbService) testrig.StandardStorageTeardown(storageBackend) @@ -165,6 +165,6 @@ return fmt.Errorf("error closing gotosocial service: %s", err) } - log.Info("done! exiting...") + log.Info(ctx, "done! exiting...") return nil } diff --git a/docs/configuration/observability.md b/docs/configuration/observability.md new file mode 100644 index 000000000..0d5f9e864 --- /dev/null +++ b/docs/configuration/observability.md @@ -0,0 +1,16 @@ +# Observability + +These settings let you tune and configure certain observability related behaviours. + +## Settings + +```yaml +################################## +##### OBSERVABILITY SETTINGS ##### +################################## + +# String. Header name to use to extract a request or trace ID from. Typically set by a +# loadbalancer or proxy. +# Default: "X-Request-Id" +request-id-header: "X-Request-Id" +``` diff --git a/example/config.yaml b/example/config.yaml index 48aa021d3..2fab24ab8 100644 --- a/example/config.yaml +++ b/example/config.yaml @@ -692,6 +692,15 @@ syslog-protocol: "udp" # Default: "localhost:514" syslog-address: "localhost:514" +################################## +##### OBSERVABILITY SETTINGS ##### +################################## + +# String. Header name to use to extract a request or trace ID from. Typically set by a +# loadbalancer or proxy. +# Default: "X-Request-Id" +request-id-header: "X-Request-Id" + ############################# ##### ADVANCED SETTINGS ##### ############################# diff --git a/internal/api/client/media/mediacreate_test.go b/internal/api/client/media/mediacreate_test.go index 320636721..8a94646ac 100644 --- a/internal/api/client/media/mediacreate_test.go +++ b/internal/api/client/media/mediacreate_test.go @@ -100,7 +100,7 @@ func (suite *MediaCreateTestSuite) SetupSuite() { func (suite *MediaCreateTestSuite) TearDownSuite() { if err := suite.db.Stop(context.Background()); err != nil { - log.Panicf("error closing db connection: %s", err) + log.Panicf(nil, "error closing db connection: %s", err) } } diff --git a/internal/api/client/media/mediaupdate_test.go b/internal/api/client/media/mediaupdate_test.go index 1425d80ef..8f4470132 100644 --- a/internal/api/client/media/mediaupdate_test.go +++ b/internal/api/client/media/mediaupdate_test.go @@ -98,7 +98,7 @@ func (suite *MediaUpdateTestSuite) SetupSuite() { func (suite *MediaUpdateTestSuite) TearDownSuite() { if err := suite.db.Stop(context.Background()); err != nil { - log.Panicf("error closing db connection: %s", err) + log.Panicf(nil, "error closing db connection: %s", err) } } diff --git a/internal/api/client/streaming/stream.go b/internal/api/client/streaming/stream.go index 99d8b23e1..a03f36d16 100644 --- a/internal/api/client/streaming/stream.go +++ b/internal/api/client/streaming/stream.go @@ -166,11 +166,12 @@ func (m *Module) StreamGETHandler(c *gin.Context) { return } - l := log.WithFields(kv.Fields{ - {"account", account.Username}, - {"streamID", stream.ID}, - {"streamType", streamType}, - }...) + l := log.WithContext(c.Request.Context()). + WithFields(kv.Fields{ + {"account", account.Username}, + {"streamID", stream.ID}, + {"streamType", streamType}, + }...) // Upgrade the incoming HTTP request, which hijacks the underlying // connection and reuses it for the websocket (non-http) protocol. diff --git a/internal/api/fileserver/fileserver_test.go b/internal/api/fileserver/fileserver_test.go index 01e090cc7..5b139454e 100644 --- a/internal/api/fileserver/fileserver_test.go +++ b/internal/api/fileserver/fileserver_test.go @@ -99,7 +99,7 @@ func (suite *FileserverTestSuite) SetupTest() { func (suite *FileserverTestSuite) TearDownSuite() { if err := suite.db.Stop(context.Background()); err != nil { - log.Panicf("error closing db connection: %s", err) + log.Panicf(nil, "error closing db connection: %s", err) } } diff --git a/internal/api/fileserver/servefile.go b/internal/api/fileserver/servefile.go index ec70ef9ae..a344e3e53 100644 --- a/internal/api/fileserver/servefile.go +++ b/internal/api/fileserver/servefile.go @@ -77,7 +77,10 @@ func (m *Module) ServeFile(c *gin.Context) { return } - content, errWithCode := m.processor.FileGet(c.Request.Context(), authed, &apimodel.GetContentRequestForm{ + // Acquire context from gin request. + ctx := c.Request.Context() + + content, errWithCode := m.processor.FileGet(ctx, authed, &apimodel.GetContentRequestForm{ AccountID: accountID, MediaType: mediaType, MediaSize: mediaSize, @@ -101,7 +104,7 @@ func (m *Module) ServeFile(c *gin.Context) { defer func() { // Close content when we're done, catch errors. if err := content.Content.Close(); err != nil { - log.Errorf("ServeFile: error closing readcloser: %s", err) + log.Errorf(ctx, "ServeFile: error closing readcloser: %s", err) } }() @@ -130,15 +133,21 @@ func (m *Module) ServeFile(c *gin.Context) { return } - // Set known content-type and serve this file range. + // Set known content-type and serve range. c.Header("Content-Type", format) - serveFileRange(c.Writer, content.Content, rng, content.ContentLength) + serveFileRange( + c.Writer, + c.Request, + content.Content, + rng, + content.ContentLength, + ) } // serveFileRange serves the range of a file from a given source reader, without the // need for implementation of io.Seeker. Instead we read the first 'start' many bytes // into a discard reader. Code is adapted from https://codeberg.org/gruf/simplehttp. -func serveFileRange(rw http.ResponseWriter, src io.Reader, rng string, size int64) { +func serveFileRange(rw http.ResponseWriter, r *http.Request, src io.Reader, rng string, size int64) { var i int if i = strings.IndexByte(rng, '='); i < 0 { @@ -219,7 +228,7 @@ func serveFileRange(rw http.ResponseWriter, src io.Reader, rng string, size int6 // Dump the first 'start' many bytes into the void... if _, err := fastcopy.CopyN(io.Discard, src, start); err != nil { - log.Errorf("error reading from source: %v", err) + log.Errorf(r.Context(), "error reading from source: %v", err) return } @@ -239,7 +248,7 @@ func serveFileRange(rw http.ResponseWriter, src io.Reader, rng string, size int6 // Read the "seeked" source reader into destination writer. if _, err := fastcopy.Copy(rw, src); err != nil { - log.Errorf("error reading from source: %v", err) + log.Errorf(r.Context(), "error reading from source: %v", err) return } } diff --git a/internal/api/util/errorhandling.go b/internal/api/util/errorhandling.go index 414b8d7e8..c0f02d114 100644 --- a/internal/api/util/errorhandling.go +++ b/internal/api/util/errorhandling.go @@ -27,6 +27,7 @@ apimodel "github.com/superseriousbusiness/gotosocial/internal/api/model" "github.com/superseriousbusiness/gotosocial/internal/gtserror" "github.com/superseriousbusiness/gotosocial/internal/log" + "github.com/superseriousbusiness/gotosocial/internal/middleware" ) // TODO: add more templated html pages here for different error types @@ -43,16 +44,20 @@ func NotFoundHandler(c *gin.Context, instanceGet func(ctx context.Context) (*apimodel.InstanceV1, gtserror.WithCode), accept string) { switch accept { case string(TextHTML): - instance, err := instanceGet(c.Request.Context()) + ctx := c.Request.Context() + instance, err := instanceGet(ctx) if err != nil { panic(err) } c.HTML(http.StatusNotFound, "404.tmpl", gin.H{ - "instance": instance, + "instance": instance, + "requestID": middleware.RequestID(ctx), }) default: - c.JSON(http.StatusNotFound, gin.H{"error": http.StatusText(http.StatusNotFound)}) + c.JSON(http.StatusNotFound, gin.H{ + "error": http.StatusText(http.StatusNotFound), + }) } } @@ -62,15 +67,17 @@ func NotFoundHandler(c *gin.Context, instanceGet func(ctx context.Context) (*api func genericErrorHandler(c *gin.Context, instanceGet func(ctx context.Context) (*apimodel.InstanceV1, gtserror.WithCode), accept string, errWithCode gtserror.WithCode) { switch accept { case string(TextHTML): - instance, err := instanceGet(c.Request.Context()) + ctx := c.Request.Context() + instance, err := instanceGet(ctx) if err != nil { panic(err) } c.HTML(errWithCode.Code(), "error.tmpl", gin.H{ - "instance": instance, - "code": errWithCode.Code(), - "error": errWithCode.Safe(), + "instance": instance, + "code": errWithCode.Code(), + "error": errWithCode.Safe(), + "requestID": middleware.RequestID(ctx), }) default: c.JSON(errWithCode.Code(), gin.H{"error": errWithCode.Safe()}) @@ -108,11 +115,12 @@ func ErrorHandler(c *gin.Context, errWithCode gtserror.WithCode, instanceGet fun // to pass any detailed errors (that might contain sensitive information) into the // errWithCode.Error() field, since the client will see this. Use your noggin! func OAuthErrorHandler(c *gin.Context, errWithCode gtserror.WithCode) { - l := log.WithFields(kv.Fields{ - {"path", c.Request.URL.Path}, - {"error", errWithCode.Error()}, - {"help", errWithCode.Safe()}, - }...) + l := log.WithContext(c.Request.Context()). + WithFields(kv.Fields{ + {"path", c.Request.URL.Path}, + {"error", errWithCode.Error()}, + {"help", errWithCode.Safe()}, + }...) statusCode := errWithCode.Code() diff --git a/internal/cache/util.go b/internal/cache/util.go index 0b22f4b49..76917c415 100644 --- a/internal/cache/util.go +++ b/internal/cache/util.go @@ -35,5 +35,5 @@ func tryUntil(msg string, count int, do func() bool) { return } } - log.Panicf("failed %s after %d tries", msg, count) + log.Panicf(nil, "failed %s after %d tries", msg, count) } diff --git a/internal/concurrency/workers.go b/internal/concurrency/workers.go index a27e5d115..d782d3f42 100644 --- a/internal/concurrency/workers.go +++ b/internal/concurrency/workers.go @@ -66,7 +66,7 @@ func NewWorkerPool[MsgType any](workers int, queueRatio int) *WorkerPool[MsgType } // Log new worker creation with worker type prefix - log.Infof("%s created with workers=%d queue=%d", + log.Infof(nil, "%s created with workers=%d queue=%d", w.wtype, workers, workers*queueRatio, @@ -77,7 +77,7 @@ func NewWorkerPool[MsgType any](workers int, queueRatio int) *WorkerPool[MsgType // Start will attempt to start the underlying worker pool, or return error. func (w *WorkerPool[MsgType]) Start() error { - log.Infof("%s starting", w.wtype) + log.Infof(nil, "%s starting", w.wtype) // Check processor was set if w.process == nil { @@ -94,7 +94,7 @@ func (w *WorkerPool[MsgType]) Start() error { // Stop will attempt to stop the underlying worker pool, or return error. func (w *WorkerPool[MsgType]) Stop() error { - log.Infof("%s stopping", w.wtype) + log.Infof(nil, "%s stopping", w.wtype) // Attempt to stop pool if !w.workers.Stop() { @@ -107,14 +107,14 @@ func (w *WorkerPool[MsgType]) Stop() error { // SetProcessor will set the Worker's processor function, which is called for each queued message. func (w *WorkerPool[MsgType]) SetProcessor(fn func(context.Context, MsgType) error) { if w.process != nil { - log.Panicf("%s Worker.process is already set", w.wtype) + log.Panicf(nil, "%s Worker.process is already set", w.wtype) } w.process = fn } // Queue will queue provided message to be processed with there's a free worker. func (w *WorkerPool[MsgType]) Queue(msg MsgType) { - log.Tracef("%s queueing message: %+v", w.wtype, msg) + log.Tracef(nil, "%s queueing message: %+v", w.wtype, msg) // Create new process function for msg process := func(ctx context.Context) { diff --git a/internal/config/config.go b/internal/config/config.go index 516fb11d6..1dea90788 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -147,6 +147,8 @@ type Configuration struct { AdminAccountPassword string `name:"password" usage:"the password to set for this account"` AdminTransPath string `name:"path" usage:"the path of the file to import from/export to"` AdminMediaPruneDryRun bool `name:"dry-run" usage:"perform a dry run and only log number of items eligible for pruning"` + + RequestIDHeader string `name:"request-id-header" usage:"Header to extract the Request ID from. Eg.,'X-Request-Id'"` } type CacheConfiguration struct { diff --git a/internal/config/defaults.go b/internal/config/defaults.go index 709f063ca..528419e97 100644 --- a/internal/config/defaults.go +++ b/internal/config/defaults.go @@ -163,4 +163,6 @@ }, AdminMediaPruneDryRun: true, + + RequestIDHeader: "X-Request-Id", } diff --git a/internal/config/flags.go b/internal/config/flags.go index d8c31368b..3ef44bf62 100644 --- a/internal/config/flags.go +++ b/internal/config/flags.go @@ -140,6 +140,8 @@ func (s *ConfigState) AddServerFlags(cmd *cobra.Command) { cmd.Flags().Int(AdvancedRateLimitRequestsFlag(), cfg.AdvancedRateLimitRequests, fieldtag("AdvancedRateLimitRequests", "usage")) cmd.Flags().Int(AdvancedThrottlingMultiplierFlag(), cfg.AdvancedThrottlingMultiplier, fieldtag("AdvancedThrottlingMultiplier", "usage")) cmd.Flags().Duration(AdvancedThrottlingRetryAfterFlag(), cfg.AdvancedThrottlingRetryAfter, fieldtag("AdvancedThrottlingRetryAfter", "usage")) + + cmd.Flags().String(RequestIDHeaderFlag(), cfg.RequestIDHeader, fieldtag("RequestIDHeader", "usage")) }) } diff --git a/internal/config/helpers.gen.go b/internal/config/helpers.gen.go index 64e7d02f7..1a4c14a82 100644 --- a/internal/config/helpers.gen.go +++ b/internal/config/helpers.gen.go @@ -2977,3 +2977,28 @@ func GetAdminMediaPruneDryRun() bool { return global.GetAdminMediaPruneDryRun() // SetAdminMediaPruneDryRun safely sets the value for global configuration 'AdminMediaPruneDryRun' field func SetAdminMediaPruneDryRun(v bool) { global.SetAdminMediaPruneDryRun(v) } + +// GetRequestIDHeader safely fetches the Configuration value for state's 'RequestIDHeader' field +func (st *ConfigState) GetRequestIDHeader() (v string) { + st.mutex.Lock() + v = st.config.RequestIDHeader + st.mutex.Unlock() + return +} + +// SetRequestIDHeader safely sets the Configuration value for state's 'RequestIDHeader' field +func (st *ConfigState) SetRequestIDHeader(v string) { + st.mutex.Lock() + defer st.mutex.Unlock() + st.config.RequestIDHeader = v + st.reloadToViper() +} + +// RequestIDHeaderFlag returns the flag name for the 'RequestIDHeader' field +func RequestIDHeaderFlag() string { return "request-id-header" } + +// GetRequestIDHeader safely fetches the value for global configuration 'RequestIDHeader' field +func GetRequestIDHeader() string { return global.GetRequestIDHeader() } + +// SetRequestIDHeader safely sets the value for global configuration 'RequestIDHeader' field +func SetRequestIDHeader(v string) { global.SetRequestIDHeader(v) } diff --git a/internal/config/testdata/test.yaml b/internal/config/testdata/test.yaml index 87fe105d2..c2d902944 100644 --- a/internal/config/testdata/test.yaml +++ b/internal/config/testdata/test.yaml @@ -415,4 +415,13 @@ cache: gts: account-max-size: 99 account-ttl: "3h" - account-sweep-freq: "1s" \ No newline at end of file + account-sweep-freq: "1s" + +################################## +##### OBSERVABILITY SETTINGS ##### +################################## + +# String. Header name to use to extract a request or trace ID from. Typically set by a +# loadbalancer or proxy. +# Default: "X-Request-Id" +request-id-header: "X-Trace-Id" diff --git a/internal/config/validate.go b/internal/config/validate.go index 765739d6c..866ec1be1 100644 --- a/internal/config/validate.go +++ b/internal/config/validate.go @@ -55,7 +55,7 @@ func Validate() error { // no problem break case "http": - log.Warnf("%s was set to 'http'; this should *only* be used for debugging and tests!", ProtocolFlag()) + log.Warnf(nil, "%s was set to 'http'; this should *only* be used for debugging and tests!", ProtocolFlag()) case "": errs = append(errs, fmt.Errorf("%s must be set", ProtocolFlag())) default: diff --git a/internal/db/bundb/account.go b/internal/db/bundb/account.go index 9fdd28342..937f4ba23 100644 --- a/internal/db/bundb/account.go +++ b/internal/db/bundb/account.go @@ -146,7 +146,7 @@ func (a *accountDB) getAccount(ctx context.Context, lookup string, dbQuery func( // Set the account's related avatar account.AvatarMediaAttachment, err = a.state.DB.GetAttachmentByID(ctx, account.AvatarMediaAttachmentID) if err != nil { - log.Errorf("error getting account %s avatar: %v", account.ID, err) + log.Errorf(ctx, "error getting account %s avatar: %v", account.ID, err) } } @@ -154,7 +154,7 @@ func (a *accountDB) getAccount(ctx context.Context, lookup string, dbQuery func( // Set the account's related header account.HeaderMediaAttachment, err = a.state.DB.GetAttachmentByID(ctx, account.HeaderMediaAttachmentID) if err != nil { - log.Errorf("error getting account %s header: %v", account.ID, err) + log.Errorf(ctx, "error getting account %s header: %v", account.ID, err) } } @@ -162,7 +162,7 @@ func (a *accountDB) getAccount(ctx context.Context, lookup string, dbQuery func( // Set the account's related emojis account.Emojis, err = a.state.DB.GetEmojisByIDs(ctx, account.EmojiIDs) if err != nil { - log.Errorf("error getting account %s emojis: %v", account.ID, err) + log.Errorf(ctx, "error getting account %s emojis: %v", account.ID, err) } } @@ -412,7 +412,7 @@ func (a *accountDB) GetAccountStatuses(ctx context.Context, accountID string, li Where("? != '{}'", bun.Ident("status.attachments")). Where("? != '[]'", bun.Ident("status.attachments")) default: - log.Panic("db dialect was neither pg nor sqlite") + log.Panic(ctx, "db dialect was neither pg nor sqlite") return q } }) @@ -540,7 +540,7 @@ func (a *accountDB) statusesFromIDs(ctx context.Context, statusIDs []string) ([] // Fetch from status from database by ID status, err := a.state.DB.GetStatusByID(ctx, id) if err != nil { - log.Errorf("statusesFromIDs: error getting status %q: %v", id, err) + log.Errorf(ctx, "error getting status %q: %v", id, err) continue } diff --git a/internal/db/bundb/admin.go b/internal/db/bundb/admin.go index 3c0415dca..a4bc46a73 100644 --- a/internal/db/bundb/admin.go +++ b/internal/db/bundb/admin.go @@ -93,7 +93,7 @@ func (a *adminDB) IsEmailAvailable(ctx context.Context, email string) (bool, db. func (a *adminDB) NewSignup(ctx context.Context, username string, reason string, requireApproval bool, email string, password string, signUpIP net.IP, locale string, appID string, emailVerified bool, externalID string, admin bool) (*gtsmodel.User, db.Error) { key, err := rsa.GenerateKey(rand.Reader, rsaKeyBits) if err != nil { - log.Errorf("error creating new rsa key: %s", err) + log.Errorf(ctx, "error creating new rsa key: %s", err) return nil, err } @@ -107,7 +107,7 @@ func (a *adminDB) NewSignup(ctx context.Context, username string, reason string, Scan(ctx); err != nil { err = a.conn.ProcessError(err) if err != db.ErrNoEntries { - log.Errorf("error checking for existing account: %s", err) + log.Errorf(ctx, "error checking for existing account: %s", err) return nil, err } @@ -207,13 +207,13 @@ func (a *adminDB) CreateInstanceAccount(ctx context.Context) db.Error { return err } if exists { - log.Infof("instance account %s already exists", username) + log.Infof(ctx, "instance account %s already exists", username) return nil } key, err := rsa.GenerateKey(rand.Reader, rsaKeyBits) if err != nil { - log.Errorf("error creating new rsa key: %s", err) + log.Errorf(ctx, "error creating new rsa key: %s", err) return err } @@ -245,7 +245,7 @@ func (a *adminDB) CreateInstanceAccount(ctx context.Context) db.Error { return err } - log.Infof("instance account %s CREATED with id %s", username, acct.ID) + log.Infof(ctx, "instance account %s CREATED with id %s", username, acct.ID) return nil } @@ -265,7 +265,7 @@ func (a *adminDB) CreateInstanceInstance(ctx context.Context) db.Error { return err } if exists { - log.Infof("instance entry already exists") + log.Infof(ctx, "instance entry already exists") return nil } @@ -290,6 +290,6 @@ func (a *adminDB) CreateInstanceInstance(ctx context.Context) db.Error { return a.conn.ProcessError(err) } - log.Infof("created instance instance %s with id %s", host, i.ID) + log.Infof(ctx, "created instance instance %s with id %s", host, i.ID) return nil } diff --git a/internal/db/bundb/basic.go b/internal/db/bundb/basic.go index d4de3f37e..71a603593 100644 --- a/internal/db/bundb/basic.go +++ b/internal/db/bundb/basic.go @@ -165,6 +165,6 @@ func (b *basicDB) IsHealthy(ctx context.Context) db.Error { } func (b *basicDB) Stop(ctx context.Context) db.Error { - log.Info("closing db connection") + log.Info(ctx, "closing db connection") return b.conn.Close() } diff --git a/internal/db/bundb/bundb.go b/internal/db/bundb/bundb.go index 990eccb6b..1d0ea4822 100644 --- a/internal/db/bundb/bundb.go +++ b/internal/db/bundb/bundb.go @@ -100,11 +100,11 @@ func doMigration(ctx context.Context, db *bun.DB) error { } if group.ID == 0 { - log.Info("there are no new migrations to run") + log.Info(ctx, "there are no new migrations to run") return nil } - log.Infof("MIGRATED DATABASE TO %s", group) + log.Infof(ctx, "MIGRATED DATABASE TO %s", group) return nil } @@ -245,7 +245,7 @@ func pgConn(ctx context.Context) (*DBConn, error) { return nil, fmt.Errorf("postgres ping: %s", err) } - log.Info("connected to POSTGRES database") + log.Info(ctx, "connected to POSTGRES database") return conn, nil } @@ -268,7 +268,7 @@ func sqliteConn(ctx context.Context) (*DBConn, error) { } if address == ":memory:" { - log.Warn("using sqlite in-memory mode; all data will be deleted when gts shuts down; this mode should only be used for debugging or running tests") + log.Warn(ctx, "using sqlite in-memory mode; all data will be deleted when gts shuts down; this mode should only be used for debugging or running tests") // Use random name for in-memory instead of ':memory:', so // multiple in-mem databases can be created without conflict. @@ -319,7 +319,7 @@ func sqliteConn(ctx context.Context) (*DBConn, error) { } return nil, fmt.Errorf("sqlite ping: %s", err) } - log.Infof("connected to SQLITE database with address %s", address) + log.Infof(ctx, "connected to SQLITE database with address %s", address) return conn, nil } @@ -464,7 +464,7 @@ func sqlitePragmas(ctx context.Context, conn *DBConn) error { return fmt.Errorf("error scanning sqlite pragma %s: %w", pv, err) } - log.Infof("sqlite pragma %s set to %s", pk, res) + log.Infof(ctx, "sqlite pragma %s set to %s", pk, res) } return nil diff --git a/internal/db/bundb/emoji.go b/internal/db/bundb/emoji.go index afca3da33..802a57ae8 100644 --- a/internal/db/bundb/emoji.go +++ b/internal/db/bundb/emoji.go @@ -372,7 +372,7 @@ func (e *emojiDB) GetEmojisByIDs(ctx context.Context, emojiIDs []string) ([]*gts for _, id := range emojiIDs { emoji, err := e.GetEmojiByID(ctx, id) if err != nil { - log.Errorf("emojisFromIDs: error getting emoji %q: %v", id, err) + log.Errorf(ctx, "emojisFromIDs: error getting emoji %q: %v", id, err) continue } @@ -405,7 +405,7 @@ func (e *emojiDB) GetEmojiCategoriesByIDs(ctx context.Context, emojiCategoryIDs for _, id := range emojiCategoryIDs { emojiCategory, err := e.GetEmojiCategory(ctx, id) if err != nil { - log.Errorf("emojiCategoriesFromIDs: error getting emoji category %q: %v", id, err) + log.Errorf(ctx, "error getting emoji category %q: %v", id, err) continue } diff --git a/internal/db/bundb/hook.go b/internal/db/bundb/hook.go index e4c44a294..e0a132bd0 100644 --- a/internal/db/bundb/hook.go +++ b/internal/db/bundb/hook.go @@ -36,17 +36,18 @@ func (queryHook) BeforeQuery(ctx context.Context, _ *bun.QueryEvent) context.Con } // AfterQuery logs the time taken to query, the operation (select, update, etc), and the query itself as translated by bun. -func (queryHook) AfterQuery(_ context.Context, event *bun.QueryEvent) { +func (queryHook) AfterQuery(ctx context.Context, event *bun.QueryEvent) { // Get the DB query duration dur := time.Since(event.StartTime) switch { // Warn on slow database queries case dur > time.Second: - log.WithFields(kv.Fields{ - {"duration", dur}, - {"query", event.Query}, - }...).Warn("SLOW DATABASE QUERY") + log.WithContext(ctx). + WithFields(kv.Fields{ + {"duration", dur}, + {"query", event.Query}, + }...).Warn("SLOW DATABASE QUERY") // On trace, we log query information, // manually crafting so DB query not escaped. diff --git a/internal/db/bundb/media.go b/internal/db/bundb/media.go index ee2bea6e5..6975df85f 100644 --- a/internal/db/bundb/media.go +++ b/internal/db/bundb/media.go @@ -58,7 +58,7 @@ func (m *mediaDB) getAttachments(ctx context.Context, ids []string) ([]*gtsmodel // Attempt fetch from DB attachment, err := m.GetAttachmentByID(ctx, id) if err != nil { - log.Errorf("error getting attachment %q: %v", id, err) + log.Errorf(ctx, "error getting attachment %q: %v", id, err) continue } diff --git a/internal/db/bundb/mention.go b/internal/db/bundb/mention.go index 4a50c1ebd..c894fbdd8 100644 --- a/internal/db/bundb/mention.go +++ b/internal/db/bundb/mention.go @@ -64,7 +64,7 @@ func (m *mentionDB) GetMentions(ctx context.Context, ids []string) ([]*gtsmodel. // Attempt fetch from DB mention, err := m.GetMention(ctx, id) if err != nil { - log.Errorf("GetMentions: error getting mention %q: %v", id, err) + log.Errorf(ctx, "error getting mention %q: %v", id, err) continue } diff --git a/internal/db/bundb/migrations/20220916122701_emojis_in_accounts.go b/internal/db/bundb/migrations/20220916122701_emojis_in_accounts.go index c72fc830e..207ac036a 100644 --- a/internal/db/bundb/migrations/20220916122701_emojis_in_accounts.go +++ b/internal/db/bundb/migrations/20220916122701_emojis_in_accounts.go @@ -38,7 +38,7 @@ func init() { case dialect.SQLite: q = q.ColumnExpr("? VARCHAR", bun.Ident("emojis")) default: - log.Panic("db dialect was neither pg nor sqlite") + log.Panic(ctx, "db dialect was neither pg nor sqlite") } if _, err := q.Exec(ctx); err != nil { diff --git a/internal/db/bundb/notification.go b/internal/db/bundb/notification.go index ec29f3d28..1884cbeff 100644 --- a/internal/db/bundb/notification.go +++ b/internal/db/bundb/notification.go @@ -94,7 +94,7 @@ func (n *notificationDB) GetNotifications(ctx context.Context, accountID string, // Attempt fetch from DB notif, err := n.GetNotification(ctx, id) if err != nil { - log.Errorf("GetNotifications: error getting notification %q: %v", id, err) + log.Errorf(ctx, "error getting notification %q: %v", id, err) continue } diff --git a/internal/db/bundb/report.go b/internal/db/bundb/report.go index baf11ddb0..1294bcf98 100644 --- a/internal/db/bundb/report.go +++ b/internal/db/bundb/report.go @@ -106,7 +106,7 @@ func (r *reportDB) GetReports(ctx context.Context, resolved *bool, accountID str for _, id := range reportIDs { report, err := r.GetReportByID(ctx, id) if err != nil { - log.Errorf("GetReports: error getting report %q: %v", id, err) + log.Errorf(ctx, "error getting report %q: %v", id, err) continue } diff --git a/internal/db/bundb/status.go b/internal/db/bundb/status.go index 709105f72..2bec07759 100644 --- a/internal/db/bundb/status.go +++ b/internal/db/bundb/status.go @@ -74,7 +74,7 @@ func (s *statusDB) GetStatuses(ctx context.Context, ids []string) ([]*gtsmodel.S // Attempt fetch from DB status, err := s.GetStatusByID(ctx, id) if err != nil { - log.Errorf("GetStatuses: error getting status %q: %v", id, err) + log.Errorf(ctx, "error getting status %q: %v", id, err) continue } @@ -387,7 +387,7 @@ func (s *statusDB) GetStatusChildren(ctx context.Context, status *gtsmodel.Statu // only append children, not the overall parent status entry, ok := e.Value.(*gtsmodel.Status) if !ok { - log.Panic("GetStatusChildren: found status could not be asserted to *gtsmodel.Status") + log.Panic(ctx, "found status could not be asserted to *gtsmodel.Status") } if entry.ID != status.ID { @@ -412,7 +412,7 @@ func (s *statusDB) statusChildren(ctx context.Context, status *gtsmodel.Status, if err := q.Scan(ctx, &childIDs); err != nil { if err != sql.ErrNoRows { - log.Errorf("statusChildren: error getting children for %q: %v", status.ID, err) + log.Errorf(ctx, "error getting children for %q: %v", status.ID, err) } return } @@ -421,7 +421,7 @@ func (s *statusDB) statusChildren(ctx context.Context, status *gtsmodel.Status, // Fetch child with ID from database child, err := s.GetStatusByID(ctx, id) if err != nil { - log.Errorf("statusChildren: error getting child status %q: %v", id, err) + log.Errorf(ctx, "error getting child status %q: %v", id, err) continue } @@ -429,7 +429,7 @@ func (s *statusDB) statusChildren(ctx context.Context, status *gtsmodel.Status, for e := foundStatuses.Front(); e != nil; e = e.Next() { entry, ok := e.Value.(*gtsmodel.Status) if !ok { - log.Panic("statusChildren: found status could not be asserted to *gtsmodel.Status") + log.Panic(ctx, "found status could not be asserted to *gtsmodel.Status") } if child.InReplyToAccountID != "" && entry.ID == child.InReplyToID { diff --git a/internal/db/bundb/timeline.go b/internal/db/bundb/timeline.go index 3340acf94..c499993e3 100644 --- a/internal/db/bundb/timeline.go +++ b/internal/db/bundb/timeline.go @@ -114,7 +114,7 @@ func (t *timelineDB) GetHomeTimeline(ctx context.Context, accountID string, maxI // Fetch status from db for ID status, err := t.state.DB.GetStatusByID(ctx, id) if err != nil { - log.Errorf("GetHomeTimeline: error fetching status %q: %v", id, err) + log.Errorf(ctx, "error fetching status %q: %v", id, err) continue } @@ -182,7 +182,7 @@ func (t *timelineDB) GetPublicTimeline(ctx context.Context, maxID string, sinceI // Fetch status from db for ID status, err := t.state.DB.GetStatusByID(ctx, id) if err != nil { - log.Errorf("GetPublicTimeline: error fetching status %q: %v", id, err) + log.Errorf(ctx, "error fetching status %q: %v", id, err) continue } @@ -242,7 +242,7 @@ func (t *timelineDB) GetFavedTimeline(ctx context.Context, accountID string, max // Fetch status from db for corresponding favourite status, err := t.state.DB.GetStatusByID(ctx, fave.StatusID) if err != nil { - log.Errorf("GetFavedTimeline: error fetching status for fave %q: %v", fave.ID, err) + log.Errorf(ctx, "error fetching status for fave %q: %v", fave.ID, err) continue } diff --git a/internal/email/confirm.go b/internal/email/confirm.go index aba09a664..087da92c2 100644 --- a/internal/email/confirm.go +++ b/internal/email/confirm.go @@ -42,7 +42,7 @@ func (s *sender) SendConfirmEmail(toAddress string, data ConfirmData) error { if err != nil { return err } - log.Trace(s.hostAddress + "\n" + config.GetSMTPUsername() + ":password" + "\n" + s.from + "\n" + toAddress + "\n\n" + string(msg) + "\n") + log.Trace(nil, s.hostAddress+"\n"+config.GetSMTPUsername()+":password"+"\n"+s.from+"\n"+toAddress+"\n\n"+string(msg)+"\n") return smtp.SendMail(s.hostAddress, s.auth, s.from, []string{toAddress}, msg) } diff --git a/internal/email/noopsender.go b/internal/email/noopsender.go index bf691b8bb..2277490e1 100644 --- a/internal/email/noopsender.go +++ b/internal/email/noopsender.go @@ -61,7 +61,7 @@ func (s *noopSender) SendConfirmEmail(toAddress string, data ConfirmData) error return err } - log.Tracef("NOT SENDING confirmation email to %s with contents: %s", toAddress, msg) + log.Tracef(nil, "NOT SENDING confirmation email to %s with contents: %s", toAddress, msg) if s.sendCallback != nil { s.sendCallback(toAddress, string(msg)) @@ -81,7 +81,7 @@ func (s *noopSender) SendResetEmail(toAddress string, data ResetData) error { return err } - log.Tracef("NOT SENDING reset email to %s with contents: %s", toAddress, msg) + log.Tracef(nil, "NOT SENDING reset email to %s with contents: %s", toAddress, msg) if s.sendCallback != nil { s.sendCallback(toAddress, string(msg)) diff --git a/internal/federation/authenticate.go b/internal/federation/authenticate.go index 157a1830b..a966bb26a 100644 --- a/internal/federation/authenticate.go +++ b/internal/federation/authenticate.go @@ -124,7 +124,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU if vi == nil { err := errors.New("http request wasn't signed or http signature was invalid") errWithCode := gtserror.NewErrorUnauthorized(err, err.Error()) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -132,7 +132,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU if !ok { err := errors.New("http request wasn't signed or http signature was invalid") errWithCode := gtserror.NewErrorUnauthorized(err, err.Error()) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -141,7 +141,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU if si == nil { err := errors.New("http request wasn't signed or http signature was invalid") errWithCode := gtserror.NewErrorUnauthorized(err, err.Error()) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -149,7 +149,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU if !ok { err := errors.New("http request wasn't signed or http signature was invalid") errWithCode := gtserror.NewErrorUnauthorized(err, err.Error()) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -157,7 +157,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU requestingPublicKeyID, err := url.Parse(verifier.KeyId()) if err != nil { errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key URL %s", verifier.KeyId())) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -170,12 +170,12 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU if host := config.GetHost(); strings.EqualFold(requestingHost, host) { // LOCAL ACCOUNT REQUEST // the request is coming from INSIDE THE HOUSE so skip the remote dereferencing - log.Tracef("proceeding without dereference for local public key %s", requestingPublicKeyID) + log.Tracef(ctx, "proceeding without dereference for local public key %s", requestingPublicKeyID) requestingLocalAccount, err = f.db.GetAccountByPubkeyID(ctx, requestingPublicKeyID.String()) if err != nil { errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("couldn't get account with public key uri %s from the database: %s", requestingPublicKeyID.String(), err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -184,18 +184,18 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU pkOwnerURI, err = url.Parse(requestingLocalAccount.URI) if err != nil { errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key owner URL %s", requestingLocalAccount.URI)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } } else if requestingRemoteAccount, err = f.db.GetAccountByPubkeyID(ctx, requestingPublicKeyID.String()); err == nil { // REMOTE ACCOUNT REQUEST WITH KEY CACHED LOCALLY // this is a remote account and we already have the public key for it so use that - log.Tracef("proceeding without dereference for cached public key %s", requestingPublicKeyID) + log.Tracef(ctx, "proceeding without dereference for cached public key %s", requestingPublicKeyID) publicKey = requestingRemoteAccount.PublicKey pkOwnerURI, err = url.Parse(requestingRemoteAccount.URI) if err != nil { errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key owner URL %s", requestingRemoteAccount.URI)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } } else { @@ -205,21 +205,21 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU gone, err := f.CheckGone(ctx, requestingPublicKeyID) if err != nil { errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error checking for tombstone for %s: %s", requestingPublicKeyID, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } if gone { errWithCode := gtserror.NewErrorGone(fmt.Errorf("account with public key %s is gone", requestingPublicKeyID)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } - log.Tracef("proceeding with dereference for uncached public key %s", requestingPublicKeyID) + log.Tracef(ctx, "proceeding with dereference for uncached public key %s", requestingPublicKeyID) trans, err := f.transportController.NewTransportForUsername(transport.WithFastfail(ctx), requestedUsername) if err != nil { errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error creating transport for %s: %s", requestedUsername, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -231,16 +231,16 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU // we should add a tombstone to our database so that we can avoid trying to deref it in future if err := f.HandleGone(ctx, requestingPublicKeyID); err != nil { errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error marking account with public key %s as gone: %s", requestingPublicKeyID, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } errWithCode := gtserror.NewErrorGone(fmt.Errorf("account with public key %s is gone", requestingPublicKeyID)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("error dereferencing public key %s: %s", requestingPublicKeyID, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -248,7 +248,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU requestingPublicKey, err := getPublicKeyFromResponse(ctx, b, requestingPublicKeyID) if err != nil { errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("error parsing public key %s: %s", requestingPublicKeyID, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -256,7 +256,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU pkPemProp := requestingPublicKey.GetW3IDSecurityV1PublicKeyPem() if pkPemProp == nil || !pkPemProp.IsXMLSchemaString() { errWithCode := gtserror.NewErrorUnauthorized(errors.New("publicKeyPem property is not provided or it is not embedded as a value")) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -265,14 +265,14 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU block, _ := pem.Decode([]byte(pubKeyPem)) if block == nil || block.Type != "PUBLIC KEY" { errWithCode := gtserror.NewErrorUnauthorized(errors.New("could not decode publicKeyPem to PUBLIC KEY pem block type")) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } publicKey, err = x509.ParsePKIXPublicKey(block.Bytes) if err != nil { errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("could not parse public key %s from block bytes: %s", requestingPublicKeyID, err)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -280,7 +280,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU pkOwnerProp := requestingPublicKey.GetW3IDSecurityV1Owner() if pkOwnerProp == nil || !pkOwnerProp.IsIRI() { errWithCode := gtserror.NewErrorUnauthorized(errors.New("publicKeyOwner property is not provided or it is not embedded as a value")) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } pkOwnerURI = pkOwnerProp.GetIRI() @@ -289,7 +289,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU // after all that, public key should be defined if publicKey == nil { errWithCode := gtserror.NewErrorInternalError(errors.New("returned public key was empty")) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } @@ -301,16 +301,16 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU } for _, algo := range algos { - log.Tracef("trying algo: %s", algo) + log.Tracef(ctx, "trying algo: %s", algo) err := verifier.Verify(publicKey, algo) if err == nil { - log.Tracef("authentication for %s PASSED with algorithm %s", pkOwnerURI, algo) + log.Tracef(ctx, "authentication for %s PASSED with algorithm %s", pkOwnerURI, algo) return pkOwnerURI, nil } - log.Tracef("authentication for %s NOT PASSED with algorithm %s: %s", pkOwnerURI, algo, err) + log.Tracef(ctx, "authentication for %s NOT PASSED with algorithm %s: %s", pkOwnerURI, algo, err) } errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("authentication not passed for public key owner %s; signature value was '%s'", pkOwnerURI, signature)) - log.Debug(errWithCode) + log.Debug(ctx, errWithCode) return nil, errWithCode } diff --git a/internal/federation/dereferencing/account.go b/internal/federation/dereferencing/account.go index ed514e493..93e0e3549 100644 --- a/internal/federation/dereferencing/account.go +++ b/internal/federation/dereferencing/account.go @@ -77,7 +77,7 @@ func (d *deref) GetAccountByURI(ctx context.Context, requestUser string, uri *ur // Try to update existing account model enriched, err := d.enrichAccount(ctx, requestUser, uri, account, false, block) if err != nil { - log.Errorf("error enriching remote account: %v", err) + log.Errorf(ctx, "error enriching remote account: %v", err) return account, nil // fall back to returning existing } @@ -114,7 +114,7 @@ func (d *deref) GetAccountByUsernameDomain(ctx context.Context, requestUser stri // Try to update existing account model enriched, err := d.enrichAccount(ctx, requestUser, nil, account, false, block) if err != nil { - log.Errorf("GetAccountByUsernameDomain: error enriching account from remote: %v", err) + log.Errorf(ctx, "error enriching account from remote: %v", err) return account, nil // fall back to returning unchanged existing account model } @@ -250,7 +250,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url. latestAcc.ID, ) if err != nil { - log.Errorf("error fetching remote avatar for account %s: %v", uri, err) + log.Errorf(ctx, "error fetching remote avatar for account %s: %v", uri, err) // Keep old avatar for now, we'll try again in $interval. latestAcc.AvatarMediaAttachmentID = account.AvatarMediaAttachmentID @@ -271,7 +271,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url. latestAcc.ID, ) if err != nil { - log.Errorf("error fetching remote header for account %s: %v", uri, err) + log.Errorf(ctx, "error fetching remote header for account %s: %v", uri, err) // Keep old header for now, we'll try again in $interval. latestAcc.HeaderMediaAttachmentID = account.HeaderMediaAttachmentID @@ -283,7 +283,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url. // Fetch the latest remote account emoji IDs used in account display name/bio. _, err = d.fetchRemoteAccountEmojis(ctx, latestAcc, requestUser) if err != nil { - log.Errorf("error fetching remote emojis for account %s: %v", uri, err) + log.Errorf(ctx, "error fetching remote emojis for account %s: %v", uri, err) } if account.CreatedAt.IsZero() { diff --git a/internal/federation/dereferencing/emoji.go b/internal/federation/dereferencing/emoji.go index 7d8526c73..15d341383 100644 --- a/internal/federation/dereferencing/emoji.go +++ b/internal/federation/dereferencing/emoji.go @@ -111,7 +111,7 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji, // have to get it from the database again gotEmoji = e } else if gotEmoji, err = d.db.GetEmojiByShortcodeDomain(ctx, e.Shortcode, e.Domain); err != nil && err != db.ErrNoEntries { - log.Errorf("populateEmojis: error checking database for emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "error checking database for emoji %s: %s", shortcodeDomain, err) continue } @@ -120,24 +120,24 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji, if gotEmoji != nil { // we had the emoji already, but refresh it if necessary if e.UpdatedAt.Unix() > gotEmoji.ImageUpdatedAt.Unix() { - log.Tracef("populateEmojis: emoji %s was updated since we last saw it, will refresh", shortcodeDomain) + log.Tracef(ctx, "emoji %s was updated since we last saw it, will refresh", shortcodeDomain) refresh = true } if !refresh && (e.URI != gotEmoji.URI) { - log.Tracef("populateEmojis: emoji %s changed URI since we last saw it, will refresh", shortcodeDomain) + log.Tracef(ctx, "emoji %s changed URI since we last saw it, will refresh", shortcodeDomain) refresh = true } if !refresh && (e.ImageRemoteURL != gotEmoji.ImageRemoteURL) { - log.Tracef("populateEmojis: emoji %s changed image URL since we last saw it, will refresh", shortcodeDomain) + log.Tracef(ctx, "emoji %s changed image URL since we last saw it, will refresh", shortcodeDomain) refresh = true } if !refresh { - log.Tracef("populateEmojis: emoji %s is up to date, will not refresh", shortcodeDomain) + log.Tracef(ctx, "emoji %s is up to date, will not refresh", shortcodeDomain) } else { - log.Tracef("populateEmojis: refreshing emoji %s", shortcodeDomain) + log.Tracef(ctx, "refreshing emoji %s", shortcodeDomain) emojiID := gotEmoji.ID // use existing ID processingEmoji, err := d.GetRemoteEmoji(ctx, requestingUsername, e.ImageRemoteURL, e.Shortcode, e.Domain, emojiID, e.URI, &media.AdditionalEmojiInfo{ Domain: &e.Domain, @@ -147,12 +147,12 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji, VisibleInPicker: gotEmoji.VisibleInPicker, }, refresh) if err != nil { - log.Errorf("populateEmojis: couldn't refresh remote emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "couldn't refresh remote emoji %s: %s", shortcodeDomain, err) continue } if gotEmoji, err = processingEmoji.LoadEmoji(ctx); err != nil { - log.Errorf("populateEmojis: couldn't load refreshed remote emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "couldn't load refreshed remote emoji %s: %s", shortcodeDomain, err) continue } } @@ -160,7 +160,7 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji, // it's new! go get it! newEmojiID, err := id.NewRandomULID() if err != nil { - log.Errorf("populateEmojis: error generating id for remote emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "error generating id for remote emoji %s: %s", shortcodeDomain, err) continue } @@ -172,12 +172,12 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji, VisibleInPicker: e.VisibleInPicker, }, refresh) if err != nil { - log.Errorf("populateEmojis: couldn't get remote emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "couldn't get remote emoji %s: %s", shortcodeDomain, err) continue } if gotEmoji, err = processingEmoji.LoadEmoji(ctx); err != nil { - log.Errorf("populateEmojis: couldn't load remote emoji %s: %s", shortcodeDomain, err) + log.Errorf(ctx, "couldn't load remote emoji %s: %s", shortcodeDomain, err) continue } } diff --git a/internal/federation/dereferencing/status.go b/internal/federation/dereferencing/status.go index da4639c5d..56545c5e0 100644 --- a/internal/federation/dereferencing/status.go +++ b/internal/federation/dereferencing/status.go @@ -318,20 +318,20 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta for _, m := range status.Mentions { if m.ID != "" { // we've already populated this mention, since it has an ID - log.Debug("populateStatusMentions: mention already populated") + log.Debug(ctx, "mention already populated") mentionIDs = append(mentionIDs, m.ID) newMentions = append(newMentions, m) continue } if m.TargetAccountURI == "" { - log.Debug("populateStatusMentions: target URI not set on mention") + log.Debug(ctx, "target URI not set on mention") continue } targetAccountURI, err := url.Parse(m.TargetAccountURI) if err != nil { - log.Debugf("populateStatusMentions: error parsing mentioned account uri %s: %s", m.TargetAccountURI, err) + log.Debugf(ctx, "error parsing mentioned account uri %s: %s", m.TargetAccountURI, err) continue } @@ -342,7 +342,7 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta if a, err := d.db.GetAccountByURI(ctx, targetAccountURI.String()); err != nil { errs = append(errs, err.Error()) } else { - log.Debugf("populateStatusMentions: got target account %s with id %s through GetAccountByURI", targetAccountURI, a.ID) + log.Debugf(ctx, "got target account %s with id %s through GetAccountByURI", targetAccountURI, a.ID) targetAccount = a } @@ -352,13 +352,13 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta if a, err := d.GetAccountByURI(ctx, requestingUsername, targetAccountURI, false); err != nil { errs = append(errs, err.Error()) } else { - log.Debugf("populateStatusMentions: got target account %s with id %s through GetRemoteAccount", targetAccountURI, a.ID) + log.Debugf(ctx, "got target account %s with id %s through GetRemoteAccount", targetAccountURI, a.ID) targetAccount = a } } if targetAccount == nil { - log.Debugf("populateStatusMentions: couldn't get target account %s: %s", m.TargetAccountURI, strings.Join(errs, " : ")) + log.Debugf(ctx, "couldn't get target account %s: %s", m.TargetAccountURI, strings.Join(errs, " : ")) continue } @@ -419,13 +419,13 @@ func (d *deref) populateStatusAttachments(ctx context.Context, status *gtsmodel. Blurhash: &a.Blurhash, }) if err != nil { - log.Errorf("populateStatusAttachments: couldn't get remote media %s: %s", a.RemoteURL, err) + log.Errorf(ctx, "couldn't get remote media %s: %s", a.RemoteURL, err) continue } attachment, err := processingMedia.LoadAttachment(ctx) if err != nil { - log.Errorf("populateStatusAttachments: couldn't load remote attachment %s: %s", a.RemoteURL, err) + log.Errorf(ctx, "couldn't load remote attachment %s: %s", a.RemoteURL, err) continue } diff --git a/internal/federation/dereferencing/thread.go b/internal/federation/dereferencing/thread.go index e89b2da7a..517d44e7a 100644 --- a/internal/federation/dereferencing/thread.go +++ b/internal/federation/dereferencing/thread.go @@ -45,10 +45,11 @@ // // This does not return error, as for robustness we do not want to error-out on a status because another further up / down has issues. func (d *deref) DereferenceThread(ctx context.Context, username string, statusIRI *url.URL, status *gtsmodel.Status, statusable ap.Statusable) { - l := log.WithFields(kv.Fields{ - {"username", username}, - {"statusIRI", status.URI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"username", username}, + {"statusIRI", status.URI}, + }...) // Log function start l.Trace("beginning") @@ -72,10 +73,11 @@ func (d *deref) dereferenceStatusAncestors(ctx context.Context, username string, ogIRI := status.URI // Start log entry with fields - l := log.WithFields(kv.Fields{ - {"username", username}, - {"statusIRI", ogIRI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"username", username}, + {"statusIRI", ogIRI}, + }...) // Log function start l.Trace("beginning") @@ -132,10 +134,11 @@ func (d *deref) dereferenceStatusDescendants(ctx context.Context, username strin ogIRI := statusIRI // Start log entry with fields - l := log.WithFields(kv.Fields{ - {"username", username}, - {"statusIRI", ogIRI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"username", username}, + {"statusIRI", ogIRI}, + }...) // Log function start l.Trace("beginning") diff --git a/internal/federation/federatingactor.go b/internal/federation/federatingactor.go index 029149a9b..71e6e8fb6 100644 --- a/internal/federation/federatingactor.go +++ b/internal/federation/federatingactor.go @@ -56,7 +56,7 @@ func newFederatingActor(c pub.CommonBehavior, s2s pub.FederatingProtocol, db pub // method will guaranteed work for non-custom Actors. For custom actors, // care should be used to not call this method if only C2S is supported. func (f *federatingActor) Send(c context.Context, outbox *url.URL, t vocab.Type) (pub.Activity, error) { - log.Infof("federating actor: send activity %s via outbox %s", t.GetTypeName(), outbox) + log.Infof(c, "send activity %s via outbox %s", t.GetTypeName(), outbox) return f.actor.Send(c, outbox, t) } diff --git a/internal/federation/federatingdb/create.go b/internal/federation/federatingdb/create.go index 62784e68d..bf3e7f75d 100644 --- a/internal/federation/federatingdb/create.go +++ b/internal/federation/federatingdb/create.go @@ -53,8 +53,9 @@ func (f *federatingDB) Create(ctx context.Context, asType vocab.Type) error { if err != nil { return err } - l := log.WithField("create", i) - l.Debug("entering Create") + l := log.WithContext(ctx). + WithField("create", i) + l.Trace("entering Create") } receivingAccount, requestingAccount := extractFromCtx(ctx) @@ -164,10 +165,11 @@ func (f *federatingDB) activityCreate(ctx context.Context, asType vocab.Type, re // createNote handles a Create activity with a Note type. func (f *federatingDB) createNote(ctx context.Context, note vocab.ActivityStreamsNote, receivingAccount *gtsmodel.Account, requestingAccount *gtsmodel.Account) error { - l := log.WithFields(kv.Fields{ - {"receivingAccount", receivingAccount.URI}, - {"requestingAccount", requestingAccount.URI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"receivingAccount", receivingAccount.URI}, + {"requestingAccount", requestingAccount.URI}, + }...) // Check if we have a forward. // In other words, was the note posted to our inbox by at least one actor who actually created the note, or are they just forwarding it? diff --git a/internal/federation/federatingdb/delete.go b/internal/federation/federatingdb/delete.go index 22434f63e..a1890b56b 100644 --- a/internal/federation/federatingdb/delete.go +++ b/internal/federation/federatingdb/delete.go @@ -35,9 +35,10 @@ // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Delete(ctx context.Context, id *url.URL) error { - l := log.WithFields(kv.Fields{ - {"id", id}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"id", id}, + }...) l.Debug("entering Delete") receivingAccount, requestingAccount := extractFromCtx(ctx) diff --git a/internal/federation/federatingdb/exists.go b/internal/federation/federatingdb/exists.go index 51e7399aa..a235770c6 100644 --- a/internal/federation/federatingdb/exists.go +++ b/internal/federation/federatingdb/exists.go @@ -32,10 +32,11 @@ // The library makes this call only after acquiring a lock first. // // Implementation note: this just straight up isn't implemented, and doesn't *really* need to be either. -func (f *federatingDB) Exists(c context.Context, id *url.URL) (exists bool, err error) { - l := log.WithFields(kv.Fields{ - {"id", id}, - }...) +func (f *federatingDB) Exists(ctx context.Context, id *url.URL) (exists bool, err error) { + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"id", id}, + }...) l.Debug("entering Exists") return false, nil } diff --git a/internal/federation/federatingdb/followers.go b/internal/federation/federatingdb/followers.go index 9a80d5f0b..c47a2b625 100644 --- a/internal/federation/federatingdb/followers.go +++ b/internal/federation/federatingdb/followers.go @@ -18,9 +18,10 @@ // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Followers(ctx context.Context, actorIRI *url.URL) (followers vocab.ActivityStreamsCollection, err error) { - l := log.WithFields(kv.Fields{ - {"id", actorIRI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"id", actorIRI}, + }...) l.Debug("entering Followers") acct, err := f.getAccountForIRI(ctx, actorIRI) diff --git a/internal/federation/federatingdb/following.go b/internal/federation/federatingdb/following.go index 2290b72f4..f4f07bb25 100644 --- a/internal/federation/federatingdb/following.go +++ b/internal/federation/federatingdb/following.go @@ -36,9 +36,10 @@ // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Following(ctx context.Context, actorIRI *url.URL) (following vocab.ActivityStreamsCollection, err error) { - l := log.WithFields(kv.Fields{ - {"id", actorIRI}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"id", actorIRI}, + }...) l.Debug("entering Following") acct, err := f.getAccountForIRI(ctx, actorIRI) diff --git a/internal/federation/federatingdb/get.go b/internal/federation/federatingdb/get.go index a55cb0280..92a79d70f 100644 --- a/internal/federation/federatingdb/get.go +++ b/internal/federation/federatingdb/get.go @@ -33,7 +33,8 @@ // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Get(ctx context.Context, id *url.URL) (value vocab.Type, err error) { - l := log.WithFields(kv.Fields{{"id", id}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"id", id}}...) l.Debug("entering Get") switch { diff --git a/internal/federation/federatingdb/owns.go b/internal/federation/federatingdb/owns.go index 070036df7..def0fa518 100644 --- a/internal/federation/federatingdb/owns.go +++ b/internal/federation/federatingdb/owns.go @@ -35,9 +35,10 @@ // the database has an entry for the IRI. // The library makes this call only after acquiring a lock first. func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { - l := log.WithFields(kv.Fields{ - {"id", id}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"id", id}, + }...) l.Debug("entering Owns") // if the id host isn't this instance host, we don't own this IRI diff --git a/internal/federation/federatingdb/util.go b/internal/federation/federatingdb/util.go index b5a9feab1..1eb27dc03 100644 --- a/internal/federation/federatingdb/util.go +++ b/internal/federation/federatingdb/util.go @@ -304,7 +304,7 @@ func extractFromCtx(ctx context.Context) (receivingAccount, requestingAccount *g var ok bool receivingAccount, ok = receivingAccountI.(*gtsmodel.Account) if !ok { - log.Panicf("extractFromCtx: context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextReceivingAccount) + log.Panicf(ctx, "context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextReceivingAccount) } } @@ -313,7 +313,7 @@ func extractFromCtx(ctx context.Context) (receivingAccount, requestingAccount *g var ok bool requestingAccount, ok = requestingAcctI.(*gtsmodel.Account) if !ok { - log.Panicf("extractFromCtx: context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextRequestingAccount) + log.Panicf(ctx, "context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextRequestingAccount) } } diff --git a/internal/federation/federatingprotocol.go b/internal/federation/federatingprotocol.go index d75570dd6..e60f278c7 100644 --- a/internal/federation/federatingprotocol.go +++ b/internal/federation/federatingprotocol.go @@ -138,10 +138,11 @@ func (f *federator) PostInboxRequestBodyHook(ctx context.Context, r *http.Reques // authenticated must be true and error nil. The request will continue // to be processed. func (f *federator) AuthenticatePostInbox(ctx context.Context, w http.ResponseWriter, r *http.Request) (context.Context, bool, error) { - l := log.WithFields(kv.Fields{ - {"useragent", r.UserAgent()}, - {"url", r.URL.String()}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"useragent", r.UserAgent()}, + {"url", r.URL.String()}, + }...) l.Trace("received request to authenticate") if !uris.IsInboxPath(r.URL) { @@ -242,7 +243,7 @@ func (f *federator) AuthenticatePostInbox(ctx context.Context, w http.ResponseWr // blocked must be false and error nil. The request will continue // to be processed. func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, error) { - log.Debugf("entering BLOCKED function with IRI list: %+v", actorIRIs) + log.Tracef(ctx, "entering BLOCKED function with IRI list: %+v", actorIRIs) // check domain blocks first for the given actor IRIs blocked, err := f.db.AreURIsBlocked(ctx, actorIRIs) @@ -257,7 +258,7 @@ func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, er otherInvolvedIRIsI := ctx.Value(ap.ContextOtherInvolvedIRIs) otherInvolvedIRIs, ok := otherInvolvedIRIsI.([]*url.URL) if !ok { - log.Error("other involved IRIs not set on request context") + log.Error(ctx, "other involved IRIs not set on request context") return false, errors.New("other involved IRIs not set on request context, so couldn't determine blocks") } blocked, err = f.db.AreURIsBlocked(ctx, otherInvolvedIRIs) @@ -272,13 +273,13 @@ func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, er receivingAccountI := ctx.Value(ap.ContextReceivingAccount) receivingAccount, ok := receivingAccountI.(*gtsmodel.Account) if !ok { - log.Error("receiving account not set on request context") + log.Error(ctx, "receiving account not set on request context") return false, errors.New("receiving account not set on request context, so couldn't determine blocks") } requestingAccountI := ctx.Value(ap.ContextRequestingAccount) requestingAccount, ok := requestingAccountI.(*gtsmodel.Account) if !ok { - log.Error("requesting account not set on request context") + log.Error(ctx, "requesting account not set on request context") return false, errors.New("requesting account not set on request context, so couldn't determine blocks") } // the receiver shouldn't block the sender @@ -384,10 +385,11 @@ func(ctx context.Context, announce vocab.ActivityStreamsAnnounce) error { // type and extension, so the unhandled ones are passed to // DefaultCallback. func (f *federator) DefaultCallback(ctx context.Context, activity pub.Activity) error { - l := log.WithFields(kv.Fields{ - {"aptype", activity.GetTypeName()}, - }...) - l.Debugf("received unhandle-able activity type so ignoring it") + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"aptype", activity.GetTypeName()}, + }...) + l.Debug("received unhandle-able activity type so ignoring it") return nil } diff --git a/internal/httpclient/client.go b/internal/httpclient/client.go index 6de975bbd..45f0c3447 100644 --- a/internal/httpclient/client.go +++ b/internal/httpclient/client.go @@ -180,12 +180,13 @@ func (c *Client) Do(req *http.Request) (*http.Response, error) { if !ok { // No spot acquired, log warning - log.WithFields(kv.Fields{ - {K: "queue", V: len(wait)}, - {K: "method", V: req.Method}, - {K: "host", V: req.Host}, - {K: "uri", V: req.URL.RequestURI()}, - }...).Warn("full request queue") + log.WithContext(req.Context()). + WithFields(kv.Fields{ + {K: "queue", V: len(wait)}, + {K: "method", V: req.Method}, + {K: "host", V: req.Host}, + {K: "uri", V: req.URL.RequestURI()}, + }...).Warn("full request queue") select { case <-req.Context().Done(): diff --git a/internal/log/entry.go b/internal/log/entry.go index 0d4e16e2b..d782be9f7 100644 --- a/internal/log/entry.go +++ b/internal/log/entry.go @@ -19,6 +19,7 @@ package log import ( + "context" "fmt" "syscall" @@ -27,91 +28,97 @@ ) type Entry struct { - fields []kv.Field + ctx context.Context + kvs []kv.Field } -func (e Entry) WithField(key string, value interface{}) Entry { - e.fields = append(e.fields, kv.Field{K: key, V: value}) +func (e Entry) WithContext(ctx context.Context) Entry { + e.ctx = ctx return e } -func (e Entry) WithFields(fields ...kv.Field) Entry { - e.fields = append(e.fields, fields...) +func (e Entry) WithField(key string, value interface{}) Entry { + e.kvs = append(e.kvs, kv.Field{K: key, V: value}) + return e +} + +func (e Entry) WithFields(kvs ...kv.Field) Entry { + e.kvs = append(e.kvs, kvs...) return e } func (e Entry) Trace(a ...interface{}) { - logf(3, level.TRACE, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.TRACE, e.kvs, args(len(a)), a...) } func (e Entry) Tracef(s string, a ...interface{}) { - logf(3, level.TRACE, e.fields, s, a...) + logf(e.ctx, 3, level.TRACE, e.kvs, s, a...) } func (e Entry) Debug(a ...interface{}) { - logf(3, level.DEBUG, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.DEBUG, e.kvs, args(len(a)), a...) } func (e Entry) Debugf(s string, a ...interface{}) { - logf(3, level.DEBUG, e.fields, s, a...) + logf(e.ctx, 3, level.DEBUG, e.kvs, s, a...) } func (e Entry) Info(a ...interface{}) { - logf(3, level.INFO, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.INFO, e.kvs, args(len(a)), a...) } func (e Entry) Infof(s string, a ...interface{}) { - logf(3, level.INFO, e.fields, s, a...) + logf(e.ctx, 3, level.INFO, e.kvs, s, a...) } func (e Entry) Warn(a ...interface{}) { - logf(3, level.WARN, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.WARN, e.kvs, args(len(a)), a...) } func (e Entry) Warnf(s string, a ...interface{}) { - logf(3, level.WARN, e.fields, s, a...) + logf(e.ctx, 3, level.WARN, e.kvs, s, a...) } func (e Entry) Error(a ...interface{}) { - logf(3, level.ERROR, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.ERROR, e.kvs, args(len(a)), a...) } func (e Entry) Errorf(s string, a ...interface{}) { - logf(3, level.ERROR, e.fields, s, a...) + logf(e.ctx, 3, level.ERROR, e.kvs, s, a...) } func (e Entry) Fatal(a ...interface{}) { defer syscall.Exit(1) - logf(3, level.FATAL, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.FATAL, e.kvs, args(len(a)), a...) } func (e Entry) Fatalf(s string, a ...interface{}) { defer syscall.Exit(1) - logf(3, level.FATAL, e.fields, s, a...) + logf(e.ctx, 3, level.FATAL, e.kvs, s, a...) } func (e Entry) Panic(a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(3, level.PANIC, e.fields, args(len(a)), a...) + logf(e.ctx, 3, level.PANIC, e.kvs, args(len(a)), a...) } func (e Entry) Panicf(s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(3, level.PANIC, e.fields, s, a...) + logf(e.ctx, 3, level.PANIC, e.kvs, s, a...) } func (e Entry) Log(lvl level.LEVEL, a ...interface{}) { - logf(3, lvl, e.fields, args(len(a)), a...) + logf(e.ctx, 3, lvl, e.kvs, args(len(a)), a...) } func (e Entry) Logf(lvl level.LEVEL, s string, a ...interface{}) { - logf(3, lvl, e.fields, s, a...) + logf(e.ctx, 3, lvl, e.kvs, s, a...) } func (e Entry) Print(a ...interface{}) { - printf(3, e.fields, args(len(a)), a...) + printf(3, e.kvs, args(len(a)), a...) } func (e Entry) Printf(s string, a ...interface{}) { - printf(3, e.fields, s, a...) + printf(3, e.kvs, s, a...) } diff --git a/internal/log/log.go b/internal/log/log.go index 78fb143b6..9240d1e79 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -19,6 +19,7 @@ package log import ( + "context" "fmt" "log/syslog" "os" @@ -38,13 +39,21 @@ // lvlstrs is the lookup table of log levels to strings. lvlstrs = level.Default() - // Syslog output, only set if enabled. + // syslog output, only set if enabled. sysout *syslog.Writer // timefmt is the logging time format used. timefmt = "02/01/2006 15:04:05.000" + + // ctxhooks allows modifying log content based on context. + ctxhooks []func(context.Context, []kv.Field) []kv.Field ) +// Hook adds the given hook to the global logger context hooks stack. +func Hook(hook func(ctx context.Context, kvs []kv.Field) []kv.Field) { + ctxhooks = append(ctxhooks, hook) +} + // Level returns the currently set log level. func Level() level.LEVEL { return level.LEVEL(loglvl.Load()) @@ -60,82 +69,86 @@ func New() Entry { return Entry{} } +func WithContext(ctx context.Context) Entry { + return Entry{ctx: ctx} +} + func WithField(key string, value interface{}) Entry { - return Entry{fields: []kv.Field{{K: key, V: value}}} + return New().WithField(key, value) } func WithFields(fields ...kv.Field) Entry { - return Entry{fields: fields} + return New().WithFields(fields...) } -func Trace(a ...interface{}) { - logf(3, level.TRACE, nil, args(len(a)), a...) +func Trace(ctx context.Context, a ...interface{}) { + logf(ctx, 3, level.TRACE, nil, args(len(a)), a...) } -func Tracef(s string, a ...interface{}) { - logf(3, level.TRACE, nil, s, a...) +func Tracef(ctx context.Context, s string, a ...interface{}) { + logf(ctx, 3, level.TRACE, nil, s, a...) } -func Debug(a ...interface{}) { - logf(3, level.DEBUG, nil, args(len(a)), a...) +func Debug(ctx context.Context, a ...interface{}) { + logf(ctx, 3, level.DEBUG, nil, args(len(a)), a...) } -func Debugf(s string, a ...interface{}) { - logf(3, level.DEBUG, nil, s, a...) +func Debugf(ctx context.Context, s string, a ...interface{}) { + logf(ctx, 3, level.DEBUG, nil, s, a...) } -func Info(a ...interface{}) { - logf(3, level.INFO, nil, args(len(a)), a...) +func Info(ctx context.Context, a ...interface{}) { + logf(ctx, 3, level.INFO, nil, args(len(a)), a...) } -func Infof(s string, a ...interface{}) { - logf(3, level.INFO, nil, s, a...) +func Infof(ctx context.Context, s string, a ...interface{}) { + logf(ctx, 3, level.INFO, nil, s, a...) } -func Warn(a ...interface{}) { - logf(3, level.WARN, nil, args(len(a)), a...) +func Warn(ctx context.Context, a ...interface{}) { + logf(ctx, 3, level.WARN, nil, args(len(a)), a...) } -func Warnf(s string, a ...interface{}) { - logf(3, level.WARN, nil, s, a...) +func Warnf(ctx context.Context, s string, a ...interface{}) { + logf(ctx, 3, level.WARN, nil, s, a...) } -func Error(a ...interface{}) { - logf(3, level.ERROR, nil, args(len(a)), a...) +func Error(ctx context.Context, a ...interface{}) { + logf(ctx, 3, level.ERROR, nil, args(len(a)), a...) } -func Errorf(s string, a ...interface{}) { - logf(3, level.ERROR, nil, s, a...) +func Errorf(ctx context.Context, s string, a ...interface{}) { + logf(ctx, 3, level.ERROR, nil, s, a...) } -func Fatal(a ...interface{}) { +func Fatal(ctx context.Context, a ...interface{}) { defer syscall.Exit(1) - logf(3, level.FATAL, nil, args(len(a)), a...) + logf(ctx, 3, level.FATAL, nil, args(len(a)), a...) } -func Fatalf(s string, a ...interface{}) { +func Fatalf(ctx context.Context, s string, a ...interface{}) { defer syscall.Exit(1) - logf(3, level.FATAL, nil, s, a...) + logf(ctx, 3, level.FATAL, nil, s, a...) } -func Panic(a ...interface{}) { +func Panic(ctx context.Context, a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(3, level.PANIC, nil, args(len(a)), a...) + logf(ctx, 3, level.PANIC, nil, args(len(a)), a...) } -func Panicf(s string, a ...interface{}) { +func Panicf(ctx context.Context, s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(3, level.PANIC, nil, s, a...) + logf(ctx, 3, level.PANIC, nil, s, a...) } // Log will log formatted args as 'msg' field to the log at given level. -func Log(lvl level.LEVEL, a ...interface{}) { - logf(3, lvl, nil, args(len(a)), a...) +func Log(ctx context.Context, lvl level.LEVEL, a ...interface{}) { + logf(ctx, 3, lvl, nil, args(len(a)), a...) } // Logf will log format string as 'msg' field to the log at given level. -func Logf(lvl level.LEVEL, s string, a ...interface{}) { - logf(3, lvl, nil, s, a...) +func Logf(ctx context.Context, lvl level.LEVEL, s string, a ...interface{}) { + logf(ctx, 3, lvl, nil, s, a...) } // Print will log formatted args to the stdout log output. @@ -186,7 +199,7 @@ func printf(depth int, fields []kv.Field, s string, a ...interface{}) { putBuf(buf) } -func logf(depth int, lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { +func logf(ctx context.Context, depth int, lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { var out *os.File // Check if enabled. @@ -220,6 +233,13 @@ func logf(depth int, lvl level.LEVEL, fields []kv.Field, s string, a ...interfac buf.B = append(buf.B, lvlstrs[lvl]...) buf.B = append(buf.B, ' ') + if ctx != nil { + // Pass context through hooks. + for _, hook := range ctxhooks { + fields = hook(ctx, fields) + } + } + // Append formatted fields with msg kv.Fields(append(fields, kv.Field{ K: "msg", V: fmt.Sprintf(s, a...), diff --git a/internal/log/syslog_test.go b/internal/log/syslog_test.go index baa4dac6c..0fb46923c 100644 --- a/internal/log/syslog_test.go +++ b/internal/log/syslog_test.go @@ -66,14 +66,14 @@ func (suite *SyslogTestSuite) TearDownTest() { } func (suite *SyslogTestSuite) TestSyslog() { - log.Info("this is a test of the emergency broadcast system!") + log.Info(nil, "this is a test of the emergency broadcast system!") entry := <-suite.syslogChannel suite.Regexp(regexp.MustCompile(`timestamp=.* func=.* level=INFO msg="this is a test of the emergency broadcast system!"`), entry["content"]) } func (suite *SyslogTestSuite) TestSyslogLongMessage() { - log.Warn(longMessage) + log.Warn(nil, longMessage) funcName := log.Caller(2) prefix := fmt.Sprintf(`timestamp="02/01/2006 15:04:05.000" func=%s level=WARN msg="`, funcName) @@ -104,7 +104,7 @@ func (suite *SyslogTestSuite) TestSyslogLongMessageUnixgram() { testrig.InitTestLog() - log.Warn(longMessage) + log.Warn(nil, longMessage) funcName := log.Caller(2) prefix := fmt.Sprintf(`timestamp="02/01/2006 15:04:05.000" func=%s level=WARN msg="`, funcName) diff --git a/internal/media/manager.go b/internal/media/manager.go index ba89aff13..36282cc45 100644 --- a/internal/media/manager.go +++ b/internal/media/manager.go @@ -454,8 +454,8 @@ func scheduleCleanupJobs(m *manager) { m.state.Workers.Scheduler.Schedule(sched.NewJob(func(now time.Time) { err := m.PruneAll(doneCtx, config.GetMediaRemoteCacheDays(), true) if err != nil { - log.Errorf("error during prune: %v", err) + log.Errorf(nil, "error during prune: %v", err) } - log.Infof("finished pruning all in %s", time.Since(now)) + log.Infof(nil, "finished pruning all in %s", time.Since(now)) }).EveryAt(midnight, day)) } diff --git a/internal/media/processingemoji.go b/internal/media/processingemoji.go index 0a36174b0..0c3e83e6b 100644 --- a/internal/media/processingemoji.go +++ b/internal/media/processingemoji.go @@ -67,7 +67,7 @@ func (p *ProcessingEmoji) LoadEmoji(ctx context.Context) (*gtsmodel.Emoji, error if !done { // Provided context was cancelled, e.g. request cancelled // early. Queue this item for asynchronous processing. - log.Warnf("reprocessing emoji %s after canceled ctx", p.emoji.ID) + log.Warnf(ctx, "reprocessing emoji %s after canceled ctx", p.emoji.ID) go p.mgr.state.Workers.Media.Enqueue(p.Process) } @@ -77,7 +77,7 @@ func (p *ProcessingEmoji) LoadEmoji(ctx context.Context) (*gtsmodel.Emoji, error // Process allows the receiving object to fit the runners.WorkerFunc signature. It performs a (blocking) load and logs on error. func (p *ProcessingEmoji) Process(ctx context.Context) { if _, _, err := p.load(ctx); err != nil { - log.Errorf("error processing emoji: %v", err) + log.Errorf(ctx, "error processing emoji: %v", err) } } @@ -167,7 +167,7 @@ func (p *ProcessingEmoji) store(ctx context.Context) error { // Ensure post callback gets called. if err := p.postFn(ctx); err != nil { - log.Errorf("error executing postdata function: %v", err) + log.Errorf(ctx, "error executing postdata function: %v", err) } }() @@ -180,7 +180,7 @@ func (p *ProcessingEmoji) store(ctx context.Context) error { defer func() { // Ensure data reader gets closed on return. if err := rc.Close(); err != nil { - log.Errorf("error closing data reader: %v", err) + log.Errorf(ctx, "error closing data reader: %v", err) } }() @@ -251,7 +251,7 @@ func (p *ProcessingEmoji) store(ctx context.Context) error { // This shouldn't already exist, but we do a check as it's worth logging. if have, _ := p.mgr.state.Storage.Has(ctx, p.emoji.ImagePath); have { - log.Warnf("emoji already exists at storage path: %s", p.emoji.ImagePath) + log.Warnf(ctx, "emoji already exists at storage path: %s", p.emoji.ImagePath) // Attempt to remove existing emoji at storage path (might be broken / out-of-date) if err := p.mgr.state.Storage.Delete(ctx, p.emoji.ImagePath); err != nil { @@ -267,8 +267,9 @@ func (p *ProcessingEmoji) store(ctx context.Context) error { // Once again check size in case none was provided previously. if size := bytesize.Size(sz); size > maxSize { + if err := p.mgr.state.Storage.Delete(ctx, p.emoji.ImagePath); err != nil { - log.Errorf("error removing too-large-emoji from storage: %v", err) + log.Errorf(ctx, "error removing too-large-emoji from storage: %v", err) } return fmt.Errorf("calculated emoji size %s greater than max allowed %s", size, maxSize) } @@ -308,8 +309,7 @@ func (p *ProcessingEmoji) finish(ctx context.Context) error { // This shouldn't already exist, but we do a check as it's worth logging. if have, _ := p.mgr.state.Storage.Has(ctx, p.emoji.ImageStaticPath); have { - log.Warnf("static emoji already exists at storage path: %s", p.emoji.ImagePath) - + log.Warnf(ctx, "static emoji already exists at storage path: %s", p.emoji.ImagePath) // Attempt to remove static existing emoji at storage path (might be broken / out-of-date) if err := p.mgr.state.Storage.Delete(ctx, p.emoji.ImageStaticPath); err != nil { return fmt.Errorf("error removing static emoji from storage: %v", err) diff --git a/internal/media/processingmedia.go b/internal/media/processingmedia.go index b4eda4072..c00c203a6 100644 --- a/internal/media/processingmedia.go +++ b/internal/media/processingmedia.go @@ -67,7 +67,7 @@ func (p *ProcessingMedia) LoadAttachment(ctx context.Context) (*gtsmodel.MediaAt if !done { // Provided context was cancelled, e.g. request cancelled // early. Queue this item for asynchronous processing. - log.Warnf("reprocessing media %s after canceled ctx", p.media.ID) + log.Warnf(ctx, "reprocessing media %s after canceled ctx", p.media.ID) go p.mgr.state.Workers.Media.Enqueue(p.Process) } @@ -77,7 +77,7 @@ func (p *ProcessingMedia) LoadAttachment(ctx context.Context) (*gtsmodel.MediaAt // Process allows the receiving object to fit the runners.WorkerFunc signature. It performs a (blocking) load and logs on error. func (p *ProcessingMedia) Process(ctx context.Context) { if _, _, err := p.load(ctx); err != nil { - log.Errorf("error processing media: %v", err) + log.Errorf(ctx, "error processing media: %v", err) } } @@ -151,7 +151,7 @@ func (p *ProcessingMedia) store(ctx context.Context) error { // ensure post callback gets called. if err := p.postFn(ctx); err != nil { - log.Errorf("error executing postdata function: %v", err) + log.Errorf(ctx, "error executing postdata function: %v", err) } }() @@ -164,7 +164,7 @@ func (p *ProcessingMedia) store(ctx context.Context) error { defer func() { // Ensure data reader gets closed on return. if err := rc.Close(); err != nil { - log.Errorf("error closing data reader: %v", err) + log.Errorf(ctx, "error closing data reader: %v", err) } }() @@ -220,7 +220,7 @@ func (p *ProcessingMedia) store(ctx context.Context) error { // This shouldn't already exist, but we do a check as it's worth logging. if have, _ := p.mgr.state.Storage.Has(ctx, p.media.File.Path); have { - log.Warnf("media already exists at storage path: %s", p.media.File.Path) + log.Warnf(ctx, "media already exists at storage path: %s", p.media.File.Path) // Attempt to remove existing media at storage path (might be broken / out-of-date) if err := p.mgr.state.Storage.Delete(ctx, p.media.File.Path); err != nil { @@ -333,7 +333,7 @@ func (p *ProcessingMedia) finish(ctx context.Context) error { // This shouldn't already exist, but we do a check as it's worth logging. if have, _ := p.mgr.state.Storage.Has(ctx, p.media.Thumbnail.Path); have { - log.Warnf("thumbnail already exists at storage path: %s", p.media.Thumbnail.Path) + log.Warnf(ctx, "thumbnail already exists at storage path: %s", p.media.Thumbnail.Path) // Attempt to remove existing thumbnail at storage path (might be broken / out-of-date) if err := p.mgr.state.Storage.Delete(ctx, p.media.Thumbnail.Path); err != nil { diff --git a/internal/media/prune.go b/internal/media/prune.go index bb0993759..975a82e33 100644 --- a/internal/media/prune.go +++ b/internal/media/prune.go @@ -48,34 +48,34 @@ func (m *manager) PruneAll(ctx context.Context, mediaCacheRemoteDays int, blocki if err != nil { errs = append(errs, fmt.Sprintf("error pruning unused local media (%s)", err)) } else { - log.Infof("pruned %d unused local media", pruned) + log.Infof(ctx, "pruned %d unused local media", pruned) } pruned, err = m.PruneUnusedRemote(innerCtx, dry) if err != nil { errs = append(errs, fmt.Sprintf("error pruning unused remote media: (%s)", err)) } else { - log.Infof("pruned %d unused remote media", pruned) + log.Infof(ctx, "pruned %d unused remote media", pruned) } pruned, err = m.UncacheRemote(innerCtx, mediaCacheRemoteDays, dry) if err != nil { errs = append(errs, fmt.Sprintf("error uncacheing remote media older than %d day(s): (%s)", mediaCacheRemoteDays, err)) } else { - log.Infof("uncached %d remote media older than %d day(s)", pruned, mediaCacheRemoteDays) + log.Infof(ctx, "uncached %d remote media older than %d day(s)", pruned, mediaCacheRemoteDays) } pruned, err = m.PruneOrphaned(innerCtx, dry) if err != nil { errs = append(errs, fmt.Sprintf("error pruning orphaned media: (%s)", err)) } else { - log.Infof("pruned %d orphaned media", pruned) + log.Infof(ctx, "pruned %d orphaned media", pruned) } if err := m.state.Storage.Storage.Clean(innerCtx); err != nil { errs = append(errs, fmt.Sprintf("error cleaning storage: (%s)", err)) } else { - log.Info("cleaned storage") + log.Info(ctx, "cleaned storage") } return errs.Combine() @@ -87,7 +87,7 @@ func (m *manager) PruneAll(ctx context.Context, mediaCacheRemoteDays int, blocki go func() { if err := f(context.Background()); err != nil { - log.Error(err) + log.Error(ctx, err) } }() diff --git a/internal/media/refetch.go b/internal/media/refetch.go index 3d572e4b9..8c2a62c94 100644 --- a/internal/media/refetch.go +++ b/internal/media/refetch.go @@ -51,7 +51,7 @@ func (m *manager) RefetchEmojis(ctx context.Context, domain string, dereferenceM if err != nil { if !errors.Is(err, db.ErrNoEntries) { // an actual error has occurred - log.Errorf("error fetching emojis from database: %s", err) + log.Errorf(ctx, "error fetching emojis from database: %s", err) } break } @@ -79,10 +79,10 @@ func (m *manager) RefetchEmojis(ctx context.Context, domain string, dereferenceM // bail early if we've got nothing to do toRefetchCount := len(refetchIDs) if toRefetchCount == 0 { - log.Debug("no remote emojis require a refetch") + log.Debug(ctx, "no remote emojis require a refetch") return 0, nil } - log.Debugf("%d remote emoji(s) require a refetch, doing that now...", toRefetchCount) + log.Debugf(ctx, "%d remote emoji(s) require a refetch, doing that now...", toRefetchCount) var totalRefetched int for _, emojiID := range refetchIDs { @@ -94,13 +94,13 @@ func (m *manager) RefetchEmojis(ctx context.Context, domain string, dereferenceM shortcodeDomain := util.ShortcodeDomain(emoji) if emoji.ImageRemoteURL == "" { - log.Errorf("remote emoji %s could not be refreshed because it has no ImageRemoteURL set", shortcodeDomain) + log.Errorf(ctx, "remote emoji %s could not be refreshed because it has no ImageRemoteURL set", shortcodeDomain) continue } emojiImageIRI, err := url.Parse(emoji.ImageRemoteURL) if err != nil { - log.Errorf("remote emoji %s could not be refreshed because its ImageRemoteURL (%s) is not a valid uri: %s", shortcodeDomain, emoji.ImageRemoteURL, err) + log.Errorf(ctx, "remote emoji %s could not be refreshed because its ImageRemoteURL (%s) is not a valid uri: %s", shortcodeDomain, emoji.ImageRemoteURL, err) continue } @@ -116,16 +116,16 @@ func (m *manager) RefetchEmojis(ctx context.Context, domain string, dereferenceM VisibleInPicker: emoji.VisibleInPicker, }, true) if err != nil { - log.Errorf("emoji %s could not be refreshed because of an error during processing: %s", shortcodeDomain, err) + log.Errorf(ctx, "emoji %s could not be refreshed because of an error during processing: %s", shortcodeDomain, err) continue } if _, err := processingEmoji.LoadEmoji(ctx); err != nil { - log.Errorf("emoji %s could not be refreshed because of an error during loading: %s", shortcodeDomain, err) + log.Errorf(ctx, "emoji %s could not be refreshed because of an error during loading: %s", shortcodeDomain, err) continue } - log.Tracef("refetched emoji %s successfully from remote", shortcodeDomain) + log.Tracef(ctx, "refetched emoji %s successfully from remote", shortcodeDomain) totalRefetched++ } diff --git a/internal/media/video.go b/internal/media/video.go index 38b2dbdce..30e7e8864 100644 --- a/internal/media/video.go +++ b/internal/media/video.go @@ -44,7 +44,7 @@ func decodeVideoFrame(r io.Reader) (*gtsVideo, error) { } defer func() { if err := tfs.Close(); err != nil { - log.Errorf("error closing temp file seeker: %s", err) + log.Errorf(nil, "error closing temp file seeker: %s", err) } }() diff --git a/internal/middleware/requestid.go b/internal/middleware/requestid.go new file mode 100644 index 000000000..56161355b --- /dev/null +++ b/internal/middleware/requestid.go @@ -0,0 +1,111 @@ +/* + GoToSocial + Copyright (C) 2021-2023 GoToSocial Authors admin@gotosocial.org + + This program is free software: you can redistribute it and/or modify + it under the terms of the GNU Affero General Public License as published by + the Free Software Foundation, either version 3 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU Affero General Public License for more details. + + You should have received a copy of the GNU Affero General Public License + along with this program. If not, see . +*/ + +package middleware + +import ( + "bufio" + "context" + "crypto/rand" + "encoding/base32" + "encoding/binary" + "io" + "sync" + "time" + + "codeberg.org/gruf/go-kv" + "github.com/gin-gonic/gin" + "github.com/superseriousbusiness/gotosocial/internal/log" +) + +type ctxType string + +var ( + // ridCtxKey is the key underwhich we store request IDs in a context. + ridCtxKey ctxType = "id" + + // crand provides buffered reads of random input. + crand = bufio.NewReader(rand.Reader) + mrand sync.Mutex + + // base32enc is a base 32 encoding based on a human-readable character set (no padding). + base32enc = base32.NewEncoding("0123456789abcdefghjkmnpqrstvwxyz").WithPadding(-1) +) + +// generateID generates a new ID string. +func generateID() string { + // 0:8 = timestamp + // 8:12 = entropy + // + // inspired by ULID. + b := make([]byte, 12) + + // Get current time in milliseconds. + ms := uint64(time.Now().UnixMilli()) + + // Store binary time data in byte buffer. + binary.LittleEndian.PutUint64(b[0:8], ms) + + mrand.Lock() + // Read random bits into buffer end. + _, _ = io.ReadFull(crand, b[8:12]) + mrand.Unlock() + + // Encode the binary time+entropy ID. + return base32enc.EncodeToString(b) +} + +// RequestID fetches the stored request ID from context. +func RequestID(ctx context.Context) string { + id, _ := ctx.Value(ridCtxKey).(string) + return id +} + +// AddRequestID returns a gin middleware which adds a unique ID to each request (both response header and context). +func AddRequestID(header string) gin.HandlerFunc { + log.Hook(func(ctx context.Context, kvs []kv.Field) []kv.Field { + if id, _ := ctx.Value(ridCtxKey).(string); id != "" { + // Add stored request ID to log entry fields. + return append(kvs, kv.Field{K: "requestID", V: id}) + } + return kvs + }) + + return func(c *gin.Context) { + // Look for existing ID. + id := c.GetHeader(header) + + if id == "" { + // Generate new ID. + // + // 0:8 = timestamp + // 8:12 = entropy + id = generateID() + // Set the request ID in the req header in case we pass the request along + // to another service + c.Request.Header.Set(header, id) + } + + // Store request ID in new request ctx and set new gin request obj. + ctx := context.WithValue(c.Request.Context(), ridCtxKey, id) + c.Request = c.Request.WithContext(ctx) + + // Set the request ID in the rsp header. + c.Writer.Header().Set(header, id) + } +} diff --git a/internal/middleware/session.go b/internal/middleware/session.go index e13d9bea3..0c6cb6d8c 100644 --- a/internal/middleware/session.go +++ b/internal/middleware/session.go @@ -41,7 +41,7 @@ func SessionOptions() sessions.Options { case "strict": samesite = http.SameSiteStrictMode default: - log.Warnf("%s set to %s which is not recognized, defaulting to 'lax'", config.AdvancedCookiesSamesiteFlag(), config.GetAdvancedCookiesSamesite()) + log.Warnf(nil, "%s set to %s which is not recognized, defaulting to 'lax'", config.AdvancedCookiesSamesiteFlag(), config.GetAdvancedCookiesSamesite()) samesite = http.SameSiteLaxMode } diff --git a/internal/middleware/signaturecheck.go b/internal/middleware/signaturecheck.go index c1f190eb5..340cb231d 100644 --- a/internal/middleware/signaturecheck.go +++ b/internal/middleware/signaturecheck.go @@ -36,13 +36,16 @@ // In case of an error, the request will be aborted with http code 500 internal server error. func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error)) func(*gin.Context) { return func(c *gin.Context) { + // Acquire ctx from gin request. + ctx := c.Request.Context() + // create the verifier from the request, this will error if the request wasn't signed verifier, err := httpsig.NewVerifier(c.Request) if err != nil { // Something went wrong, so we need to return regardless, but only actually // *abort* the request with 401 if a signature was present but malformed if err.Error() != noSignatureError { - log.Debugf("http signature was present but invalid: %s", err) + log.Debugf(ctx, "http signature was present but invalid: %s", err) c.AbortWithStatus(http.StatusUnauthorized) } return @@ -54,13 +57,13 @@ func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error requestingPublicKeyIDString := verifier.KeyId() requestingPublicKeyID, err := url.Parse(requestingPublicKeyIDString) if err != nil { - log.Debugf("http signature requesting public key id %s could not be parsed as a url: %s", requestingPublicKeyIDString, err) + log.Debugf(ctx, "http signature requesting public key id %s could not be parsed as a url: %s", requestingPublicKeyIDString, err) c.AbortWithStatus(http.StatusUnauthorized) return } else if requestingPublicKeyID == nil { // Key can sometimes be nil, according to url parse function: // 'Trying to parse a hostname and path without a scheme is invalid but may not necessarily return an error, due to parsing ambiguities' - log.Debugf("http signature requesting public key id %s was nil after parsing as a url", requestingPublicKeyIDString) + log.Debugf(ctx, "http signature requesting public key id %s was nil after parsing as a url", requestingPublicKeyIDString) c.AbortWithStatus(http.StatusUnauthorized) return } @@ -68,11 +71,11 @@ func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error // we managed to parse the url! // if the domain is blocked we want to bail as early as possible if blocked, err := isURIBlocked(c.Request.Context(), requestingPublicKeyID); err != nil { - log.Errorf("could not tell if domain %s was blocked or not: %s", requestingPublicKeyID.Host, err) + log.Errorf(ctx, "could not tell if domain %s was blocked or not: %s", requestingPublicKeyID.Host, err) c.AbortWithStatus(http.StatusInternalServerError) return } else if blocked { - log.Infof("domain %s is blocked", requestingPublicKeyID.Host) + log.Infof(ctx, "domain %s is blocked", requestingPublicKeyID.Host) c.AbortWithStatus(http.StatusForbidden) return } diff --git a/internal/middleware/tokencheck.go b/internal/middleware/tokencheck.go index 8d2af2cbd..79aeda1ab 100644 --- a/internal/middleware/tokencheck.go +++ b/internal/middleware/tokencheck.go @@ -52,6 +52,7 @@ // Bearer token set (eg., for public instance information and so on). func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2.TokenInfo, error)) func(*gin.Context) { return func(c *gin.Context) { + // Acquire context from gin request. ctx := c.Request.Context() if c.Request.Header.Get("Authorization") == "" { @@ -61,38 +62,38 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2. ti, err := validateBearerToken(c.Copy().Request) if err != nil { - log.Debugf("token was passed in Authorization header but we could not validate it: %s", err) + log.Debugf(ctx, "token was passed in Authorization header but we could not validate it: %s", err) return } c.Set(oauth.SessionAuthorizedToken, ti) // check for user-level token if userID := ti.GetUserID(); userID != "" { - log.Tracef("authenticated user %s with bearer token, scope is %s", userID, ti.GetScope()) + log.Tracef(ctx, "authenticated user %s with bearer token, scope is %s", userID, ti.GetScope()) // fetch user for this token user, err := dbConn.GetUserByID(ctx, userID) if err != nil { if err != db.ErrNoEntries { - log.Errorf("database error looking for user with id %s: %s", userID, err) + log.Errorf(ctx, "database error looking for user with id %s: %s", userID, err) return } - log.Warnf("no user found for userID %s", userID) + log.Warnf(ctx, "no user found for userID %s", userID) return } if user.ConfirmedAt.IsZero() { - log.Warnf("authenticated user %s has never confirmed thier email address", userID) + log.Warnf(ctx, "authenticated user %s has never confirmed thier email address", userID) return } if !*user.Approved { - log.Warnf("authenticated user %s's account was never approved by an admin", userID) + log.Warnf(ctx, "authenticated user %s's account was never approved by an admin", userID) return } if *user.Disabled { - log.Warnf("authenticated user %s's account was disabled'", userID) + log.Warnf(ctx, "authenticated user %s's account was disabled'", userID) return } @@ -103,17 +104,17 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2. acct, err := dbConn.GetAccountByID(ctx, user.AccountID) if err != nil { if err != db.ErrNoEntries { - log.Errorf("database error looking for account with id %s: %s", user.AccountID, err) + log.Errorf(ctx, "database error looking for account with id %s: %s", user.AccountID, err) return } - log.Warnf("no account found for userID %s", userID) + log.Warnf(ctx, "no account found for userID %s", userID) return } user.Account = acct } if !user.Account.SuspendedAt.IsZero() { - log.Warnf("authenticated user %s's account (accountId=%s) has been suspended", userID, user.AccountID) + log.Warnf(ctx, "authenticated user %s's account (accountId=%s) has been suspended", userID, user.AccountID) return } @@ -122,16 +123,16 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2. // check for application token if clientID := ti.GetClientID(); clientID != "" { - log.Tracef("authenticated client %s with bearer token, scope is %s", clientID, ti.GetScope()) + log.Tracef(ctx, "authenticated client %s with bearer token, scope is %s", clientID, ti.GetScope()) // fetch app for this token app := >smodel.Application{} if err := dbConn.GetWhere(ctx, []db.Where{{Key: "client_id", Value: clientID}}, app); err != nil { if err != db.ErrNoEntries { - log.Errorf("database error looking for application with clientID %s: %s", clientID, err) + log.Errorf(ctx, "database error looking for application with clientID %s: %s", clientID, err) return } - log.Warnf("no app found for client %s", clientID) + log.Warnf(ctx, "no app found for client %s", clientID) return } c.Set(oauth.SessionAuthorizedApplication, app) diff --git a/internal/oauth/server.go b/internal/oauth/server.go index b8470aa41..c4e2f6bf3 100644 --- a/internal/oauth/server.go +++ b/internal/oauth/server.go @@ -103,12 +103,12 @@ func New(ctx context.Context, database db.Basic) Server { srv := server.NewServer(sc, manager) srv.SetInternalErrorHandler(func(err error) *errors.Response { - log.Errorf("internal oauth error: %s", err) + log.Errorf(nil, "internal oauth error: %s", err) return nil }) srv.SetResponseErrorHandler(func(re *errors.Response) { - log.Errorf("internal response error: %s", re.Error) + log.Errorf(nil, "internal response error: %s", re.Error) }) srv.SetUserAuthorizationHandler(func(w http.ResponseWriter, r *http.Request) (string, error) { @@ -272,7 +272,7 @@ func (s *s) GenerateUserAccessToken(ctx context.Context, ti oauth2.TokenInfo, cl if authToken == nil { return nil, errors.New("generated auth token was empty") } - log.Tracef("obtained auth token: %+v", authToken) + log.Tracef(ctx, "obtained auth token: %+v", authToken) accessToken, err := s.server.Manager.GenerateAccessToken(ctx, oauth2.AuthorizationCode, &oauth2.TokenGenerateRequest{ ClientID: authToken.GetClientID(), @@ -287,7 +287,7 @@ func (s *s) GenerateUserAccessToken(ctx context.Context, ti oauth2.TokenInfo, cl if accessToken == nil { return nil, errors.New("generated user-level access token was empty") } - log.Tracef("obtained user-level access token: %+v", accessToken) + log.Tracef(ctx, "obtained user-level access token: %+v", accessToken) return accessToken, nil } diff --git a/internal/oauth/tokenstore.go b/internal/oauth/tokenstore.go index fa0390708..f81c3470b 100644 --- a/internal/oauth/tokenstore.go +++ b/internal/oauth/tokenstore.go @@ -53,12 +53,12 @@ func newTokenStore(ctx context.Context, db db.Basic) oauth2.TokenStore { for { select { case <-ctx.Done(): - log.Info("breaking cleanloop") + log.Info(ctx, "breaking cleanloop") break cleanloop case <-time.After(1 * time.Minute): - log.Trace("sweeping out old oauth entries broom broom") + log.Trace(ctx, "sweeping out old oauth entries broom broom") if err := ts.sweep(ctx); err != nil { - log.Errorf("error while sweeping oauth entries: %s", err) + log.Errorf(ctx, "error while sweeping oauth entries: %s", err) } } } diff --git a/internal/oidc/handlecallback.go b/internal/oidc/handlecallback.go index 770789362..8fa7dbbac 100644 --- a/internal/oidc/handlecallback.go +++ b/internal/oidc/handlecallback.go @@ -33,23 +33,23 @@ func (i *idp) HandleCallback(ctx context.Context, code string) (*Claims, gtserro return nil, gtserror.NewErrorBadRequest(err, err.Error()) } - log.Debug("exchanging code for oauth2token") + log.Debug(ctx, "exchanging code for oauth2token") oauth2Token, err := i.oauth2Config.Exchange(ctx, code) if err != nil { err := fmt.Errorf("error exchanging code for oauth2token: %s", err) return nil, gtserror.NewErrorInternalError(err) } - log.Debug("extracting id_token") + log.Debug(ctx, "extracting id_token") rawIDToken, ok := oauth2Token.Extra("id_token").(string) if !ok { err := errors.New("no id_token in oauth2token") return nil, gtserror.NewErrorBadRequest(err, err.Error()) } - log.Debugf("raw id token: %s", rawIDToken) + log.Debugf(ctx, "raw id token: %s", rawIDToken) // Parse and verify ID Token payload. - log.Debug("verifying id_token") + log.Debug(ctx, "verifying id_token") idTokenVerifier := i.provider.Verifier(i.oidcConf) idToken, err := idTokenVerifier.Verify(ctx, rawIDToken) if err != nil { @@ -57,7 +57,7 @@ func (i *idp) HandleCallback(ctx context.Context, code string) (*Claims, gtserro return nil, gtserror.NewErrorUnauthorized(err, err.Error()) } - log.Debug("extracting claims from id_token") + log.Debug(ctx, "extracting claims from id_token") claims := &Claims{} if err := idToken.Claims(claims); err != nil { err := fmt.Errorf("could not parse claims from idToken: %s", err) diff --git a/internal/processing/account/create.go b/internal/processing/account/create.go index 11d77a302..b0efccf7e 100644 --- a/internal/processing/account/create.go +++ b/internal/processing/account/create.go @@ -59,13 +59,13 @@ func (p *processor) Create(ctx context.Context, applicationToken oauth2.TokenInf reason = "" } - log.Trace("creating new username and account") + log.Trace(ctx, "creating new username and account") user, err := p.db.NewSignup(ctx, form.Username, text.SanitizePlaintext(reason), approvalRequired, form.Email, form.Password, form.IP, form.Locale, application.ID, false, "", false) if err != nil { return nil, gtserror.NewErrorInternalError(fmt.Errorf("error creating new signup in the database: %s", err)) } - log.Tracef("generating a token for user %s with account %s and application %s", user.ID, user.AccountID, application.ID) + log.Tracef(ctx, "generating a token for user %s with account %s and application %s", user.ID, user.AccountID, application.ID) accessToken, err := p.oauthServer.GenerateUserAccessToken(ctx, applicationToken, application.ClientSecret, user.ID) if err != nil { return nil, gtserror.NewErrorInternalError(fmt.Errorf("error creating new access token for user %s: %s", user.ID, err)) diff --git a/internal/processing/account/delete.go b/internal/processing/account/delete.go index b06a7b960..32321e196 100644 --- a/internal/processing/account/delete.go +++ b/internal/processing/account/delete.go @@ -64,7 +64,7 @@ func (p *processor) Delete(ctx context.Context, account *gtsmodel.Account, origi }) } - l := log.WithFields(fields...) + l := log.WithContext(ctx).WithFields(fields...) l.Trace("beginning account delete process") // 1. Delete account's application(s), clients, and oauth tokens diff --git a/internal/processing/account/update.go b/internal/processing/account/update.go index dc4081915..675793800 100644 --- a/internal/processing/account/update.go +++ b/internal/processing/account/update.go @@ -97,7 +97,7 @@ func (p *processor) Update(ctx context.Context, account *gtsmodel.Account, form } account.AvatarMediaAttachmentID = avatarInfo.ID account.AvatarMediaAttachment = avatarInfo - log.Tracef("new avatar info for account %s is %+v", account.ID, avatarInfo) + log.Tracef(ctx, "new avatar info for account %s is %+v", account.ID, avatarInfo) } if form.Header != nil && form.Header.Size != 0 { @@ -107,7 +107,7 @@ func (p *processor) Update(ctx context.Context, account *gtsmodel.Account, form } account.HeaderMediaAttachmentID = headerInfo.ID account.HeaderMediaAttachment = headerInfo - log.Tracef("new header info for account %s is %+v", account.ID, headerInfo) + log.Tracef(ctx, "new header info for account %s is %+v", account.ID, headerInfo) } if form.Locked != nil { diff --git a/internal/processing/admin/createdomainblock.go b/internal/processing/admin/createdomainblock.go index 1c80ee78f..5c3542f79 100644 --- a/internal/processing/admin/createdomainblock.go +++ b/internal/processing/admin/createdomainblock.go @@ -89,9 +89,10 @@ func (p *processor) DomainBlockCreate(ctx context.Context, account *gtsmodel.Acc // 2. Delete the instance account for that instance if it exists. // 3. Select all accounts from this instance and pass them through the delete functionality of the processor. func (p *processor) initiateDomainBlockSideEffects(ctx context.Context, account *gtsmodel.Account, block *gtsmodel.DomainBlock) { - l := log.WithFields(kv.Fields{ - {"domain", block.Domain}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"domain", block.Domain}, + }...) l.Debug("processing domain block side effects") diff --git a/internal/processing/admin/mediarefetch.go b/internal/processing/admin/mediarefetch.go index 6bb068d58..a73580d98 100644 --- a/internal/processing/admin/mediarefetch.go +++ b/internal/processing/admin/mediarefetch.go @@ -35,12 +35,12 @@ func (p *processor) MediaRefetch(ctx context.Context, requestingAccount *gtsmode } go func() { - log.Info("starting emoji refetch") + log.Info(ctx, "starting emoji refetch") refetched, err := p.mediaManager.RefetchEmojis(context.Background(), domain, transport.DereferenceMedia) if err != nil { - log.Errorf("error refetching emojis: %s", err) + log.Errorf(ctx, "error refetching emojis: %s", err) } else { - log.Infof("refetched %d emojis from remote", refetched) + log.Infof(ctx, "refetched %d emojis from remote", refetched) } }() diff --git a/internal/processing/fromclientapi.go b/internal/processing/fromclientapi.go index 6035130e2..ef834a570 100644 --- a/internal/processing/fromclientapi.go +++ b/internal/processing/fromclientapi.go @@ -50,7 +50,7 @@ func (p *processor) ProcessFromClientAPI(ctx context.Context, clientMsg messages } // Log this federated message - l := log.WithFields(fields...) + l := log.WithContext(ctx).WithFields(fields...) l.Info("processing from client") switch clientMsg.APActivityType { diff --git a/internal/processing/fromfederator.go b/internal/processing/fromfederator.go index e37488794..7a3508840 100644 --- a/internal/processing/fromfederator.go +++ b/internal/processing/fromfederator.go @@ -59,7 +59,7 @@ func (p *processor) ProcessFromFederator(ctx context.Context, federatorMsg messa } // Log this federated message - l := log.WithFields(fields...) + l := log.WithContext(ctx).WithFields(fields...) l.Info("processing from federator") switch federatorMsg.APActivityType { diff --git a/internal/processing/media/getemoji.go b/internal/processing/media/getemoji.go index 592fc682f..4b1e76772 100644 --- a/internal/processing/media/getemoji.go +++ b/internal/processing/media/getemoji.go @@ -40,7 +40,7 @@ func (p *processor) GetCustomEmojis(ctx context.Context) ([]*apimodel.Emoji, gts for _, gtsEmoji := range emojis { apiEmoji, err := p.tc.EmojiToAPIEmoji(ctx, gtsEmoji) if err != nil { - log.Errorf("error converting emoji with id %s: %s", gtsEmoji.ID, err) + log.Errorf(ctx, "error converting emoji with id %s: %s", gtsEmoji.ID, err) continue } apiEmojis = append(apiEmojis, &apiEmoji) diff --git a/internal/processing/notification.go b/internal/processing/notification.go index 47b5f07a9..b13ab0ca0 100644 --- a/internal/processing/notification.go +++ b/internal/processing/notification.go @@ -46,7 +46,7 @@ func (p *processor) NotificationsGet(ctx context.Context, authed *oauth.Auth, ex for i, n := range notifs { item, err := p.tc.NotificationToAPINotification(ctx, n) if err != nil { - log.Debugf("got an error converting a notification to api, will skip it: %s", err) + log.Debugf(ctx, "got an error converting a notification to api, will skip it: %s", err) continue } diff --git a/internal/processing/search.go b/internal/processing/search.go index 90e361cf7..44f38db12 100644 --- a/internal/processing/search.go +++ b/internal/processing/search.go @@ -57,7 +57,8 @@ func (p *processor) SearchGet(ctx context.Context, authed *oauth.Auth, search *a return nil, gtserror.NewErrorBadRequest(err, err.Error()) } - l := log.WithFields(kv.Fields{{"query", query}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"query", query}}...) searchResult := &apimodel.SearchResult{ Accounts: []apimodel.Account{}, diff --git a/internal/processing/statustimeline.go b/internal/processing/statustimeline.go index 447a2a000..45a1c4508 100644 --- a/internal/processing/statustimeline.go +++ b/internal/processing/statustimeline.go @@ -72,7 +72,7 @@ func StatusFilterFunction(database db.DB, filter visibility.Filter) timeline.Fil timelineable, err := filter.StatusHometimelineable(ctx, status, requestingAccount) if err != nil { - log.Warnf("error checking hometimelineability of status %s for account %s: %s", status.ID, timelineAccountID, err) + log.Warnf(ctx, "error checking hometimelineability of status %s for account %s: %s", status.ID, timelineAccountID, err) } return timelineable, nil // we don't return the error here because we want to just skip this item if something goes wrong @@ -257,7 +257,7 @@ func (p *processor) filterPublicStatuses(ctx context.Context, authed *oauth.Auth targetAccount := >smodel.Account{} if err := p.db.GetByID(ctx, s.AccountID, targetAccount); err != nil { if err == db.ErrNoEntries { - log.Debugf("filterPublicStatuses: skipping status %s because account %s can't be found in the db", s.ID, s.AccountID) + log.Debugf(ctx, "skipping status %s because account %s can't be found in the db", s.ID, s.AccountID) continue } return nil, gtserror.NewErrorInternalError(fmt.Errorf("filterPublicStatuses: error getting status author: %s", err)) @@ -265,7 +265,7 @@ func (p *processor) filterPublicStatuses(ctx context.Context, authed *oauth.Auth timelineable, err := p.filter.StatusPublictimelineable(ctx, s, authed.Account) if err != nil { - log.Debugf("filterPublicStatuses: skipping status %s because of an error checking status visibility: %s", s.ID, err) + log.Debugf(ctx, "skipping status %s because of an error checking status visibility: %s", s.ID, err) continue } if !timelineable { @@ -274,7 +274,7 @@ func (p *processor) filterPublicStatuses(ctx context.Context, authed *oauth.Auth apiStatus, err := p.tc.StatusToAPIStatus(ctx, s, authed.Account) if err != nil { - log.Debugf("filterPublicStatuses: skipping status %s because it couldn't be converted to its api representation: %s", s.ID, err) + log.Debugf(ctx, "skipping status %s because it couldn't be converted to its api representation: %s", s.ID, err) continue } @@ -290,7 +290,7 @@ func (p *processor) filterFavedStatuses(ctx context.Context, authed *oauth.Auth, targetAccount := >smodel.Account{} if err := p.db.GetByID(ctx, s.AccountID, targetAccount); err != nil { if err == db.ErrNoEntries { - log.Debugf("filterFavedStatuses: skipping status %s because account %s can't be found in the db", s.ID, s.AccountID) + log.Debugf(ctx, "skipping status %s because account %s can't be found in the db", s.ID, s.AccountID) continue } return nil, gtserror.NewErrorInternalError(fmt.Errorf("filterPublicStatuses: error getting status author: %s", err)) @@ -298,7 +298,7 @@ func (p *processor) filterFavedStatuses(ctx context.Context, authed *oauth.Auth, timelineable, err := p.filter.StatusVisible(ctx, s, authed.Account) if err != nil { - log.Debugf("filterFavedStatuses: skipping status %s because of an error checking status visibility: %s", s.ID, err) + log.Debugf(ctx, "skipping status %s because of an error checking status visibility: %s", s.ID, err) continue } if !timelineable { @@ -307,7 +307,7 @@ func (p *processor) filterFavedStatuses(ctx context.Context, authed *oauth.Auth, apiStatus, err := p.tc.StatusToAPIStatus(ctx, s, authed.Account) if err != nil { - log.Debugf("filterFavedStatuses: skipping status %s because it couldn't be converted to its api representation: %s", s.ID, err) + log.Debugf(ctx, "skipping status %s because it couldn't be converted to its api representation: %s", s.ID, err) continue } diff --git a/internal/processing/streaming/openstream.go b/internal/processing/streaming/openstream.go index 0ad5135fb..7913e6745 100644 --- a/internal/processing/streaming/openstream.go +++ b/internal/processing/streaming/openstream.go @@ -32,11 +32,11 @@ ) func (p *processor) OpenStreamForAccount(ctx context.Context, account *gtsmodel.Account, streamTimeline string) (*stream.Stream, gtserror.WithCode) { - l := log.WithFields(kv.Fields{ - - {"account", account.ID}, - {"streamType", streamTimeline}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"account", account.ID}, + {"streamType", streamTimeline}, + }...) l.Debug("received open stream request") // each stream needs a unique ID so we know to close it diff --git a/internal/router/router.go b/internal/router/router.go index 5225214ab..0b9b63494 100644 --- a/internal/router/router.go +++ b/internal/router/router.go @@ -101,10 +101,10 @@ func (r *router) Start() { ) // Start the LetsEncrypt autocert manager HTTP server. - log.Infof("letsencrypt listening on %s", srv.Addr) + log.Infof(nil, "letsencrypt listening on %s", srv.Addr) if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { - log.Fatalf("letsencrypt: listen: %s", err) + log.Fatalf(nil, "letsencrypt: listen: %s", err) } }() @@ -119,23 +119,23 @@ func (r *router) Start() { r.srv.Handler = debug.WithPprof(r.srv.Handler) if debug.DEBUG { // Profiling requires timeouts longer than 30s, so reset these. - log.Warn("resetting http.Server{} timeout to support profiling") + log.Warn(nil, "resetting http.Server{} timeout to support profiling") r.srv.ReadTimeout = 0 r.srv.WriteTimeout = 0 } // Start the main listener. go func() { - log.Infof("listening on %s", r.srv.Addr) + log.Infof(nil, "listening on %s", r.srv.Addr) if err := listen(); err != nil && err != http.ErrServerClosed { - log.Fatalf("listen: %s", err) + log.Fatalf(nil, "listen: %s", err) } }() } // Stop shuts down the router nicely func (r *router) Stop(ctx context.Context) error { - log.Infof("shutting down http router with %s grace period", shutdownTimeout) + log.Infof(nil, "shutting down http router with %s grace period", shutdownTimeout) timeout, cancel := context.WithTimeout(ctx, shutdownTimeout) defer cancel() @@ -143,7 +143,7 @@ func (r *router) Stop(ctx context.Context) error { return fmt.Errorf("error shutting down http router: %s", err) } - log.Info("http router closed connections and shut down gracefully") + log.Info(nil, "http router closed connections and shut down gracefully") return nil } diff --git a/internal/router/template.go b/internal/router/template.go index dedfd2011..88adb8a9b 100644 --- a/internal/router/template.go +++ b/internal/router/template.go @@ -87,7 +87,7 @@ func noescapeAttr(str string) template.HTMLAttr { func timestamp(stamp string) string { t, err := util.ParseISO8601(stamp) if err != nil { - log.Errorf("error parsing timestamp %s: %s", stamp, err) + log.Errorf(nil, "error parsing timestamp %s: %s", stamp, err) return badTimestamp } @@ -110,7 +110,7 @@ func timestamp(stamp string) string { func timestampPrecise(stamp string) string { t, err := util.ParseISO8601(stamp) if err != nil { - log.Errorf("error parsing timestamp %s: %s", stamp, err) + log.Errorf(nil, "error parsing timestamp %s: %s", stamp, err) return badTimestamp } return t.Local().Format(dateYearTime) @@ -119,7 +119,7 @@ func timestampPrecise(stamp string) string { func timestampVague(stamp string) string { t, err := util.ParseISO8601(stamp) if err != nil { - log.Errorf("error parsing timestamp %s: %s", stamp, err) + log.Errorf(nil, "error parsing timestamp %s: %s", stamp, err) return badTimestamp } return t.Format(monthYear) diff --git a/internal/storage/storage.go b/internal/storage/storage.go index f73185268..b66545185 100644 --- a/internal/storage/storage.go +++ b/internal/storage/storage.go @@ -128,8 +128,9 @@ func NewFileStorage() (*Driver, error) { return nil, fmt.Errorf("error opening disk storage: %w", err) } + // Perform an initial storage clean to delete old dirs. if err := disk.Clean(context.Background()); err != nil { - log.Errorf("error performing storage cleanup: %v", err) + log.Errorf(nil, "error performing storage cleanup: %v", err) } return &Driver{ diff --git a/internal/text/emojionly.go b/internal/text/emojionly.go index 1a3c0e968..127028643 100644 --- a/internal/text/emojionly.go +++ b/internal/text/emojionly.go @@ -57,7 +57,7 @@ func (f *formatter) FromPlainEmojiOnly(ctx context.Context, pmf gtsmodel.ParseMe var htmlContentBytes bytes.Buffer err := md.Convert([]byte(plain), &htmlContentBytes) if err != nil { - log.Errorf("error formatting plaintext to HTML: %s", err) + log.Errorf(ctx, "error formatting plaintext to HTML: %s", err) } result.HTML = htmlContentBytes.String() @@ -65,7 +65,10 @@ func (f *formatter) FromPlainEmojiOnly(ctx context.Context, pmf gtsmodel.ParseMe result.HTML = SanitizeHTML(result.HTML) // shrink ray - result.HTML = minifyHTML(result.HTML) + result.HTML, err = m.String("text/html", result.HTML) + if err != nil { + log.Errorf(ctx, "error minifying HTML: %s", err) + } return result } diff --git a/internal/text/goldmark_extension.go b/internal/text/goldmark_extension.go index 11e4fde28..419410e97 100644 --- a/internal/text/goldmark_extension.go +++ b/internal/text/goldmark_extension.go @@ -53,9 +53,11 @@ type emoji struct { Segment text.Segment } -var kindMention = ast.NewNodeKind("Mention") -var kindHashtag = ast.NewNodeKind("Hashtag") -var kindEmoji = ast.NewNodeKind("Emoji") +var ( + kindMention = ast.NewNodeKind("Mention") + kindHashtag = ast.NewNodeKind("Hashtag") + kindEmoji = ast.NewNodeKind("Emoji") +) func (n *mention) Kind() ast.NodeKind { return kindMention @@ -106,14 +108,11 @@ func newEmoji(s text.Segment) *emoji { } // mentionParser and hashtagParser fulfil the goldmark parser.InlineParser interface. -type mentionParser struct { -} +type mentionParser struct{} -type hashtagParser struct { -} +type hashtagParser struct{} -type emojiParser struct { -} +type emojiParser struct{} func (p *mentionParser) Trigger() []byte { return []byte{'@'} @@ -239,7 +238,7 @@ func (r *customRenderer) renderMention(w mdutil.BufWriter, source []byte, node a n, ok := node.(*mention) // this function is only registered for kindMention if !ok { - log.Errorf("type assertion failed") + log.Panic(nil, "type assertion failed") } text := string(n.Segment.Value(source)) @@ -247,7 +246,7 @@ func (r *customRenderer) renderMention(w mdutil.BufWriter, source []byte, node a // we don't have much recourse if this fails if _, err := w.WriteString(html); err != nil { - log.Errorf("error writing HTML: %s", err) + log.Errorf(nil, "error writing HTML: %s", err) } return ast.WalkSkipChildren, nil } @@ -259,7 +258,7 @@ func (r *customRenderer) renderHashtag(w mdutil.BufWriter, source []byte, node a n, ok := node.(*hashtag) // this function is only registered for kindHashtag if !ok { - log.Errorf("type assertion failed") + log.Panic(nil, "type assertion failed") } text := string(n.Segment.Value(source)) @@ -268,7 +267,7 @@ func (r *customRenderer) renderHashtag(w mdutil.BufWriter, source []byte, node a _, err := w.WriteString(html) // we don't have much recourse if this fails if err != nil { - log.Errorf("error writing HTML: %s", err) + log.Errorf(nil, "error writing HTML: %s", err) } return ast.WalkSkipChildren, nil } @@ -281,7 +280,7 @@ func (r *customRenderer) renderEmoji(w mdutil.BufWriter, source []byte, node ast n, ok := node.(*emoji) // this function is only registered for kindEmoji if !ok { - log.Errorf("type assertion failed") + log.Panic(nil, "type assertion failed") } text := string(n.Segment.Value(source)) shortcode := text[1 : len(text)-1] @@ -289,7 +288,7 @@ func (r *customRenderer) renderEmoji(w mdutil.BufWriter, source []byte, node ast emoji, err := r.f.db.GetEmojiByShortcodeDomain(r.ctx, shortcode, "") if err != nil { if err != db.ErrNoEntries { - log.Errorf("error getting local emoji with shortcode %s: %s", shortcode, err) + log.Errorf(nil, "error getting local emoji with shortcode %s: %s", shortcode, err) } } else if *emoji.VisibleInPicker && !*emoji.Disabled { listed := false @@ -306,7 +305,7 @@ func (r *customRenderer) renderEmoji(w mdutil.BufWriter, source []byte, node ast // we don't have much recourse if this fails if _, err := w.WriteString(text); err != nil { - log.Errorf("error writing HTML: %s", err) + log.Errorf(nil, "error writing HTML: %s", err) } return ast.WalkSkipChildren, nil } diff --git a/internal/text/markdown.go b/internal/text/markdown.go index 232f0f723..341ec1f00 100644 --- a/internal/text/markdown.go +++ b/internal/text/markdown.go @@ -53,7 +53,7 @@ func (f *formatter) FromMarkdown(ctx context.Context, pmf gtsmodel.ParseMentionF var htmlContentBytes bytes.Buffer err := md.Convert([]byte(markdownText), &htmlContentBytes) if err != nil { - log.Errorf("error formatting markdown to HTML: %s", err) + log.Errorf(ctx, "error formatting markdown to HTML: %s", err) } result.HTML = htmlContentBytes.String() @@ -61,7 +61,10 @@ func (f *formatter) FromMarkdown(ctx context.Context, pmf gtsmodel.ParseMentionF result.HTML = SanitizeHTML(result.HTML) // shrink ray - result.HTML = minifyHTML(result.HTML) + result.HTML, err = m.String("text/html", result.HTML) + if err != nil { + log.Errorf(ctx, "error minifying HTML: %s", err) + } return result } diff --git a/internal/text/minify.go b/internal/text/minify.go index 62562c7ca..96cb30464 100644 --- a/internal/text/minify.go +++ b/internal/text/minify.go @@ -19,27 +19,16 @@ package text import ( - "github.com/superseriousbusiness/gotosocial/internal/log" "github.com/tdewolff/minify/v2" "github.com/tdewolff/minify/v2/html" ) -var ( - m *minify.M -) - -func minifyHTML(content string) string { - if m == nil { - m = minify.New() - m.Add("text/html", &html.Minifier{ - KeepEndTags: true, - KeepQuotes: true, - }) - } - - minified, err := m.String("text/html", content) - if err != nil { - log.Errorf("error minifying HTML: %s", err) - } - return minified -} +// m is the global minify instance. +var m = func() *minify.M { + m := minify.New() + m.Add("text/html", &html.Minifier{ + KeepEndTags: true, + KeepQuotes: true, + }) + return m +}() diff --git a/internal/text/plain.go b/internal/text/plain.go index 3549200c6..bcdb0c0f4 100644 --- a/internal/text/plain.go +++ b/internal/text/plain.go @@ -60,7 +60,7 @@ func (f *formatter) FromPlain(ctx context.Context, pmf gtsmodel.ParseMentionFunc var htmlContentBytes bytes.Buffer err := md.Convert([]byte(plain), &htmlContentBytes) if err != nil { - log.Errorf("error formatting plaintext to HTML: %s", err) + log.Errorf(ctx, "error formatting plaintext to HTML: %s", err) } result.HTML = htmlContentBytes.String() @@ -68,7 +68,10 @@ func (f *formatter) FromPlain(ctx context.Context, pmf gtsmodel.ParseMentionFunc result.HTML = SanitizeHTML(result.HTML) // shrink ray - result.HTML = minifyHTML(result.HTML) + result.HTML, err = m.String("text/html", result.HTML) + if err != nil { + log.Errorf(ctx, "error minifying HTML: %s", err) + } return result } diff --git a/internal/text/replace.go b/internal/text/replace.go index 5deab5d4d..03275fe3d 100644 --- a/internal/text/replace.go +++ b/internal/text/replace.go @@ -20,11 +20,12 @@ import ( "errors" + "strings" + "github.com/superseriousbusiness/gotosocial/internal/db" "github.com/superseriousbusiness/gotosocial/internal/log" "github.com/superseriousbusiness/gotosocial/internal/util" "golang.org/x/text/unicode/norm" - "strings" ) const ( @@ -39,13 +40,13 @@ func (r *customRenderer) replaceMention(text string) string { menchie, err := r.parseMention(r.ctx, text, r.accountID, r.statusID) if err != nil { - log.Errorf("error parsing mention %s from status: %s", text, err) + log.Errorf(nil, "error parsing mention %s from status: %s", text, err) return text } if r.statusID != "" { if err := r.f.db.Put(r.ctx, menchie); err != nil { - log.Errorf("error putting mention in db: %s", err) + log.Errorf(nil, "error putting mention in db: %s", err) return text } } @@ -66,7 +67,7 @@ func (r *customRenderer) replaceMention(text string) string { if menchie.TargetAccount == nil { a, err := r.f.db.GetAccountByID(r.ctx, menchie.TargetAccountID) if err != nil { - log.Errorf("error getting account with id %s from the db: %s", menchie.TargetAccountID, err) + log.Errorf(nil, "error getting account with id %s from the db: %s", menchie.TargetAccountID, err) return text } menchie.TargetAccount = a @@ -105,7 +106,7 @@ func (r *customRenderer) replaceHashtag(text string) string { tag, err := r.f.db.TagStringToTag(r.ctx, normalized, r.accountID) if err != nil { - log.Errorf("error generating hashtags from status: %s", err) + log.Errorf(nil, "error generating hashtags from status: %s", err) return text } @@ -121,7 +122,7 @@ func (r *customRenderer) replaceHashtag(text string) string { err = r.f.db.Put(r.ctx, tag) if err != nil { if !errors.Is(err, db.ErrAlreadyExists) { - log.Errorf("error putting tags in db: %s", err) + log.Errorf(nil, "error putting tags in db: %s", err) return text } } diff --git a/internal/timeline/get.go b/internal/timeline/get.go index 4bad67a6b..f9a5444fc 100644 --- a/internal/timeline/get.go +++ b/internal/timeline/get.go @@ -38,14 +38,15 @@ func (t *timeline) LastGot() time.Time { } func (t *timeline) Get(ctx context.Context, amount int, maxID string, sinceID string, minID string, prepareNext bool) ([]Preparable, error) { - l := log.WithFields(kv.Fields{ - {"accountID", t.accountID}, - {"amount", amount}, - {"maxID", maxID}, - {"sinceID", sinceID}, - {"minID", minID}, - }...) - l.Debug("entering get and updating t.lastGot") + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"accountID", t.accountID}, + {"amount", amount}, + {"maxID", maxID}, + {"sinceID", sinceID}, + {"minID", minID}, + }...) + l.Trace("entering get and updating t.lastGot") // regardless of what happens below, update the // last time Get was called for this timeline @@ -154,11 +155,12 @@ func (t *timeline) getXFromTop(ctx context.Context, amount int) ([]Preparable, e // // This corresponds to an api call to /timelines/home?max_id=WHATEVER func (t *timeline) getXBehindID(ctx context.Context, amount int, behindID string, attempts *int) ([]Preparable, error) { - l := log.WithFields(kv.Fields{ - {"amount", amount}, - {"behindID", behindID}, - {"attempts", attempts}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"amount", amount}, + {"behindID", behindID}, + {"attempts", attempts}, + }...) newAttempts := *attempts newAttempts++ diff --git a/internal/timeline/index.go b/internal/timeline/index.go index a85863f21..e7e0e17fe 100644 --- a/internal/timeline/index.go +++ b/internal/timeline/index.go @@ -35,58 +35,9 @@ func (t *timeline) ItemIndexLength(ctx context.Context) int { return t.indexedItems.data.Len() } -// func (t *timeline) indexBefore(ctx context.Context, itemID string, amount int) error { -// l := log.WithFields(kv.Fields{{"amount", amount}}...) - -// // lazily initialize index if it hasn't been done already -// if t.indexedItems.data == nil { -// t.indexedItems.data = &list.List{} -// t.indexedItems.data.Init() -// } - -// toIndex := []Timelineable{} -// offsetID := itemID - -// l.Trace("entering grabloop") -// grabloop: -// for i := 0; len(toIndex) < amount && i < 5; i++ { // try the grabloop 5 times only -// // first grab items using the caller-provided grab function -// l.Trace("grabbing...") -// items, stop, err := t.grabFunction(ctx, t.accountID, "", "", offsetID, amount) -// if err != nil { -// return err -// } -// if stop { -// break grabloop -// } - -// l.Trace("filtering...") -// // now filter each item using the caller-provided filter function -// for _, item := range items { -// shouldIndex, err := t.filterFunction(ctx, t.accountID, item) -// if err != nil { -// return err -// } -// if shouldIndex { -// toIndex = append(toIndex, item) -// } -// offsetID = item.GetID() -// } -// } -// l.Trace("left grabloop") - -// // index the items we got -// for _, s := range toIndex { -// if _, err := t.IndexOne(ctx, s.GetID(), s.GetBoostOfID(), s.GetAccountID(), s.GetBoostOfAccountID()); err != nil { -// return fmt.Errorf("indexBefore: error indexing item with id %s: %s", s.GetID(), err) -// } -// } - -// return nil -// } - func (t *timeline) indexBehind(ctx context.Context, itemID string, amount int) error { - l := log.WithFields(kv.Fields{{"amount", amount}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"amount", amount}}...) // lazily initialize index if it hasn't been done already if t.indexedItems.data == nil { diff --git a/internal/timeline/manager.go b/internal/timeline/manager.go index 83d138f51..48c4bec83 100644 --- a/internal/timeline/manager.go +++ b/internal/timeline/manager.go @@ -134,10 +134,11 @@ func (m *manager) Stop() error { } func (m *manager) Ingest(ctx context.Context, item Timelineable, timelineAccountID string) (bool, error) { - l := log.WithFields(kv.Fields{ - {"timelineAccountID", timelineAccountID}, - {"itemID", item.GetID()}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"timelineAccountID", timelineAccountID}, + {"itemID", item.GetID()}, + }...) t, err := m.getOrCreateTimeline(ctx, timelineAccountID) if err != nil { @@ -149,10 +150,11 @@ func (m *manager) Ingest(ctx context.Context, item Timelineable, timelineAccount } func (m *manager) IngestAndPrepare(ctx context.Context, item Timelineable, timelineAccountID string) (bool, error) { - l := log.WithFields(kv.Fields{ - {"timelineAccountID", timelineAccountID}, - {"itemID", item.GetID()}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"timelineAccountID", timelineAccountID}, + {"itemID", item.GetID()}, + }...) t, err := m.getOrCreateTimeline(ctx, timelineAccountID) if err != nil { @@ -164,10 +166,11 @@ func (m *manager) IngestAndPrepare(ctx context.Context, item Timelineable, timel } func (m *manager) Remove(ctx context.Context, timelineAccountID string, itemID string) (int, error) { - l := log.WithFields(kv.Fields{ - {"timelineAccountID", timelineAccountID}, - {"itemID", itemID}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"timelineAccountID", timelineAccountID}, + {"itemID", itemID}, + }...) t, err := m.getOrCreateTimeline(ctx, timelineAccountID) if err != nil { @@ -179,7 +182,8 @@ func (m *manager) Remove(ctx context.Context, timelineAccountID string, itemID s } func (m *manager) GetTimeline(ctx context.Context, timelineAccountID string, maxID string, sinceID string, minID string, limit int, local bool) ([]Preparable, error) { - l := log.WithFields(kv.Fields{{"timelineAccountID", timelineAccountID}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"timelineAccountID", timelineAccountID}}...) t, err := m.getOrCreateTimeline(ctx, timelineAccountID) if err != nil { diff --git a/internal/timeline/prepare.go b/internal/timeline/prepare.go index 41ef36fed..fbf2d9d9e 100644 --- a/internal/timeline/prepare.go +++ b/internal/timeline/prepare.go @@ -31,7 +31,8 @@ ) func (t *timeline) PrepareFromTop(ctx context.Context, amount int) error { - l := log.WithFields(kv.Fields{{"amount", amount}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"amount", amount}}...) // lazily initialize prepared posts if it hasn't been done already if t.preparedItems.data == nil { @@ -85,12 +86,13 @@ func (t *timeline) PrepareFromTop(ctx context.Context, amount int) error { } func (t *timeline) prepareNextQuery(ctx context.Context, amount int, maxID string, sinceID string, minID string) error { - l := log.WithFields(kv.Fields{ - {"amount", amount}, - {"maxID", maxID}, - {"sinceID", sinceID}, - {"minID", minID}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"amount", amount}, + {"maxID", maxID}, + {"sinceID", sinceID}, + {"minID", minID}, + }...) var err error switch { diff --git a/internal/timeline/remove.go b/internal/timeline/remove.go index f0bd4618b..1693ed03a 100644 --- a/internal/timeline/remove.go +++ b/internal/timeline/remove.go @@ -28,10 +28,11 @@ ) func (t *timeline) Remove(ctx context.Context, statusID string) (int, error) { - l := log.WithFields(kv.Fields{ - {"accountTimeline", t.accountID}, - {"statusID", statusID}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"accountTimeline", t.accountID}, + {"statusID", statusID}, + }...) t.Lock() defer t.Unlock() @@ -80,10 +81,11 @@ func (t *timeline) Remove(ctx context.Context, statusID string) (int, error) { } func (t *timeline) RemoveAllBy(ctx context.Context, accountID string) (int, error) { - l := log.WithFields(kv.Fields{ - {"accountTimeline", t.accountID}, - {"accountID", accountID}, - }...) + l := log.WithContext(ctx). + WithFields(kv.Fields{ + {"accountTimeline", t.accountID}, + {"accountID", accountID}, + }...) t.Lock() defer t.Unlock() diff --git a/internal/trans/import.go b/internal/trans/import.go index 68b7d4e16..1d52add41 100644 --- a/internal/trans/import.go +++ b/internal/trans/import.go @@ -48,7 +48,7 @@ func (i *importer) Import(ctx context.Context, path string) error { err := decoder.Decode(&entry) if err != nil { if err == io.EOF { - log.Infof("Import: reached end of file") + log.Infof(ctx, "reached end of file") return neatClose(file) } return fmt.Errorf("Import: error decoding in readLoop: %s", err) @@ -74,7 +74,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, account); err != nil { return fmt.Errorf("inputEntry: error adding account to database: %s", err) } - log.Infof("inputEntry: added account with id %s", account.ID) + log.Infof(ctx, "added account with id %s", account.ID) return nil case transmodel.TransBlock: block, err := i.blockDecode(entry) @@ -84,7 +84,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, block); err != nil { return fmt.Errorf("inputEntry: error adding block to database: %s", err) } - log.Infof("inputEntry: added block with id %s", block.ID) + log.Infof(ctx, "added block with id %s", block.ID) return nil case transmodel.TransDomainBlock: block, err := i.domainBlockDecode(entry) @@ -94,7 +94,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, block); err != nil { return fmt.Errorf("inputEntry: error adding domain block to database: %s", err) } - log.Infof("inputEntry: added domain block with id %s", block.ID) + log.Infof(ctx, "added domain block with id %s", block.ID) return nil case transmodel.TransFollow: follow, err := i.followDecode(entry) @@ -104,7 +104,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, follow); err != nil { return fmt.Errorf("inputEntry: error adding follow to database: %s", err) } - log.Infof("inputEntry: added follow with id %s", follow.ID) + log.Infof(ctx, "added follow with id %s", follow.ID) return nil case transmodel.TransFollowRequest: fr, err := i.followRequestDecode(entry) @@ -114,7 +114,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, fr); err != nil { return fmt.Errorf("inputEntry: error adding follow request to database: %s", err) } - log.Infof("inputEntry: added follow request with id %s", fr.ID) + log.Infof(ctx, "added follow request with id %s", fr.ID) return nil case transmodel.TransInstance: inst, err := i.instanceDecode(entry) @@ -124,7 +124,7 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, inst); err != nil { return fmt.Errorf("inputEntry: error adding instance to database: %s", err) } - log.Infof("inputEntry: added instance with id %s", inst.ID) + log.Infof(ctx, "added instance with id %s", inst.ID) return nil case transmodel.TransUser: user, err := i.userDecode(entry) @@ -134,11 +134,11 @@ func (i *importer) inputEntry(ctx context.Context, entry transmodel.Entry) error if err := i.putInDB(ctx, user); err != nil { return fmt.Errorf("inputEntry: error adding user to database: %s", err) } - log.Infof("inputEntry: added user with id %s", user.ID) + log.Infof(ctx, "added user with id %s", user.ID) return nil } - log.Errorf("inputEntry: didn't recognize transtype '%s', skipping it", t) + log.Errorf(ctx, "didn't recognize transtype '%s', skipping it", t) return nil } diff --git a/internal/transport/controller.go b/internal/transport/controller.go index 6c2aec052..abcccfe1e 100644 --- a/internal/transport/controller.go +++ b/internal/transport/controller.go @@ -76,13 +76,13 @@ func NewController(db db.DB, federatingDB federatingdb.DB, clock pub.Clock, clie // Transport cache has TTL=1hr freq=1min c.trspCache.SetTTL(time.Hour, false) if !c.trspCache.Start(time.Minute) { - log.Panic("failed to start transport controller cache") + log.Panic(nil, "failed to start transport controller cache") } // Bad hosts cache has TTL=15min freq=1min c.badHosts.SetTTL(15*time.Minute, false) if !c.badHosts.Start(time.Minute) { - log.Panic("failed to start transport controller cache") + log.Panic(nil, "failed to start transport controller cache") } return c diff --git a/internal/transport/derefinstance.go b/internal/transport/derefinstance.go index b8be2f717..e46b52554 100644 --- a/internal/transport/derefinstance.go +++ b/internal/transport/derefinstance.go @@ -45,26 +45,26 @@ func (t *transport) DereferenceInstance(ctx context.Context, iri *url.URL) (*gts // This will provide the most complete picture of an instance, and avoid unnecessary api calls. // // This will only work with Mastodon-api compatible instances: Mastodon, some Pleroma instances, GoToSocial. - log.Debugf("trying to dereference instance %s by /api/v1/instance", iri.Host) + log.Debugf(ctx, "trying to dereference instance %s by /api/v1/instance", iri.Host) i, err = dereferenceByAPIV1Instance(ctx, t, iri) if err == nil { - log.Debugf("successfully dereferenced instance using /api/v1/instance") + log.Debugf(ctx, "successfully dereferenced instance using /api/v1/instance") return i, nil } - log.Debugf("couldn't dereference instance using /api/v1/instance: %s", err) + log.Debugf(ctx, "couldn't dereference instance using /api/v1/instance: %s", err) // If that doesn't work, try to dereference using /.well-known/nodeinfo. // This will involve two API calls and return less info overall, but should be more widely compatible. - log.Debugf("trying to dereference instance %s by /.well-known/nodeinfo", iri.Host) + log.Debugf(ctx, "trying to dereference instance %s by /.well-known/nodeinfo", iri.Host) i, err = dereferenceByNodeInfo(ctx, t, iri) if err == nil { - log.Debugf("successfully dereferenced instance using /.well-known/nodeinfo") + log.Debugf(ctx, "successfully dereferenced instance using /.well-known/nodeinfo") return i, nil } - log.Debugf("couldn't dereference instance using /.well-known/nodeinfo: %s", err) + log.Debugf(ctx, "couldn't dereference instance using /.well-known/nodeinfo: %s", err) // we couldn't dereference the instance using any of the known methods, so just return a minimal representation - log.Debugf("returning minimal representation of instance %s", iri.Host) + log.Debugf(ctx, "returning minimal representation of instance %s", iri.Host) id, err := id.NewRandomULID() if err != nil { return nil, fmt.Errorf("error creating new id for instance %s: %s", iri.Host, err) diff --git a/internal/transport/transport.go b/internal/transport/transport.go index 8095e6612..18c40f79f 100644 --- a/internal/transport/transport.go +++ b/internal/transport/transport.go @@ -130,11 +130,12 @@ func (t *transport) do(r *http.Request, signer func(*http.Request) error) (*http fastFail := IsFastfail(r.Context()) // Start a log entry for this request - l := log.WithFields(kv.Fields{ - {"pubKeyID", t.pubKeyID}, - {"method", r.Method}, - {"url", r.URL.String()}, - }...) + l := log.WithContext(r.Context()). + WithFields(kv.Fields{ + {"pubKeyID", t.pubKeyID}, + {"method", r.Method}, + {"url", r.URL.String()}, + }...) r.Header.Set("User-Agent", t.controller.userAgent) diff --git a/internal/typeutils/astointernal.go b/internal/typeutils/astointernal.go index fff9c807a..2ed1d52d3 100644 --- a/internal/typeutils/astointernal.go +++ b/internal/typeutils/astointernal.go @@ -82,7 +82,7 @@ func (c *converter) ASRepresentationToAccount(ctx context.Context, accountable a // account emojis (used in bio, display name, fields) if emojis, err := ap.ExtractEmojis(accountable); err != nil { - log.Infof("ASRepresentationToAccount: error extracting account emojis: %s", err) + log.Infof(nil, "error extracting account emojis: %s", err) } else { acct.Emojis = emojis } @@ -217,13 +217,13 @@ func (c *converter) extractAttachments(i ap.WithAttachment) []*gtsmodel.MediaAtt attachmentable, ok := t.(ap.Attachmentable) if !ok { - log.Error("ap attachment was not attachmentable") + log.Error(nil, "ap attachment was not attachmentable") continue } attachment, err := ap.ExtractAttachment(attachmentable) if err != nil { - log.Errorf("error extracting attachment: %s", err) + log.Errorf(nil, "error extracting attachment: %s", err) continue } @@ -684,7 +684,7 @@ func (c *converter) ASFlagToReport(ctx context.Context, flaggable ap.Flaggable) return nil, fmt.Errorf("ASFlagToReport: db error getting status with url %s: %w", statusURIString, err) } - log.Warnf("ASFlagToReport: reported status %s could not be found in the db, skipping it", statusURIString) + log.Warnf(nil, "reported status %s could not be found in the db, skipping it", statusURIString) continue } } diff --git a/internal/typeutils/defaulticons.go b/internal/typeutils/defaulticons.go index 8ce715b31..e7d683dba 100644 --- a/internal/typeutils/defaulticons.go +++ b/internal/typeutils/defaulticons.go @@ -41,13 +41,13 @@ func populateDefaultAvatars() (defaultAvatars []string) { webAssetsAbsFilePath, err := filepath.Abs(config.GetWebAssetBaseDir()) if err != nil { - log.Panicf("populateDefaultAvatars: error getting abs path for web assets: %s", err) + log.Panicf(nil, "error getting abs path for web assets: %s", err) } defaultAvatarsAbsFilePath := filepath.Join(webAssetsAbsFilePath, "default_avatars") defaultAvatarFiles, err := os.ReadDir(defaultAvatarsAbsFilePath) if err != nil { - log.Warnf("populateDefaultAvatars: error reading default avatars at %s: %s", defaultAvatarsAbsFilePath, err) + log.Warnf(nil, "error reading default avatars at %s: %s", defaultAvatarsAbsFilePath, err) return } diff --git a/internal/typeutils/internaltoas.go b/internal/typeutils/internaltoas.go index 2ae58b317..06b49c18f 100644 --- a/internal/typeutils/internaltoas.go +++ b/internal/typeutils/internaltoas.go @@ -252,7 +252,7 @@ func (c *converter) AccountToAS(ctx context.Context, a *gtsmodel.Account) (vocab if err == nil { a.AvatarMediaAttachment = avatar } else { - log.Errorf("AccountToAS: error getting Avatar with id %s: %s", a.AvatarMediaAttachmentID, err) + log.Errorf(ctx, "error getting Avatar with id %s: %s", a.AvatarMediaAttachmentID, err) } } @@ -286,7 +286,7 @@ func (c *converter) AccountToAS(ctx context.Context, a *gtsmodel.Account) (vocab if err == nil { a.HeaderMediaAttachment = header } else { - log.Errorf("AccountToAS: error getting Header with id %s: %s", a.HeaderMediaAttachmentID, err) + log.Errorf(ctx, "error getting Header with id %s: %s", a.HeaderMediaAttachmentID, err) } } diff --git a/internal/typeutils/internaltofrontend.go b/internal/typeutils/internaltofrontend.go index 738155532..6e6bc381e 100644 --- a/internal/typeutils/internaltofrontend.go +++ b/internal/typeutils/internaltofrontend.go @@ -119,7 +119,7 @@ func (c *converter) AccountToAPIAccountPublic(ctx context.Context, a *gtsmodel.A if a.AvatarMediaAttachment == nil { avi, err := c.db.GetAttachmentByID(ctx, a.AvatarMediaAttachmentID) if err != nil { - log.Errorf("AccountToAPIAccountPublic: error getting Avatar with id %s: %s", a.AvatarMediaAttachmentID, err) + log.Errorf(ctx, "error getting Avatar with id %s: %s", a.AvatarMediaAttachmentID, err) } a.AvatarMediaAttachment = avi } @@ -136,7 +136,7 @@ func (c *converter) AccountToAPIAccountPublic(ctx context.Context, a *gtsmodel.A if a.HeaderMediaAttachment == nil { avi, err := c.db.GetAttachmentByID(ctx, a.HeaderMediaAttachmentID) if err != nil { - log.Errorf("AccountToAPIAccountPublic: error getting Header with id %s: %s", a.HeaderMediaAttachmentID, err) + log.Errorf(ctx, "error getting Header with id %s: %s", a.HeaderMediaAttachmentID, err) } a.HeaderMediaAttachment = avi } @@ -164,7 +164,7 @@ func (c *converter) AccountToAPIAccountPublic(ctx context.Context, a *gtsmodel.A // convert account gts model emojis to frontend api model emojis apiEmojis, err := c.convertEmojisToAPIEmojis(ctx, a.Emojis, a.EmojiIDs) if err != nil { - log.Errorf("error converting account emojis: %v", err) + log.Errorf(ctx, "error converting account emojis: %v", err) } var ( @@ -577,31 +577,31 @@ func (c *converter) StatusToAPIStatus(ctx context.Context, s *gtsmodel.Status, r // convert status gts model attachments to frontend api model attachments apiAttachments, err := c.convertAttachmentsToAPIAttachments(ctx, s.Attachments, s.AttachmentIDs) if err != nil { - log.Errorf("error converting status attachments: %v", err) + log.Errorf(ctx, "error converting status attachments: %v", err) } // convert status gts model mentions to frontend api model mentions apiMentions, err := c.convertMentionsToAPIMentions(ctx, s.Mentions, s.MentionIDs) if err != nil { - log.Errorf("error converting status mentions: %v", err) + log.Errorf(ctx, "error converting status mentions: %v", err) } // convert status gts model tags to frontend api model tags apiTags, err := c.convertTagsToAPITags(ctx, s.Tags, s.TagIDs) if err != nil { - log.Errorf("error converting status tags: %v", err) + log.Errorf(ctx, "error converting status tags: %v", err) } // convert status gts model emojis to frontend api model emojis apiEmojis, err := c.convertEmojisToAPIEmojis(ctx, s.Emojis, s.EmojiIDs) if err != nil { - log.Errorf("error converting status emojis: %v", err) + log.Errorf(ctx, "error converting status emojis: %v", err) } // Fetch status interaction flags for acccount interacts, err := c.interactionsWithStatusForAccount(ctx, s, requestingAccount) if err != nil { - log.Errorf("error getting interactions for status %s for account %s: %v", s.ID, requestingAccount.ID, err) + log.Errorf(ctx, "error getting interactions for status %s for account %s: %v", s.ID, requestingAccount.ID, err) // Ensure a non nil object interacts = &statusInteractions{} diff --git a/internal/typeutils/internaltorss.go b/internal/typeutils/internaltorss.go index 64cfa1211..cc241e0b9 100644 --- a/internal/typeutils/internaltorss.go +++ b/internal/typeutils/internaltorss.go @@ -130,7 +130,7 @@ func (c *converter) StatusToRSSItem(ctx context.Context, s *gtsmodel.Status) (*f for _, gtsEmoji := range s.Emojis { apiEmoji, err := c.EmojiToAPIEmoji(ctx, gtsEmoji) if err != nil { - log.Errorf("error converting emoji with id %s: %s", gtsEmoji.ID, err) + log.Errorf(ctx, "error converting emoji with id %s: %s", gtsEmoji.ID, err) continue } apiEmojis = append(apiEmojis, apiEmoji) @@ -141,12 +141,12 @@ func (c *converter) StatusToRSSItem(ctx context.Context, s *gtsmodel.Status) (*f for _, e := range s.EmojiIDs { gtsEmoji := >smodel.Emoji{} if err := c.db.GetByID(ctx, e, gtsEmoji); err != nil { - log.Errorf("error getting emoji with id %s: %s", e, err) + log.Errorf(ctx, "error getting emoji with id %s: %s", e, err) continue } apiEmoji, err := c.EmojiToAPIEmoji(ctx, gtsEmoji) if err != nil { - log.Errorf("error converting emoji with id %s: %s", gtsEmoji.ID, err) + log.Errorf(ctx, "error converting emoji with id %s: %s", gtsEmoji.ID, err) continue } apiEmojis = append(apiEmojis, apiEmoji) diff --git a/internal/visibility/statusboostable.go b/internal/visibility/statusboostable.go index c463ee372..ec6839d42 100644 --- a/internal/visibility/statusboostable.go +++ b/internal/visibility/statusboostable.go @@ -39,23 +39,23 @@ func (f *filter) StatusBoostable(ctx context.Context, targetStatus *gtsmodel.Sta // direct messages are never boostable, even if they're visible if targetStatus.Visibility == gtsmodel.VisibilityDirect { - log.Trace("status is not boostable because it is a DM") + log.Trace(ctx, "status is not boostable because it is a DM") return false, nil } // the original account should always be able to boost its own non-DM statuses if requestingAccount.ID == targetStatus.Account.ID { - log.Trace("status is boostable because author is booster") + log.Trace(ctx, "status is boostable because author is booster") return true, nil } // if status is followers-only and not the author's, it is not boostable if targetStatus.Visibility == gtsmodel.VisibilityFollowersOnly { - log.Trace("status not boostable because it is followers-only") + log.Trace(ctx, "status not boostable because it is followers-only") return false, nil } // otherwise, status is as boostable as it says it is - log.Trace("defaulting to status.boostable value") + log.Trace(ctx, "defaulting to status.boostable value") return *targetStatus.Boostable, nil } diff --git a/internal/visibility/statushometimelineable.go b/internal/visibility/statushometimelineable.go index 19a39aa51..b2fbecd85 100644 --- a/internal/visibility/statushometimelineable.go +++ b/internal/visibility/statushometimelineable.go @@ -30,7 +30,8 @@ ) func (f *filter) StatusHometimelineable(ctx context.Context, targetStatus *gtsmodel.Status, timelineOwnerAccount *gtsmodel.Account) (bool, error) { - l := log.WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) // don't timeline statuses more than 5 min in the future maxID, err := id.NewULIDFromTime(time.Now().Add(5 * time.Minute)) diff --git a/internal/visibility/statuspublictimelineable.go b/internal/visibility/statuspublictimelineable.go index 113249fe1..05a94bf8e 100644 --- a/internal/visibility/statuspublictimelineable.go +++ b/internal/visibility/statuspublictimelineable.go @@ -30,7 +30,8 @@ ) func (f *filter) StatusPublictimelineable(ctx context.Context, targetStatus *gtsmodel.Status, timelineOwnerAccount *gtsmodel.Account) (bool, error) { - l := log.WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) // don't timeline statuses more than 5 min in the future maxID, err := id.NewULIDFromTime(time.Now().Add(5 * time.Minute)) diff --git a/internal/visibility/statusvisible.go b/internal/visibility/statusvisible.go index 002db1119..2f89727ee 100644 --- a/internal/visibility/statusvisible.go +++ b/internal/visibility/statusvisible.go @@ -29,7 +29,8 @@ ) func (f *filter) StatusVisible(ctx context.Context, targetStatus *gtsmodel.Status, requestingAccount *gtsmodel.Account) (bool, error) { - l := log.WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) + l := log.WithContext(ctx). + WithFields(kv.Fields{{"statusID", targetStatus.ID}}...) // Fetch any relevant accounts for the target status const getBoosted = true diff --git a/internal/web/assets.go b/internal/web/assets.go index 31d09f4be..8f662017a 100644 --- a/internal/web/assets.go +++ b/internal/web/assets.go @@ -102,6 +102,9 @@ func (m *Module) getAssetETag(filePath string, fs http.FileSystem) (string, erro // package along with the other middlewares func (m *Module) assetsCacheControlMiddleware(fs http.FileSystem) gin.HandlerFunc { return func(c *gin.Context) { + // Acquire context from gin request. + ctx := c.Request.Context() + // set this Cache-Control header to instruct clients to validate the response with us // before each reuse (https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Cache-Control) c.Header(cacheControlHeader, cacheControlNoCache) @@ -118,7 +121,7 @@ func (m *Module) assetsCacheControlMiddleware(fs http.FileSystem) gin.HandlerFun // either fetch etag from ttlcache or generate it eTag, err := m.getAssetETag(assetFilePath, fs) if err != nil { - log.Errorf("error getting ETag for %s: %s", assetFilePath, err) + log.Errorf(ctx, "error getting ETag for %s: %s", assetFilePath, err) return } diff --git a/internal/web/etag.go b/internal/web/etag.go index 72c3bb762..096aa9c83 100644 --- a/internal/web/etag.go +++ b/internal/web/etag.go @@ -34,7 +34,7 @@ func newETagCache() cache.Cache[string, eTagCacheEntry] { eTagCache := cache.New[string, eTagCacheEntry](0, 1000, 0) eTagCache.SetTTL(time.Hour, false) if !eTagCache.Start(time.Minute) { - log.Panic("could not start eTagCache") + log.Panic(nil, "could not start eTagCache") } return eTagCache } diff --git a/internal/web/rss.go b/internal/web/rss.go index 757c3ffb5..dccb49542 100644 --- a/internal/web/rss.go +++ b/internal/web/rss.go @@ -61,14 +61,16 @@ func (m *Module) GetRSSETag(urlPath string, lastModified time.Time, getRSSFeed f return eTag, nil } -func extractIfModifiedSince(header string) time.Time { - if header == "" { +func extractIfModifiedSince(r *http.Request) time.Time { + hdr := r.Header.Get(ifModifiedSinceHeader) + + if hdr == "" { return time.Time{} } - t, err := http.ParseTime(header) + t, err := http.ParseTime(hdr) if err != nil { - log.Errorf("couldn't parse if-modified-since %s: %s", header, err) + log.Errorf(r.Context(), "couldn't parse if-modified-since %s: %s", hdr, err) return time.Time{} } @@ -95,7 +97,7 @@ func (m *Module) rssFeedGETHandler(c *gin.Context) { } ifNoneMatch := c.Request.Header.Get(ifNoneMatchHeader) - ifModifiedSince := extractIfModifiedSince(c.Request.Header.Get(ifModifiedSinceHeader)) + ifModifiedSince := extractIfModifiedSince(c.Request) getRssFeed, accountLastPostedPublic, errWithCode := m.processor.AccountGetRSSFeedForUsername(ctx, username) if errWithCode != nil { diff --git a/internal/web/web.go b/internal/web/web.go index 0fc1644c8..08bac4583 100644 --- a/internal/web/web.go +++ b/internal/web/web.go @@ -79,7 +79,7 @@ func (m *Module) Route(r router.Router, mi ...gin.HandlerFunc) { // so that they can use the same cache control middleware. webAssetsAbsFilePath, err := filepath.Abs(config.GetWebAssetBaseDir()) if err != nil { - log.Panicf("error getting absolute path of assets dir: %s", err) + log.Panicf(nil, "error getting absolute path of assets dir: %s", err) } fs := fileSystem{http.Dir(webAssetsAbsFilePath)} assetsGroup := r.AttachGroup(assetsPathPrefix) diff --git a/mkdocs.yml b/mkdocs.yml index cf002a48d..b50b9186f 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -49,6 +49,7 @@ nav: - "configuration/smtp.md" - "configuration/syslog.md" - "configuration/advanced.md" + - "configuration/observability.md" - "Admin": - "admin/settings.md" - "admin/cli.md" diff --git a/test/envparsing.sh b/test/envparsing.sh index 1c31e3038..2c725f23a 100755 --- a/test/envparsing.sh +++ b/test/envparsing.sh @@ -2,7 +2,7 @@ set -eu -EXPECT='{"account-domain":"peepee","accounts-allow-custom-css":true,"accounts-approval-required":false,"accounts-reason-required":false,"accounts-registration-open":true,"advanced-cookies-samesite":"strict","advanced-rate-limit-requests":6969,"advanced-throttling-multiplier":-1,"advanced-throttling-retry-after":10000000000,"application-name":"gts","bind-address":"127.0.0.1","cache":{"gts":{"account-max-size":99,"account-sweep-freq":1000000000,"account-ttl":10800000000000,"block-max-size":100,"block-sweep-freq":10000000000,"block-ttl":300000000000,"domain-block-max-size":1000,"domain-block-sweep-freq":60000000000,"domain-block-ttl":86400000000000,"emoji-category-max-size":100,"emoji-category-sweep-freq":10000000000,"emoji-category-ttl":300000000000,"emoji-max-size":500,"emoji-sweep-freq":10000000000,"emoji-ttl":300000000000,"mention-max-size":500,"mention-sweep-freq":10000000000,"mention-ttl":300000000000,"notification-max-size":500,"notification-sweep-freq":10000000000,"notification-ttl":300000000000,"report-max-size":100,"report-sweep-freq":10000000000,"report-ttl":300000000000,"status-max-size":500,"status-sweep-freq":10000000000,"status-ttl":300000000000,"tombstone-max-size":100,"tombstone-sweep-freq":10000000000,"tombstone-ttl":300000000000,"user-max-size":100,"user-sweep-freq":10000000000,"user-ttl":300000000000}},"config-path":"internal/config/testdata/test.yaml","db-address":":memory:","db-database":"gotosocial_prod","db-max-open-conns-multiplier":3,"db-password":"hunter2","db-port":6969,"db-sqlite-busy-timeout":1000000000,"db-sqlite-cache-size":0,"db-sqlite-journal-mode":"DELETE","db-sqlite-synchronous":"FULL","db-tls-ca-cert":"","db-tls-mode":"disable","db-type":"sqlite","db-user":"sex-haver","dry-run":true,"email":"","host":"example.com","instance-deliver-to-shared-inboxes":false,"instance-expose-peers":true,"instance-expose-public-timeline":true,"instance-expose-suspended":true,"instance-expose-suspended-web":true,"landing-page-user":"admin","letsencrypt-cert-dir":"/gotosocial/storage/certs","letsencrypt-email-address":"","letsencrypt-enabled":true,"letsencrypt-port":80,"log-db-queries":true,"log-level":"info","media-description-max-chars":5000,"media-description-min-chars":69,"media-emoji-local-max-size":420,"media-emoji-remote-max-size":420,"media-image-max-size":420,"media-remote-cache-days":30,"media-video-max-size":420,"oidc-client-id":"1234","oidc-client-secret":"shhhh its a secret","oidc-enabled":true,"oidc-idp-name":"sex-haver","oidc-issuer":"whoknows","oidc-link-existing":true,"oidc-scopes":["read","write"],"oidc-skip-verification":true,"password":"","path":"","port":6969,"protocol":"http","smtp-from":"queen.rip.in.piss@terfisland.org","smtp-host":"example.com","smtp-password":"hunter2","smtp-port":4269,"smtp-username":"sex-haver","software-version":"","statuses-cw-max-chars":420,"statuses-max-chars":69,"statuses-media-max-files":1,"statuses-poll-max-options":1,"statuses-poll-option-max-chars":50,"storage-backend":"local","storage-local-base-path":"/root/store","storage-s3-access-key":"minio","storage-s3-bucket":"gts","storage-s3-endpoint":"localhost:9000","storage-s3-proxy":true,"storage-s3-secret-key":"miniostorage","storage-s3-use-ssl":false,"syslog-address":"127.0.0.1:6969","syslog-enabled":true,"syslog-protocol":"udp","trusted-proxies":["127.0.0.1/32","docker.host.local"],"username":"","web-asset-base-dir":"/root","web-template-base-dir":"/root"}' +EXPECT='{"account-domain":"peepee","accounts-allow-custom-css":true,"accounts-approval-required":false,"accounts-reason-required":false,"accounts-registration-open":true,"advanced-cookies-samesite":"strict","advanced-rate-limit-requests":6969,"advanced-throttling-multiplier":-1,"advanced-throttling-retry-after":10000000000,"application-name":"gts","bind-address":"127.0.0.1","cache":{"gts":{"account-max-size":99,"account-sweep-freq":1000000000,"account-ttl":10800000000000,"block-max-size":100,"block-sweep-freq":10000000000,"block-ttl":300000000000,"domain-block-max-size":1000,"domain-block-sweep-freq":60000000000,"domain-block-ttl":86400000000000,"emoji-category-max-size":100,"emoji-category-sweep-freq":10000000000,"emoji-category-ttl":300000000000,"emoji-max-size":500,"emoji-sweep-freq":10000000000,"emoji-ttl":300000000000,"mention-max-size":500,"mention-sweep-freq":10000000000,"mention-ttl":300000000000,"notification-max-size":500,"notification-sweep-freq":10000000000,"notification-ttl":300000000000,"report-max-size":100,"report-sweep-freq":10000000000,"report-ttl":300000000000,"status-max-size":500,"status-sweep-freq":10000000000,"status-ttl":300000000000,"tombstone-max-size":100,"tombstone-sweep-freq":10000000000,"tombstone-ttl":300000000000,"user-max-size":100,"user-sweep-freq":10000000000,"user-ttl":300000000000}},"config-path":"internal/config/testdata/test.yaml","db-address":":memory:","db-database":"gotosocial_prod","db-max-open-conns-multiplier":3,"db-password":"hunter2","db-port":6969,"db-sqlite-busy-timeout":1000000000,"db-sqlite-cache-size":0,"db-sqlite-journal-mode":"DELETE","db-sqlite-synchronous":"FULL","db-tls-ca-cert":"","db-tls-mode":"disable","db-type":"sqlite","db-user":"sex-haver","dry-run":true,"email":"","host":"example.com","instance-deliver-to-shared-inboxes":false,"instance-expose-peers":true,"instance-expose-public-timeline":true,"instance-expose-suspended":true,"instance-expose-suspended-web":true,"landing-page-user":"admin","letsencrypt-cert-dir":"/gotosocial/storage/certs","letsencrypt-email-address":"","letsencrypt-enabled":true,"letsencrypt-port":80,"log-db-queries":true,"log-level":"info","media-description-max-chars":5000,"media-description-min-chars":69,"media-emoji-local-max-size":420,"media-emoji-remote-max-size":420,"media-image-max-size":420,"media-remote-cache-days":30,"media-video-max-size":420,"oidc-client-id":"1234","oidc-client-secret":"shhhh its a secret","oidc-enabled":true,"oidc-idp-name":"sex-haver","oidc-issuer":"whoknows","oidc-link-existing":true,"oidc-scopes":["read","write"],"oidc-skip-verification":true,"password":"","path":"","port":6969,"protocol":"http","request-id-header":"X-Trace-Id","smtp-from":"queen.rip.in.piss@terfisland.org","smtp-host":"example.com","smtp-password":"hunter2","smtp-port":4269,"smtp-username":"sex-haver","software-version":"","statuses-cw-max-chars":420,"statuses-max-chars":69,"statuses-media-max-files":1,"statuses-poll-max-options":1,"statuses-poll-option-max-chars":50,"storage-backend":"local","storage-local-base-path":"/root/store","storage-s3-access-key":"minio","storage-s3-bucket":"gts","storage-s3-endpoint":"localhost:9000","storage-s3-proxy":true,"storage-s3-secret-key":"miniostorage","storage-s3-use-ssl":false,"syslog-address":"127.0.0.1:6969","syslog-enabled":true,"syslog-protocol":"udp","trusted-proxies":["127.0.0.1/32","docker.host.local"],"username":"","web-asset-base-dir":"/root","web-template-base-dir":"/root"}' # Set all the environment variables to # ensure that these are parsed without panic @@ -84,6 +84,7 @@ GTS_ADVANCED_COOKIES_SAMESITE='strict' \ GTS_ADVANCED_RATE_LIMIT_REQUESTS=6969 \ GTS_ADVANCED_THROTTLING_MULTIPLIER=-1 \ GTS_ADVANCED_THROTTLING_RETRY_AFTER='10s' \ +GTS_REQUEST_ID_HEADER='X-Trace-Id' \ go run ./cmd/gotosocial/... --config-path internal/config/testdata/test.yaml debug config) OUTPUT_OUT=$(mktemp) diff --git a/testrig/db.go b/testrig/db.go index 65ec391a7..8479347eb 100644 --- a/testrig/db.go +++ b/testrig/db.go @@ -93,7 +93,7 @@ func NewTestDB() db.DB { testDB, err := bundb.NewBunDBService(context.Background(), &state) if err != nil { - log.Panic(err) + log.Panic(nil, err) } state.DB = testDB @@ -106,7 +106,7 @@ func CreateTestTables(db db.DB) { ctx := context.Background() for _, m := range testModels { if err := db.CreateTable(ctx, m); err != nil { - log.Panicf("error creating table for %+v: %s", m, err) + log.Panicf(nil, "error creating table for %+v: %s", m, err) } } } @@ -121,7 +121,7 @@ func CreateTestTables(db db.DB) { // verification will fail. func StandardDBSetup(db db.DB, accounts map[string]*gtsmodel.Account) { if db == nil { - log.Panic("db setup: db was nil") + log.Panic(nil, "db setup: db was nil") } CreateTestTables(db) @@ -130,164 +130,164 @@ func StandardDBSetup(db db.DB, accounts map[string]*gtsmodel.Account) { for _, v := range NewTestTokens() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestClients() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestApplications() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestBlocks() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestReports() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestDomainBlocks() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestInstances() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestUsers() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } if accounts == nil { for _, v := range NewTestAccounts() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } } else { for _, v := range accounts { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } } for _, v := range NewTestAttachments() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestStatuses() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestEmojis() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestEmojiCategories() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestStatusToEmojis() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestTags() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestStatusToTags() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestMentions() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestFaves() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestFollows() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestNotifications() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestTombstones() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } for _, v := range NewTestBookmarks() { if err := db.Put(ctx, v); err != nil { - log.Panic(err) + log.Panic(nil, err) } } if err := db.CreateInstanceAccount(ctx); err != nil { - log.Panic(err) + log.Panic(nil, err) } if err := db.CreateInstanceInstance(ctx); err != nil { - log.Panic(err) + log.Panic(nil, err) } - log.Debug("testing db setup complete") + log.Debug(nil, "testing db setup complete") } // StandardDBTeardown drops all the standard testing tables/models from the database to ensure it's clean for the next test. func StandardDBTeardown(db db.DB) { ctx := context.Background() if db == nil { - log.Panic("db teardown: db was nil") + log.Panic(nil, "db was nil") } for _, m := range testModels { if err := db.DropTable(ctx, m); err != nil { - log.Panic(err) + log.Panic(nil, err) } } } diff --git a/testrig/log.go b/testrig/log.go index 2d7911484..cd61aced4 100644 --- a/testrig/log.go +++ b/testrig/log.go @@ -29,7 +29,7 @@ func InitTestLog() { // Set the global log level from configuration if err := log.ParseLevel(config.GetLogLevel()); err != nil { - log.Panicf("error parsing log level: %v", err) + log.Panicf(nil, "error parsing log level: %v", err) } if config.GetSyslogEnabled() { @@ -38,7 +38,7 @@ func InitTestLog() { config.GetSyslogProtocol(), config.GetSyslogAddress(), ); err != nil { - log.Panicf("error enabling syslogging: %v", err) + log.Panicf(nil, "error enabling syslogging: %v", err) } } } diff --git a/testrig/transportcontroller.go b/testrig/transportcontroller.go index 09775f6a2..7565a741c 100644 --- a/testrig/transportcontroller.go +++ b/testrig/transportcontroller.go @@ -203,7 +203,7 @@ func NewMockHTTPClient(do func(req *http.Request) (*http.Response, error), relat responseContentLength = 0 } - log.Debugf("returning response %s", string(responseBytes)) + log.Debugf(nil, "returning response %s", string(responseBytes)) reader := bytes.NewReader(responseBytes) readCloser := io.NopCloser(reader) return &http.Response{ @@ -296,7 +296,7 @@ func WebfingerResponse(req *http.Request) (responseCode int, responseBytes []byt } if wfr == nil { - log.Debugf("webfinger response not available for %s", req.URL) + log.Debugf(nil, "webfinger response not available for %s", req.URL) responseCode = http.StatusNotFound responseBytes = []byte(`{"error":"not found"}`) responseContentType = applicationJSON diff --git a/web/template/404.tmpl b/web/template/404.tmpl index 3c1769210..bd38c824b 100644 --- a/web/template/404.tmpl +++ b/web/template/404.tmpl @@ -29,7 +29,8 @@

If you believe this 404 was an error, you can contact - the instance admin. + the instance admin. Provide them with the following request + Request ID: {{.requestID}}.

diff --git a/web/template/error.tmpl b/web/template/error.tmpl index eb5645c2a..9cc21b296 100644 --- a/web/template/error.tmpl +++ b/web/template/error.tmpl @@ -20,6 +20,7 @@
❌ 
{{.error}}
+ Request ID {{.requestID}}
{{ template "footer.tmpl" .}} \ No newline at end of file