diff --git a/cluster/logging.go b/cluster/logging.go new file mode 100644 index 00000000..553348e9 --- /dev/null +++ b/cluster/logging.go @@ -0,0 +1,33 @@ +/* +Copyright 2025 Dima Krasner + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package cluster + +import ( + "log/slog" + "os" + + "github.com/dimkr/tootik/logcontext" +) + +func init() { + opts := slog.HandlerOptions{ + Level: slog.LevelDebug, + AddSource: true, + } + + slog.SetDefault(slog.New(logcontext.NewHandler(slog.NewJSONHandler(os.Stderr, &opts)))) +} diff --git a/cmd/tootik/main.go b/cmd/tootik/main.go index b8bdaa3d..3c542d3a 100644 --- a/cmd/tootik/main.go +++ b/cmd/tootik/main.go @@ -49,6 +49,7 @@ import ( "github.com/dimkr/tootik/httpsig" "github.com/dimkr/tootik/icon" "github.com/dimkr/tootik/inbox" + "github.com/dimkr/tootik/logcontext" "github.com/dimkr/tootik/migrations" "github.com/dimkr/tootik/outbox" _ "github.com/mattn/go-sqlite3" @@ -141,7 +142,7 @@ func main() { opts.AddSource = true } - slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &opts))) + slog.SetDefault(slog.New(logcontext.NewHandler(slog.NewJSONHandler(os.Stderr, &opts)))) slog.SetLogLoggerLevel(slog.Level(*logLevel)) var blockList *fed.BlockList @@ -188,7 +189,7 @@ func main() { wg.Go(func() { select { case <-sigs: - slog.Info("Received termination signal") + slog.InfoContext(ctx, "Received termination signal") cancel() case <-ctx.Done(): } @@ -385,8 +386,8 @@ func main() { }, } { wg.Go(func() { - if err := svc.Listener.ListenAndServe(ctx); err != nil { - slog.Error("Listener has failed", "listener", svc.Name, "error", err) + if err := svc.Listener.ListenAndServe(logcontext.Add(ctx, "listener", svc.Name)); err != nil { + slog.ErrorContext(ctx, "Listener has failed", "listener", svc.Name, "error", err) } cancel() }) @@ -419,8 +420,8 @@ func main() { }, } { wg.Go(func() { - if err := queue.Queue.Process(ctx); err != nil { - slog.Error("Failed to process queue", "queue", queue.Name, "error", err) + if err := queue.Queue.Process(logcontext.Add(ctx, "queue", queue.Name)); err != nil { + slog.ErrorContext(ctx, "Failed to process queue", "queue", queue.Name, "error", err) } cancel() }) @@ -498,17 +499,19 @@ func main() { t := time.NewTicker(job.Interval) defer t.Stop() + jobCtx := logcontext.Add(ctx, "job", job.Name) + for { - slog.Info("Running periodic job", "job", job.Name) + slog.InfoContext(ctx, "Running periodic job", "job", job.Name) start := time.Now() - if err := job.Runner.Run(ctx); err != nil { - slog.Error("Periodic job has failed", "job", job.Name, "error", err) + if err := job.Runner.Run(jobCtx); err != nil { + slog.ErrorContext(ctx, "Periodic job has failed", "job", job.Name, "error", err) break } - slog.Info("Done running periodic job", "job", job.Name, "duration", time.Since(start).String()) + slog.InfoContext(ctx, "Done running periodic job", "job", job.Name, "duration", time.Since(start).String()) select { - case <-ctx.Done(): + case <-jobCtx.Done(): return case <-t.C: @@ -518,6 +521,6 @@ func main() { } <-ctx.Done() - slog.Info("Shutting down") + slog.InfoContext(ctx, "Shutting down") wg.Wait() } diff --git a/fed/activity.go b/fed/activity.go index 3f5c0dae..e82a4662 100644 --- a/fed/activity.go +++ b/fed/activity.go @@ -30,7 +30,7 @@ import ( func (l *Listener) handleActivity(w http.ResponseWriter, r *http.Request, prefix string) { activityID := fmt.Sprintf("https://%s/%s/%s", l.Domain, prefix, r.PathValue("hash")) - slog.Info("Fetching activity", "activity", activityID) + slog.InfoContext(r.Context(), "Fetching activity", "activity", activityID) var raw string var activity ap.Activity @@ -38,13 +38,13 @@ func (l *Listener) handleActivity(w http.ResponseWriter, r *http.Request, prefix w.WriteHeader(http.StatusNotFound) return } else if err != nil { - slog.Warn("Failed to fetch activity", "activity", activityID, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch activity", "activity", activityID, "error", err) w.WriteHeader(http.StatusInternalServerError) return } if !activity.IsPublic() { - slog.Warn("Refused attempt to fetch a non-public activity", "activity", activityID) + slog.WarnContext(r.Context(), "Refused attempt to fetch a non-public activity", "activity", activityID) w.WriteHeader(http.StatusNotFound) return } diff --git a/fed/apgateway.go b/fed/apgateway.go index d4d34323..e67cd1a4 100644 --- a/fed/apgateway.go +++ b/fed/apgateway.go @@ -42,7 +42,7 @@ func (l *Listener) handleAPGatewayPost(w http.ResponseWriter, r *http.Request) { m := inboxRegex.FindStringSubmatch(resource) if m == nil { - slog.Info("Invalid resource", "resource", resource) + slog.InfoContext(r.Context(), "Invalid resource", "resource", resource) w.WriteHeader(http.StatusNotFound) return } @@ -52,25 +52,25 @@ func (l *Listener) handleAPGatewayPost(w http.ResponseWriter, r *http.Request) { var actor ap.Actor var rsaPrivKeyPem, ed25519PrivKeyMultibase string if err := l.DB.QueryRowContext(r.Context(), `select json(actor), rsaprivkey, ed25519privkey from persons where cid = ? and ed25519privkey is not null`, receiver).Scan(&actor, &rsaPrivKeyPem, &ed25519PrivKeyMultibase); errors.Is(err, sql.ErrNoRows) { - slog.Debug("Receiving user does not exist", "receiver", receiver) + slog.DebugContext(r.Context(), "Receiving user does not exist", "receiver", receiver) w.WriteHeader(http.StatusNotFound) return } else if err != nil { - slog.Warn("Failed to check if receiving user exists", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to check if receiving user exists", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } rsaPrivKey, err := data.ParseRSAPrivateKey(rsaPrivKeyPem) if err != nil { - slog.Warn("Failed to parse RSA private key", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to parse RSA private key", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Warn("Failed to decode Ed25519 private key", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to decode Ed25519 private key", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -84,7 +84,7 @@ func (l *Listener) handleAPGatewayPost(w http.ResponseWriter, r *http.Request) { func (l *Listener) handleApGatewayFollowers(w http.ResponseWriter, r *http.Request, did string) { _, sender, err := l.verifyRequest(r, nil, ap.InstanceActor, l.ActorKeys) if err != nil { - slog.Warn("Failed to verify followers request", "error", err) + slog.WarnContext(r.Context(), "Failed to verify followers request", "error", err) w.WriteHeader(http.StatusUnauthorized) return } @@ -97,7 +97,7 @@ func (l *Listener) handleApGatewayFollowers(w http.ResponseWriter, r *http.Reque rows, err := l.DB.QueryContext(r.Context(), `SELECT follower FROM follows WHERE followed = 'https://' || ? || '/.well-known/apgateway/' || ? || '/actor' AND follower LIKE 'https://' || ? || '/%' AND accepted = 1`, l.Domain, did, u.Host) if err != nil { - slog.Warn("Failed to fetch followers", "did", did, "host", u.Host, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch followers", "did", did, "host", u.Host, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -107,7 +107,7 @@ func (l *Listener) handleApGatewayFollowers(w http.ResponseWriter, r *http.Reque for rows.Next() { var follower string if err := rows.Scan(&follower); err != nil { - slog.Warn("Failed to fetch followers", "did", did, "host", u.Host, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch followers", "did", did, "host", u.Host, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -116,7 +116,7 @@ func (l *Listener) handleApGatewayFollowers(w http.ResponseWriter, r *http.Reque defer rows.Close() if err := rows.Err(); err != nil { - slog.Warn("Failed to fetch followers", "did", did, "host", u.Host, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch followers", "did", did, "host", u.Host, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -128,12 +128,12 @@ func (l *Listener) handleApGatewayFollowers(w http.ResponseWriter, r *http.Reque "orderedItems": items, }) if err != nil { - slog.Warn("Failed to fetch followers", "did", did, "host", u.Host, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch followers", "did", did, "host", u.Host, "error", err) w.WriteHeader(http.StatusInternalServerError) return } - slog.Info("Received followers request", "sender", sender.ID, "did", did, "host", u.Host, "count", len(items.OrderedMap)) + slog.InfoContext(r.Context(), "Received followers request", "sender", sender.ID, "did", did, "host", u.Host, "count", len(items.OrderedMap)) w.Header().Set("Content-Type", `application/activity+json; charset=utf-8`) w.Write([]byte(collection)) @@ -149,14 +149,14 @@ func (l *Listener) handleAPGatewayGet(w http.ResponseWriter, r *http.Request) { id := portableObjectRegex.FindString(resource) if id == "" { - slog.Info("Invalid resource", "resource", resource) + slog.InfoContext(r.Context(), "Invalid resource", "resource", resource) w.WriteHeader(http.StatusNotFound) return } id = "ap://" + id - slog.Info("Fetching object", "id", id) + slog.InfoContext(r.Context(), "Fetching object", "id", id) var raw string if err := l.DB.QueryRowContext( @@ -180,11 +180,11 @@ func (l *Listener) handleAPGatewayGet(w http.ResponseWriter, r *http.Request) { id, ap.Public, ).Scan(&raw); errors.Is(err, sql.ErrNoRows) { - slog.Info("Notifying about missing object", "id", id) + slog.InfoContext(r.Context(), "Notifying about missing object", "id", id) w.WriteHeader(http.StatusNotFound) return } else if err != nil { - slog.Warn("Failed to fetch object", "id", id, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch object", "id", id, "error", err) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/fed/deliver.go b/fed/deliver.go index c8c34860..225ac9f1 100644 --- a/fed/deliver.go +++ b/fed/deliver.go @@ -34,6 +34,7 @@ import ( "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/data" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" ) type Queue struct { @@ -77,7 +78,7 @@ func (q *Queue) Process(ctx context.Context) error { case <-t.C: if _, err := q.ProcessBatch(ctx); err != nil { - slog.Error("Failed to deliver posts", "error", err) + slog.ErrorContext(ctx, "Failed to deliver posts", "error", err) } } } @@ -85,7 +86,7 @@ func (q *Queue) Process(ctx context.Context) error { // ProcessBatch delivers one batch of outgoing activites in the queue. func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { - slog.Debug("Polling delivery queue") + slog.DebugContext(ctx, "Polling delivery queue") rows, err := q.DB.QueryContext( ctx, @@ -160,10 +161,10 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { &rsaPrivKeyPem, &ed25519PrivKeyMultibase, ); err != nil { - slog.Error("Failed to fetch post to deliver", "error", err) + slog.ErrorContext(ctx, "Failed to fetch post to deliver", "error", err) continue } else if len(actor.AssertionMethod) == 0 { - slog.Error("Actor has no Ed25519 key", "error", err) + slog.ErrorContext(ctx, "Actor has no Ed25519 key", "error", err) continue } @@ -171,13 +172,13 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { rsaPrivKey, err := data.ParseRSAPrivateKey(rsaPrivKeyPem) if err != nil { - slog.Error("Failed to parse RSA private key", "error", err) + slog.ErrorContext(ctx, "Failed to parse RSA private key", "error", err) continue } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Error("Failed to decode Ed25519 private key", "error", err) + slog.ErrorContext(ctx, "Failed to decode Ed25519 private key", "error", err) continue } @@ -193,7 +194,7 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { ap.Canonical(activity.ID), actor.ID, ); err != nil { - slog.Error("Failed to save last delivery attempt time", "id", activity.ID, "attempts", deliveryAttempts, "error", err) + slog.ErrorContext(ctx, "Failed to save last delivery attempt time", "id", activity.ID, "attempts", deliveryAttempts, "error", err) continue } @@ -215,7 +216,7 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { tasks, events, ); err != nil { - slog.Warn("Failed to queue activity for delivery", "id", activity.ID, "attempts", deliveryAttempts, "error", err) + slog.WarnContext(ctx, "Failed to queue activity for delivery", "id", activity.ID, "attempts", deliveryAttempts, "error", err) } } @@ -233,7 +234,7 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { // receive and save job results for job, done := range <-results { if !done { - slog.Info("Failed to deliver an activity to at least one recipient", "id", job.Activity.ID) + slog.InfoContext(ctx, "Failed to deliver an activity to at least one recipient", "id", job.Activity.ID) continue } @@ -243,9 +244,9 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { ap.Canonical(job.Activity.ID), job.Sender.ID, ); err != nil { - slog.Error("Failed to mark delivery as completed", "id", job.Activity.ID, "error", err) + slog.ErrorContext(ctx, "Failed to mark delivery as completed", "id", job.Activity.ID, "error", err) } else { - slog.Info("Successfully delivered an activity to all recipients", "id", job.Activity.ID) + slog.InfoContext(ctx, "Successfully delivered an activity to all recipients", "id", job.Activity.ID) } } @@ -265,7 +266,7 @@ func (q *Queue) deliverWithTimeout(parent context.Context, task deliveryTask) er return err } -func (q *Queue) consume(ctx context.Context, requests <-chan deliveryTask, events chan<- deliveryEvent) { +func (q *Queue) consume(parent context.Context, requests <-chan deliveryTask, events chan<- deliveryEvent) { tried := map[string]map[string]struct{}{} for task := range requests { @@ -279,6 +280,8 @@ func (q *Queue) consume(ctx context.Context, requests <-chan deliveryTask, event tried[task.Job.Activity.ID] = map[string]struct{}{task.Request.Host: {}} } + ctx := logcontext.Add(parent, slog.Group("delivery", "sender", task.Job.Sender.ID, "inbox", task.Inbox, "activity", task.Job.Activity.ID)) + var delivered int if err := q.DB.QueryRowContext( ctx, @@ -286,22 +289,22 @@ func (q *Queue) consume(ctx context.Context, requests <-chan deliveryTask, event ap.Canonical(task.Job.Activity.ID), task.Request.Host, ).Scan(&delivered); err != nil { - slog.Error("Failed to check if delivered already", "inbox", task.Inbox, "activity", task.Job.Activity.ID, "error", err) + slog.ErrorContext(ctx, "Failed to check if delivered already", "error", err) events <- deliveryEvent{task.Job, false} continue } if delivered == 1 { - slog.Info("Skipping recipient", "inbox", task.Inbox, "activity", task.Job.Activity.ID) + slog.InfoContext(ctx, "Skipping recipient") continue } - slog.Info("Delivering activity to recipient", "inbox", task.Inbox, "activity", task.Job.Activity.ID) + slog.InfoContext(ctx, "Delivering activity to recipient") if err := q.deliverWithTimeout(ctx, task); err == nil { - slog.Info("Successfully sent an activity", "from", task.Job.Sender.ID, "inbox", task.Inbox, "activity", task.Job.Activity.ID) + slog.InfoContext(ctx, "Successfully sent an activity") } else { - slog.Warn("Failed to send an activity", "from", task.Job.Sender.ID, "inbox", task.Inbox, "activity", task.Job.Activity.ID, "error", err) + slog.WarnContext(ctx, "Failed to send an activity", "error", err) if !errors.Is(err, ErrBlockedDomain) { events <- deliveryEvent{task.Job, false} } @@ -315,7 +318,7 @@ func (q *Queue) consume(ctx context.Context, requests <-chan deliveryTask, event ap.Canonical(task.Job.Activity.ID), task.Request.Host, ); err != nil { - slog.Error("Failed to record delivery", "activity", task.Job.Activity.ID, "inbox", task.Inbox, "error", err) + slog.ErrorContext(ctx, "Failed to record delivery", "to", task.Inbox, "error", err) events <- deliveryEvent{task.Job, false} } } @@ -330,15 +333,17 @@ func (q *Queue) queueTask( tasks []chan deliveryTask, events chan<- deliveryEvent, ) { + ctx = logcontext.Add(ctx, slog.Group("task", "activity", job.Activity.ID, "inbox", inbox)) + req, err := http.NewRequest(http.MethodPost, inbox, strings.NewReader(job.RawActivity)) if err != nil { - slog.Warn("Failed to create new request", "inbox", inbox, "activity", job.Activity.ID, "inbox", inbox, "error", err) + slog.WarnContext(ctx, "Failed to create new request", "error", err) events <- deliveryEvent{job, false} return } if req.URL.Host == q.Domain { - slog.Debug("Skipping local recipient inbox", "inbox", inbox, "activity", job.Activity.ID, "inbox", inbox) + slog.DebugContext(ctx, "Skipping local recipient inbox") return } @@ -349,11 +354,11 @@ func (q *Queue) queueTask( if digest, err := followers.Digest(ctx, q.DB, q.Domain, job.Sender, req.URL.Host); err == nil { req.Header.Set("Collection-Synchronization", digest) } else { - slog.Warn("Failed to digest followers", "inbox", inbox, "activity", job.Activity.ID, "inbox", inbox, "error", err) + slog.WarnContext(ctx, "Failed to digest followers", "error", err) } } - slog.Info("Queueing activity for delivery", "inbox", inbox, "activity", job.Activity.ID) + slog.InfoContext(ctx, "Queueing activity for delivery") // assign a task to a random worker but use one worker per inbox, so activities are delivered once per inbox tasks[crc32.ChecksumIEEE([]byte(inbox))%uint32(len(tasks))] <- deliveryTask{ @@ -377,6 +382,8 @@ func (q *Queue) queueTasks( return err } + ctx = logcontext.Add(ctx, slog.Group("job", "activity", job.Activity.ID, "sender", job.Sender.ID)) + recipients := ap.Audience{} // deduplicate recipients or skip if we're forwarding an activity @@ -410,12 +417,12 @@ func (q *Queue) queueTasks( fmt.Sprintf("https://%s/%%", activityID.Host), ) if err != nil { - slog.Warn("Failed to list followers", "activity", job.Activity.ID, "error", err) + slog.WarnContext(ctx, "Failed to list followers", "error", err) } else { for inboxes.Next() { var inbox string if err := inboxes.Scan(&inbox); err != nil { - slog.Warn("Skipped an inbox", "activity", job.Activity.ID, "error", err) + slog.WarnContext(ctx, "Skipped an inbox", "error", err) continue } @@ -443,13 +450,13 @@ func (q *Queue) queueTasks( // assume that all other federated recipients are actors and not collections for actorID := range recipients.Keys() { if ap.Canonical(actorID) == author || actorID == ap.Public || actorID == job.Sender.Followers { - slog.Debug("Skipping recipient", "to", actorID, "activity", job.Activity.ID) + slog.DebugContext(ctx, "Skipping recipient", "to", actorID) continue } to, err := q.Resolver.ResolveID(ctx, keys, actorID, ap.Offline) if err != nil { - slog.Warn("Failed to resolve a recipient", "to", actorID, "activity", job.Activity.ID, "error", err) + slog.WarnContext(ctx, "Failed to resolve a recipient", "to", actorID, "error", err) if !errors.Is(err, ErrActorGone) && !errors.Is(err, ErrBlockedDomain) { events <- deliveryEvent{job, false} } @@ -460,7 +467,7 @@ func (q *Queue) queueTasks( inbox := to.Inbox if wideDelivery { if sharedInbox, ok := to.Endpoints["sharedInbox"]; ok && sharedInbox != "" { - slog.Debug("Using shared inbox", "to", actorID, "activity", job.Activity.ID, "shared_inbox", inbox) + slog.DebugContext(ctx, "Using shared inbox", "to", actorID, "shared_inbox", inbox) inbox = sharedInbox } } @@ -480,7 +487,7 @@ func (q *Queue) queueTasks( // if this is an activity by a portable actor, forward it to all gateways if ap.IsPortable(job.Sender.ID) && len(job.Sender.Gateways) > 1 { for _, gw := range job.Sender.Gateways[1:] { - slog.Info("Forwarding activity to gateway", "activity", job.Activity.ID, "sender", job.Sender.ID, "gateway", gw) + slog.InfoContext(ctx, "Forwarding activity to gateway", "gateway", gw) q.queueTask( ctx, diff --git a/fed/followers.go b/fed/followers.go index 87ef11d6..176f7caa 100644 --- a/fed/followers.go +++ b/fed/followers.go @@ -130,7 +130,7 @@ func (l *Listener) handleFollowers(w http.ResponseWriter, r *http.Request) { _, sender, err := l.verifyRequest(r, nil, ap.InstanceActor, l.ActorKeys) if err != nil { - slog.Warn("Failed to verify followers request", "error", err) + slog.WarnContext(r.Context(), "Failed to verify followers request", "error", err) w.WriteHeader(http.StatusUnauthorized) return } @@ -171,7 +171,7 @@ func (l *Listener) handleFollowers(w http.ResponseWriter, r *http.Request) { return } - slog.Info("Received followers request", "sender", sender.ID, "username", name, "host", u.Host, "count", len(items.OrderedMap)) + slog.InfoContext(r.Context(), "Received followers request", "sender", sender.ID, "username", name, "host", u.Host, "count", len(items.OrderedMap)) w.Header().Set("Content-Type", `application/activity+json; charset=utf-8`) w.Write([]byte(collection)) @@ -237,7 +237,7 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf if digest, err := digestFollowers(ctx, db, d.Followed, domain); err != nil { return err } else if digest == d.Digest { - slog.Debug("Follower collections are synchronized", "followed", d.Followed) + slog.DebugContext(ctx, "Follower collections are synchronized", "followed", d.Followed) return nil } @@ -246,7 +246,7 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf return err } - slog.Info("Synchronizing followers", "followed", d.Followed) + slog.InfoContext(ctx, "Synchronizing followers", "followed", d.Followed) resp, err := resolver.Get(ctx, keys, d.URL) if err != nil { @@ -270,7 +270,7 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf continue } - slog.Info("Found unknown local follow", "followed", d.Followed, "follower", follower) + slog.InfoContext(ctx, "Found unknown local follow", "followed", d.Followed, "follower", follower) if _, err := db.ExecContext( ctx, @@ -278,7 +278,7 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf follower, d.Followed, ); err != nil { - slog.Warn("Failed to remove local follow", "followed", d.Followed, "follower", follower, "error", err) + slog.WarnContext(ctx, "Failed to remove local follow", "followed", d.Followed, "follower", follower, "error", err) } } @@ -293,15 +293,15 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf continue } - slog.Info("Found unknown remote follow", "followed", d.Followed, "follower", follower) + slog.InfoContext(ctx, "Found unknown remote follow", "followed", d.Followed, "follower", follower) var actor ap.Actor var ed25519PrivKeyMultibase string if err := db.QueryRowContext(ctx, `SELECT JSON(persons.actor), persons.ed25519privkey FROM persons WHERE id = ? AND persons.ed25519privkey IS NOT NULL`, follower).Scan(&actor, &ed25519PrivKeyMultibase); errors.Is(err, sql.ErrNoRows) { - slog.Info("Follower does not exist", "followed", d.Followed, "follower", follower) + slog.InfoContext(ctx, "Follower does not exist", "followed", d.Followed, "follower", follower) continue } else if err != nil { - slog.Warn("Failed to fetch actor of unknown remote follow", "followed", d.Followed, "follower", follower, "error", err) + slog.WarnContext(ctx, "Failed to fetch actor of unknown remote follow", "followed", d.Followed, "follower", follower, "error", err) continue } @@ -309,23 +309,23 @@ func (d *followersDigest) Sync(ctx context.Context, domain string, cfg *cfg.Conf if err := db.QueryRowContext(ctx, `SELECT id FROM follows WHERE follower = ? AND followed = ?`, follower, d.Followed).Scan(&followID); err != nil && errors.Is(err, sql.ErrNoRows) { followID, err = d.Inbox.NewID(actor.ID, "follow") if err != nil { - slog.Warn("Failed to generate fake follow ID", "followed", d.Followed, "follower", follower, "error", err) + slog.WarnContext(ctx, "Failed to generate fake follow ID", "followed", d.Followed, "follower", follower, "error", err) continue } - slog.Warn("Using fake follow ID to remove unknown remote follow", "followed", d.Followed, "follower", follower, "id", followID) + slog.WarnContext(ctx, "Using fake follow ID to remove unknown remote follow", "followed", d.Followed, "follower", follower, "id", followID) } else if err != nil { - slog.Warn("Failed to fetch follow ID of unknown remote follow", "followed", d.Followed, "follower", follower, "error", err) + slog.WarnContext(ctx, "Failed to fetch follow ID of unknown remote follow", "followed", d.Followed, "follower", follower, "error", err) continue } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Error("Failed to decode Ed25519 private key", "followed", d.Followed, "follower", follower, "error", err) + slog.ErrorContext(ctx, "Failed to decode Ed25519 private key", "followed", d.Followed, "follower", follower, "error", err) continue } if err := d.Inbox.Unfollow(ctx, &actor, httpsig.Key{ID: actor.AssertionMethod[0].ID, PrivateKey: ed25519PrivKey}, d.Followed, followID); err != nil { - slog.Warn("Failed to remove remote follow", "followed", d.Followed, "follower", follower, "error", err) + slog.WarnContext(ctx, "Failed to remove remote follow", "followed", d.Followed, "follower", follower, "error", err) } } @@ -354,7 +354,7 @@ func (s *Syncer) ProcessBatch(ctx context.Context) (int, error) { Inbox: s.Inbox, } if err := rows.Scan(&job.Followed, &job.URL, &job.Digest); err != nil { - slog.Error("Failed to scan digest", "error", err) + slog.ErrorContext(ctx, "Failed to scan digest", "error", err) continue } jobs = append(jobs, job) @@ -363,7 +363,7 @@ func (s *Syncer) ProcessBatch(ctx context.Context) (int, error) { for _, job := range jobs { if err := job.Sync(ctx, s.Domain, s.Config, s.DB, s.Resolver, s.Keys); err != nil { - slog.Warn("Failed to sync followers", "actor", job.Followed, "error", err) + slog.WarnContext(ctx, "Failed to sync followers", "actor", job.Followed, "error", err) } if _, err := s.DB.ExecContext(ctx, `UPDATE follows_sync SET changed = UNIXEPOCH() WHERE actor = ?`, job.Followed); err != nil { diff --git a/fed/icon.go b/fed/icon.go index eebb5c5c..85bc92b7 100644 --- a/fed/icon.go +++ b/fed/icon.go @@ -34,15 +34,15 @@ func (l *Listener) handleIcon(w http.ResponseWriter, r *http.Request) { } name = name[:len(name)-len(icon.FileNameExtension)] - slog.Info("Looking up cached icon", "name", name) + slog.InfoContext(r.Context(), "Looking up cached icon", "name", name) var cache []byte if err := l.DB.QueryRowContext(r.Context(), `select buf from icons where name = ?`, name).Scan(&cache); err != nil && !errors.Is(err, sql.ErrNoRows) { - slog.Warn("Failed to get cached icon", "name", name, "error", err) + slog.WarnContext(r.Context(), "Failed to get cached icon", "name", name, "error", err) w.WriteHeader(http.StatusInternalServerError) return } else if len(cache) > 0 { - slog.Debug("Sending cached icon", "name", name) + slog.DebugContext(r.Context(), "Sending cached icon", "name", name) w.Header().Set("Content-Type", icon.MediaType) w.Write(cache) return @@ -50,27 +50,27 @@ func (l *Listener) handleIcon(w http.ResponseWriter, r *http.Request) { var exists int if err := l.DB.QueryRowContext(r.Context(), `select exists (select 1 from persons where actor->>'$.preferredUsername' = ? and host = ?)`, name, l.Domain).Scan(&exists); err != nil { - slog.Warn("Failed to check if user exists", "name", name, "error", err) + slog.WarnContext(r.Context(), "Failed to check if user exists", "name", name, "error", err) w.WriteHeader(http.StatusInternalServerError) return } if exists == 0 { - slog.Warn("No icon for non-existing user", "name", name) + slog.WarnContext(r.Context(), "No icon for non-existing user", "name", name) w.WriteHeader(http.StatusNotFound) return } - slog.Info("Generating an icon", "name", name) + slog.InfoContext(r.Context(), "Generating an icon", "name", name) buf, err := icon.Generate(name) if err != nil { - slog.Warn("Failed to generate icon", "name", name, "error", err) + slog.WarnContext(r.Context(), "Failed to generate icon", "name", name, "error", err) w.WriteHeader(http.StatusInternalServerError) return } if _, err := l.DB.ExecContext(r.Context(), `insert into icons(name, buf) values(?,?)`, name, buf); err != nil { - slog.Warn("Failed to cache icon", "name", name, "error", err) + slog.WarnContext(r.Context(), "Failed to cache icon", "name", name, "error", err) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/fed/inbox.go b/fed/inbox.go index 644645a2..5fd0bea4 100644 --- a/fed/inbox.go +++ b/fed/inbox.go @@ -31,6 +31,7 @@ import ( "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/data" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" "github.com/dimkr/tootik/proof" ) @@ -65,7 +66,7 @@ func (l *Listener) getActivityOrigin(activity *ap.Activity, sender *ap.Actor) (s return activityOrigin, senderOrigin, nil } -func (l *Listener) validateActivity(activity *ap.Activity, origin string, depth uint) error { +func (l *Listener) validateActivity(ctx context.Context, activity *ap.Activity, origin string, depth uint) error { if depth == ap.MaxActivityDepth { return errors.New("activity is too nested") } @@ -74,7 +75,7 @@ func (l *Listener) validateActivity(activity *ap.Activity, origin string, depth return errors.New("invalid origin") } - slog.Debug("Validating activity origin", "activity", activity, "origin", origin, "depth", depth) + slog.DebugContext(ctx, "Validating activity origin", "activity", activity, "origin", origin, "depth", depth) if activity.ID == "" { return errors.New("unspecified activity ID") @@ -165,7 +166,7 @@ func (l *Listener) validateActivity(activity *ap.Activity, origin string, depth } // $origin can only undo actions performed by actors from $origin - if err := l.validateActivity(inner, origin, depth+1); err != nil { + if err := l.validateActivity(ctx, inner, origin, depth+1); err != nil { return err } } else { @@ -284,25 +285,25 @@ func (l *Listener) handleInbox(w http.ResponseWriter, r *http.Request) { var actor ap.Actor var rsaPrivKeyPem, ed25519PrivKeyMultibase string if err := l.DB.QueryRowContext(r.Context(), `select json(actor), rsaprivkey, ed25519privkey from persons where actor->>'$.preferredUsername' = ? and ed25519privkey is not null`, receiver).Scan(&actor, &rsaPrivKeyPem, &ed25519PrivKeyMultibase); errors.Is(err, sql.ErrNoRows) { - slog.Debug("Receiving user does not exist", "receiver", receiver) + slog.DebugContext(r.Context(), "Receiving user does not exist", "receiver", receiver) w.WriteHeader(http.StatusNotFound) return } else if err != nil { - slog.Warn("Failed to check if receiving user exists", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to check if receiving user exists", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } rsaPrivKey, err := data.ParseRSAPrivateKey(rsaPrivKeyPem) if err != nil { - slog.Warn("Failed to parse RSA private key", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to parse RSA private key", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Warn("Failed to decode Ed25519 private key", "receiver", receiver, "error", err) + slog.WarnContext(r.Context(), "Failed to decode Ed25519 private key", "receiver", receiver, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -315,7 +316,7 @@ func (l *Listener) handleInbox(w http.ResponseWriter, r *http.Request) { func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2]httpsig.Key) { if r.ContentLength > l.Config.MaxRequestBodySize { - slog.Warn("Ignoring big request", "size", r.ContentLength) + slog.WarnContext(r.Context(), "Ignoring big request", "size", r.ContentLength) w.WriteHeader(http.StatusRequestEntityTooLarge) return } @@ -328,11 +329,13 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 var activity ap.Activity if err := json.Unmarshal(rawActivity, &activity); err != nil { - slog.Warn("Failed to unmarshal activity", "body", string(rawActivity), "error", err) + slog.WarnContext(r.Context(), "Failed to unmarshal activity", "body", string(rawActivity), "error", err) w.WriteHeader(http.StatusInternalServerError) return } + r = r.WithContext(logcontext.Add(r.Context(), "activity", &activity)) + r.Body = io.NopCloser(bytes.NewReader(rawActivity)) // if actor is deleted, ignore this activity if we don't know this actor @@ -347,14 +350,14 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 // if activity has an integrity proof, pretend it was sent by its actor even if forwarded by another sender, err = l.verifyProof(r.Context(), activity.Proof, &activity, rawActivity, flags, keys) if err != nil { - slog.Warn("Failed to verify integrity proof", "activity", &activity, "proof", &activity.Proof, "error", err) + slog.WarnContext(r.Context(), "Failed to verify integrity proof", "proof", &activity.Proof, "error", err) w.WriteHeader(http.StatusUnauthorized) w.Header().Set("Content-Type", "application/json") json.NewEncoder(w).Encode(map[string]any{"error": err.Error()}) return } } else if ap.IsPortable(activity.ID) { - slog.Warn("Portable activity has no integrity proof", "activity", &activity) + slog.WarnContext(r.Context(), "Portable activity has no integrity proof") w.WriteHeader(http.StatusUnauthorized) w.Header().Set("Content-Type", "application/json") json.NewEncoder(w).Encode(map[string]any{"error": "integrity proof is required"}) @@ -368,15 +371,15 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } if errors.Is(err, ErrActorNotCached) { - slog.Debug("Ignoring Delete activity for unknown actor", "error", err) + slog.DebugContext(r.Context(), "Ignoring Delete activity for unknown actor", "error", err) w.WriteHeader(http.StatusAccepted) return } if errors.Is(err, ErrBlockedDomain) { - slog.Debug("Failed to verify activity", "activity", &activity, "error", err) + slog.DebugContext(r.Context(), "Failed to verify activity", "error", err) } else { - slog.Warn("Failed to verify activity", "activity", &activity, "error", err) + slog.WarnContext(r.Context(), "Failed to verify activity", "error", err) } w.WriteHeader(http.StatusUnauthorized) @@ -387,6 +390,8 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } } + r = r.WithContext(logcontext.Add(r.Context(), "sender", sender.ID)) + /* we have 4 activities: 1. the one we received, in its JSON form (rawActivity): we need it in case we're going to forward it @@ -408,7 +413,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 if inner, ok := queued.Object.(*ap.Activity); ok { queued = inner } else if o, ok := queued.Object.(*ap.Object); ok { - slog.Debug("Wrapping object with Update activity", "activity", &activity, "sender", sender.ID, "object", o.ID) + slog.DebugContext(r.Context(), "Wrapping object with Update activity", "object", o.ID) // hack for Lemmy: wrap a Page inside Announce with Update queued = &ap.Activity{ @@ -425,7 +430,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } if _, ok := unsupportedActivityTypes[queued.Type]; ok { - slog.Debug("Ignoring unsupported activity", "activity", &activity, "sender", sender.ID) + slog.DebugContext(r.Context(), "Ignoring unsupported activity") w.WriteHeader(http.StatusAccepted) return } @@ -436,20 +441,22 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 */ origin, senderOrigin, err := l.getActivityOrigin(queued, sender) if err != nil { - slog.Warn("Failed to determine whether or not activity is forwarded", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Failed to determine whether or not activity is forwarded", "error", err) w.WriteHeader(http.StatusInternalServerError) return } + r = r.WithContext(logcontext.Add(r.Context(), "origin", origin)) + forwarded := origin != senderOrigin /* if we don't support this activity or it's invalid, we don't want to fetch it (we validate again later) */ - if err := l.validateActivity(queued, origin, 0); errors.Is(err, ap.ErrUnsupportedActivity) { - slog.Debug("Activity is unsupported", "activity", &activity, "sender", sender.ID, "error", err) + if err := l.validateActivity(r.Context(), queued, origin, 0); errors.Is(err, ap.ErrUnsupportedActivity) { + slog.DebugContext(r.Context(), "Activity is unsupported", "error", err) w.WriteHeader(http.StatusAccepted) return } else if err != nil { - slog.Warn("Activity is invalid", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Activity is invalid", "error", err) w.WriteHeader(http.StatusBadRequest) return } else if forwarded { @@ -462,13 +469,13 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 case string: id = o default: - slog.Warn("Ignoring invalid forwarded Delete activity", "activity", &activity, "sender", sender.ID) + slog.WarnContext(r.Context(), "Ignoring invalid forwarded Delete activity") w.WriteHeader(http.StatusBadRequest) return } } - slog.Info("Fetching forwarded object", "activity", &activity, "id", id, "sender", sender.ID) + slog.InfoContext(r.Context(), "Fetching forwarded object", "id", id) if exists, fetched, err := l.fetchObject(r.Context(), id, keys); !exists && queued.Type == ap.Delete { queued = &ap.Activity{ @@ -480,17 +487,17 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } else if err == nil && exists && queued.Type == ap.Delete { var parsed ap.Object if err := json.Unmarshal([]byte(fetched), &parsed); err != nil { - slog.Warn("Ignoring invalid forwarded Delete activity", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Ignoring invalid forwarded Delete activity", "error", err) w.WriteHeader(http.StatusBadRequest) return } else if parsed.Type != ap.Tombstone { - slog.Warn("Ignoring forwarded Delete activity for existing object", "activity", &activity, "id", id, "sender", sender.ID) + slog.WarnContext(r.Context(), "Ignoring forwarded Delete activity for existing object", "id", id) w.WriteHeader(http.StatusBadRequest) return } // hack for Mastodon: a deleted Note is replaced with a Tombstone - slog.Debug("Wrapping Tombstone with Delete", "activity", &activity, "sender", sender.ID) + slog.DebugContext(r.Context(), "Wrapping Tombstone with Delete") queued = &ap.Activity{ ID: queued.ID, Type: ap.Delete, @@ -498,7 +505,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 Object: &parsed, } } else if err != nil { - slog.Warn("Failed to fetch forwarded object", "activity", &activity, "id", id, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch forwarded object", "id", id, "error", err) w.WriteHeader(http.StatusInternalServerError) return } else if queued.Type == ap.Update { @@ -507,12 +514,12 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 // hack for Mastodon: we get the updated Note when we fetch an Update activity var post ap.Object if err := json.Unmarshal([]byte(fetched), &post); err != nil { - slog.Warn("Ignoring invalid forwarded Update activity", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Ignoring invalid forwarded Update activity", "error", err) w.WriteHeader(http.StatusBadRequest) return } - slog.Debug("Wrapping forwarded Update activity", "activity", &activity, "sender", sender.ID) + slog.DebugContext(r.Context(), "Wrapping forwarded Update activity") queued = &ap.Activity{ ID: queued.ID, Type: ap.Update, @@ -525,7 +532,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } else { var parsed ap.Activity if err := json.Unmarshal([]byte(fetched), &parsed); err != nil { - slog.Warn("Ignoring invalid forwarded activity", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Ignoring invalid forwarded activity", "error", err) w.WriteHeader(http.StatusBadRequest) return } @@ -534,12 +541,12 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 } // we must validate the original activity because the forwarded one can be valid while the original isn't - if err := l.validateActivity(queued, origin, 0); errors.Is(err, ap.ErrUnsupportedActivity) { - slog.Debug("Activity is unsupported", "activity", &activity, "sender", sender.ID, "error", err) + if err := l.validateActivity(r.Context(), queued, origin, 0); errors.Is(err, ap.ErrUnsupportedActivity) { + slog.DebugContext(r.Context(), "Activity is unsupported", "error", err) w.WriteHeader(http.StatusAccepted) return } else if err != nil { - slog.Warn("Activity is invalid", "activity", &activity, "sender", sender.ID, "error", err) + slog.WarnContext(r.Context(), "Activity is invalid", "error", err) w.WriteHeader(http.StatusBadRequest) return } @@ -552,7 +559,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 queued, string(rawActivity), ); err != nil { - slog.Error("Failed to insert activity", "sender", sender.ID, "error", err) + slog.ErrorContext(r.Context(), "Failed to insert activity", "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -560,7 +567,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 followersSync := r.Header.Get("Collection-Synchronization") if followersSync != "" { if err := l.saveFollowersDigest(r.Context(), sender, followersSync); err != nil { - slog.Warn("Failed to save followers sync header", "sender", sender.ID, "header", followersSync, "error", err) + slog.WarnContext(r.Context(), "Failed to save followers sync header", "header", followersSync, "error", err) } } @@ -592,7 +599,7 @@ func (l *Listener) doHandleInbox(w http.ResponseWriter, r *http.Request, keys [2 senderOrigin, capabilities, ); err != nil { - slog.Error("Failed to record server capabilities", "server", senderOrigin, "error", err) + slog.ErrorContext(r.Context(), "Failed to record server capabilities", "server", senderOrigin, "error", err) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/fed/listener.go b/fed/listener.go index acb5295b..5b2b0586 100644 --- a/fed/listener.go +++ b/fed/listener.go @@ -31,6 +31,7 @@ import ( "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" "github.com/fsnotify/fsnotify" ) @@ -47,8 +48,20 @@ type Listener struct { Plain bool } +type loggingHandler struct { + inner http.Handler +} + const certReloadDelay = time.Second * 5 +func (h loggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + h.inner.ServeHTTP(w, r.WithContext(logcontext.Add(r.Context(), slog.Group("http_request", "path", r.URL.String())))) +} + +func withLogging(h http.Handler) http.Handler { + return &loggingHandler{inner: h} +} + // NewHandler returns a [http.Handler] that handles ActivityPub requests. func (l *Listener) NewHandler() (http.Handler, error) { mux := http.NewServeMux() @@ -68,7 +81,7 @@ func (l *Listener) NewHandler() (http.Handler, error) { mux.HandleFunc("GET /{$}", l.handleIndex) mux.HandleFunc("GET /", func(w http.ResponseWriter, r *http.Request) { - slog.Debug("Received request to non-existing path", "path", r.URL.Path) + slog.DebugContext(r.Context(), "Received request to non-existing path", "path", r.URL.Path) w.WriteHeader(http.StatusNotFound) }) @@ -78,7 +91,7 @@ func (l *Listener) NewHandler() (http.Handler, error) { addHostMeta(mux, l.Domain) - return mux, nil + return withLogging(mux), nil } // ListenAndServe handles HTTP requests from other servers. @@ -133,7 +146,7 @@ func (l *Listener) ListenAndServe(ctx context.Context) error { // shut down gracefully only on reload if ctx.Err() == nil { - slog.Info("Shutting down server") + slog.InfoContext(ctx, "Shutting down server") server.Shutdown(ctx) } @@ -155,7 +168,7 @@ func (l *Listener) ListenAndServe(ctx context.Context) error { } if (event.Has(fsnotify.Write) || event.Has(fsnotify.Create)) && (event.Name == certAbsPath || event.Name == keyAbsPath) { - slog.Info("Stopping server: file has changed", "name", event.Name) + slog.InfoContext(ctx, "Stopping server: file has changed", "name", event.Name) timer.Reset(certReloadDelay) } @@ -168,7 +181,7 @@ func (l *Listener) ListenAndServe(ctx context.Context) error { } }) - slog.Info("Starting server") + slog.InfoContext(ctx, "Starting server") var err error if l.Plain { err = server.ListenAndServe() diff --git a/fed/nodeinfo.go b/fed/nodeinfo.go index 802b817f..e858af61 100644 --- a/fed/nodeinfo.go +++ b/fed/nodeinfo.go @@ -95,7 +95,7 @@ func addNodeInfo(mux *http.ServeMux, domain string, closed bool, cfg *cfg.Config mux.HandleFunc("GET /nodeinfo/2.0", func(w http.ResponseWriter, r *http.Request) { if err := l.Lock(r.Context()); err != nil { - slog.Warn("Failed to build nodeinfo response", "error", err) + slog.WarnContext(r.Context(), "Failed to build nodeinfo response", "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -128,7 +128,7 @@ func addNodeInfo(mux *http.ServeMux, domain string, closed bool, cfg *cfg.Config `, domain, ).Scan(&total, &activeHalfYear, &activeMonth, &localPosts); err != nil { - slog.Warn("Failed to build nodeinfo response", "error", err) + slog.WarnContext(r.Context(), "Failed to build nodeinfo response", "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -160,7 +160,7 @@ func addNodeInfo(mux *http.ServeMux, domain string, closed bool, cfg *cfg.Config "openRegistrations": !closed, "metadata": map[string]any{}, }); err != nil { - slog.Warn("Failed to build nodeinfo response", "error", err) + slog.WarnContext(r.Context(), "Failed to build nodeinfo response", "error", err) w.WriteHeader(http.StatusInternalServerError) } else { w.Header().Set("Content-Type", "application/json") diff --git a/fed/outbox.go b/fed/outbox.go index 0347a67e..1346d9bf 100644 --- a/fed/outbox.go +++ b/fed/outbox.go @@ -17,6 +17,7 @@ limitations under the License. package fed import ( + "context" "database/sql" "encoding/json" "fmt" @@ -28,7 +29,7 @@ import ( "github.com/dimkr/tootik/ap" ) -func (l *Listener) getCollection(w http.ResponseWriter, username string) { +func (l *Listener) getCollection(ctx context.Context, w http.ResponseWriter, username string) { first := fmt.Sprintf("https://%s/outbox/%s?0", l.Domain, username) collection := map[string]any{ @@ -40,11 +41,11 @@ func (l *Listener) getCollection(w http.ResponseWriter, username string) { "totalItems": 0, } - slog.Info("Listing activities by user", "username", username) + slog.InfoContext(ctx, "Listing activities by user", "username", username) j, err := json.Marshal(collection) if err != nil { - slog.Warn("Failed to marshal collection", "username", username, "error", err) + slog.WarnContext(ctx, "Failed to marshal collection", "username", username, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -58,7 +59,7 @@ func (l *Listener) handleOutbox(w http.ResponseWriter, r *http.Request) { var actorID sql.NullString if err := l.DB.QueryRowContext(r.Context(), `select id from persons where actor->>'$.preferredUsername' = ? and host = ?`, username, l.Domain).Scan(&actorID); err != nil { - slog.Warn("Failed to check if user exists", "username", username, "error", err) + slog.WarnContext(r.Context(), "Failed to check if user exists", "username", username, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -69,22 +70,22 @@ func (l *Listener) handleOutbox(w http.ResponseWriter, r *http.Request) { if shouldRedirect(r) { outbox := fmt.Sprintf("gemini://%s/outbox/%s", l.Domain, strings.TrimPrefix(actorID.String, "https://")) - slog.Info("Redirecting to outbox over Gemini", "outbox", outbox) + slog.InfoContext(r.Context(), "Redirecting to outbox over Gemini", "outbox", outbox) w.Header().Set("Location", outbox) w.WriteHeader(http.StatusMovedPermanently) return } - slog.Info("Fetching activities by user", "username", username) + slog.InfoContext(r.Context(), "Fetching activities by user", "username", username) if r.URL.RawQuery == "" { - l.getCollection(w, username) + l.getCollection(r.Context(), w, username) return } since, err := strconv.ParseInt(r.URL.RawQuery, 10, 64) if err != nil { - slog.Warn("Failed to parse offset", "username", username, "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context(), "Failed to parse offset", "username", username, "query", r.URL.RawQuery, "error", err) w.WriteHeader(http.StatusBadRequest) return } @@ -108,7 +109,7 @@ func (l *Listener) handleOutbox(w http.ResponseWriter, r *http.Request) { j, err := json.Marshal(page) if err != nil { - slog.Warn("Failed to marshal page", "username", username, "since", since, "error", err) + slog.WarnContext(r.Context(), "Failed to marshal page", "username", username, "since", since, "error", err) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/fed/post.go b/fed/post.go index 37d6b130..3ceaead7 100644 --- a/fed/post.go +++ b/fed/post.go @@ -29,20 +29,20 @@ func (l *Listener) handlePost(w http.ResponseWriter, r *http.Request) { if shouldRedirect(r) { url := fmt.Sprintf("gemini://%s/view/%s%s", l.Domain, l.Domain, r.URL.Path) - slog.Info("Redirecting to post over Gemini", "url", url) + slog.InfoContext(r.Context(), "Redirecting to post over Gemini", "url", url) w.Header().Set("Location", url) w.WriteHeader(http.StatusMovedPermanently) return } - slog.Info("Fetching post", "post", postID) + slog.InfoContext(r.Context(), "Fetching post", "post", postID) var note string if err := l.DB.QueryRowContext(r.Context(), `select json(object) from notes where id = ? and public = 1`, postID).Scan(¬e); err != nil && errors.Is(err, sql.ErrNoRows) { w.WriteHeader(http.StatusNotFound) return } else if err != nil { - slog.Warn("Failed to fetch post", "post", postID, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch post", "post", postID, "error", err) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/fed/resolve.go b/fed/resolve.go index fa9682f9..31884c87 100644 --- a/fed/resolve.go +++ b/fed/resolve.go @@ -96,7 +96,7 @@ func (r *Resolver) ResolveID(ctx context.Context, keys [2]httpsig.Key, id string return nil, ErrInvalidScheme } - if actor, err := r.validate(func() (*ap.Actor, *ap.Actor, error) { return r.tryResolveID(ctx, keys, u, id, flags) }); err != nil { + if actor, err := r.validate(ctx, func() (*ap.Actor, *ap.Actor, error) { return r.tryResolveID(ctx, keys, u, id, flags) }); err != nil { return nil, err } else if actor.Suspended { return nil, ErrSuspendedActor @@ -109,7 +109,7 @@ func (r *Resolver) ResolveID(ctx context.Context, keys [2]httpsig.Key, id string // Resolve retrieves an actor object by host and name. func (r *Resolver) Resolve(ctx context.Context, keys [2]httpsig.Key, host, name string, flags ap.ResolverFlag) (*ap.Actor, error) { - if actor, err := r.validate(func() (*ap.Actor, *ap.Actor, error) { return r.tryResolve(ctx, keys, host, name, flags) }); err != nil { + if actor, err := r.validate(ctx, func() (*ap.Actor, *ap.Actor, error) { return r.tryResolve(ctx, keys, host, name, flags) }); err != nil { return nil, err } else if actor.Suspended { return nil, ErrSuspendedActor @@ -120,13 +120,13 @@ func (r *Resolver) Resolve(ctx context.Context, keys [2]httpsig.Key, host, name } } -func (r *Resolver) validate(try func() (*ap.Actor, *ap.Actor, error)) (*ap.Actor, error) { +func (r *Resolver) validate(ctx context.Context, try func() (*ap.Actor, *ap.Actor, error)) (*ap.Actor, error) { actor, cachedActor, err := try() if err != nil && cachedActor != nil && cachedActor.Published != (ap.Time{}) && time.Since(cachedActor.Published.Time) < r.Config.MinActorAge { - slog.Warn("Failed to update cached actor", "id", cachedActor.ID, "error", err) + slog.WarnContext(ctx, "Failed to update cached actor", "id", cachedActor.ID, "error", err) return nil, ErrYoungActor } else if err != nil && cachedActor != nil { - slog.Warn("Using old cache entry for actor", "id", cachedActor.ID, "error", err) + slog.WarnContext(ctx, "Using old cache entry for actor", "id", cachedActor.ID, "error", err) return cachedActor, nil } else if actor == nil { return cachedActor, err @@ -138,46 +138,46 @@ func (r *Resolver) validate(try func() (*ap.Actor, *ap.Actor, error)) (*ap.Actor func deleteActor(ctx context.Context, db *sql.DB, id string) { if _, err := db.ExecContext(ctx, `delete from notesfts where exists (select 1 from notes where notes.author = ? and notesfts.id = notes.id)`, id); err != nil { - slog.Warn("Failed to delete notes by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete notes by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from shares where by = $1 or exists (select 1 from notes where notes.author = $1 and notes.id = shares.note)`, id); err != nil { - slog.Warn("Failed to delete shares by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete shares by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from bookmarks where exists (select 1 from notes where notes.author = ? and notes.id = bookmarks.note)`, id); err != nil { - slog.Warn("Failed to delete bookmarks by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete bookmarks by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from feed where sharer->>'$.id' = ?`, id); err != nil { - slog.Warn("Failed to delete shares by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete shares by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from feed where author->>'$.id' = ?`, id); err != nil { - slog.Warn("Failed to delete shares by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete shares by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from notes where author = ?`, id); err != nil { - slog.Warn("Failed to delete notes by actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete notes by actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from follows where follower = $1 or followed = $1`, id); err != nil { - slog.Warn("Failed to delete follows for actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete follows for actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from keys where actor = ?`, id); err != nil { - slog.Warn("Failed to delete keys for actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete keys for actor", "id", id, "error", err) } if _, err := db.ExecContext(ctx, `delete from persons where id = ?`, id); err != nil { - slog.Warn("Failed to delete actor", "id", id, "error", err) + slog.WarnContext(ctx, "Failed to delete actor", "id", id, "error", err) } } func (r *Resolver) handleFetchFailure(ctx context.Context, fetched string, cachedActor *ap.Actor, sinceLastUpdate time.Duration, resp *http.Response, err error) (*ap.Actor, *ap.Actor, error) { if resp != nil && (resp.StatusCode == http.StatusGone || resp.StatusCode == http.StatusNotFound) { if cachedActor != nil { - slog.Warn("Actor is gone, deleting associated objects", "id", cachedActor.ID) + slog.WarnContext(ctx, "Actor is gone, deleting associated objects", "id", cachedActor.ID) deleteActor(ctx, r.db, cachedActor.ID) } return nil, nil, fmt.Errorf("failed to fetch %s: %w", fetched, ErrActorGone) @@ -191,7 +191,7 @@ func (r *Resolver) handleFetchFailure(ctx context.Context, fetched string, cache // if it's been a while since the last update and the server's domain is expired (NXDOMAIN), actor is gone if sinceLastUpdate > r.Config.MaxInstanceRecoveryTime && errors.As(err, &urlError) && errors.As(urlError.Err, &opError) && errors.As(opError.Err, &dnsError) && dnsError.IsNotFound { if cachedActor != nil { - slog.Warn("Server is probably gone, deleting associated objects", "id", cachedActor.ID) + slog.WarnContext(ctx, "Server is probably gone, deleting associated objects", "id", cachedActor.ID) deleteActor(ctx, r.db, cachedActor.ID) } return nil, nil, fmt.Errorf("failed to fetch %s: %w", fetched, err) @@ -201,7 +201,7 @@ func (r *Resolver) handleFetchFailure(ctx context.Context, fetched string, cache } func (r *Resolver) tryResolve(ctx context.Context, keys [2]httpsig.Key, host, name string, flags ap.ResolverFlag) (*ap.Actor, *ap.Actor, error) { - slog.Debug("Resolving actor", "host", host, "name", name) + slog.DebugContext(ctx, "Resolving actor", "host", host, "name", name) if r.BlockedDomains != nil && r.BlockedDomains.Contains(host) { return nil, nil, ErrBlockedDomain @@ -247,9 +247,9 @@ func (r *Resolver) tryResolve(ctx context.Context, keys [2]httpsig.Key, host, na sinceLastUpdate = time.Since(time.Unix(updated, 0)) if !isLocal && flags&ap.Offline == 0 && sinceLastUpdate >= r.Config.ResolverCacheTTL && (!fetched.Valid || time.Since(time.Unix(fetched.Int64, 0)) >= r.Config.ResolverRetryInterval) { - slog.Info("Updating old cache entry for actor", "id", cachedActor.ID) + slog.InfoContext(ctx, "Updating old cache entry for actor", "id", cachedActor.ID) } else { - slog.Debug("Resolved actor using cache", "id", cachedActor.ID) + slog.DebugContext(ctx, "Resolved actor using cache", "id", cachedActor.ID) return nil, cachedActor, nil } } @@ -339,7 +339,7 @@ func (r *Resolver) tryResolve(ctx context.Context, keys [2]httpsig.Key, host, na } func (r *Resolver) tryResolveID(ctx context.Context, keys [2]httpsig.Key, u *url.URL, id string, flags ap.ResolverFlag) (*ap.Actor, *ap.Actor, error) { - slog.Debug("Resolving actor", "id", id) + slog.DebugContext(ctx, "Resolving actor", "id", id) if r.BlockedDomains != nil && r.BlockedDomains.Contains(u.Host) { return nil, nil, ErrBlockedDomain @@ -375,9 +375,9 @@ func (r *Resolver) tryResolveID(ctx context.Context, keys [2]httpsig.Key, u *url sinceLastUpdate = time.Since(time.Unix(updated, 0)) if !isLocal && flags&ap.Offline == 0 && sinceLastUpdate > r.Config.ResolverCacheTTL && (!fetched.Valid || time.Since(time.Unix(fetched.Int64, 0)) >= r.Config.ResolverRetryInterval) { - slog.Info("Updating old cache entry for actor", "id", cachedActor.ID) + slog.InfoContext(ctx, "Updating old cache entry for actor", "id", cachedActor.ID) } else { - slog.Debug("Resolved actor using cache", "id", cachedActor.ID) + slog.DebugContext(ctx, "Resolved actor using cache", "id", cachedActor.ID) return nil, cachedActor, nil } } @@ -475,11 +475,11 @@ func (r *Resolver) fetchActor(ctx context.Context, keys [2]httpsig.Key, host, pr } if keyOrigin, err := ap.Origin(actor.PublicKey.ID); err != nil { - slog.Debug("Failed to parse public key ID", "actor", actor.ID, "key", actor.PublicKey.ID, "error", err) + slog.DebugContext(ctx, "Failed to parse public key ID", "actor", actor.ID, "key", actor.PublicKey.ID, "error", err) } else if keyOrigin == actorOrigin { keyIDs[actor.PublicKey.ID] = struct{}{} } else { - slog.Warn("Public key ID belongs to a different host", "actor", actor.ID, "key", actor.PublicKey.ID) + slog.WarnContext(ctx, "Public key ID belongs to a different host", "actor", actor.ID, "key", actor.PublicKey.ID) } for _, method := range actor.AssertionMethod { @@ -488,11 +488,11 @@ func (r *Resolver) fetchActor(ctx context.Context, keys [2]httpsig.Key, host, pr } if methodOrigin, err := ap.Origin(method.ID); err != nil { - slog.Debug("Failed to parse assertion method ID", "actor", actor.ID, "key", method.ID, "error", err) + slog.DebugContext(ctx, "Failed to parse assertion method ID", "actor", actor.ID, "key", method.ID, "error", err) } else if methodOrigin == actorOrigin { keyIDs[method.ID] = struct{}{} } else { - slog.Warn("Assertion method ID belongs to a different host", "actor", actor.ID, "key", method.ID) + slog.WarnContext(ctx, "Assertion method ID belongs to a different host", "actor", actor.ID, "key", method.ID) } } diff --git a/fed/send.go b/fed/send.go index fea3968e..acdf8def 100644 --- a/fed/send.go +++ b/fed/send.go @@ -31,6 +31,7 @@ import ( "github.com/dimkr/tootik/buildinfo" "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" ) type sender struct { @@ -53,41 +54,43 @@ func (s *sender) send(keys [2]httpsig.Key, req *http.Request) (*http.Response, e return nil, fmt.Errorf("invalid host in %s: %s", urlString, req.URL.Host) } + req = req.WithContext(logcontext.Add(req.Context(), slog.Group("outgoing_request", "method", req.Method, "url", urlString))) + req.Header.Set("User-Agent", userAgent) req.Header.Set("Content-Type", `application/ld+json; profile="https://www.w3.org/ns/activitystreams"`) - slog.Debug("Sending request", "url", urlString) + slog.DebugContext(req.Context(), "Sending request") capabilities := ap.CavageDraftSignatures if err := s.DB.QueryRowContext(req.Context(), `select capabilities from servers where host = ?`, req.URL.Host).Scan(&capabilities); errors.Is(err, sql.ErrNoRows) { - slog.Debug("Server capabilities are unknown", "url", urlString) + slog.DebugContext(req.Context(), "Server capabilities are unknown") } else if err != nil { return nil, fmt.Errorf("failed to query server capabilities for %s: %w", req.URL.Host, err) } if capabilities&ap.RFC9421Ed25519Signatures == 0 && req.Method == http.MethodPost && rand.Float32() > s.Config.Ed25519Threshold { - slog.Debug("Randomly enabling RFC9421 with Ed25519", "server", req.URL.Host) + slog.DebugContext(req.Context(), "Randomly enabling RFC9421 with Ed25519", "server", req.URL.Host) capabilities = ap.RFC9421Ed25519Signatures } else if capabilities&ap.RFC9421RSASignatures == 0 && req.Method == http.MethodPost && rand.Float32() > s.Config.RFC9421Threshold { - slog.Debug("Randomly enabling RFC9421 with RSA", "server", req.URL.Host) + slog.DebugContext(req.Context(), "Randomly enabling RFC9421 with RSA", "server", req.URL.Host) capabilities = ap.RFC9421RSASignatures } if capabilities&ap.RFC9421Ed25519Signatures > 0 { - slog.Debug("Signing request using RFC9421 with Ed25519", "method", req.Method, "url", urlString, "key", keys[1].ID) + slog.DebugContext(req.Context(), "Signing request using RFC9421 with Ed25519", "key", keys[1].ID) if err := httpsig.SignRFC9421(req, keys[1], time.Now(), time.Time{}, httpsig.RFC9421DigestSHA256, "ed25519", nil); err != nil { return nil, fmt.Errorf("failed to sign request for %s: %w", urlString, err) } } else if capabilities&ap.RFC9421RSASignatures > 0 { - slog.Debug("Signing request using RFC9421 with RSA", "method", req.Method, "url", urlString, "key", keys[0].ID) + slog.DebugContext(req.Context(), "Signing request using RFC9421 with RSA", "key", keys[0].ID) if err := httpsig.SignRFC9421(req, keys[0], time.Now(), time.Time{}, httpsig.RFC9421DigestSHA256, "rsa-v1_5-sha256", nil); err != nil { return nil, fmt.Errorf("failed to sign request for %s: %w", urlString, err) } } else if err := httpsig.Sign(req, keys[0], time.Now()); err != nil { - slog.Debug("Signing request using draft-cavage-http-signatures", "method", req.Method, "url", urlString, "key", keys[0].ID) + slog.DebugContext(req.Context(), "Signing request using draft-cavage-http-signatures", "key", keys[0].ID) return nil, fmt.Errorf("failed to sign request for %s: %w", urlString, err) } @@ -119,7 +122,7 @@ func (s *sender) send(keys [2]httpsig.Key, req *http.Request) (*http.Response, e req.URL.Host, capabilities, ); err != nil { - slog.Warn("Failed to record server capabilities", "server", req.URL.Host, "error", err) + slog.WarnContext(req.Context(), "Failed to record server capabilities", "server", req.URL.Host, "error", err) } } diff --git a/fed/user.go b/fed/user.go index 558a6504..2d8e6b92 100644 --- a/fed/user.go +++ b/fed/user.go @@ -26,11 +26,11 @@ import ( ) func (l *Listener) doHandleUser(w http.ResponseWriter, r *http.Request, name string) { - slog.Info("Looking up user", "name", name) + slog.InfoContext(r.Context(), "Looking up user", "name", name) var actorID, actorString string if err := l.DB.QueryRowContext(r.Context(), `select id, json(actor) from persons where actor->>'$.preferredUsername' = ? and host = ?`, name, l.Domain).Scan(&actorID, &actorString); err != nil && errors.Is(err, sql.ErrNoRows) { - slog.Info("Notifying about deleted user", "name", name) + slog.InfoContext(r.Context(), "Notifying about deleted user", "name", name) w.WriteHeader(http.StatusNotFound) return } else if err != nil { @@ -41,7 +41,7 @@ func (l *Listener) doHandleUser(w http.ResponseWriter, r *http.Request, name str // redirect browsers to the outbox page over Gemini if shouldRedirect(r) { outbox := fmt.Sprintf("gemini://%s/outbox/%s", l.Domain, strings.TrimPrefix(actorID, "https://")) - slog.Info("Redirecting to outbox over Gemini", "outbox", outbox) + slog.InfoContext(r.Context(), "Redirecting to outbox over Gemini", "outbox", outbox) w.Header().Set("Location", outbox) w.WriteHeader(http.StatusMovedPermanently) return diff --git a/fed/verify.go b/fed/verify.go index 9177d7ea..2a541ddb 100644 --- a/fed/verify.go +++ b/fed/verify.go @@ -30,6 +30,7 @@ import ( "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/data" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" "github.com/dimkr/tootik/proof" ) @@ -64,6 +65,8 @@ func (l *Listener) verifyRequest(r *http.Request, body []byte, flags ap.Resolver return nil, nil, fmt.Errorf("failed to verify message: %w", err) } + r = r.WithContext(logcontext.Add(r.Context(), "key_id", sig.KeyID)) + if sig.Alg == "ed25519" && ap.IsPortable(sig.KeyID) { if m := ap.KeyRegex.FindStringSubmatch(sig.KeyID); m != nil { if keyOrigin, err := ap.Origin(sig.KeyID); err != nil { @@ -139,11 +142,11 @@ func (l *Listener) verifyProof(ctx context.Context, p ap.Proof, activity *ap.Act return nil, fmt.Errorf("failed to verify proof using %s: %w", p.VerificationMethod, err) } - return l.Resolver.ResolveID(ctx, keys, activity.Actor, flags) + return l.Resolver.ResolveID(logcontext.Add(ctx, "verification_method", p.VerificationMethod), keys, activity.Actor, flags) } } - actor, err := l.Resolver.ResolveID(ctx, keys, p.VerificationMethod, flags) + actor, err := l.Resolver.ResolveID(logcontext.Add(ctx, "verification_method", p.VerificationMethod), keys, p.VerificationMethod, flags) if err != nil { return nil, fmt.Errorf("failed to get key %s to verify proof: %w", p.VerificationMethod, err) } diff --git a/fed/webfinger.go b/fed/webfinger.go index 3fa70eb6..5a32baf8 100644 --- a/fed/webfinger.go +++ b/fed/webfinger.go @@ -55,7 +55,7 @@ func (l *Listener) handleWebFinger(w http.ResponseWriter, r *http.Request) { resource, err := url.QueryUnescape(query.Get("resource")) if err != nil { - slog.Info("Failed to decode query", "resource", r.URL.RawQuery, "error", err) + slog.InfoContext(r.Context(), "Failed to decode query", "resource", r.URL.RawQuery, "error", err) w.WriteHeader(http.StatusBadRequest) return } @@ -71,14 +71,14 @@ func (l *Listener) handleWebFinger(w http.ResponseWriter, r *http.Request) { var fields = strings.Split(resource, "@") if len(fields) > 2 { - slog.Info("Received invalid resource", "resource", resource) + slog.InfoContext(r.Context(), "Received invalid resource", "resource", resource) w.WriteHeader(http.StatusBadRequest) w.Write([]byte("Resource must contain zero or one @")) return } if len(fields) == 2 && fields[1] != l.Domain { - slog.Info("Received invalid resource", "resource", resource, "domain", fields[1]) + slog.InfoContext(r.Context(), "Received invalid resource", "resource", resource, "domain", fields[1]) w.WriteHeader(http.StatusBadRequest) fmt.Fprintf(w, "Resource must end with @%s", l.Domain) return @@ -92,11 +92,11 @@ func (l *Listener) handleWebFinger(w http.ResponseWriter, r *http.Request) { username = "nobody" } - slog.Info("Looking up resource", "resource", resource, "user", username) + slog.InfoContext(r.Context(), "Looking up resource", "resource", resource, "user", username) rows, err := l.DB.QueryContext(r.Context(), `select id, actor->>'$.type' from persons where actor->>'$.preferredUsername' = ? and host = ?`, username, l.Domain) if err != nil { - slog.Warn("Failed to fetch user", "user", username, "error", err) + slog.WarnContext(r.Context(), "Failed to fetch user", "user", username, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -110,7 +110,7 @@ func (l *Listener) handleWebFinger(w http.ResponseWriter, r *http.Request) { var actorID sql.NullString var actorType string if err := rows.Scan(&actorID, &actorType); err != nil { - slog.Warn("Failed to scan user", "user", username, "error", err) + slog.WarnContext(r.Context(), "Failed to scan user", "user", username, "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -126,7 +126,7 @@ func (l *Listener) handleWebFinger(w http.ResponseWriter, r *http.Request) { } if len(resp.Links) == 0 { - slog.Info("Notifying that user does not exist", "user", username) + slog.InfoContext(r.Context(), "Notifying that user does not exist", "user", username) w.WriteHeader(http.StatusNotFound) return } diff --git a/front/accept.go b/front/accept.go index 72528810..ac156f9a 100644 --- a/front/accept.go +++ b/front/accept.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/front/text" ) @@ -33,7 +34,7 @@ func (h *Handler) accept(w text.Writer, r *Request, args ...string) { tx, err := h.DB.BeginTx(r.Context, nil) if err != nil { - r.Log.Warn("Failed to accept follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to accept follow request", "follower", follower, "error", err) w.Error() return } @@ -46,23 +47,23 @@ func (h *Handler) accept(w text.Writer, r *Request, args ...string) { r.User.ID, follower, ).Scan(&followID); errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Failed to fetch follow request to approve", "follower", follower) + slog.WarnContext(r.Context, "Failed to fetch follow request to approve", "follower", follower) w.Status(40, "No such follow request") return } else if err != nil { - r.Log.Warn("Failed to accept follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to accept follow request", "follower", follower, "error", err) w.Error() return } if err := h.Inbox.Accept(r.Context, r.User, r.Keys[1], follower, followID, tx); err != nil { - r.Log.Warn("Failed to accept follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to accept follow request", "follower", follower, "error", err) w.Error() return } if err := tx.Commit(); err != nil { - r.Log.Warn("Failed to accept follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to accept follow request", "follower", follower, "error", err) w.Error() return } diff --git a/front/alias.go b/front/alias.go index 71689575..225d78f4 100644 --- a/front/alias.go +++ b/front/alias.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "net/url" "strings" "time" @@ -38,7 +39,7 @@ func (h *Handler) alias(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to set alias", "can", can) + slog.WarnContext(r.Context, "Throttled request to set alias", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -50,21 +51,21 @@ func (h *Handler) alias(w text.Writer, r *Request, args ...string) { alias, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to decode alias", "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to decode alias", "query", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } tokens := strings.SplitN(alias, "@", 3) if len(tokens) != 2 { - r.Log.Warn("Alias is invalid", "alias", alias) + slog.WarnContext(r.Context, "Alias is invalid", "alias", alias) w.Status(40, "Bad input") return } actor, err := h.Resolver.Resolve(r.Context, r.Keys, tokens[1], tokens[0], 0) if err != nil { - r.Log.Warn("Failed to resolve alias", "alias", alias, "error", err) + slog.WarnContext(r.Context, "Failed to resolve alias", "alias", alias, "error", err) w.Status(40, "Failed to resolve "+alias) return } @@ -73,7 +74,7 @@ func (h *Handler) alias(w text.Writer, r *Request, args ...string) { r.User.Updated.Time = now if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to update alias", "error", err) + slog.ErrorContext(r.Context, "Failed to update alias", "error", err) w.Error() return } diff --git a/front/approve.go b/front/approve.go index 2bf39dd1..f0379f53 100644 --- a/front/approve.go +++ b/front/approve.go @@ -1,5 +1,5 @@ /* -Copyright 2024 Dima Krasner +Copyright 2024, 2025 Dima Krasner Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -16,7 +16,11 @@ limitations under the License. package front -import "github.com/dimkr/tootik/front/text" +import ( + "log/slog" + + "github.com/dimkr/tootik/front/text" +) func (h *Handler) approve(w text.Writer, r *Request, args ...string) { if r.User == nil { @@ -26,7 +30,7 @@ func (h *Handler) approve(w text.Writer, r *Request, args ...string) { hash := args[1] - r.Log.Info("Approving certificate", "user", r.User.PreferredUsername, "hash", hash) + slog.InfoContext(r.Context, "Approving certificate", "user", r.User.PreferredUsername, "hash", hash) if res, err := h.DB.ExecContext( r.Context, @@ -37,15 +41,15 @@ func (h *Handler) approve(w text.Writer, r *Request, args ...string) { r.User.PreferredUsername, hash, ); err != nil { - r.Log.Warn("Failed to approve certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) + slog.WarnContext(r.Context, "Failed to approve certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) w.Error() return } else if n, err := res.RowsAffected(); err != nil { - r.Log.Warn("Failed to approve certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) + slog.WarnContext(r.Context, "Failed to approve certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) w.Error() return } else if n == 0 { - r.Log.Warn("Certificate doesn't exist or already approved", "user", r.User.PreferredUsername, "hash", hash) + slog.WarnContext(r.Context, "Certificate doesn't exist or already approved", "user", r.User.PreferredUsername, "hash", hash) w.Status(40, "Cannot approve certificate") return } diff --git a/front/avatar.go b/front/avatar.go index 28d17e34..d1a19911 100644 --- a/front/avatar.go +++ b/front/avatar.go @@ -19,6 +19,7 @@ package front import ( "fmt" "io" + "log/slog" "strconv" "time" @@ -47,26 +48,26 @@ func (h *Handler) uploadAvatar(w text.Writer, r *Request, args ...string) { sizeStr = args[4] mimeType = args[2] } else { - r.Log.Warn("Invalid parameters") + slog.WarnContext(r.Context, "Invalid parameters") w.Error() return } size, err := strconv.ParseInt(sizeStr, 10, 64) if err != nil { - r.Log.Warn("Failed to parse avatar size", "error", err) + slog.WarnContext(r.Context, "Failed to parse avatar size", "error", err) w.Status(40, "Invalid size") return } if size > h.Config.MaxAvatarSize { - r.Log.Warn("Image is too big", "size", size) + slog.WarnContext(r.Context, "Image is too big", "size", size) w.Status(40, "Image is too big") return } if _, ok := supportedImageTypes[mimeType]; !ok { - r.Log.Warn("Image type is unsupported", "type", mimeType) + slog.WarnContext(r.Context, "Image type is unsupported", "type", mimeType) w.Status(40, "Unsupported image type") return } @@ -78,7 +79,7 @@ func (h *Handler) uploadAvatar(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to set avatar", "can", can) + slog.WarnContext(r.Context, "Throttled request to set avatar", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -86,27 +87,27 @@ func (h *Handler) uploadAvatar(w text.Writer, r *Request, args ...string) { buf := make([]byte, size) n, err := io.ReadFull(r.Body, buf) if err != nil { - r.Log.Warn("Failed to read avatar", "error", err) + slog.WarnContext(r.Context, "Failed to read avatar", "error", err) w.Error() return } if int64(n) != size { - r.Log.Warn("Avatar is truncated") + slog.WarnContext(r.Context, "Avatar is truncated") w.Error() return } resized, err := icon.Scale(h.Config, buf) if err != nil { - r.Log.Warn("Failed to read avatar", "error", err) + slog.WarnContext(r.Context, "Failed to read avatar", "error", err) w.Error() return } tx, err := h.DB.BeginTx(r.Context, nil) if err != nil { - r.Log.Warn("Failed to set avatar", "error", err) + slog.WarnContext(r.Context, "Failed to set avatar", "error", err) w.Error() return } @@ -118,7 +119,7 @@ func (h *Handler) uploadAvatar(w text.Writer, r *Request, args ...string) { r.User.PreferredUsername, string(resized), ); err != nil { - r.Log.Error("Failed to set avatar", "error", err) + slog.ErrorContext(r.Context, "Failed to set avatar", "error", err) w.Error() return } @@ -130,13 +131,13 @@ func (h *Handler) uploadAvatar(w text.Writer, r *Request, args ...string) { r.User.Updated.Time = now if err := h.Inbox.UpdateActorTx(r.Context, tx, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to set avatar", "error", err) + slog.ErrorContext(r.Context, "Failed to set avatar", "error", err) w.Error() return } if err := tx.Commit(); err != nil { - r.Log.Error("Failed to set avatar", "error", err) + slog.ErrorContext(r.Context, "Failed to set avatar", "error", err) w.Error() return } diff --git a/front/bio.go b/front/bio.go index 21c68141..325ac849 100644 --- a/front/bio.go +++ b/front/bio.go @@ -18,6 +18,7 @@ package front import ( "fmt" + "log/slog" "time" "unicode/utf8" @@ -76,7 +77,7 @@ func (h *Handler) doSetBio(w text.Writer, r *Request, readInput func(text.Writer can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to set bio", "can", can) + slog.WarnContext(r.Context, "Throttled request to set bio", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -95,7 +96,7 @@ func (h *Handler) doSetBio(w text.Writer, r *Request, readInput func(text.Writer r.User.Updated.Time = now if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to update bio", "error", err) + slog.ErrorContext(r.Context, "Failed to update bio", "error", err) w.Error() return } diff --git a/front/bookmark.go b/front/bookmark.go index 7b0e555f..31f20e41 100644 --- a/front/bookmark.go +++ b/front/bookmark.go @@ -18,6 +18,7 @@ package front import ( "database/sql" + "log/slog" "time" "github.com/dimkr/tootik/front/text" @@ -33,7 +34,7 @@ func (h *Handler) bookmark(w text.Writer, r *Request, args ...string) { tx, err := h.DB.BeginTx(r.Context, nil) if err != nil { - r.Log.Warn("Failed to insert bookmark", "error", err) + slog.WarnContext(r.Context, "Failed to insert bookmark", "error", err) w.Error() return } @@ -59,11 +60,11 @@ func (h *Handler) bookmark(w text.Writer, r *Request, args ...string) { postID, r.User.ID, ).Scan(&exists); err != nil { - r.Log.Warn("Failed to check if bookmarked post exists", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to check if bookmarked post exists", "post", postID, "error", err) w.Error() return } else if exists == 0 { - r.Log.Info("Post was not found", "post", postID) + slog.InfoContext(r.Context, "Post was not found", "post", postID) w.Status(40, "Post not found") return } @@ -73,13 +74,13 @@ func (h *Handler) bookmark(w text.Writer, r *Request, args ...string) { var count int var last sql.NullInt64 if err := tx.QueryRowContext(r.Context, `select count(*), max(inserted) from bookmarks where by = ?`, r.User.ID).Scan(&count, &last); err != nil { - r.Log.Warn("Failed to check if bookmark needs to be throttled", "error", err) + slog.WarnContext(r.Context, "Failed to check if bookmark needs to be throttled", "error", err) w.Error() return } if count >= h.Config.MaxBookmarksPerUser { - r.Log.Warn("User has reached bookmarks limit", "post", postID) + slog.WarnContext(r.Context, "User has reached bookmarks limit", "post", postID) w.Status(40, "Reached bookmarks limit") return } @@ -87,20 +88,20 @@ func (h *Handler) bookmark(w text.Writer, r *Request, args ...string) { if last.Valid { t := time.Unix(last.Int64, 0) if now.Sub(t) < h.Config.MinBookmarkInterval { - r.Log.Warn("User is bookmarking too frequently") + slog.WarnContext(r.Context, "User is bookmarking too frequently") w.Status(40, "Please wait before bookmarking") return } } if _, err := tx.ExecContext(r.Context, `insert into bookmarks(note, by) values(?, ?)`, postID, r.User.ID); err != nil { - r.Log.Warn("Failed to insert bookmark", "error", err) + slog.WarnContext(r.Context, "Failed to insert bookmark", "error", err) w.Error() return } if err := tx.Commit(); err != nil { - r.Log.Warn("Failed to insert bookmark", "error", err) + slog.WarnContext(r.Context, "Failed to insert bookmark", "error", err) w.Error() return } diff --git a/front/cache.go b/front/cache.go index 55c30d3a..77127080 100644 --- a/front/cache.go +++ b/front/cache.go @@ -19,6 +19,7 @@ package front import ( "bytes" "context" + "log/slog" "slices" "sync" "time" @@ -64,7 +65,7 @@ func callAndCache(r *Request, w text.Writer, args []string, f func(text.Writer, if !ok { // always call Flush() if err := w.Flush(); err != nil && send { - r.Log.Warn("Failed to send response", "error", err) + slog.WarnContext(r.Context, "Failed to send response", "error", err) } break @@ -73,7 +74,7 @@ func callAndCache(r *Request, w text.Writer, args []string, f func(text.Writer, // send response chunks to the client, until error if send { if _, err := w.Write(chunk); err != nil { - r.Log.Warn("Failed to send response", "error", err) + slog.WarnContext(r.Context, "Failed to send response", "error", err) send = false } } @@ -101,18 +102,18 @@ func withCache(f func(text.Writer, *Request, ...string), d time.Duration, cache entry, cached := cache.Load(key) if !cached { - r.Log.Info("Generating first response", "key", key) + slog.InfoContext(r.Context, "Generating first response", "key", key) callAndCache(r, w, args, f, key, now, cache) return } if entry.(cacheEntry).Created.After(now.Add(-d)) { - r.Log.Info("Sending cached response", "key", key) + slog.InfoContext(r.Context, "Sending cached response", "key", key) w.Write(entry.(cacheEntry).Value) return } - r.Log.Info("Generating new response", "key", key) + slog.InfoContext(r.Context, "Generating new response", "key", key) callAndCache(r, w, args, f, key, now, cache) } } diff --git a/front/certificates.go b/front/certificates.go index 889ed751..6be68bca 100644 --- a/front/certificates.go +++ b/front/certificates.go @@ -1,5 +1,5 @@ /* -Copyright 2024 Dima Krasner +Copyright 2024, 2025 Dima Krasner Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "time" "github.com/dimkr/tootik/front/text" @@ -38,7 +39,7 @@ func (h *Handler) certificates(w text.Writer, r *Request, args ...string) { r.User.PreferredUsername, ) if err != nil { - r.Log.Warn("Failed to fetch certificates", "user", r.User.PreferredUsername, "error", err) + slog.WarnContext(r.Context, "Failed to fetch certificates", "user", r.User.PreferredUsername, "error", err) w.Error() return } @@ -54,7 +55,7 @@ func (h *Handler) certificates(w text.Writer, r *Request, args ...string) { var hash string var approved int if err := rows.Scan(&inserted, &hash, &approved, &expires); err != nil { - r.Log.Warn("Failed to fetch certificate", "user", r.User.PreferredUsername, "error", err) + slog.WarnContext(r.Context, "Failed to fetch certificate", "user", r.User.PreferredUsername, "error", err) continue } diff --git a/front/communities.go b/front/communities.go index a2fa3f81..1841eecd 100644 --- a/front/communities.go +++ b/front/communities.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "strings" "time" @@ -52,7 +53,7 @@ func (h *Handler) communities(w text.Writer, r *Request, args ...string) { h.Domain, ) if err != nil { - r.Log.Error("Failed to list communities", "error", err) + slog.ErrorContext(r.Context, "Failed to list communities", "error", err) w.Error() return } @@ -67,7 +68,7 @@ func (h *Handler) communities(w text.Writer, r *Request, args ...string) { var id, username string var last int64 if err := rows.Scan(&id, &username, &last); err != nil { - r.Log.Warn("Failed to scan community", "error", err) + slog.WarnContext(r.Context, "Failed to scan community", "error", err) continue } diff --git a/front/delete.go b/front/delete.go index 5b3dd744..2f38e731 100644 --- a/front/delete.go +++ b/front/delete.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "strings" "github.com/dimkr/tootik/ap" @@ -35,17 +36,17 @@ func (h *Handler) delete(w text.Writer, r *Request, args ...string) { var note ap.Object if err := h.DB.QueryRowContext(r.Context, `select json(object) from notes where id = ? and author in (select id from persons where cid = ?)`, postID, ap.Canonical(r.User.ID)).Scan(¬e); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Attempted to delete a non-existing post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Attempted to delete a non-existing post", "post", postID, "error", err) w.Error() return } else if err != nil { - r.Log.Warn("Failed to fetch post to delete", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to fetch post to delete", "post", postID, "error", err) w.Error() return } if err := h.Inbox.Delete(r.Context, r.User, r.Keys[1], ¬e); err != nil { - r.Log.Error("Failed to delete post", "note", note.ID, "error", err) + slog.ErrorContext(r.Context, "Failed to delete post", "note", note.ID, "error", err) w.Error() return } diff --git a/front/edit.go b/front/edit.go index 8df7a3e3..b77fd9c4 100644 --- a/front/edit.go +++ b/front/edit.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "math" "time" @@ -36,24 +37,24 @@ func (h *Handler) doEdit(w text.Writer, r *Request, args []string, readInput inp var note ap.Object if err := h.DB.QueryRowContext(r.Context, `select json(object) from notes where id = ? and author in (select id from persons where cid = ?)`, postID, ap.Canonical(r.User.ID)).Scan(¬e); errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Attempted to edit non-existing post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Attempted to edit non-existing post", "post", postID, "error", err) w.Error() return } else if err != nil { - r.Log.Warn("Failed to fetch post to edit", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to fetch post to edit", "post", postID, "error", err) w.Error() return } if note.Name != "" { - r.Log.Warn("Cannot edit votes", "vote", note.ID) + slog.WarnContext(r.Context, "Cannot edit votes", "vote", note.ID) w.Status(40, "Cannot edit votes") return } var edits int if err := h.DB.QueryRowContext(r.Context, `select count(*) from outbox where activity->>'$.object.id' = ? and sender = ? and (activity->>'$.type' = 'Update' or activity->>'$.type' = 'Create')`, note.ID, r.User.ID).Scan(&edits); err != nil { - r.Log.Warn("Failed to count post edits", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to count post edits", "post", postID, "error", err) w.Error() return } @@ -66,7 +67,7 @@ func (h *Handler) doEdit(w text.Writer, r *Request, args []string, readInput inp canEdit := lastEditTime.Add(h.Config.EditThrottleUnit * time.Duration(math.Pow(h.Config.EditThrottleFactor, float64(edits)))) until := time.Until(canEdit) if until > 0 { - r.Log.Warn("Throttled request to edit post", "note", note.ID, "can", canEdit) + slog.WarnContext(r.Context, "Throttled request to edit post", "note", note.ID, "can", canEdit) w.Statusf(40, "Please wait for %s", until.Truncate(time.Second).String()) return } @@ -78,9 +79,9 @@ func (h *Handler) doEdit(w text.Writer, r *Request, args []string, readInput inp var parent ap.Object if err := h.DB.QueryRowContext(r.Context, `select json(object) from notes where cid = ?`, ap.Canonical(note.InReplyTo)).Scan(&parent); errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Parent post does not exist", "parent", note.InReplyTo) + slog.WarnContext(r.Context, "Parent post does not exist", "parent", note.InReplyTo) } else if err != nil { - r.Log.Warn("Failed to fetch parent post", "parent", note.InReplyTo, "error", err) + slog.WarnContext(r.Context, "Failed to fetch parent post", "parent", note.InReplyTo, "error", err) w.Error() return } diff --git a/front/export.go b/front/export.go index bb759e26..4a400247 100644 --- a/front/export.go +++ b/front/export.go @@ -19,6 +19,7 @@ package front import ( "bufio" "encoding/csv" + "log/slog" "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/front/text" @@ -52,7 +53,7 @@ func (h *Handler) export(w text.Writer, r *Request, args ...string) { csvRows, ) if err != nil { - r.Log.Warn("Failed to fetch activities", "error", err) + slog.WarnContext(r.Context, "Failed to fetch activities", "error", err) w.Error() return } @@ -61,24 +62,24 @@ func (h *Handler) export(w text.Writer, r *Request, args ...string) { w.Status(20, "text/csv") if err := output.Write(csvHeader); err != nil { - r.Log.Warn("Failed to write header", "error", err) + slog.WarnContext(r.Context, "Failed to write header", "error", err) return } var fields [4]string for rows.Next() { if err := rows.Scan(&fields[0], &fields[1], &fields[2], &fields[3]); err != nil { - r.Log.Warn("Failed to scan activity", "error", err) + slog.WarnContext(r.Context, "Failed to scan activity", "error", err) continue } if err := output.Write(fields[:]); err != nil { - r.Log.Warn("Failed to write a line", "error", err) + slog.WarnContext(r.Context, "Failed to write a line", "error", err) return } } output.Flush() if err := output.Error(); err != nil { - r.Log.Warn("Failed to flush output", "error", err) + slog.WarnContext(r.Context, "Failed to flush output", "error", err) } } diff --git a/front/finger/finger.go b/front/finger/finger.go index 56ed72ef..9945b073 100644 --- a/front/finger/finger.go +++ b/front/finger/finger.go @@ -45,7 +45,7 @@ type Listener struct { func (fl *Listener) handle(ctx context.Context, conn net.Conn) { if err := conn.SetDeadline(time.Now().Add(fl.Config.GuppyRequestTimeout)); err != nil { - slog.Warn("Failed to set deadline", "error", err) + slog.WarnContext(ctx, "Failed to set deadline", "error", err) return } @@ -54,20 +54,20 @@ func (fl *Listener) handle(ctx context.Context, conn net.Conn) { for { n, err := conn.Read(req[total:]) if err != nil && total == 0 && errors.Is(err, io.EOF) { - slog.Debug("Failed to receive request", "error", err) + slog.DebugContext(ctx, "Failed to receive request", "error", err) return } else if err != nil { - slog.Warn("Failed to receive request", "error", err) + slog.WarnContext(ctx, "Failed to receive request", "error", err) return } if n <= 0 { - slog.Warn("Failed to receive request") + slog.WarnContext(ctx, "Failed to receive request") return } total += n if total == cap(req) { - slog.Warn("Request is too big") + slog.WarnContext(ctx, "Request is too big") return } @@ -184,7 +184,7 @@ func (fl *Listener) handle(ctx context.Context, conn net.Conn) { // ListenAndServe handles Finger queries. func (fl *Listener) ListenAndServe(ctx context.Context) error { if fl.Config.RequireRegistration { - slog.Warn("Disabling the Finger listener because registration is required") + slog.WarnContext(ctx, "Disabling the Finger listener because registration is required") <-ctx.Done() return nil } @@ -207,7 +207,7 @@ func (fl *Listener) ListenAndServe(ctx context.Context) error { for ctx.Err() == nil { conn, err := l.Accept() if err != nil { - slog.Warn("Failed to accept a connection", "error", err) + slog.WarnContext(ctx, "Failed to accept a connection", "error", err) continue } diff --git a/front/follow.go b/front/follow.go index 426a94fd..fc9bd8cd 100644 --- a/front/follow.go +++ b/front/follow.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/front/text" ) @@ -33,20 +34,20 @@ func (h *Handler) follow(w text.Writer, r *Request, args ...string) { var exists int if err := h.DB.QueryRowContext(r.Context, `select exists (select 1 from persons where id = ?)`, followed).Scan(&exists); err != nil { - r.Log.Warn("Failed to check if user exists", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Failed to check if user exists", "followed", followed, "error", err) w.Error() return } if exists == 0 { - r.Log.Warn("Cannot follow a non-existing user", "followed", followed) + slog.WarnContext(r.Context, "Cannot follow a non-existing user", "followed", followed) w.Status(40, "No such user") return } var follows int if err := h.DB.QueryRowContext(r.Context, `select count(*) from follows where follower = ?`, r.User.ID).Scan(&follows); err != nil { - r.Log.Warn("Failed to count follows", "error", err) + slog.WarnContext(r.Context, "Failed to count follows", "error", err) w.Error() return } @@ -58,7 +59,7 @@ func (h *Handler) follow(w text.Writer, r *Request, args ...string) { var accepted sql.NullInt32 if err := h.DB.QueryRowContext(r.Context, `select accepted from follows where follower = ? and followed = ?`, r.User.ID, followed).Scan(&accepted); err != nil && !errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Failed to check if user is already followed", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Failed to check if user is already followed", "followed", followed, "error", err) w.Error() return } else if err == nil && accepted.Valid && accepted.Int32 == 1 { @@ -70,7 +71,7 @@ func (h *Handler) follow(w text.Writer, r *Request, args ...string) { } if err := h.Inbox.Follow(r.Context, r.User, r.Keys[1], followed); err != nil { - r.Log.Warn("Failed to follow user", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Failed to follow user", "followed", followed, "error", err) w.Error() return } diff --git a/front/followers.go b/front/followers.go index fb3fa82d..d3129285 100644 --- a/front/followers.go +++ b/front/followers.go @@ -18,6 +18,7 @@ package front import ( "database/sql" + "log/slog" "net/url" "strings" "time" @@ -52,7 +53,7 @@ func (h *Handler) followers(w text.Writer, r *Request, args ...string) { } if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Warn("Failed to toggle manual approval", "error", err) + slog.WarnContext(r.Context, "Failed to toggle manual approval", "error", err) w.Error() return } @@ -75,7 +76,7 @@ func (h *Handler) followers(w text.Writer, r *Request, args ...string) { r.User.ID, ) if err != nil { - r.Log.Warn("Failed to list followers", "error", err) + slog.WarnContext(r.Context, "Failed to list followers", "error", err) w.Error() return } @@ -88,7 +89,7 @@ func (h *Handler) followers(w text.Writer, r *Request, args ...string) { var follower ap.Actor var accepted sql.NullInt32 if err := rows.Scan(&inserted, &follower, &accepted); err != nil { - r.Log.Warn("Failed to list a follow request", "error", err) + slog.WarnContext(r.Context, "Failed to list a follow request", "error", err) continue } diff --git a/front/follows.go b/front/follows.go index 19a3fc91..10fff58d 100644 --- a/front/follows.go +++ b/front/follows.go @@ -18,6 +18,7 @@ package front import ( "database/sql" + "log/slog" "strings" "time" @@ -63,7 +64,7 @@ func (h *Handler) follows(w text.Writer, r *Request, args ...string) { r.User.ID, ) if err != nil { - r.Log.Warn("Failed to list followed users", "error", err) + slog.WarnContext(r.Context, "Failed to list followed users", "error", err) w.Error() return } @@ -80,7 +81,7 @@ func (h *Handler) follows(w text.Writer, r *Request, args ...string) { var last sql.NullInt64 var accepted sql.NullInt32 if err := rows.Scan(&actor, &last, &accepted); err != nil { - r.Log.Warn("Failed to list a followed user", "error", err) + slog.WarnContext(r.Context, "Failed to list a followed user", "error", err) continue } diff --git a/front/fts.go b/front/fts.go index 6a4ce01b..fba6e74b 100644 --- a/front/fts.go +++ b/front/fts.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "fmt" + "log/slog" "net/url" "regexp" "strconv" @@ -36,7 +37,7 @@ func (h *Handler) fts(w text.Writer, r *Request, args ...string) { query, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Info("Failed to decode query", "url", r.URL, "error", err) + slog.InfoContext(r.Context, "Failed to decode query", "url", r.URL, "error", err) w.Status(40, "Bad input") return } @@ -45,7 +46,7 @@ func (h *Handler) fts(w text.Writer, r *Request, args ...string) { if loc := skipRegex.FindStringSubmatchIndex(query); loc != nil { offset64, err := strconv.ParseInt(query[loc[2]:loc[3]], 10, 32) if err != nil { - r.Log.Info("Failed to parse offset", "query", query, "error", err) + slog.InfoContext(r.Context, "Failed to parse offset", "query", query, "error", err) w.Status(40, "Invalid offset") return } @@ -146,7 +147,7 @@ func (h *Handler) fts(w text.Writer, r *Request, args ...string) { ) } if err != nil { - r.Log.Warn("Failed to search for posts", "query", query, "error", err) + slog.WarnContext(r.Context, "Failed to search for posts", "query", query, "error", err) w.Error() return } diff --git a/front/gemini/gemini.go b/front/gemini/gemini.go index 8b8f38e5..43f22b06 100644 --- a/front/gemini/gemini.go +++ b/front/gemini/gemini.go @@ -37,6 +37,7 @@ import ( "github.com/dimkr/tootik/front" "github.com/dimkr/tootik/front/text/gmi" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" ) type Listener struct { @@ -87,7 +88,7 @@ func (gl *Listener) getUser(ctx context.Context, tlsConn *tls.Conn) (*ap.Actor, return nil, [2]httpsig.Key{}, fmt.Errorf("failed to decode Ed15519 private key for %s: %w", certHash, err) } - slog.Debug("Found existing user", "hash", certHash, "user", actor.ID) + slog.DebugContext(ctx, "Found existing user", "hash", certHash, "user", actor.ID) return &actor, [2]httpsig.Key{ {ID: actor.PublicKey.ID, PrivateKey: rsaPrivKey}, {ID: actor.AssertionMethod[0].ID, PrivateKey: ed25519PrivKey}, @@ -97,18 +98,18 @@ func (gl *Listener) getUser(ctx context.Context, tlsConn *tls.Conn) (*ap.Actor, // Handle handles a Gemini request. func (gl *Listener) Handle(ctx context.Context, conn net.Conn) { if err := conn.SetDeadline(time.Now().Add(gl.Config.GeminiRequestTimeout)); err != nil { - slog.Warn("Failed to set deadline", "error", err) + slog.WarnContext(ctx, "Failed to set deadline", "error", err) return } tlsConn, ok := conn.(*tls.Conn) if !ok { - slog.Warn("Invalid connection") + slog.WarnContext(ctx, "Invalid connection") return } if err := tlsConn.HandshakeContext(ctx); err != nil { - slog.Warn("Handshake failed", "error", err) + slog.WarnContext(ctx, "Handshake failed", "error", err) return } @@ -117,20 +118,20 @@ func (gl *Listener) Handle(ctx context.Context, conn net.Conn) { for { n, err := conn.Read(req[total : total+1]) if err != nil && total == 0 && errors.Is(err, io.EOF) { - slog.Debug("Failed to receive request", "error", err) + slog.DebugContext(ctx, "Failed to receive request", "error", err) return } else if err != nil { - slog.Warn("Failed to receive request", "error", err) + slog.WarnContext(ctx, "Failed to receive request", "error", err) return } if n <= 0 { - slog.Warn("Failed to receive request") + slog.WarnContext(ctx, "Failed to receive request") return } total += n if total == cap(req) { - slog.Warn("Request is too big") + slog.WarnContext(ctx, "Request is too big") return } @@ -147,7 +148,7 @@ func (gl *Listener) Handle(ctx context.Context, conn net.Conn) { var err error r.URL, err = url.Parse(string(req[:total-2])) if err != nil { - slog.Warn("Failed to parse request", "request", string(req[:total-2]), "error", err) + slog.WarnContext(ctx, "Failed to parse request", "request", string(req[:total-2]), "error", err) return } @@ -156,14 +157,14 @@ func (gl *Listener) Handle(ctx context.Context, conn net.Conn) { r.User, r.Keys, err = gl.getUser(ctx, tlsConn) if err != nil && errors.Is(err, front.ErrNotRegistered) && r.URL.Path == "/users" { - slog.Info("Redirecting new user") + slog.InfoContext(ctx, "Redirecting new user") w.Redirect("/users/register") return } else if errors.Is(err, front.ErrNotApproved) { w.Status(40, "Client certificate is awaiting approval") return } else if err != nil && !errors.Is(err, front.ErrNotRegistered) { - slog.Warn("Failed to get user", "error", err) + slog.WarnContext(ctx, "Failed to get user", "error", err) w.Error() return } else if err == nil && r.User == nil && r.URL.Path == "/users" { @@ -175,9 +176,9 @@ func (gl *Listener) Handle(ctx context.Context, conn net.Conn) { } if r.User == nil { - r.Log = slog.With(slog.Group("request", "path", r.URL.Path)) + r.Context = logcontext.Add(ctx, slog.Group("gemini_request", "path", r.URL.Path)) } else { - r.Log = slog.With(slog.Group("request", "path", r.URL.Path, "user", r.User.PreferredUsername)) + r.Context = logcontext.Add(ctx, slog.Group("gemini_request", "path", r.URL.Path, "user", r.User.PreferredUsername)) } gl.Handler.Handle(&r, w) @@ -213,7 +214,7 @@ func (gl *Listener) ListenAndServe(ctx context.Context) error { for ctx.Err() == nil { conn, err := l.Accept() if err != nil { - slog.Warn("Failed to accept a connection", "error", err) + slog.WarnContext(ctx, "Failed to accept a connection", "error", err) continue } diff --git a/front/gopher/gopher.go b/front/gopher/gopher.go index 0e4653d5..ee856d16 100644 --- a/front/gopher/gopher.go +++ b/front/gopher/gopher.go @@ -30,6 +30,7 @@ import ( "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/front" "github.com/dimkr/tootik/front/text/gmap" + "github.com/dimkr/tootik/logcontext" ) type Listener struct { @@ -41,7 +42,7 @@ type Listener struct { func (gl *Listener) handle(ctx context.Context, conn net.Conn) { if err := conn.SetDeadline(time.Now().Add(gl.Config.GopherRequestTimeout)); err != nil { - slog.Warn("Failed to set deadline", "error", err) + slog.WarnContext(ctx, "Failed to set deadline", "error", err) return } @@ -50,20 +51,20 @@ func (gl *Listener) handle(ctx context.Context, conn net.Conn) { for { n, err := conn.Read(req[total:]) if err != nil && total == 0 && errors.Is(err, io.EOF) { - slog.Debug("Failed to receive request", "error", err) + slog.DebugContext(ctx, "Failed to receive request", "error", err) return } else if err != nil { - slog.Warn("Failed to receive request", "error", err) + slog.WarnContext(ctx, "Failed to receive request", "error", err) return } if n <= 0 { - slog.Warn("Failed to receive request") + slog.WarnContext(ctx, "Failed to receive request") return } total += n if total == cap(req) { - slog.Warn("Request is too big") + slog.WarnContext(ctx, "Request is too big") return } @@ -77,19 +78,16 @@ func (gl *Listener) handle(ctx context.Context, conn net.Conn) { path = "/" } - r := front.Request{ - Context: ctx, - Body: conn, - } + var r front.Request var err error r.URL, err = url.Parse(path) if err != nil { - slog.Warn("Failed to parse request", "path", path, "error", err) + slog.WarnContext(ctx, "Failed to parse request", "path", path, "error", err) return } - r.Log = slog.With(slog.Group("request", "path", r.URL.Path)) + r.Context = logcontext.Add(ctx, slog.Group("gopher_request", "path", r.URL.Path)) w := gmap.Wrap(conn, gl.Domain, gl.Config) defer w.Flush() @@ -100,7 +98,7 @@ func (gl *Listener) handle(ctx context.Context, conn net.Conn) { // ListenAndServe handles Gopher requests. func (gl *Listener) ListenAndServe(ctx context.Context) error { if gl.Config.RequireRegistration { - slog.Warn("Disabling the Gopher listener because registration is required") + slog.WarnContext(ctx, "Disabling the Gopher listener because registration is required") <-ctx.Done() return nil } @@ -123,7 +121,7 @@ func (gl *Listener) ListenAndServe(ctx context.Context) error { for ctx.Err() == nil { conn, err := l.Accept() if err != nil { - slog.Warn("Failed to accept a connection", "error", err) + slog.WarnContext(ctx, "Failed to accept a connection", "error", err) continue } diff --git a/front/guppy/guppy.go b/front/guppy/guppy.go index 46fd8251..80f9d536 100644 --- a/front/guppy/guppy.go +++ b/front/guppy/guppy.go @@ -33,6 +33,7 @@ import ( "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/front" "github.com/dimkr/tootik/front/text/guppy" + "github.com/dimkr/tootik/logcontext" ) type Listener struct { @@ -74,21 +75,21 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks }() if req[len(req)-1] == '\r' && req[len(req)] == '\n' { - slog.Warn("Invalid request") + slog.WarnContext(ctx, "Invalid request") return } - r := front.Request{ - Context: ctx, - } + r := front.Request{} var err error r.URL, err = url.Parse(string(req[:len(req)-2])) if err != nil { - slog.Warn("Invalid request", "request", string(req[:len(req)-2]), "error", err) + slog.WarnContext(r.Context, "Invalid request", "request", string(req[:len(req)-2]), "error", err) return } + r.Context = logcontext.Add(ctx, slog.Group("guppy_request", "path", r.URL.Path, "from", from)) + seq := 6 + rand.IntN(math.MaxInt16/2) c := make(chan []byte) @@ -96,12 +97,10 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks var wg sync.WaitGroup wg.Go(func() { - if r.URL.Host != gl.Domain { w.Status(4, "Wrong host") } else { - slog.Info("Handling request", "path", r.URL.Path, "from", from) - r.Log = slog.With(slog.Group("request", "path", r.URL.Path)) + slog.InfoContext(r.Context, "Handling request") gl.Handler.Handle(&r, w) } @@ -114,7 +113,7 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks chunk, ok := <-c if !ok { - slog.Warn("Failed to read first respone chunk", "path", r.URL.Path, "from", from) + slog.WarnContext(r.Context, "Failed to read first respone chunk") return } @@ -132,45 +131,45 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks retry := time.NewTicker(retryInterval) defer retry.Stop() - slog.Debug("Sending response", "path", r.URL.Path, "from", from, "first", chunks[0].Seq) + slog.DebugContext(r.Context, "Sending response", "first", chunks[0].Seq) eofReceived := false for { select { case <-ctx.Done(): - slog.Warn("Session timed out", "path", r.URL.Path, "from", from) + slog.WarnContext(r.Context, "Session timed out") return case ack, ok := <-acks: if !ok { - slog.Warn("Session timed out", "path", r.URL.Path, "from", from) + slog.WarnContext(r.Context, "Session timed out") return } var ackedSeq int n, err := fmt.Sscanf(string(ack), "%d\r\n", &ackedSeq) if err != nil { - slog.Debug("Received invalid ack", "path", r.URL.Path, "from", from, "ack", string(ack), "error", err) + slog.DebugContext(r.Context, "Received invalid ack", "ack", string(ack), "error", err) continue } if n < 1 { - slog.Debug("Received invalid ack", "path", r.URL.Path, "from", from, "ack", string(ack)) + slog.DebugContext(r.Context, "Received invalid ack", "ack", string(ack)) continue } i := ackedSeq - chunks[0].Seq if i < 0 || i >= len(chunks) { - slog.Debug("Received invalid ack", "path", r.URL.Path, "from", from, "ack", string(ack)) + slog.DebugContext(r.Context, "Received invalid ack", "ack", string(ack)) continue } if chunks[i].Acked { - slog.Debug("Received duplicate ack", "path", r.URL.Path, "from", from, "acked", ackedSeq) + slog.DebugContext(r.Context, "Received duplicate ack", "acked", ackedSeq) continue } - slog.Debug("Marking packet as received", "path", r.URL.Path, "from", from, "acked", ackedSeq) + slog.DebugContext(r.Context, "Marking packet as received", "acked", ackedSeq) chunks[i].Acked = true // stop if the acked packet is the EOF packet @@ -203,9 +202,9 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks break } if chunks[i].Sent.IsZero() { - slog.Debug("Sending packet", "path", r.URL.Path, "from", from, "seq", chunks[i].Seq) + slog.DebugContext(r.Context, "Sending packet", "seq", chunks[i].Seq) } else { - slog.Debug("Resending packet", "path", r.URL.Path, "from", from, "seq", chunks[i].Seq) + slog.DebugContext(r.Context, "Resending packet", "seq", chunks[i].Seq) } s.WriteTo(chunks[i].Data, from) chunks[i].Sent = now @@ -217,7 +216,7 @@ func (gl *Listener) handle(ctx context.Context, from net.Addr, req []byte, acks // ListenAndServe handles Guppy requests. func (gl *Listener) ListenAndServe(ctx context.Context) error { if gl.Config.RequireRegistration { - slog.Warn("Disabling the Guppy listener because registration is required") + slog.WarnContext(ctx, "Disabling the Guppy listener because registration is required") <-ctx.Done() return nil } @@ -238,7 +237,7 @@ func (gl *Listener) ListenAndServe(ctx context.Context) error { for { n, from, err := l.ReadFrom(buf) if err != nil { - slog.Error("Failed to receive a packet", "error", err) + slog.ErrorContext(ctx, "Failed to receive a packet", "error", err) return } incoming <- incomingPacket{buf[:n], from} @@ -281,7 +280,7 @@ loop: continue } if len(sessions) > gl.Config.MaxGuppySessions { - slog.Warn("Too many sessions") + slog.WarnContext(ctx, "Too many sessions") l.WriteTo([]byte("4 Too many sessions\r\n"), pkt.From) continue } diff --git a/front/handler.go b/front/handler.go index d196861a..a6ffc345 100644 --- a/front/handler.go +++ b/front/handler.go @@ -20,6 +20,7 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "regexp" "sync" "time" @@ -191,7 +192,7 @@ func (h *Handler) Handle(r *Request, w text.Writer) { } } - r.Log.Warn("Received an invalid request") + slog.WarnContext(r.Context, "Received an invalid request") if r.URL.Scheme == "titan" && r.User == nil { w.Redirectf("gemini://%s/oops", h.Domain) diff --git a/front/hashtags.go b/front/hashtags.go index 0651b4b8..9c1a10b7 100644 --- a/front/hashtags.go +++ b/front/hashtags.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "fmt" + "log/slog" "github.com/dimkr/tootik/front/graph" "github.com/dimkr/tootik/front/text" @@ -30,7 +31,7 @@ func scanHashtags(r *Request, rows *sql.Rows) []string { for rows.Next() { var tag string if err := rows.Scan(&tag); err != nil { - r.Log.Warn("Failed to scan hashtag", "error", err) + slog.WarnContext(r.Context, "Failed to scan hashtag", "error", err) continue } @@ -88,7 +89,7 @@ func (h *Handler) hashtags(w text.Writer, r *Request, args ...string) { fmt.Sprintf("https://%s/%%", h.Domain), ) if err != nil { - r.Log.Warn("Failed to list hashtags", "error", err) + slog.WarnContext(r.Context, "Failed to list hashtags", "error", err) w.Error() return } @@ -120,7 +121,7 @@ func (h *Handler) hashtags(w text.Writer, r *Request, args ...string) { last desc limit 30 `) if err != nil { - r.Log.Warn("Failed to list hashtags", "error", err) + slog.WarnContext(r.Context, "Failed to list hashtags", "error", err) w.Error() return } @@ -152,7 +153,7 @@ func (h *Handler) hashtags(w text.Writer, r *Request, args ...string) { day desc `) if err != nil { - r.Log.Warn("Failed to list hashtags", "error", err) + slog.WarnContext(r.Context, "Failed to list hashtags", "error", err) w.Error() return } @@ -163,7 +164,7 @@ func (h *Handler) hashtags(w text.Writer, r *Request, args ...string) { var label string var value int64 if err := rows.Scan(&label, &value); err != nil { - r.Log.Warn("Failed to scan hashtag", "error", err) + slog.WarnContext(r.Context, "Failed to scan hashtag", "error", err) continue } diff --git a/front/input.go b/front/input.go index 937209c3..50c89e59 100644 --- a/front/input.go +++ b/front/input.go @@ -18,6 +18,7 @@ package front import ( "io" + "log/slog" "net/url" "strconv" @@ -59,32 +60,32 @@ func (h *Handler) readBody(w text.Writer, r *Request, args []string) (string, bo sizeStr = args[2] mimeType = "text/plain" } else { - r.Log.Warn("Invalid parameters") + slog.WarnContext(r.Context, "Invalid parameters") w.Status(40, "Invalid parameters") return "", false } if mimeType != "text/plain" { - r.Log.Warn("Content type is unsupported", "type", mimeType) + slog.WarnContext(r.Context, "Content type is unsupported", "type", mimeType) w.Status(40, "Only text/plain is supported") return "", false } size, err := strconv.ParseInt(sizeStr, 10, 64) if err != nil { - r.Log.Warn("Failed to parse content size", "error", err) + slog.WarnContext(r.Context, "Failed to parse content size", "error", err) w.Status(40, "Invalid size") return "", false } if size == 0 { - r.Log.Warn("Content is empty") + slog.WarnContext(r.Context, "Content is empty") w.Status(40, "Content is empty") return "", false } if size > int64(h.Config.MaxPostsLength)*4 { - r.Log.Warn("Content is too big", "size", size) + slog.WarnContext(r.Context, "Content is too big", "size", size) w.Status(40, "Content is too big") return "", false } @@ -92,13 +93,13 @@ func (h *Handler) readBody(w text.Writer, r *Request, args []string) (string, bo buf := make([]byte, size) n, err := io.ReadFull(r.Body, buf) if err != nil { - r.Log.Warn("Failed to read content", "error", err) + slog.WarnContext(r.Context, "Failed to read content", "error", err) w.Error() return "", false } if int64(n) != size { - r.Log.Warn("Content is truncated") + slog.WarnContext(r.Context, "Content is truncated") w.Error() return "", false } diff --git a/front/metadata.go b/front/metadata.go index 0d593750..d23f08cd 100644 --- a/front/metadata.go +++ b/front/metadata.go @@ -18,6 +18,7 @@ package front import ( "html" + "log/slog" "net/url" "regexp" "slices" @@ -76,7 +77,7 @@ func (h *Handler) metadataAdd(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to add metadata field", "can", can) + slog.WarnContext(r.Context, "Throttled request to add metadata field", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -93,14 +94,14 @@ func (h *Handler) metadataAdd(w text.Writer, r *Request, args ...string) { s, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to parse metadata field", "raw", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse metadata field", "raw", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } m := metadataRegex.FindStringSubmatch(s) if m == nil { - r.Log.Warn("Invalid metadata field", "field", s) + slog.WarnContext(r.Context, "Invalid metadata field", "field", s) w.Status(40, "Bad input") return } @@ -109,7 +110,7 @@ func (h *Handler) metadataAdd(w text.Writer, r *Request, args ...string) { for _, field := range r.User.Attachment { if field.Name == name { - r.Log.Error("Cannot add metadata field", "name", field.Name) + slog.ErrorContext(r.Context, "Cannot add metadata field", "name", field.Name) w.Status(40, "Cannot add metadata field") return } @@ -121,13 +122,13 @@ func (h *Handler) metadataAdd(w text.Writer, r *Request, args ...string) { Val: plain.ToHTML(m[2], nil), } - r.Log.Info("Adding metadata field", "name", attachment.Name) + slog.InfoContext(r.Context, "Adding metadata field", "name", attachment.Name) r.User.Attachment = append(r.User.Attachment, attachment) r.User.Updated.Time = now if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to add metadata field", "name", attachment.Name, "error", err) + slog.ErrorContext(r.Context, "Failed to add metadata field", "name", attachment.Name, "error", err) w.Error() return } @@ -148,7 +149,7 @@ func (h *Handler) metadataRemove(w text.Writer, r *Request, args ...string) { key, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to parse metadata field key", "raw", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse metadata field key", "raw", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } @@ -161,18 +162,18 @@ func (h *Handler) metadataRemove(w text.Writer, r *Request, args ...string) { } } - r.Log.Warn("Metadata field key does not exist", "raw", r.URL.RawQuery) + slog.WarnContext(r.Context, "Metadata field key does not exist", "raw", r.URL.RawQuery) w.Status(40, "Field does not exist") return found: - r.Log.Info("Removing metadata field", "key", key) + slog.InfoContext(r.Context, "Removing metadata field", "key", key) r.User.Attachment = slices.Delete(r.User.Attachment, id, id+1) r.User.Updated.Time = time.Now() if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to remove metadata field", "key", key, "id", id, "error", err) + slog.ErrorContext(r.Context, "Failed to remove metadata field", "key", key, "id", id, "error", err) w.Error() return } diff --git a/front/move.go b/front/move.go index 2572a707..62b9ff76 100644 --- a/front/move.go +++ b/front/move.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "net/url" "strings" "time" @@ -32,7 +33,7 @@ func (h *Handler) move(w text.Writer, r *Request, args ...string) { } if r.User.MovedTo != "" { - r.Log.Warn("User cannot be moved again", "movedTo", r.User.MovedTo) + slog.WarnContext(r.Context, "User cannot be moved again", "movedTo", r.User.MovedTo) w.Status(40, "Already moved to "+r.User.MovedTo) return } @@ -44,7 +45,7 @@ func (h *Handler) move(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to move account", "can", can) + slog.WarnContext(r.Context, "Throttled request to move account", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -56,39 +57,39 @@ func (h *Handler) move(w text.Writer, r *Request, args ...string) { target, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to decode move target", "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to decode move target", "query", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } tokens := strings.SplitN(target, "@", 3) if len(tokens) != 2 { - r.Log.Warn("Target is invalid", "target", target) + slog.WarnContext(r.Context, "Target is invalid", "target", target) w.Status(40, "Bad input") return } actor, err := h.Resolver.Resolve(r.Context, r.Keys, tokens[1], tokens[0], 0) if err != nil { - r.Log.Warn("Failed to resolve target", "target", target, "error", err) + slog.WarnContext(r.Context, "Failed to resolve target", "target", target, "error", err) w.Status(40, "Failed to resolve "+target) return } if !r.User.AlsoKnownAs.Contains(actor.ID) { - r.Log.Warn("Move source is not an alias for target", "target", target) + slog.WarnContext(r.Context, "Move source is not an alias for target", "target", target) w.Statusf(40, "%s is not an alias for %s", r.User.ID, actor.ID) return } if !actor.AlsoKnownAs.Contains(r.User.ID) { - r.Log.Warn("Move target is not an alias for source", "target", target) + slog.WarnContext(r.Context, "Move target is not an alias for source", "target", target) w.Statusf(40, "%s is not an alias for %s", actor.ID, r.User.ID) return } if err := h.Inbox.Move(r.Context, r.User, r.Keys[1], actor.ID); err != nil { - r.Log.Error("Failed to move user", "error", err) + slog.ErrorContext(r.Context, "Failed to move user", "error", err) w.Error() return } diff --git a/front/name.go b/front/name.go index 8df8818d..3efd4e55 100644 --- a/front/name.go +++ b/front/name.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "net/url" "strings" "time" @@ -61,7 +62,7 @@ func (h *Handler) setName(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to set name", "can", can) + slog.WarnContext(r.Context, "Throttled request to set name", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -93,7 +94,7 @@ func (h *Handler) setName(w text.Writer, r *Request, args ...string) { r.User.Updated.Time = now if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to update name", "error", err) + slog.ErrorContext(r.Context, "Failed to update name", "error", err) w.Error() return } diff --git a/front/outbox.go b/front/outbox.go index d3d4ba1b..34aa034b 100644 --- a/front/outbox.go +++ b/front/outbox.go @@ -20,6 +20,7 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "strings" "time" @@ -56,23 +57,23 @@ func (h *Handler) userOutbox(w text.Writer, r *Request, args ...string) { var actor ap.Actor if err := h.DB.QueryRowContext(r.Context, `select json(actor) from persons where id = ?`, actorID).Scan(&actor); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Info("Person was not found", "actor", actorID) + slog.InfoContext(r.Context, "Person was not found", "actor", actorID) w.Status(40, "User not found") return } else if err != nil { - r.Log.Warn("Failed to find person by ID", "actor", actorID, "error", err) + slog.WarnContext(r.Context, "Failed to find person by ID", "actor", actorID, "error", err) w.Error() return } offset, err := getOffset(r.URL) if err != nil { - r.Log.Info("Failed to parse query", "url", r.URL, "error", err) + slog.InfoContext(r.Context, "Failed to parse query", "url", r.URL, "error", err) w.Status(40, "Invalid query") return } - r.Log.Info("Viewing outbox", "actor", actorID, "offset", offset) + slog.InfoContext(r.Context, "Viewing outbox", "actor", actorID, "offset", offset) var rows *sql.Rows if actor.Type == ap.Group && r.User == nil { @@ -217,7 +218,7 @@ func (h *Handler) userOutbox(w text.Writer, r *Request, args ...string) { ) } if err != nil { - r.Log.Warn("Failed to fetch posts", "actor", actorID, "error", err) + slog.WarnContext(r.Context, "Failed to fetch posts", "actor", actorID, "error", err) w.Error() return } @@ -322,7 +323,7 @@ func (h *Handler) userOutbox(w text.Writer, r *Request, args ...string) { } else if errors.Is(err, sql.ErrNoRows) { w.Linkf("/users/follow/"+strings.TrimPrefix(actorID, "https://"), "⚡ Follow %s", actor.PreferredUsername) } else if err != nil { - r.Log.Warn("Failed to check if user is followed", "actor", actorID, "error", err) + slog.WarnContext(r.Context, "Failed to check if user is followed", "actor", actorID, "error", err) } else if accepted.Valid && accepted.Int32 == 0 { w.Linkf("/users/unfollow/"+strings.TrimPrefix(actorID, "https://"), "🔌 Unfollow %s (rejected)", actor.PreferredUsername) } else { diff --git a/front/page.go b/front/page.go index 0ba57386..eddee737 100644 --- a/front/page.go +++ b/front/page.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "fmt" + "log/slog" "net/url" "strconv" @@ -46,20 +47,20 @@ func getOffset(requestUrl *url.URL) (int, error) { func (h *Handler) showFeedPage(w text.Writer, r *Request, title string, query func(int) (*sql.Rows, error), printDaySeparators bool) { offset, err := getOffset(r.URL) if err != nil { - r.Log.Info("Failed to parse query", "url", r.URL, "error", err) + slog.InfoContext(r.Context, "Failed to parse query", "url", r.URL, "error", err) w.Status(40, "Invalid query") return } if offset > h.Config.MaxOffset { - r.Log.Warn("Offset is too big", "offset", offset) + slog.WarnContext(r.Context, "Offset is too big", "offset", offset) w.Statusf(40, "Offset must be <= %d", h.Config.MaxOffset) return } rows, err := query(offset) if err != nil { - r.Log.Warn("Failed to fetch posts", "error", err) + slog.WarnContext(r.Context, "Failed to fetch posts", "error", err) w.Error() return } diff --git a/front/portability.go b/front/portability.go index f8b74353..4fe1a41a 100644 --- a/front/portability.go +++ b/front/portability.go @@ -18,6 +18,7 @@ package front import ( "crypto/ed25519" + "log/slog" "net/url" "regexp" "slices" @@ -100,7 +101,7 @@ func (h *Handler) gatewayAdd(w text.Writer, r *Request, args ...string) { can = r.User.Updated.Time.Add(h.Config.MinActorEditInterval) } if now.Before(can) { - r.Log.Warn("Throttled request to add gateway", "can", can) + slog.WarnContext(r.Context, "Throttled request to add gateway", "can", can) w.Statusf(40, "Please wait for %s", time.Until(can).Truncate(time.Second).String()) return } @@ -117,13 +118,13 @@ func (h *Handler) gatewayAdd(w text.Writer, r *Request, args ...string) { gw, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to parse gateway", "raw", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse gateway", "raw", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } if !gatewayRegex.MatchString(gw) { - r.Log.Warn("Invalid gateway", "gateway", gw) + slog.WarnContext(r.Context, "Invalid gateway", "gateway", gw) w.Status(40, "Bad input") return } @@ -133,13 +134,13 @@ func (h *Handler) gatewayAdd(w text.Writer, r *Request, args ...string) { return } - r.Log.Info("Adding gateway", "gateway", gw) + slog.InfoContext(r.Context, "Adding gateway", "gateway", gw) r.User.Gateways = append(r.User.Gateways, "https://"+gw) r.User.Updated.Time = now if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to add gateway", "gateway", gw, "error", err) + slog.ErrorContext(r.Context, "Failed to add gateway", "gateway", gw, "error", err) w.Error() return } @@ -165,7 +166,7 @@ func (h *Handler) gatewayRemove(w text.Writer, r *Request, args ...string) { gw, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to parse gateway", "raw", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse gateway", "raw", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } @@ -185,18 +186,18 @@ func (h *Handler) gatewayRemove(w text.Writer, r *Request, args ...string) { } } - r.Log.Warn("Gateway does not exist", "gw", gw) + slog.WarnContext(r.Context, "Gateway does not exist", "gw", gw) w.Status(40, "Gateway does not exist") return found: - r.Log.Info("Removing gateway", "gateway", gw) + slog.InfoContext(r.Context, "Removing gateway", "gateway", gw) r.User.Gateways = slices.Delete(r.User.Gateways, id, id+1) r.User.Updated.Time = time.Now() if err := h.Inbox.UpdateActor(r.Context, r.User, r.Keys[1]); err != nil { - r.Log.Error("Failed to remove gateway", "gateway", gw, "id", id, "error", err) + slog.ErrorContext(r.Context, "Failed to remove gateway", "gateway", gw, "id", id, "error", err) w.Error() return } diff --git a/front/post.go b/front/post.go index b05e4509..942b4222 100644 --- a/front/post.go +++ b/front/post.go @@ -20,6 +20,7 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "regexp" "strings" "time" @@ -48,13 +49,13 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo if oldNote == nil { var today, last sql.NullInt64 if err := h.DB.QueryRowContext(r.Context, `select count(*), max(inserted) from outbox where activity->>'$.actor' = $1 and sender = $1 and activity->>'$.type' = 'Create' and inserted > $2`, r.User.ID, now.Add(-24*time.Hour).Unix()).Scan(&today, &last); err != nil { - r.Log.Warn("Failed to check if new post needs to be throttled", "error", err) + slog.WarnContext(r.Context, "Failed to check if new post needs to be throttled", "error", err) w.Error() return } if today.Valid && today.Int64 >= h.Config.MaxPostsPerDay { - r.Log.Warn("User has exceeded the daily posts quota", "posts", today.Int64) + slog.WarnContext(r.Context, "User has exceeded the daily posts quota", "posts", today.Int64) w.Status(40, "Reached daily posts quota") return } @@ -64,7 +65,7 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo can := t.Add(max(1, time.Duration(today.Int64/h.Config.PostThrottleFactor)) * h.Config.PostThrottleUnit) until := time.Until(can) if until > 0 { - r.Log.Warn("User is posting too frequently", "last", t, "can", can) + slog.WarnContext(r.Context, "User is posting too frequently", "last", t, "can", can) w.Statusf(40, "Please wait for %s", until.Truncate(time.Second).String()) return } @@ -86,7 +87,7 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo var err error postID, err = h.Inbox.NewID(r.User.ID, "post") if err != nil { - r.Log.Error("Failed to generate post ID", "error", err) + slog.ErrorContext(r.Context, "Failed to generate post ID", "error", err) w.Error() return } @@ -116,14 +117,14 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo if err != nil { if errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Failed to guess mentioned actor ID", "mention", mention[0]) + slog.WarnContext(r.Context, "Failed to guess mentioned actor ID", "mention", mention[0]) } else { - r.Log.Warn("Failed to guess mentioned actor ID", "mention", mention[0], "error", err) + slog.WarnContext(r.Context, "Failed to guess mentioned actor ID", "mention", mention[0], "error", err) } continue } - r.Log.Info("Adding mention", "name", mention[0], "actor", actorID) + slog.InfoContext(r.Context, "Adding mention", "name", mention[0], "actor", actorID) tags = append(tags, ap.Tag{Type: ap.Mention, Name: mention[0], Href: actorID}) cc.Add(actorID) } @@ -211,7 +212,7 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo if m := pollRegex.FindStringSubmatchIndex(note.Content); m != nil { optionNames := strings.SplitN(note.Content[m[4]:], pollOptionsDelimeter, h.Config.PollMaxOptions+1) if len(optionNames) < pollMinOptions || len(optionNames) > h.Config.PollMaxOptions { - r.Log.Info("Received invalid poll", "content", note.Content) + slog.InfoContext(r.Context, "Received invalid poll", "content", note.Content) w.Statusf(40, "Polls must have %d to %d options", pollMinOptions, h.Config.PollMaxOptions) return } @@ -257,7 +258,7 @@ func (h *Handler) post(w text.Writer, r *Request, oldNote *ap.Object, inReplyTo err = h.Inbox.Create(r.Context, h.Config, ¬e, r.User, r.Keys[1]) } if err != nil { - r.Log.Error("Failed to insert post", "error", err) + slog.ErrorContext(r.Context, "Failed to insert post", "error", err) if errors.Is(err, inbox.ErrDeliveryQueueFull) { w.Status(40, "Please try again later") } else { diff --git a/front/print.go b/front/print.go index 9cfd4c97..02275e35 100644 --- a/front/print.go +++ b/front/print.go @@ -225,7 +225,7 @@ func (h *Handler) getNoteContent(note *ap.Object, compact bool) ([]string, data. func (h *Handler) printCompactNote(w text.Writer, r *Request, note *ap.Object, author *ap.Actor, sharer *ap.Actor, published time.Time, printParentAuthor bool) { if note.AttributedTo == "" { - r.Log.Warn("Note has no author", "id", note.ID) + slog.WarnContext(r.Context, "Note has no author", "id", note.ID) return } @@ -233,12 +233,12 @@ func (h *Handler) printCompactNote(w text.Writer, r *Request, note *ap.Object, a var replies int if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where object->>'$.inReplyTo' = ?`, note.ID).Scan(&replies); err != nil { - r.Log.Warn("Failed to count replies", "id", note.ID, "error", err) + slog.WarnContext(r.Context, "Failed to count replies", "id", note.ID, "error", err) } var quotes int if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where object->>'$.quote' = ?`, note.ID).Scan("es); err != nil { - r.Log.Warn("Failed to count quotes", "id", note.ID, "error", err) + slog.WarnContext(r.Context, "Failed to count quotes", "id", note.ID, "error", err) } authorDisplayName := author.PreferredUsername @@ -257,9 +257,9 @@ func (h *Handler) printCompactNote(w text.Writer, r *Request, note *ap.Object, a var parentAuthor sql.Null[ap.Actor] if note.InReplyTo != "" { if err := h.DB.QueryRowContext(r.Context, `select json(persons.actor) from notes join persons on persons.id = notes.author where notes.id = ?`, note.InReplyTo).Scan(&parentAuthor); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Info("Parent post or author is missing", "id", note.InReplyTo) + slog.InfoContext(r.Context, "Parent post or author is missing", "id", note.InReplyTo) } else if err != nil { - r.Log.Warn("Failed to query parent post author", "id", note.InReplyTo, "error", err) + slog.WarnContext(r.Context, "Failed to query parent post author", "id", note.InReplyTo, "error", err) } } @@ -322,17 +322,17 @@ func (h *Handler) PrintNotes(w text.Writer, r *Request, rows *sql.Rows, printPar var sharer sql.Null[ap.Actor] var published int64 if err := rows.Scan(¬e, &author, &sharer, &published); err != nil { - r.Log.Warn("Failed to scan post", "error", err) + slog.WarnContext(r.Context, "Failed to scan post", "error", err) continue } if note.Type != ap.Note && note.Type != ap.Page && note.Type != ap.Article && note.Type != ap.Question { - r.Log.Warn("Post type is unsupported", "type", note.Type) + slog.WarnContext(r.Context, "Post type is unsupported", "type", note.Type) continue } if !author.Valid { - r.Log.Warn("Post author is unknown", "note", note.ID, "author", note.AttributedTo) + slog.WarnContext(r.Context, "Post author is unknown", "note", note.ID, "author", note.AttributedTo) continue } diff --git a/front/register.go b/front/register.go index 91a7edc3..0b65100f 100644 --- a/front/register.go +++ b/front/register.go @@ -20,6 +20,7 @@ import ( "crypto/ed25519" "crypto/tls" "database/sql" + "log/slog" "time" "github.com/dimkr/tootik/ap" @@ -30,14 +31,14 @@ import ( func (h *Handler) register(w text.Writer, r *Request, args ...string) { if r.User != nil { - r.Log.Warn("Registered user cannot register again") + slog.WarnContext(r.Context, "Registered user cannot register again") w.Statusf(40, "Already registered as %s", r.User.PreferredUsername) return } tlsConn, ok := w.Unwrap().(*tls.Conn) if !ok { - r.Log.Error("Invalid connection") + slog.ErrorContext(r.Context, "Invalid connection") w.Error() return } @@ -45,7 +46,7 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { state := tlsConn.ConnectionState() if len(state.PeerCertificates) == 0 { - r.Log.Warn("No client certificate") + slog.WarnContext(r.Context, "No client certificate") w.Redirect("/users") return } @@ -54,7 +55,7 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { userName := clientCert.Subject.CommonName if time.Now().After(clientCert.NotAfter) { - r.Log.Warn("Client certificate has expired", "name", userName, "expired", clientCert.NotAfter) + slog.WarnContext(r.Context, "Client certificate has expired", "name", userName, "expired", clientCert.NotAfter) w.Status(40, "Client certificate has expired") return } @@ -76,7 +77,7 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { var lastRegister sql.NullInt64 if err := h.DB.QueryRowContext(r.Context, `select max(inserted) from certificates`).Scan(&lastRegister); err != nil { - r.Log.Warn("Failed to check last registration time", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to check last registration time", "name", userName, "error", err) w.Error() return } @@ -89,7 +90,7 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { } } - r.Log.Info("Creating new user", "name", userName) + slog.InfoContext(r.Context, "Creating new user", "name", userName) switch r.URL.RawQuery { case "": @@ -97,14 +98,14 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { w.Status(10, "Create portable user? (y/n)") return } else if _, _, err := user.Create(r.Context, h.Domain, h.DB, h.Config, userName, ap.Person, clientCert); err != nil { - r.Log.Warn("Failed to create new user", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to create new user", "name", userName, "error", err) w.Status(40, "Failed to create new user") return } case "n": if _, _, err := user.Create(r.Context, h.Domain, h.DB, h.Config, userName, ap.Person, clientCert); err != nil { - r.Log.Warn("Failed to create new user", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to create new user", "name", userName, "error", err) w.Status(40, "Failed to create new user") return } @@ -125,13 +126,13 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { pub, priv, err := ed25519.GenerateKey(nil) if err != nil { - r.Log.Warn("Failed to generate key", "error", err) + slog.WarnContext(r.Context, "Failed to generate key", "error", err) w.Status(40, "Failed to generate key") return } if _, _, err := user.CreatePortable(r.Context, h.Domain, h.DB, h.Config, userName, clientCert, priv, data.EncodeEd25519PrivateKey(priv), pub); err != nil { - r.Log.Warn("Failed to create new portable user", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to create new portable user", "name", userName, "error", err) w.Status(40, "Failed to create new user") return } @@ -144,13 +145,13 @@ func (h *Handler) register(w text.Writer, r *Request, args ...string) { key, err := data.DecodeEd25519PrivateKey(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to decode Ed25519 private key", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to decode Ed25519 private key", "name", userName, "error", err) w.Statusf(40, "Invalid key: %s", err.Error()) return } if _, _, err := user.CreatePortable(r.Context, h.Domain, h.DB, h.Config, userName, clientCert, key, r.URL.RawQuery, key.Public().(ed25519.PublicKey)); err != nil { - r.Log.Warn("Failed to create new portable user", "name", userName, "error", err) + slog.WarnContext(r.Context, "Failed to create new portable user", "name", userName, "error", err) w.Status(40, "Failed to create new user") return } diff --git a/front/reject.go b/front/reject.go index 0bc5ccf1..499af14f 100644 --- a/front/reject.go +++ b/front/reject.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/front/text" ) @@ -33,7 +34,7 @@ func (h *Handler) reject(w text.Writer, r *Request, args ...string) { tx, err := h.DB.BeginTx(r.Context, nil) if err != nil { - r.Log.Warn("Failed to reject follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to reject follow request", "follower", follower, "error", err) w.Error() return } @@ -46,23 +47,23 @@ func (h *Handler) reject(w text.Writer, r *Request, args ...string) { follower, r.User.ID, ).Scan(&followID); errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Failed to fetch follow request to reject", "follower", follower) + slog.WarnContext(r.Context, "Failed to fetch follow request to reject", "follower", follower) w.Status(40, "No such follow request") return } else if err != nil { - r.Log.Warn("Failed to reject follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to reject follow request", "follower", follower, "error", err) w.Error() return } if err := h.Inbox.Reject(r.Context, r.User, r.Keys[1], follower, followID, tx); err != nil { - r.Log.Warn("Failed to reject follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to reject follow request", "follower", follower, "error", err) w.Error() return } if err := tx.Commit(); err != nil { - r.Log.Warn("Failed to reject follow request", "follower", follower, "error", err) + slog.WarnContext(r.Context, "Failed to reject follow request", "follower", follower, "error", err) w.Error() return } diff --git a/front/reply.go b/front/reply.go index 99c65494..44250496 100644 --- a/front/reply.go +++ b/front/reply.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/front/text" @@ -65,11 +66,11 @@ func (h *Handler) replyOrQuote(w text.Writer, r *Request, args []string, quote b postID, r.User.ID, ).Scan(¬e); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Post does not exist", "post", postID) + slog.WarnContext(r.Context, "Post does not exist", "post", postID) w.Status(40, "Post not found") return } else if err != nil { - r.Log.Warn("Failed to find post by ID", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to find post by ID", "post", postID, "error", err) w.Error() return } @@ -78,10 +79,10 @@ func (h *Handler) replyOrQuote(w text.Writer, r *Request, args []string, quote b cc := ap.Audience{} if quote { - r.Log.Info("Quoting post", "post", note.ID) + slog.InfoContext(r.Context, "Quoting post", "post", note.ID) if !note.CanQuote() { - r.Log.Warn("Post cannot be quoted", "post", postID) + slog.WarnContext(r.Context, "Post cannot be quoted", "post", postID) w.Status(40, "Post cannot be quoted") return } @@ -96,7 +97,7 @@ func (h *Handler) replyOrQuote(w text.Writer, r *Request, args []string, quote b return } - r.Log.Info("Replying to post", "post", note.ID) + slog.InfoContext(r.Context, "Replying to post", "post", note.ID) if note.AttributedTo == r.User.ID { to = note.To diff --git a/front/request.go b/front/request.go index c2fed2ae..1da3d049 100644 --- a/front/request.go +++ b/front/request.go @@ -19,7 +19,6 @@ package front import ( "context" "io" - "log/slog" "net/url" "github.com/dimkr/tootik/ap" @@ -34,9 +33,6 @@ type Request struct { // URL specifies the requested URL. URL *url.URL - // Log specifies a slog.Logger used while handling the request. - Log *slog.Logger - // Body optionally specifies an io.Reader to read the request body from. Body io.Reader diff --git a/front/resolve.go b/front/resolve.go index 0b95f1a1..d51dafe1 100644 --- a/front/resolve.go +++ b/front/resolve.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "net/url" "regexp" "strings" @@ -40,7 +41,7 @@ func (h *Handler) resolve(w text.Writer, r *Request, args ...string) { query, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Info("Failed to decode user name", "url", r.URL, "error", err) + slog.InfoContext(r.Context, "Failed to decode user name", "url", r.URL, "error", err) w.Status(40, "Bad input") return } @@ -63,11 +64,11 @@ func (h *Handler) resolve(w text.Writer, r *Request, args ...string) { host = h.Domain } - r.Log.Info("Resolving user ID", "host", host, "name", name) + slog.InfoContext(r.Context, "Resolving user ID", "host", host, "name", name) person, err := h.Resolver.Resolve(r.Context, r.Keys, host, name, flags) if err != nil { - r.Log.Warn("Failed to resolve user ID", "host", host, "name", name, "error", err) + slog.WarnContext(r.Context, "Failed to resolve user ID", "host", host, "name", name, "error", err) w.Statusf(40, "Failed to resolve %s@%s", name, host) return } diff --git a/front/revoke.go b/front/revoke.go index c305aec5..88c51f8f 100644 --- a/front/revoke.go +++ b/front/revoke.go @@ -1,5 +1,5 @@ /* -Copyright 2024 Dima Krasner +Copyright 2024, 2025 Dima Krasner Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -16,7 +16,11 @@ limitations under the License. package front -import "github.com/dimkr/tootik/front/text" +import ( + "log/slog" + + "github.com/dimkr/tootik/front/text" +) func (h *Handler) revoke(w text.Writer, r *Request, args ...string) { if r.User == nil { @@ -26,7 +30,7 @@ func (h *Handler) revoke(w text.Writer, r *Request, args ...string) { hash := args[1] - r.Log.Info("Revoking certificate", "user", r.User.PreferredUsername, "hash", hash) + slog.InfoContext(r.Context, "Revoking certificate", "user", r.User.PreferredUsername, "hash", hash) if res, err := h.DB.ExecContext( r.Context, @@ -37,15 +41,15 @@ func (h *Handler) revoke(w text.Writer, r *Request, args ...string) { r.User.PreferredUsername, hash, ); err != nil { - r.Log.Warn("Failed to revoke certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) + slog.WarnContext(r.Context, "Failed to revoke certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) w.Error() return } else if n, err := res.RowsAffected(); err != nil { - r.Log.Warn("Failed to revoke certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) + slog.WarnContext(r.Context, "Failed to revoke certificate", "user", r.User.PreferredUsername, "hash", hash, "error", err) w.Error() return } else if n == 0 { - r.Log.Warn("Certificate doesn't exist or already revoked", "user", r.User.PreferredUsername, "hash", hash) + slog.WarnContext(r.Context, "Certificate doesn't exist or already revoked", "user", r.User.PreferredUsername, "hash", hash) w.Status(40, "Cannot revoke certificate") return } diff --git a/front/search.go b/front/search.go index 91d990ab..63728646 100644 --- a/front/search.go +++ b/front/search.go @@ -17,6 +17,7 @@ limitations under the License. package front import ( + "log/slog" "net/url" "github.com/dimkr/tootik/front/text" @@ -30,7 +31,7 @@ func search(w text.Writer, r *Request, args ...string) { hashtag, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Info("Failed to decode query", "url", r.URL, "error", err) + slog.InfoContext(r.Context, "Failed to decode query", "url", r.URL, "error", err) w.Status(40, "Bad input") return } diff --git a/front/share.go b/front/share.go index 7ec148f3..d99d7b3f 100644 --- a/front/share.go +++ b/front/share.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "time" "github.com/dimkr/tootik/ap" @@ -52,41 +53,41 @@ func (h *Handler) share(w text.Writer, r *Request, args ...string) { var note ap.Object if err := h.DB.QueryRowContext(r.Context, `select json(object) from notes where id = $1 and public = 1 and author != $2 and not exists (select 1 from shares where note = notes.id and by = $2)`, postID, r.User.ID).Scan(¬e); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Attempted to share non-existing post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Attempted to share non-existing post", "post", postID, "error", err) w.Error() return } else if err != nil { - r.Log.Warn("Failed to fetch post to share", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to fetch post to share", "post", postID, "error", err) w.Error() return } if throttle, err := h.shouldThrottleShare(r); err != nil { - r.Log.Warn("Failed to check if share needs to be throttled", "error", err) + slog.WarnContext(r.Context, "Failed to check if share needs to be throttled", "error", err) w.Error() return } else if throttle { - r.Log.Warn("User is sharing and unsharing too frequently") + slog.WarnContext(r.Context, "User is sharing and unsharing too frequently") w.Status(40, "Please wait before sharing") return } tx, err := h.DB.BeginTx(r.Context, nil) if err != nil { - r.Log.Warn("Failed to share post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to share post", "post", postID, "error", err) w.Error() return } defer tx.Rollback() if err := h.Inbox.Announce(r.Context, tx, r.User, r.Keys[1], ¬e); err != nil { - r.Log.Warn("Failed to share post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to share post", "post", postID, "error", err) w.Error() return } if err := tx.Commit(); err != nil { - r.Log.Warn("Failed to share post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to share post", "post", postID, "error", err) w.Error() return } diff --git a/front/status.go b/front/status.go index 1e03da6b..630a6563 100644 --- a/front/status.go +++ b/front/status.go @@ -18,6 +18,7 @@ package front import ( "database/sql" + "log/slog" "time" "github.com/dimkr/tootik/ap" @@ -28,7 +29,7 @@ import ( func (h *Handler) getGraph(r *Request, keys []string, values []int64, query string, args ...any) string { rows, err := h.DB.QueryContext(r.Context, query, args...) if err != nil { - r.Log.Warn("Failed to data points", "query", query, "error", err) + slog.WarnContext(r.Context, "Failed to data points", "query", query, "error", err) return "" } defer rows.Close() @@ -36,7 +37,7 @@ func (h *Handler) getGraph(r *Request, keys []string, values []int64, query stri i := 0 for rows.Next() { if err := rows.Scan(&keys[i], &values[i]); err != nil { - r.Log.Warn("Failed to data point", "error", err) + slog.WarnContext(r.Context, "Failed to data point", "error", err) i++ continue } @@ -120,67 +121,67 @@ func (h *Handler) status(w text.Writer, r *Request, args ...string) { var outboxSize, inboxSize int if err := h.DB.QueryRowContext(r.Context, `select count(*) from persons where host = ?`, h.Domain).Scan(&usersCount); err != nil { - r.Log.Info("Failed to get users count", "error", err) + slog.InfoContext(r.Context, "Failed to get users count", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where host = ?`, h.Domain).Scan(&postsCount); err != nil { - r.Log.Info("Failed to get posts count", "error", err) + slog.InfoContext(r.Context, "Failed to get posts count", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where host = ? and inserted >= unixepoch() - 24*60*60`, h.Domain).Scan(&postsToday); err != nil { - r.Log.Info("Failed to get daily posts count", "error", err) + slog.InfoContext(r.Context, "Failed to get daily posts count", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where host != ?`, h.Domain).Scan(&federatedPostsCount); err != nil { - r.Log.Info("Failed to get federated posts count", "error", err) + slog.InfoContext(r.Context, "Failed to get federated posts count", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(*) from notes where host != ? and inserted >= unixepoch() - 24*60*60`, h.Domain).Scan(&federatedPostsToday); err != nil { - r.Log.Info("Failed to get daily federated posts count", "error", err) + slog.InfoContext(r.Context, "Failed to get daily federated posts count", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select max(inserted) from notes where host = ?`, h.Domain).Scan(&lastPost); err != nil { - r.Log.Info("Failed to get last post time", "error", err) + slog.InfoContext(r.Context, "Failed to get last post time", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select max(inserted) from notes where host != ?`, h.Domain).Scan(&lastFederatedPost); err != nil { - r.Log.Info("Failed to get last federated post time", "error", err) + slog.InfoContext(r.Context, "Failed to get last federated post time", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select max(inserted) from persons where host = ?`, h.Domain).Scan(&lastRegister); err != nil { - r.Log.Info("Failed to get last post time", "error", err) + slog.InfoContext(r.Context, "Failed to get last post time", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select max(max(inserted), max(updated)) from persons where host != ?`, h.Domain).Scan(&lastFederatedUser); err != nil { - r.Log.Info("Failed to get last post time", "error", err) + slog.InfoContext(r.Context, "Failed to get last post time", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(*) from inbox`).Scan(&inboxSize); err != nil { - r.Log.Info("Failed to get activities queue size", "error", err) + slog.InfoContext(r.Context, "Failed to get activities queue size", "error", err) w.Error() return } if err := h.DB.QueryRowContext(r.Context, `select count(distinct cid) from outbox where sent = 0 and attempts < ?`, h.Config.MaxDeliveryAttempts).Scan(&outboxSize); err != nil { - r.Log.Info("Failed to get delivery queue size", "error", err) + slog.InfoContext(r.Context, "Failed to get delivery queue size", "error", err) w.Error() return } diff --git a/front/ttl.go b/front/ttl.go index 9abefcc1..9779391f 100644 --- a/front/ttl.go +++ b/front/ttl.go @@ -18,6 +18,7 @@ package front import ( "database/sql" + "log/slog" "net/url" "strconv" @@ -40,27 +41,27 @@ func (h *Handler) ttl(w text.Writer, r *Request, args ...string) { `select ttl from persons where id = ?`, r.User.ID, ).Scan(&ttl); err != nil { - r.Log.Warn("Failed to fetch TTL", "error", err) + slog.WarnContext(r.Context, "Failed to fetch TTL", "error", err) w.Error() return } } else { s, err := url.QueryUnescape(r.URL.RawQuery) if err != nil { - r.Log.Warn("Failed to decode number of days", "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to decode number of days", "query", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } days, err := strconv.ParseInt(s, 10, 64) if err != nil { - r.Log.Warn("Failed to parse number of days", "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse number of days", "query", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } if days < 0 || days > maxDays { - r.Log.Warn("Failed to parse number of days", "query", r.URL.RawQuery, "error", err) + slog.WarnContext(r.Context, "Failed to parse number of days", "query", r.URL.RawQuery, "error", err) w.Status(40, "Bad input") return } @@ -72,7 +73,7 @@ func (h *Handler) ttl(w text.Writer, r *Request, args ...string) { days, r.User.ID, ); err != nil { - r.Log.Error("Failed to set TTL", "error", err) + slog.ErrorContext(r.Context, "Failed to set TTL", "error", err) w.Error() return } @@ -84,7 +85,7 @@ func (h *Handler) ttl(w text.Writer, r *Request, args ...string) { `update persons set ttl = null where id = ?`, r.User.ID, ); err != nil { - r.Log.Error("Failed to clear TTL", "error", err) + slog.ErrorContext(r.Context, "Failed to clear TTL", "error", err) w.Error() return } diff --git a/front/unbookmark.go b/front/unbookmark.go index ae14df01..73112352 100644 --- a/front/unbookmark.go +++ b/front/unbookmark.go @@ -1,5 +1,5 @@ /* -Copyright 2024 Dima Krasner +Copyright 2024, 2025 Dima Krasner Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -16,7 +16,11 @@ limitations under the License. package front -import "github.com/dimkr/tootik/front/text" +import ( + "log/slog" + + "github.com/dimkr/tootik/front/text" +) func (h *Handler) unbookmark(w text.Writer, r *Request, args ...string) { if r.User == nil { @@ -27,7 +31,7 @@ func (h *Handler) unbookmark(w text.Writer, r *Request, args ...string) { postID := "https://" + args[1] if _, err := h.DB.ExecContext(r.Context, `delete from bookmarks where note = ? and by = ?`, postID, r.User.ID); err != nil { - r.Log.Warn("Failed to delete bookmark", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to delete bookmark", "post", postID, "error", err) w.Error() return } diff --git a/front/unfollow.go b/front/unfollow.go index 40966430..d4d4d78d 100644 --- a/front/unfollow.go +++ b/front/unfollow.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/front/text" ) @@ -33,17 +34,17 @@ func (h *Handler) unfollow(w text.Writer, r *Request, args ...string) { var followID string if err := h.DB.QueryRowContext(r.Context, `select follows.id from persons join follows on persons.id = follows.followed where persons.id = ? and follows.follower = ?`, followed, r.User.ID).Scan(&followID); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Cannot undo a non-existing follow", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Cannot undo a non-existing follow", "followed", followed, "error", err) w.Status(40, "No such follow") return } else if err != nil { - r.Log.Warn("Failed to find followed user", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Failed to find followed user", "followed", followed, "error", err) w.Error() return } if err := h.Inbox.Unfollow(r.Context, r.User, r.Keys[1], followed, followID); err != nil { - r.Log.Warn("Failed undo follow", "followed", followed, "error", err) + slog.WarnContext(r.Context, "Failed undo follow", "followed", followed, "error", err) w.Error() return } diff --git a/front/unshare.go b/front/unshare.go index bf7fe33e..bb8a875c 100644 --- a/front/unshare.go +++ b/front/unshare.go @@ -19,6 +19,7 @@ package front import ( "database/sql" "errors" + "log/slog" "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/front/text" @@ -34,17 +35,17 @@ func (h *Handler) unshare(w text.Writer, r *Request, args ...string) { var share ap.Activity if err := h.DB.QueryRowContext(r.Context, `select json(activity) from outbox where activity->>'$.actor' = $1 and sender = $1 and activity->>'$.type' = 'Announce' and activity->>'$.object' = $2`, r.User.ID, postID).Scan(&share); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Attempted to unshare non-existing share", "post", postID, "error", err) + slog.WarnContext(r.Context, "Attempted to unshare non-existing share", "post", postID, "error", err) w.Error() return } else if err != nil { - r.Log.Warn("Failed to fetch share to unshare", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to fetch share to unshare", "post", postID, "error", err) w.Error() return } if err := h.Inbox.Undo(r.Context, r.User, r.Keys[1], &share); err != nil { - r.Log.Warn("Failed to unshare post", "post", postID, "error", err) + slog.WarnContext(r.Context, "Failed to unshare post", "post", postID, "error", err) w.Error() return } diff --git a/front/view.go b/front/view.go index d8bec6de..63844b9e 100644 --- a/front/view.go +++ b/front/view.go @@ -20,6 +20,7 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "net/url" "strings" "time" @@ -34,12 +35,12 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { offset, err := getOffset(r.URL) if err != nil { - r.Log.Info("Failed to parse query", "error", err) + slog.InfoContext(r.Context, "Failed to parse query", "error", err) w.Status(40, "Invalid query") return } - r.Log.Info("Viewing post", "post", postID) + slog.InfoContext(r.Context, "Viewing post", "post", postID) var note ap.Object var author ap.Actor @@ -94,11 +95,11 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { ).Scan(¬e, &author, &group) } if err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Info("Post was not found", "post", postID) + slog.InfoContext(r.Context, "Post was not found", "post", postID) w.Status(40, "Post not found") return } else if err != nil { - r.Log.Info("Failed to find post", "post", postID, "error", err) + slog.InfoContext(r.Context, "Failed to find post", "post", postID, "error", err) w.Error() return } @@ -137,7 +138,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { note.InReplyTo, h.Config.PostContextDepth, ); err != nil { - r.Log.Warn("Failed to fetch context", "error", err) + slog.WarnContext(r.Context, "Failed to fetch context", "error", err) } else { defer parents.Close() @@ -147,7 +148,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { var parentAuthor ap.Actor var currentDepth int if err := parents.Scan(&parent, &parentAuthor, ¤tDepth); err != nil { - r.Log.Info("Failed to fetch context", "error", err) + slog.InfoContext(r.Context, "Failed to fetch context", "error", err) break } @@ -200,7 +201,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { } if err := parents.Err(); err != nil { - r.Log.Info("Failed to fetch context", "error", err) + slog.InfoContext(r.Context, "Failed to fetch context", "error", err) } } @@ -221,10 +222,10 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { for mentionID := range mentionedUsers.Keys() { var mentionUserName string if err := h.DB.QueryRowContext(r.Context, `select actor->>'$.preferredUsername' from persons where id = ?`, mentionID).Scan(&mentionUserName); err != nil && errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Mentioned user is unknown", "mention", mentionID) + slog.WarnContext(r.Context, "Mentioned user is unknown", "mention", mentionID) continue } else if err != nil { - r.Log.Warn("Failed to get mentioned user name", "mention", mentionID, "error", err) + slog.WarnContext(r.Context, "Failed to get mentioned user name", "mention", mentionID, "error", err) continue } @@ -308,12 +309,12 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { ) } if err != nil && !errors.Is(err, sql.ErrNoRows) { - r.Log.Warn("Failed to query sharers", "error", err) + slog.WarnContext(r.Context, "Failed to query sharers", "error", err) } else if err == nil { for rows.Next() { var sharerID, sharerName string if err := rows.Scan(&sharerID, &sharerName); err != nil { - r.Log.Warn("Failed to scan sharer", "error", err) + slog.WarnContext(r.Context, "Failed to scan sharer", "error", err) continue } links.Store("/users/outbox/"+strings.TrimPrefix(sharerID, "https://"), "🔄 "+sharerName) @@ -334,12 +335,12 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { note.ID, h.Config.QuotesPerPost, ); err != nil { - r.Log.Warn("Failed to query quotes", "error", err) + slog.WarnContext(r.Context, "Failed to query quotes", "error", err) } else { for quotes.Next() { var quoteID, quoter string if err := quotes.Scan("eID, "er); err != nil { - r.Log.Warn("Failed to scan quoter", "error", err) + slog.WarnContext(r.Context, "Failed to scan quoter", "error", err) } else if r.User == nil { links.Store("/view/"+strings.TrimPrefix(quoteID, "https://"), "♻️ "+quoter) } else { @@ -388,7 +389,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { for tag := range hashtags.Values() { var exists int if err := h.DB.QueryRowContext(r.Context, `select exists (select 1 from hashtags where hashtag = ? and note != ?)`, tag, note.ID).Scan(&exists); err != nil { - r.Log.Warn("Failed to check if hashtag is used by other posts", "note", note.ID, "hashtag", tag) + slog.WarnContext(r.Context, "Failed to check if hashtag is used by other posts", "note", note.ID, "hashtag", tag) continue } @@ -419,7 +420,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { if r.User != nil && note.IsPublic() && ap.Canonical(note.AttributedTo) != ap.Canonical(r.User.ID) { var shared int if err := h.DB.QueryRowContext(r.Context, `select exists (select 1 from shares where note = ? and by = ?)`, note.ID, r.User.ID).Scan(&shared); err != nil { - r.Log.Warn("Failed to check if post is shared", "id", note.ID, "error", err) + slog.WarnContext(r.Context, "Failed to check if post is shared", "id", note.ID, "error", err) } else if shared == 0 { w.Link("/users/share/"+strings.TrimPrefix(note.ID, "https://"), "🔁 Share") } else { @@ -430,7 +431,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { if r.User != nil { var bookmarked int if err := h.DB.QueryRowContext(r.Context, `select exists (select 1 from bookmarks where note = ? and by = ?)`, note.ID, r.User.ID).Scan(&bookmarked); err != nil { - r.Log.Warn("Failed to check if post is bookmarked", "id", note.ID, "error", err) + slog.WarnContext(r.Context, "Failed to check if post is bookmarked", "id", note.ID, "error", err) } else if bookmarked == 0 { w.Link("/users/bookmark/"+strings.TrimPrefix(note.ID, "https://"), "🔖 Bookmark") } else { @@ -492,7 +493,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { ).Scan("e, "eAuthor); errors.Is(err, sql.ErrNoRows) { w.Text("[Missing]") } else if err != nil { - r.Log.Warn("Failed to scan quote", "error", err) + slog.WarnContext(r.Context, "Failed to scan quote", "error", err) w.Text("[Error]") } else { if r.User == nil { @@ -572,7 +573,7 @@ func (h *Handler) view(w text.Writer, r *Request, args ...string) { ) } if err != nil { - r.Log.Warn("Failed to fetch replies", "error", err) + slog.WarnContext(r.Context, "Failed to fetch replies", "error", err) } else { count = h.PrintNotes(w, r, replies, false, false, "No replies.") replies.Close() diff --git a/inbox/forward.go b/inbox/forward.go index 53741e85..21908266 100644 --- a/inbox/forward.go +++ b/inbox/forward.go @@ -88,7 +88,7 @@ func (inbox *Inbox) forwardToGroup(ctx context.Context, tx *sql.Tx, note *ap.Obj return true, nil } - slog.Info("Forwarding post to group followers", "activity", activity.ID, "note", note.ID, "group", group.ID) + slog.InfoContext(ctx, "Forwarding post to group followers", "activity", activity.ID, "note", note.ID, "group", group.ID) if _, err := tx.ExecContext( ctx, @@ -139,13 +139,13 @@ func (inbox *Inbox) forwardActivity(ctx context.Context, tx *sql.Tx, note *ap.Ob var depth int if err := tx.QueryRowContext(ctx, `with recursive thread(id, author, parent, depth) as (select notes.id, notes.author, notes.object->>'$.inReplyTo' as parent, 1 as depth from notes where id = $1 union all select notes.id, notes.author, notes.object->>'$.inReplyTo' as parent, t.depth + 1 from thread t join notes on notes.id = t.parent where t.depth <= $2) select id, author, depth from thread order by depth desc limit 1`, note.ID, inbox.Config.MaxForwardingDepth+1).Scan(&firstPostID, &threadStarterID, &depth); err != nil && errors.Is(err, sql.ErrNoRows) { - slog.Info("Failed to find thread for post", "activity", activity.ID, "note", note.ID) + slog.InfoContext(ctx, "Failed to find thread for post", "activity", activity.ID, "note", note.ID) return nil } else if err != nil { return fmt.Errorf("failed to fetch first post in thread: %w", err) } if depth > inbox.Config.MaxForwardingDepth { - slog.Debug("Thread exceeds depth limit for forwarding", "activity", activity.ID, "note", note.ID) + slog.DebugContext(ctx, "Thread exceeds depth limit for forwarding", "activity", activity.ID, "note", note.ID) return nil } @@ -163,7 +163,7 @@ func (inbox *Inbox) forwardActivity(ctx context.Context, tx *sql.Tx, note *ap.Ob } if err := tx.QueryRowContext(ctx, `select id from persons where cid = ? and ed25519privkey is not null`, ap.Canonical(threadStarterID)).Scan(&threadStarterID); errors.Is(err, sql.ErrNoRows) { - slog.Debug("Thread starter is federated", "activity", activity.ID, "note", note.ID) + slog.DebugContext(ctx, "Thread starter is federated", "activity", activity.ID, "note", note.ID) return nil } else if err != nil { return err @@ -174,7 +174,7 @@ func (inbox *Inbox) forwardActivity(ctx context.Context, tx *sql.Tx, note *ap.Ob return err } if shouldForward == 0 { - slog.Debug("Activity does not need to be forwarded", "activity", activity.ID, "note", note.ID) + slog.DebugContext(ctx, "Activity does not need to be forwarded", "activity", activity.ID, "note", note.ID) return nil } @@ -187,6 +187,6 @@ func (inbox *Inbox) forwardActivity(ctx context.Context, tx *sql.Tx, note *ap.Ob return err } - slog.Info("Forwarding activity to followers of thread starter", "domain", inbox.Domain, "activity", activity.ID, "note", note.ID, "thread", firstPostID, "starter", threadStarterID) + slog.InfoContext(ctx, "Forwarding activity to followers of thread starter", "domain", inbox.Domain, "activity", activity.ID, "note", note.ID, "thread", firstPostID, "starter", threadStarterID) return nil } diff --git a/inbox/inbox.go b/inbox/inbox.go index 9fbd63e1..ca9b3c0f 100644 --- a/inbox/inbox.go +++ b/inbox/inbox.go @@ -59,7 +59,7 @@ func (inbox *Inbox) processCreateActivity(ctx context.Context, tx *sql.Tx, sende } if len(post.To.OrderedMap)+len(post.CC.OrderedMap) > inbox.Config.MaxRecipients { - slog.Warn("Post has too many recipients", "activity", activity, "to", len(post.To.OrderedMap), "cc", len(post.CC.OrderedMap)) + slog.WarnContext(ctx, "Post has too many recipients", "to", len(post.To.OrderedMap), "cc", len(post.CC.OrderedMap)) return nil } @@ -99,7 +99,7 @@ func (inbox *Inbox) processCreateActivity(ctx context.Context, tx *sql.Tx, sende } } - slog.Debug("Post is a duplicate", "activity", activity, "post", post.ID) + slog.DebugContext(ctx, "Post is a duplicate", "post", post.ID) return nil } @@ -128,7 +128,7 @@ func (inbox *Inbox) processCreateActivity(ctx context.Context, tx *sql.Tx, sende return fmt.Errorf("cannot forward %s: %w", post.ID, err) } - slog.Info("Received a new post", "activity", activity, "post", post.ID) + slog.InfoContext(ctx, "Received a new post", "post", post.ID) return nil } @@ -138,7 +138,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return ErrActivityTooNested } - slog.Debug("Processing activity", "activity", activity) + slog.DebugContext(ctx, "Processing activity") switch activity.Type { case ap.Delete: @@ -152,7 +152,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return errors.New("received an invalid delete activity") } - slog.Info("Received delete request", "activity", activity, "deleted", deleted) + slog.InfoContext(ctx, "Received delete request", "deleted", deleted) if deleted == activity.Actor { if _, err := tx.ExecContext(ctx, `delete from persons where id = ?`, deleted); err != nil { @@ -161,7 +161,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. } else { var note ap.Object if err := tx.QueryRowContext(ctx, `select json(object) from notes where id = ?`, deleted).Scan(¬e); err != nil && errors.Is(err, sql.ErrNoRows) { - slog.Debug("Received delete request for non-existing post", "activity", activity, "deleted", deleted) + slog.DebugContext(ctx, "Received delete request for non-existing post", "deleted", deleted) return nil } else if err != nil { return fmt.Errorf("failed to delete %s: %w", deleted, err) @@ -218,7 +218,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. } if !ed25519PrivKeyMultibase.Valid || followed.ManuallyApprovesFollowers { - slog.Info("Not approving follow request", "activity", activity, "follower", activity.Actor, "followed", followed.ID) + slog.InfoContext(ctx, "Not approving follow request", "follower", activity.Actor, "followed", followed.ID) if _, err := tx.ExecContext( ctx, @@ -230,7 +230,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return fmt.Errorf("failed to insert follow %s: %w", activity.ID, err) } } else if ed25519PrivKeyMultibase.Valid && !followed.ManuallyApprovesFollowers { - slog.Info("Approving follow request", "activity", activity, "follower", activity.Actor, "followed", followed.ID) + slog.InfoContext(ctx, "Approving follow request", "follower", activity.Actor, "followed", followed.ID) if _, err := tx.ExecContext( ctx, @@ -267,7 +267,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return errors.New("received an invalid Accept") } - slog.Info("Follow is accepted", "activity", activity, "follow", followID) + slog.InfoContext(ctx, "Follow is accepted", "follow", followID) if _, err := tx.ExecContext( ctx, @@ -294,7 +294,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. } } - slog.Info("Follow is rejected", "activity", activity, "follow", followID) + slog.InfoContext(ctx, "Follow is rejected", "follow", followID) if res, err := tx.ExecContext(ctx, `update follows set accepted = 0 where id = ? and followed = ? and (accepted is null or accepted = 1)`, followID, sender.ID); err != nil { return fmt.Errorf("failed to reject follow %s: %w", followID, err) @@ -327,7 +327,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. } if inner.Type != ap.Follow { - slog.Debug("Ignoring request to undo a non-Follow activity", "activity", activity) + slog.DebugContext(ctx, "Ignoring request to undo a non-Follow activity") return nil } @@ -355,7 +355,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return fmt.Errorf("failed to remove follow of %s by %s: %w", followed, follower, err) } - slog.Info("Removed a Follow", "activity", activity, "follower", follower, "followed", followed) + slog.InfoContext(ctx, "Removed a Follow", "follower", follower, "followed", followed) case ap.Create: post, ok := activity.Object.(*ap.Object) @@ -379,7 +379,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return fmt.Errorf("cannot insert share for %s by %s: %w", postID, sender.ID, err) } } else { - slog.Debug("Ignoring unsupported Announce object", "activity", activity) + slog.DebugContext(ctx, "Ignoring unsupported Announce object") } return nil } @@ -390,7 +390,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. case ap.Update: post, ok := activity.Object.(*ap.Object) if !ok || ap.Canonical(post.ID) == ap.Canonical(activity.Actor) || ap.Canonical(post.ID) == ap.Canonical(sender.ID) { - slog.Debug("Ignoring unsupported Update object", "activity", activity) + slog.DebugContext(ctx, "Ignoring unsupported Update object") return nil } @@ -401,7 +401,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. var oldPost ap.Object var lastChange int64 if err := tx.QueryRowContext(ctx, `select max(inserted, updated), json(object) from notes where id = ? and author in (select id from persons where cid = ?)`, post.ID, ap.Canonical(post.AttributedTo)).Scan(&lastChange, &oldPost); err != nil && errors.Is(err, sql.ErrNoRows) { - slog.Debug("Received Update for non-existing post", "activity", activity) + slog.DebugContext(ctx, "Received Update for non-existing post") return inbox.processCreateActivity(ctx, tx, sender, activity, rawActivity, post, shared) } else if err != nil { return fmt.Errorf("failed to get last update time for %s: %w", post.ID, err) @@ -417,7 +417,7 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. } if (post.Type == ap.Question && post.Updated != (ap.Time{}) && lastChange >= post.Updated.UnixNano()) || (post.Type != ap.Question && (post.Updated == (ap.Time{}) || lastChange >= post.Updated.UnixNano())) { - slog.Debug("Received old update request for new post", "activity", activity) + slog.DebugContext(ctx, "Received old update request for new post") return nil } @@ -459,19 +459,19 @@ func (inbox *Inbox) ProcessActivity(ctx context.Context, tx *sql.Tx, sender *ap. return fmt.Errorf("failed to forward update post %s: %w", post.ID, err) } - slog.Info("Updated post", "activity", activity, "post", post.ID) + slog.InfoContext(ctx, "Updated post", "post", post.ID) case ap.Move: - slog.Debug("Ignoring Move activity", "activity", activity) + slog.DebugContext(ctx, "Ignoring Move activity") case ap.Like, ap.Dislike, ap.EmojiReact, ap.Add, ap.Remove: - slog.Debug("Ignoring activity", "activity", activity) + slog.DebugContext(ctx, "Ignoring activity") default: if sender.ID == activity.Actor { - slog.Warn("Received unknown request", "activity", activity) + slog.WarnContext(ctx, "Received unknown request") } else { - slog.Warn("Received unknown, unauthorized request", "activity", activity) + slog.WarnContext(ctx, "Received unknown, unauthorized request") } } diff --git a/inbox/note/insert.go b/inbox/note/insert.go index 1ce791dd..99b48de8 100644 --- a/inbox/note/insert.go +++ b/inbox/note/insert.go @@ -105,7 +105,7 @@ func Insert(ctx context.Context, tx *sql.Tx, note *ap.Object) error { for _, hashtag := range hashtags { if _, err := tx.ExecContext(ctx, `insert into hashtags (note, hashtag) values(?,?)`, note.ID, hashtag); err != nil { - slog.Warn("Failed to tag post", "post", note.ID, "hashtag", hashtag, "error", err) + slog.WarnContext(ctx, "Failed to tag post", "post", note.ID, "hashtag", hashtag, "error", err) } } diff --git a/inbox/queue.go b/inbox/queue.go index 3be1e4ef..9e63fd87 100644 --- a/inbox/queue.go +++ b/inbox/queue.go @@ -26,6 +26,7 @@ import ( "github.com/dimkr/tootik/ap" "github.com/dimkr/tootik/cfg" "github.com/dimkr/tootik/httpsig" + "github.com/dimkr/tootik/logcontext" ) type Queue struct { @@ -47,25 +48,27 @@ func (q *Queue) processActivityWithTimeout(parent context.Context, sender *ap.Ac ctx, cancel := context.WithTimeout(parent, q.Config.ActivityProcessingTimeout) defer cancel() + ctx = logcontext.Add(ctx, "activity", activity, "sender", sender.ID) + tx, err := q.DB.BeginTx(ctx, nil) if err != nil { - slog.Warn("Failed to start transaction", "activity", activity, "error", err) + slog.WarnContext(ctx, "Failed to start transaction", "error", err) return } defer tx.Rollback() if _, err := q.Resolver.ResolveID(ctx, q.Keys, activity.Actor, 0); err != nil { - slog.Warn("Failed to resolve actor", "activity", activity, "error", err) + slog.WarnContext(ctx, "Failed to resolve actor", "error", err) } else if err := q.Inbox.ProcessActivity(ctx, tx, sender, activity, rawActivity, 1, shared); err != nil { - slog.Warn("Failed to process activity", "activity", activity, "error", err) + slog.WarnContext(ctx, "Failed to process activity", "error", err) } else if err := tx.Commit(); err != nil { - slog.Warn("Failed to commit changes", "activity", activity, "error", err) + slog.WarnContext(ctx, "Failed to commit changes", "error", err) } } // ProcessBatch processes one batch of incoming activites in the queue. func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { - slog.Debug("Polling activities queue") + slog.DebugContext(ctx, "Polling activities queue") rows, err := q.DB.QueryContext(ctx, `select inbox.id, json(persons.actor), json(inbox.activity), inbox.raw, inbox.raw->>'$.type' = 'Announce' as shared from (select * from inbox limit -1 offset case when (select count(*) from inbox) >= $1 then $1/10 else 0 end) inbox left join persons on persons.id = inbox.sender order by inbox.id limit $2`, q.Config.MaxActivitiesQueueSize, q.Config.ActivitiesBatchSize) if err != nil { @@ -86,14 +89,14 @@ func (q *Queue) ProcessBatch(ctx context.Context) (int, error) { var sender sql.Null[ap.Actor] var shared bool if err := rows.Scan(&id, &sender, &activity, &activityString, &shared); err != nil { - slog.Error("Failed to scan activity", "error", err) + slog.ErrorContext(ctx, "Failed to scan activity", "error", err) continue } maxID = id if !sender.Valid { - slog.Warn("Sender is unknown", "id", id) + slog.WarnContext(ctx, "Sender is unknown", "id", id) continue } diff --git a/logcontext/add.go b/logcontext/add.go new file mode 100644 index 00000000..da11fe5a --- /dev/null +++ b/logcontext/add.go @@ -0,0 +1,32 @@ +/* +Copyright 2025 Dima Krasner + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package logcontext + +import "context" + +// Add adds log fields to a [context.Context]. +// +// Arguments should be in the same format as [slog.Logger.Log]. +// +// Use [NewHandler] to obtain a [slog.Handler] that logs these fields. +func Add(ctx context.Context, args ...any) context.Context { + if v := ctx.Value(key); v != nil { + return context.WithValue(ctx, key, append(v.([]any), args...)) + } + + return context.WithValue(ctx, key, args) +} diff --git a/logcontext/handler.go b/logcontext/handler.go new file mode 100644 index 00000000..770a77a9 --- /dev/null +++ b/logcontext/handler.go @@ -0,0 +1,51 @@ +/* +Copyright 2025 Dima Krasner + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package logcontext + +import ( + "context" + "log/slog" +) + +type handler struct { + inner slog.Handler +} + +func (h handler) Enabled(ctx context.Context, level slog.Level) bool { + return h.inner.Enabled(ctx, level) +} + +func (h handler) Handle(ctx context.Context, r slog.Record) error { + if v := ctx.Value(key); v != nil { + r.Add(v.([]any)...) + } + + return h.inner.Handle(ctx, r) +} + +func (h handler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &handler{h.inner.WithAttrs(attrs)} +} + +func (h handler) WithGroup(name string) slog.Handler { + return &handler{h.inner.WithGroup(name)} +} + +// NewHandler returns a [slog.Handler] that adds the log fields passed to [Add]. +func NewHandler(inner slog.Handler) slog.Handler { + return handler{inner: inner} +} diff --git a/logcontext/key.go b/logcontext/key.go new file mode 100644 index 00000000..f59505ae --- /dev/null +++ b/logcontext/key.go @@ -0,0 +1,21 @@ +/* +Copyright 2025 Dima Krasner + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package logcontext + +type keyType int + +var key keyType diff --git a/logcontext/package.go b/logcontext/package.go new file mode 100644 index 00000000..59d7b259 --- /dev/null +++ b/logcontext/package.go @@ -0,0 +1,18 @@ +/* +Copyright 2025 Dima Krasner + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +// Package logcontext enriches logs with additional context. +package logcontext diff --git a/migrations/migration.go b/migrations/migration.go index c9782485..4ab5458f 100644 --- a/migrations/migration.go +++ b/migrations/migration.go @@ -1,5 +1,5 @@ /* -Copyright 2023, 2024 Dima Krasner +Copyright 2023 - 2025 Dima Krasner Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -69,11 +69,11 @@ func Run(ctx context.Context, domain string, db *sql.DB) error { if err := db.QueryRowContext(ctx, `select datetime(applied, 'unixepoch') from migrations where id = ?`, m.ID).Scan(&applied); err != nil && !errors.Is(err, sql.ErrNoRows) { return fmt.Errorf("failed to check if %s is applied: %w", m.ID, err) } else if err == nil { - slog.Debug("Skipping migration", "id", m.ID, "applied", applied) + slog.DebugContext(ctx, "Skipping migration", "id", m.ID, "applied", applied) continue } - slog.Info("Applying migration", "id", m.ID) + slog.InfoContext(ctx, "Applying migration", "id", m.ID) if err := applyMigration(ctx, domain, db, m); err != nil { return err } diff --git a/outbox/deleter.go b/outbox/deleter.go index 146b712d..74c9981b 100644 --- a/outbox/deleter.go +++ b/outbox/deleter.go @@ -76,7 +76,7 @@ func (d *Deleter) undoShares(ctx context.Context) (bool, error) { } if count > 0 { - slog.Info("Removed old shared posts", "count", count) + slog.InfoContext(ctx, "Removed old shared posts", "count", count) return true, nil } @@ -125,7 +125,7 @@ func (d *Deleter) deletePosts(ctx context.Context) (bool, error) { } if count > 0 { - slog.Info("Deleted old posts", "count", count) + slog.InfoContext(ctx, "Deleted old posts", "count", count) return true, nil } diff --git a/outbox/mover.go b/outbox/mover.go index d1dece8d..d3a49657 100644 --- a/outbox/mover.go +++ b/outbox/mover.go @@ -45,18 +45,18 @@ func (m *Mover) updatedMoveTargets(ctx context.Context, prefix string) error { for rows.Next() { var oldID, newID string if err := rows.Scan(&oldID, &newID); err != nil { - slog.Error("Failed to scan moved actor", "error", err) + slog.ErrorContext(ctx, "Failed to scan moved actor", "error", err) continue } actor, err := m.Resolver.ResolveID(ctx, m.Keys, newID, 0) if err != nil { - slog.Warn("Failed to resolve move target", "old", oldID, "new", newID, "error", err) + slog.WarnContext(ctx, "Failed to resolve move target", "old", oldID, "new", newID, "error", err) continue } if !actor.AlsoKnownAs.Contains(oldID) { - slog.Warn("New account does not point to old account", "new", newID, "old", oldID) + slog.WarnContext(ctx, "New account does not point to old account", "new", newID, "old", oldID) } } @@ -107,27 +107,27 @@ func (m *Mover) Run(ctx context.Context) error { var oldID, NewID, oldFollowID string var onlyRemove bool if err := rows.Scan(&actor, &ed25519PrivKeyMultibase, &oldID, &NewID, &oldFollowID, &onlyRemove); err != nil { - slog.Error("Failed to scan follow to move", "error", err) + slog.ErrorContext(ctx, "Failed to scan follow to move", "error", err) continue } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Error("Failed to decode Ed25519 private key", "error", err) + slog.ErrorContext(ctx, "Failed to decode Ed25519 private key", "error", err) continue } if onlyRemove { - slog.Info("Removing follow of moved actor", "follow", oldFollowID, "old", oldID, "new", NewID) + slog.InfoContext(ctx, "Removing follow of moved actor", "follow", oldFollowID, "old", oldID, "new", NewID) } else { - slog.Info("Moving follow", "follow", oldFollowID, "old", oldID, "new", NewID) + slog.InfoContext(ctx, "Moving follow", "follow", oldFollowID, "old", oldID, "new", NewID) if err := m.Inbox.Follow(ctx, &actor, httpsig.Key{ID: actor.AssertionMethod[0].ID, PrivateKey: ed25519PrivKey}, NewID); err != nil { - slog.Warn("Failed to follow new actor", "follow", oldFollowID, "old", oldID, "new", NewID, "error", err) + slog.WarnContext(ctx, "Failed to follow new actor", "follow", oldFollowID, "old", oldID, "new", NewID, "error", err) continue } } if err := m.Inbox.Unfollow(ctx, &actor, httpsig.Key{ID: actor.AssertionMethod[0].ID, PrivateKey: ed25519PrivKey}, oldID, oldFollowID); err != nil { - slog.Warn("Failed to unfollow old actor", "follow", oldFollowID, "old", oldID, "new", NewID, "error", err) + slog.WarnContext(ctx, "Failed to unfollow old actor", "follow", oldFollowID, "old", oldID, "new", NewID, "error", err) } } diff --git a/outbox/poller.go b/outbox/poller.go index d4a565d7..4b15c9a0 100644 --- a/outbox/poller.go +++ b/outbox/poller.go @@ -56,7 +56,7 @@ func (p *Poller) Run(ctx context.Context) error { var option sql.NullString var count int64 if err := rows.Scan(&pollID, &option, &count); err != nil { - slog.Warn("Failed to scan poll result", "error", err) + slog.WarnContext(ctx, "Failed to scan poll result", "error", err) continue } @@ -71,13 +71,13 @@ func (p *Poller) Run(ctx context.Context) error { var author ap.Actor var ed25519PrivKeyMultibase string if err := p.DB.QueryRowContext(ctx, "select json(notes.object), json(persons.actor), persons.ed25519privkey from notes join persons on persons.id = notes.author where notes.id = ?", pollID).Scan(&obj, &author, &ed25519PrivKeyMultibase); err != nil { - slog.Warn("Failed to fetch poll", "poll", pollID, "error", err) + slog.WarnContext(ctx, "Failed to fetch poll", "poll", pollID, "error", err) continue } ed25519PrivKey, err := data.DecodeEd25519PrivateKey(ed25519PrivKeyMultibase) if err != nil { - slog.Error("Failed to decode Ed25519 private key", "poll", pollID, "author", author.ID, "error", err) + slog.ErrorContext(ctx, "Failed to decode Ed25519 private key", "poll", pollID, "author", author.ID, "error", err) continue } @@ -122,11 +122,11 @@ func (p *Poller) Run(ctx context.Context) error { poll.Updated = now - slog.Info("Updating poll results", "poll", poll.ID) + slog.InfoContext(ctx, "Updating poll results", "poll", poll.ID) author := authors[pollID] if err := p.Inbox.UpdateNote(ctx, author, httpsig.Key{ID: author.AssertionMethod[0].ID, PrivateKey: keys[pollID]}, poll); err != nil { - slog.Warn("Failed to update poll results", "poll", poll.ID, "error", err) + slog.WarnContext(ctx, "Failed to update poll results", "poll", poll.ID, "error", err) } } diff --git a/test/server.go b/test/server.go index 6929c3ac..511dec32 100644 --- a/test/server.go +++ b/test/server.go @@ -20,7 +20,6 @@ import ( "bytes" "context" "database/sql" - "log/slog" "net/http" "net/url" "os" @@ -147,7 +146,6 @@ func (s *server) Handle(request string, user *ap.Actor) string { &front.Request{ Context: context.Background(), URL: u, - Log: slog.Default(), User: user, }, w, @@ -170,7 +168,6 @@ func (s *server) Upload(request string, user *ap.Actor, body []byte) string { &front.Request{ Context: context.Background(), URL: u, - Log: slog.Default(), Body: bytes.NewBuffer(body), User: user, },