all: start to switch to slog

Author: davecheney

Diff for: activitypub/activitypub.go

@@ -14,11 +14,18 @@ import (
 	"github.com/go-chi/chi/v5"
 	"github.com/go-json-experiment/json"
 	"gorm.io/gorm"
+
+	"golang.org/x/exp/slog"
 )
 
 type Env struct {
 	*gorm.DB
 	*streaming.Mux
+	Logger *slog.Logger
+}
+
+func (e *Env) Log() *slog.Logger {
+	return e.Logger
 }
 
 func Followers(env *Env, w http.ResponseWriter, r *http.Request) error {

Diff for: activitypub/inbox.go

@@ -15,6 +15,7 @@ import (
 	"github.com/davecheney/pub/models"
 	"github.com/go-fed/httpsig"
 	"github.com/go-json-experiment/json"
+	"golang.org/x/exp/slog"
 	"gorm.io/gorm"
 	"gorm.io/gorm/clause"
 )
@@ -43,6 +44,7 @@ func (i *InboxController) Create(env *Env, w http.ResponseWriter, r *http.Reques
 	// if we need to make an activity pub request, we need to sign it with the
 	// instance's admin account.
 	processor := &inboxProcessor{
+		logger: env.Logger.With("instance", instance.Domain),
 		req:    r,
 		db:     i.db,
 		signAs: instance.Admin,
@@ -85,6 +87,7 @@ func (i *InboxController) fetchActor(uri string) (*models.Actor, error) {
 }
 
 type inboxProcessor struct {
+	logger *slog.Logger
 	req    *http.Request
 	db     *gorm.DB
 	signAs *models.Account
@@ -95,7 +98,8 @@ type inboxProcessor struct {
 // blocking, it is handled immediately. If the activity requires blocking, it is
 // queued for later processing.
 func (i *inboxProcessor) processActivity(act *Activity) error {
-	fmt.Println("processActivity: type:", act.Type, "id:", act.ID)
+	i.logger = i.logger.With("id", act.ID, "type", act.Type)
+	i.logger.Info("processActivity")
 	switch act.Type {
 	case "":
 		return httpx.Error(http.StatusBadRequest, errors.New("missing type"))
@@ -194,28 +198,16 @@ func (i *inboxProcessor) processAnnounce(act *Activity) error {
 		updatedAt = publishedAt
 	}
 
-	conv := models.Conversation{
-		Visibility: "public",
-	}
-	if err := i.db.Create(&conv).Error; err != nil {
-		return err
-	}
-
 	status := &models.Status{
-		ID:               snowflake.TimeToID(publishedAt),
-		UpdatedAt:        updatedAt,
-		ActorID:          actor.ID,
-		Actor:            actor,
-		ConversationID:   conv.ID,
-		URI:              act.ID,
-		InReplyToID:      nil,
-		InReplyToActorID: nil,
-		Sensitive:        false,
-		SpoilerText:      "",
-		Visibility:       "public",
-		Language:         "",
-		Note:             "",
-		ReblogID:         &original.ID,
+		ID:        snowflake.TimeToID(publishedAt),
+		UpdatedAt: updatedAt,
+		Actor:     actor,
+		Conversation: &models.Conversation{
+			Visibility: "public",
+		},
+		URI:        act.ID,
+		Visibility: "public",
+		ReblogID:   &original.ID,
 	}
 
 	return i.db.Create(status).Error
@@ -410,7 +402,6 @@ func inReplyToActorID(inReplyTo *models.Status) *snowflake.ID {
 }
 
 func objToStatusAttachment(obj map[string]any) *models.StatusAttachment {
-	fmt.Println("objToStatusAttachment:", obj)
 	return &models.StatusAttachment{
 		Attachment: models.Attachment{
 			ID:         snowflake.Now(),
@@ -591,19 +582,21 @@ func (i *inboxProcessor) processDeleteStatus(uri string) error {
 }
 
 func (i *inboxProcessor) processDeleteActor(uri string) error {
-	// load actor to delete it so we can fire the delete hooks.
-	actor, err := models.NewActors(i.db).FindByURI(uri)
-	if err != nil {
-		if errors.Is(err, gorm.ErrRecordNotFound) {
-			// already deleted
-			return nil
-		}
+	// use this form to avoid firing gorm's ErrNotFound mechanism;
+	// most deletes we don't know about, and that's fine.
+	var actors []*models.Actor
+	if err := i.db.Limit(1).Where("uri = ?", uri).Find(&actors).Error; err != nil {
 		return err
 	}
+	if len(actors) == 0 {
+		// already deleted
+		return nil
+	}
+	actor := actors[0]
 	if err := i.validateSignature(); err != nil {
 		return httpx.Error(http.StatusUnauthorized, err)
 	}
-	return i.db.Delete(&actor).Error
+	return i.db.Delete(actor).Error
 }
 
 func (i *inboxProcessor) validateSignature() error {

Diff for: go.mod

@@ -14,6 +14,7 @@ require (
 	github.com/pkg/group v1.0.0
 	github.com/stretchr/testify v1.8.2
 	golang.org/x/crypto v0.8.0
+	golang.org/x/exp v0.0.0-20230321023759-10a507213a29
 	golang.org/x/image v0.7.0
 	golang.org/x/net v0.9.0
 	gorm.io/driver/mysql v1.5.0
@@ -28,7 +29,6 @@ require (
 	github.com/jinzhu/now v1.1.5 // indirect
 	github.com/mattn/go-sqlite3 v1.14.16 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	golang.org/x/exp v0.0.0-20230321023759-10a507213a29 // indirect
 	golang.org/x/sys v0.7.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

Diff for: internal/httpx/handler.go

@@ -5,10 +5,10 @@ package httpx
 
 import (
 	"errors"
-	"log"
 	"net/http"
 
 	"github.com/go-json-experiment/json"
+	"golang.org/x/exp/slog"
 )
 
 // Error is a convenience function for returning an error with an associated HTTP status code.
@@ -32,25 +32,25 @@ func (se *StatusError) Status() int {
 	return se.Code
 }
 
+type env interface {
+	Log() *slog.Logger
+}
+
 // HandlerFunc adapts a function that returns an error to an http.HandlerFunc.
-func HandlerFunc[E any](envFn func(r *http.Request) *E, fn func(*E, http.ResponseWriter, *http.Request) error) http.HandlerFunc {
+func HandlerFunc[E env](envFn func(r *http.Request) E, fn func(E, http.ResponseWriter, *http.Request) error) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		env := envFn(r)
 		err := fn(env, w, r)
 		if err != nil {
-			w.Header().Set("Content-Type", "application/json; charset=utf-8")
+			status := http.StatusInternalServerError
 			if se := new(StatusError); errors.As(err, &se) {
-				log.Printf("HTTP: method: %s, path: %s, status: %d, error: %s", r.Method, r.URL.Path, se.Status(), err)
-				w.WriteHeader(se.Status())
-				json.MarshalFull(w, map[string]any{
-					"error": se.Error(),
-				})
-				return
+				status = se.Code
 			}
-			log.Printf("HTTP: method: %s, path: %s, status: %d, error: %s", r.Method, r.URL.Path, http.StatusInternalServerError, err)
-			w.WriteHeader(http.StatusInternalServerError)
+			env.Log().Error("HTTP", "method", r.Method, "path", r.URL.Path, "status", status, "error", err)
+			w.Header().Set("Content-Type", "application/json; charset=utf-8")
+			w.WriteHeader(status)
 			json.MarshalFull(w, map[string]any{
-				"error": http.StatusInternalServerError,
+				"error": err.Error(),
 			})
 		}
 	}

Diff for: main.go

@@ -1,6 +1,10 @@
 package main
 
 import (
+	"os"
+
+	"golang.org/x/exp/slog"
+
 	"github.com/alecthomas/kong"
 	"gorm.io/gorm"
 	"gorm.io/gorm/logger"
@@ -9,6 +13,8 @@ import (
 type Context struct {
 	Debug bool
 
+	Logger *slog.Logger
+
 	gorm.Config
 	gorm.Dialector
 }
@@ -29,7 +35,8 @@ var cli struct {
 func main() {
 	ctx := kong.Parse(&cli)
 	err := ctx.Run(&Context{
-		Debug: cli.LogSQL,
+		Debug:  cli.LogSQL,
+		Logger: slog.New(slog.NewTextHandler(os.Stderr)),
 		Config: gorm.Config{
 			Logger: logger.Default.LogMode(func() logger.LogLevel {
 				if cli.LogSQL {

Diff for: mastodon/mastodon.go

@@ -12,12 +12,18 @@ import (
 	"github.com/davecheney/pub/internal/snowflake"
 	"github.com/davecheney/pub/internal/streaming"
 	"github.com/davecheney/pub/models"
+	"golang.org/x/exp/slog"
 	"gorm.io/gorm"
 )
 
 type Env struct {
 	*gorm.DB
 	*streaming.Mux
+	Logger *slog.Logger
+}
+
+func (e *Env) Log() *slog.Logger {
+	return e.Logger
 }
 
 // authenticate authenticates the bearer token attached to the request and, if

Diff for: models/actor.go

@@ -1,7 +1,6 @@
 package models
 
 import (
-	"errors"
 	"fmt"
 	"net/http"
 	"time"
@@ -157,14 +156,15 @@ func NewActors(db *gorm.DB) *Actors {
 
 // FindOrCreate finds an account by its URI, or creates it if it doesn't exist.
 func (a *Actors) FindOrCreate(uri string, createFn func(string) (*Actor, error)) (*Actor, error) {
-	actor, err := a.FindByURI(uri)
-	if err == nil {
-		// found cached key
-		return actor, nil
-	}
-	if !errors.Is(err, gorm.ErrRecordNotFound) {
+	// use find to avoid record not found error in case of empty result
+	var actors []Actor
+	if err := a.db.Limit(1).Find(&actors, "uri = ?", uri).Error; err != nil {
 		return nil, err
 	}
+	if len(actors) > 0 {
+		// found cached key
+		return &actors[0], nil
+	}
 
 	acc, err := createFn(uri)
 	if err != nil {
@@ -176,15 +176,9 @@ func (a *Actors) FindOrCreate(uri string, createFn func(string) (*Actor, error))
 
 // FindByURI returns an account by its URI if it exists locally.
 func (a *Actors) FindByURI(uri string) (*Actor, error) {
-	// use find to avoid record not found error in case of empty result
-	var actors []Actor
-	if err := a.db.Limit(1).Find(&actors, "uri = ?", uri).Error; err != nil {
-		return nil, err
-	}
-	if len(actors) == 0 {
-		return nil, gorm.ErrRecordNotFound
-	}
-	return &actors[0], nil
+	var actor Actor
+	err := a.db.Where("URI = ?", uri).Take(&actor).Error
+	return &actor, err
 }
 
 // Refesh schedules a refresh of an actor's data.

Diff for: models/env.go

@@ -1,10 +1,16 @@
 package models
 
 import (
+	"golang.org/x/exp/slog"
 	"gorm.io/gorm"
 )
 
 type Env struct {
 	// DB is the database connection.
-	DB *gorm.DB
+	DB     *gorm.DB
+	Logger *slog.Logger
+}
+
+func (e *Env) Log() *slog.Logger {
+	return e.Logger
 }

Diff for: serve.go

@@ -62,8 +62,9 @@ func (s *ServeCmd) Run(ctx *Context) error {
 	r.Route("/api", func(r chi.Router) {
 		envFn := func(r *http.Request) *mastodon.Env {
 			return &mastodon.Env{
-				DB:  db.WithContext(r.Context()),
-				Mux: &mux,
+				DB:     db.WithContext(r.Context()),
+				Mux:    &mux,
+				Logger: ctx.Logger,
 			}
 		}
 		r.Route("/v1", func(r chi.Router) {
@@ -150,8 +151,9 @@ func (s *ServeCmd) Run(ctx *Context) error {
 
 	envFn := func(r *http.Request) *activitypub.Env {
 		return &activitypub.Env{
-			DB:  db.WithContext(r.Context()),
-			Mux: &mux,
+			DB:     db.WithContext(r.Context()),
+			Mux:    &mux,
+			Logger: ctx.Logger,
 		}
 	}
 
@@ -182,7 +184,8 @@ func (s *ServeCmd) Run(ctx *Context) error {
 
 	modelEnvFn := func(r *http.Request) *models.Env {
 		return &models.Env{
-			DB: db.WithContext(r.Context()),
+			DB:     db.WithContext(r.Context()),
+			Logger: ctx.Logger,
 		}
 	}
 
@@ -223,7 +226,7 @@ func (s *ServeCmd) Run(ctx *Context) error {
 		return svr.ListenAndServe()
 	})
 
-	g.Add(workers.NewRelationshipRequestProcessor(db))
+	g.Add(workers.NewRelationshipRequestProcessor(ctx.Logger, db))
 	g.Add(workers.NewReactionRequestProcessor(db))
 	g.Add(workers.NewStatusAttachmentRequestProcessor(db))
 

Diff for: workers/relationships.go

@@ -7,18 +7,22 @@ import (
 
 	"github.com/davecheney/pub/activitypub"
 	"github.com/davecheney/pub/models"
+	"golang.org/x/exp/slog"
 	"gorm.io/gorm"
 )
 
 // RelationshipRequestProcessor handles delivery of relationship requests.
-func NewRelationshipRequestProcessor(db *gorm.DB) func(ctx context.Context) error {
+func NewRelationshipRequestProcessor(log *slog.Logger, db *gorm.DB) func(ctx context.Context) error {
+	log = log.With("worker", "RelationshipRequestProcessor")
 	return func(ctx context.Context) error {
-		fmt.Println("RelationshipRequestProcessor started")
-		defer fmt.Println("RelationshipRequestProcessor stopped")
+		log.Info("started")
+		defer log.Info("stopped")
 
 		db := db.WithContext(ctx)
 		for {
-			if err := process(db, relationshipRequestScope, processRelationshipRequest); err != nil {
+			if err := process(db, relationshipRequestScope, func(db *gorm.DB, request *models.RelationshipRequest) error {
+				return processRelationshipRequest(log, db, request)
+			}); err != nil {
 				return err
 			}
 			select {
@@ -35,8 +39,8 @@ func relationshipRequestScope(db *gorm.DB) *gorm.DB {
 	return db.Preload("Actor").Preload("Target").Where("attempts < 3")
 }
 
-func processRelationshipRequest(db *gorm.DB, request *models.RelationshipRequest) error {
-	fmt.Println("RelationshipRequestProcessor: actor:", request.Actor.URI, "target:", request.Target.URI, "action:", request.Action)
+func processRelationshipRequest(log *slog.Logger, db *gorm.DB, request *models.RelationshipRequest) error {
+	log.Info("", "request", request.ID, "actor_id", request.Actor.ID, "target_id", request.Target.ID, "action", request.Action)
 	accounts := models.NewAccounts(db)
 	account, err := accounts.AccountForActor(request.Actor)
 	if err != nil {