From 11f582346a027b59bc70320c57163e443e108e35 Mon Sep 17 00:00:00 2001 From: oppiliappan Date: Thu, 9 Oct 2025 14:04:19 +0100 Subject: [PATCH] knotserver: improve the logging situation Change-Id: louxkrpvxypnpuoptxnnmuqvwrpllzwo Signed-off-by: oppiliappan --- cmd/knot/main.go | 9 ++++++--- knotserver/events.go | 5 ++--- knotserver/git.go | 36 ++++++++++++++++++------------------ knotserver/internal.go | 5 ++++- knotserver/middleware.go | 35 +++++++++++++++++++++++++++++++++++ knotserver/router.go | 25 ++++++++++++++++--------- knotserver/server.go | 9 +++++---- log/log.go | 32 +++++++++++++++++++++++--------- 8 files changed, 109 insertions(+), 47 deletions(-) create mode 100644 knotserver/middleware.go diff --git a/cmd/knot/main.go b/cmd/knot/main.go index 615466e0..89c6c7ef 100644 --- a/cmd/knot/main.go +++ b/cmd/knot/main.go @@ -2,6 +2,7 @@ package main import ( "context" + "log/slog" "os" "github.com/urfave/cli/v3" @@ -9,7 +10,7 @@ import ( "tangled.org/core/hook" "tangled.org/core/keyfetch" "tangled.org/core/knotserver" - "tangled.org/core/log" + tlog "tangled.org/core/log" ) func main() { @@ -24,9 +25,11 @@ 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()) diff --git a/knotserver/events.go b/knotserver/events.go index 0aa58b9b..cd2e6d68 100644 --- a/knotserver/events.go +++ b/knotserver/events.go @@ -8,6 +8,7 @@ import ( "time" "github.com/gorilla/websocket" + "tangled.org/core/log" ) var upgrader = websocket.Upgrader{ @@ -16,7 +17,7 @@ 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) @@ -75,7 +76,6 @@ func (h *Knot) Events(w http.ResponseWriter, r *http.Request) { } 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) } @@ -89,7 +89,6 @@ func (h *Knot) streamOps(conn *websocket.Conn, cursor *int64) error { 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 diff --git a/knotserver/git.go b/knotserver/git.go index 0258239c..4c89a90a 100644 --- a/knotserver/git.go +++ b/knotserver/git.go @@ -13,20 +13,20 @@ import ( "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 } @@ -46,23 +46,23 @@ func (d *Knot) InfoRefs(w http.ResponseWriter, r *http.Request) { 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 } @@ -77,7 +77,7 @@ func (d *Knot) UploadPack(w http.ResponseWriter, r *http.Request) { 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() @@ -88,7 +88,7 @@ func (d *Knot) UploadPack(w http.ResponseWriter, r *http.Request) { 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"), @@ -100,25 +100,25 @@ func (d *Knot) UploadPack(w http.ResponseWriter, r *http.Request) { 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") @@ -131,7 +131,7 @@ func (d *Knot) RejectPush(w http.ResponseWriter, r *http.Request, unqualifiedRep 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] } diff --git a/knotserver/internal.go b/knotserver/internal.go index e87dd984..f4d10928 100644 --- a/knotserver/internal.go +++ b/knotserver/internal.go @@ -20,6 +20,7 @@ import ( "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" @@ -314,8 +315,10 @@ func (h *InternalHandle) triggerPipeline(clientMsgs *[]string, line git.PostRece 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, diff --git a/knotserver/middleware.go b/knotserver/middleware.go new file mode 100644 index 00000000..ae6280d6 --- /dev/null +++ b/knotserver/middleware.go @@ -0,0 +1,35 @@ +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)), + ), + ) + }) +} diff --git a/knotserver/router.go b/knotserver/router.go index 53e01659..56fd9eac 100644 --- a/knotserver/router.go +++ b/knotserver/router.go @@ -12,7 +12,7 @@ import ( "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" @@ -28,14 +28,12 @@ type Knot struct { 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(), @@ -67,6 +65,14 @@ func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, j 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")) }) @@ -86,24 +92,25 @@ func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, j // 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()) + 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() } diff --git a/knotserver/server.go b/knotserver/server.go index 98c259bd..9d90b7f4 100644 --- a/knotserver/server.go +++ b/knotserver/server.go @@ -43,7 +43,8 @@ func Command() *cli.Command { 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 { @@ -80,19 +81,19 @@ func Run(ctx context.Context, cmd *cli.Command) error { 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, ¬ifier) + mux, err := Setup(ctx, c, db, e, jc, ¬ifier) if err != nil { return fmt.Errorf("failed to setup server: %w", err) } - imux := Internal(ctx, c, db, e, iLogger, ¬ifier) + imux := Internal(ctx, c, db, e, ¬ifier) logger.Info("starting internal server", "address", c.Server.InternalListenAddr) go http.ListenAndServe(c.Server.InternalListenAddr, imux) diff --git a/log/log.go b/log/log.go index ab0590c2..2d83475e 100644 --- a/log/log.go +++ b/log/log.go @@ -4,19 +4,16 @@ import ( "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 { @@ -49,3 +46,20 @@ func FromContext(ctx context.Context) *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)) +} -- 2.43.0