knotserver: improve the logging situation

Signed-off-by: oppiliappan <[e-mail]>

cmd/knot/main.go

···
 
 import (
 	"context"
+	"log/slog"
 	"os"
 
 	"github.com/urfave/cli/v3"
···
 	"tangled.org/core/hook"
 	"tangled.org/core/keyfetch"
 	"tangled.org/core/knotserver"
-	"tangled.org/core/log"
+	tlog "tangled.org/core/log"
 )
 
 func main() {
···
 		},
 	}
 
+	logger := tlog.New("knot")
+	slog.SetDefault(logger)
+
 	ctx := context.Background()
-	logger := log.New("knot")
-	ctx = log.IntoContext(ctx, logger.With("command", cmd.Name))
+	ctx = tlog.IntoContext(ctx, logger)
 
 	if err := cmd.Run(ctx, os.Args); err != nil {
 		logger.Error(err.Error())

knotserver/events.go

···
 	"time"
 
 	"github.com/gorilla/websocket"
+	"tangled.org/core/log"
 )
 
 var upgrader = websocket.Upgrader{
···
 }
 
 func (h *Knot) Events(w http.ResponseWriter, r *http.Request) {
-	l := h.l.With("handler", "OpLog")
+	l := log.SubLogger(h.l, "eventstream")
 	l.Debug("received new connection")
 
 	conn, err := upgrader.Upgrade(w, r, nil)
···
 			}
 		case <-time.After(30 * time.Second):
 			// send a keep-alive
-			l.Debug("sent keepalive")
 			if err = conn.WriteControl(websocket.PingMessage, []byte{}, time.Now().Add(time.Second)); err != nil {
 				l.Error("failed to write control", "err", err)
 			}
···
 		h.l.Error("failed to fetch events from db", "err", err, "cursor", cursor)
 		return err
 	}
-	h.l.Debug("ops", "ops", events)
 
 	for _, event := range events {
 		// first extract the inner json into a map

knotserver/git.go

···
 	"tangled.org/core/knotserver/git/service"
 )
 
-func (d *Knot) InfoRefs(w http.ResponseWriter, r *http.Request) {
+func (h *Knot) InfoRefs(w http.ResponseWriter, r *http.Request) {
 	did := chi.URLParam(r, "did")
 	name := chi.URLParam(r, "name")
 	repoName, err := securejoin.SecureJoin(did, name)
 	if err != nil {
 		gitError(w, "repository not found", http.StatusNotFound)
-		d.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)
+		h.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)
 		return
 	}
 
-	repoPath, err := securejoin.SecureJoin(d.c.Repo.ScanPath, repoName)
+	repoPath, err := securejoin.SecureJoin(h.c.Repo.ScanPath, repoName)
 	if err != nil {
 		gitError(w, "repository not found", http.StatusNotFound)
-		d.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)
+		h.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)
 		return
 	}
 
···
 
 		if err := cmd.InfoRefs(); err != nil {
 			gitError(w, err.Error(), http.StatusInternalServerError)
-			d.l.Error("git: process failed", "handler", "InfoRefs", "service", serviceName, "error", err)
+			h.l.Error("git: process failed", "handler", "InfoRefs", "service", serviceName, "error", err)
 			return
 		}
 	case "git-receive-pack":
-		d.RejectPush(w, r, name)
+		h.RejectPush(w, r, name)
 	default:
 		gitError(w, fmt.Sprintf("service unsupported: '%s'", serviceName), http.StatusForbidden)
 	}
 }
 
-func (d *Knot) UploadPack(w http.ResponseWriter, r *http.Request) {
+func (h *Knot) UploadPack(w http.ResponseWriter, r *http.Request) {
 	did := chi.URLParam(r, "did")
 	name := chi.URLParam(r, "name")
-	repo, err := securejoin.SecureJoin(d.c.Repo.ScanPath, filepath.Join(did, name))
+	repo, err := securejoin.SecureJoin(h.c.Repo.ScanPath, filepath.Join(did, name))
 	if err != nil {
 		gitError(w, err.Error(), http.StatusInternalServerError)
-		d.l.Error("git: failed to secure join repo path", "handler", "UploadPack", "error", err)
+		h.l.Error("git: failed to secure join repo path", "handler", "UploadPack", "error", err)
 		return
 	}
 
···
 		gzipReader, err := gzip.NewReader(r.Body)
 		if err != nil {
 			gitError(w, err.Error(), http.StatusInternalServerError)
-			d.l.Error("git: failed to create gzip reader", "handler", "UploadPack", "error", err)
+			h.l.Error("git: failed to create gzip reader", "handler", "UploadPack", "error", err)
 			return
 		}
 		defer gzipReader.Close()
···
 	w.Header().Set("Connection", "Keep-Alive")
 	w.Header().Set("Cache-Control", "no-cache, max-age=0, must-revalidate")
 
-	d.l.Info("git: executing git-upload-pack", "handler", "UploadPack", "repo", repo)
+	h.l.Info("git: executing git-upload-pack", "handler", "UploadPack", "repo", repo)
 
 	cmd := service.ServiceCommand{
 		GitProtocol: r.Header.Get("Git-Protocol"),
···
 	w.WriteHeader(http.StatusOK)
 
 	if err := cmd.UploadPack(); err != nil {
-		d.l.Error("git: failed to execute git-upload-pack", "handler", "UploadPack", "error", err)
+		h.l.Error("git: failed to execute git-upload-pack", "handler", "UploadPack", "error", err)
 		return
 	}
 }
 
-func (d *Knot) ReceivePack(w http.ResponseWriter, r *http.Request) {
+func (h *Knot) ReceivePack(w http.ResponseWriter, r *http.Request) {
 	did := chi.URLParam(r, "did")
 	name := chi.URLParam(r, "name")
-	_, err := securejoin.SecureJoin(d.c.Repo.ScanPath, filepath.Join(did, name))
+	_, err := securejoin.SecureJoin(h.c.Repo.ScanPath, filepath.Join(did, name))
 	if err != nil {
 		gitError(w, err.Error(), http.StatusForbidden)
-		d.l.Error("git: failed to secure join repo path", "handler", "ReceivePack", "error", err)
+		h.l.Error("git: failed to secure join repo path", "handler", "ReceivePack", "error", err)
 		return
 	}
 
-	d.RejectPush(w, r, name)
+	h.RejectPush(w, r, name)
 }
 
-func (d *Knot) RejectPush(w http.ResponseWriter, r *http.Request, unqualifiedRepoName string) {
+func (h *Knot) RejectPush(w http.ResponseWriter, r *http.Request, unqualifiedRepoName string) {
 	// A text/plain response will cause git to print each line of the body
 	// prefixed with "remote: ".
 	w.Header().Set("content-type", "text/plain; charset=UTF-8")
···
 	ownerHandle := r.Header.Get("x-tangled-repo-owner-handle")
 	ownerHandle = strings.TrimPrefix(ownerHandle, "@")
 	if ownerHandle != "" && !strings.ContainsAny(ownerHandle, ":") {
-		hostname := d.c.Server.Hostname
+		hostname := h.c.Server.Hostname
 		if strings.Contains(hostname, ":") {
 			hostname = strings.Split(hostname, ":")[0]
 		}

knotserver/internal.go

···
 	"tangled.org/core/knotserver/config"
 	"tangled.org/core/knotserver/db"
 	"tangled.org/core/knotserver/git"
+	"tangled.org/core/log"
 	"tangled.org/core/notifier"
 	"tangled.org/core/rbac"
 	"tangled.org/core/workflow"
···
 	return h.db.InsertEvent(event, h.n)
 }
 
-func Internal(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, l *slog.Logger, n *notifier.Notifier) http.Handler {
+func Internal(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, n *notifier.Notifier) http.Handler {
 	r := chi.NewRouter()
+	l := log.FromContext(ctx)
+	l = log.SubLogger(l, "internal")
 
 	h := InternalHandle{
 		db,

knotserver/middleware.go

···
+package knotserver
+
+import (
+	"log/slog"
+	"net/http"
+	"time"
+)
+
+func (h *Knot) RequestLogger(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+
+		next.ServeHTTP(w, r)
+
+		// Build query params as slog.Attrs for the group
+		queryParams := r.URL.Query()
+		queryAttrs := make([]any, 0, len(queryParams))
+		for key, values := range queryParams {
+			if len(values) == 1 {
+				queryAttrs = append(queryAttrs, slog.String(key, values[0]))
+			} else {
+				queryAttrs = append(queryAttrs, slog.Any(key, values))
+			}
+		}
+
+		h.l.LogAttrs(r.Context(), slog.LevelInfo, "",
+			slog.Group("request",
+				slog.String("method", r.Method),
+				slog.String("path", r.URL.Path),
+				slog.Group("query", queryAttrs...),
+				slog.Duration("duration", time.Since(start)),
+			),
+		)
+	})
+}

knotserver/router.go

···
 	"tangled.org/core/knotserver/config"
 	"tangled.org/core/knotserver/db"
 	"tangled.org/core/knotserver/xrpc"
-	tlog "tangled.org/core/log"
+	"tangled.org/core/log"
 	"tangled.org/core/notifier"
 	"tangled.org/core/rbac"
 	"tangled.org/core/xrpc/serviceauth"
···
 	resolver *idresolver.Resolver
 }
 
-func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, jc *jetstream.JetstreamClient, l *slog.Logger, n *notifier.Notifier) (http.Handler, error) {
-	r := chi.NewRouter()
-
+func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, jc *jetstream.JetstreamClient, n *notifier.Notifier) (http.Handler, error) {
 	h := Knot{
 		c:        c,
 		db:       db,
 		e:        e,
-		l:        l,
+		l:        log.FromContext(ctx),
 		jc:       jc,
 		n:        n,
 		resolver: idresolver.DefaultResolver(),
···
 		return nil, fmt.Errorf("failed to start jetstream: %w", err)
 	}
 
+	return h.Router(), nil
+}
+
+func (h *Knot) Router() http.Handler {
+	r := chi.NewRouter()
+
+	r.Use(h.RequestLogger)
+
 	r.Get("/", func(w http.ResponseWriter, r *http.Request) {
 		w.Write([]byte("This is a knot server. More info at https://tangled.sh"))
 	})
···
 	// Socket that streams git oplogs
 	r.Get("/events", h.Events)
 
-	return r, nil
+	return r
 }
 
 func (h *Knot) XrpcRouter() http.Handler {
-	logger := tlog.New("knots")
+	serviceAuth := serviceauth.NewServiceAuth(h.l, h.resolver, h.c.Server.Did().String())
 
-	serviceAuth := serviceauth.NewServiceAuth(h.l, h.resolver, h.c.Server.Did().String())
+	l := log.SubLogger(h.l, "xrpc")
 
 	xrpc := &xrpc.Xrpc{
 		Config:      h.c,
 		Db:          h.db,
 		Ingester:    h.jc,
 		Enforcer:    h.e,
-		Logger:      logger,
+		Logger:      l,
 		Notifier:    h.n,
 		Resolver:    h.resolver,
 		ServiceAuth: serviceAuth,
 	}
+
 	return xrpc.Router()
 }
 

knotserver/server.go

···
 
 func Run(ctx context.Context, cmd *cli.Command) error {
 	logger := log.FromContext(ctx)
-	iLogger := log.New("knotserver/internal")
+	logger = log.SubLogger(logger, cmd.Name)
+	ctx = log.IntoContext(ctx, logger)
 
 	c, err := config.Load(ctx)
 	if err != nil {
···
 		tangled.KnotMemberNSID,
 		tangled.RepoPullNSID,
 		tangled.RepoCollaboratorNSID,
-	}, nil, logger, db, true, c.Server.LogDids)
+	}, nil, log.SubLogger(logger, "jetstream"), db, true, c.Server.LogDids)
 	if err != nil {
 		logger.Error("failed to setup jetstream", "error", err)
 	}
 
 	notifier := notifier.New()
 
-	mux, err := Setup(ctx, c, db, e, jc, logger, &notifier)
+	mux, err := Setup(ctx, c, db, e, jc, &notifier)
 	if err != nil {
 		return fmt.Errorf("failed to setup server: %w", err)
 	}
 
-	imux := Internal(ctx, c, db, e, iLogger, &notifier)
+	imux := Internal(ctx, c, db, e, &notifier)
 
 	logger.Info("starting internal server", "address", c.Server.InternalListenAddr)
 	go http.ListenAndServe(c.Server.InternalListenAddr, imux)

log/log.go

···
 	"context"
 	"log/slog"
 	"os"
+
+	"github.com/charmbracelet/log"
 )
 
-// NewHandler sets up a new slog.Handler with the service name
-// as an attribute
 func NewHandler(name string) slog.Handler {
-	handler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
-		Level: slog.LevelDebug,
+	return log.NewWithOptions(os.Stderr, log.Options{
+		ReportTimestamp: true,
+		Prefix:          name,
+		Level:           log.DebugLevel,
 	})
-
-	var attrs []slog.Attr
-	attrs = append(attrs, slog.Attr{Key: "service", Value: slog.StringValue(name)})
-	handler.WithAttrs(attrs)
-	return handler
 }
 
 func New(name string) *slog.Logger {
···
 
 	return slog.Default()
 }
+
+// sublogger derives a new logger from an existing one by appending a suffix to its prefix.
+func SubLogger(base *slog.Logger, suffix string) *slog.Logger {
+	// try to get the underlying charmbracelet logger
+	if cl, ok := base.Handler().(*log.Logger); ok {
+		prefix := cl.GetPrefix()
+		if prefix != "" {
+			prefix = prefix + "/" + suffix
+		} else {
+			prefix = suffix
+		}
+		return slog.New(NewHandler(prefix))
+	}
+
+	// Fallback: no known handler type
+	return slog.New(NewHandler(suffix))
+}