Log slow API requests with server spans and client timing

internal/server/changes.go

@@ -40,7 +40,7 @@ func (s *Server) GetTaskChanges(w http.ResponseWriter, r *http.Request, taskID s
 		}
 	}
 
-	changes, err := git.Changes(t.WorktreePath, p.DefaultBranch, since)
+	changes, err := git.Changes(r.Context(), t.WorktreePath, p.DefaultBranch, since)
 	if err != nil {
 		writeError(w, http.StatusInternalServerError, err)
 		return
@@ -64,7 +64,7 @@ func (s *Server) snapshotChanges(w http.ResponseWriter, r *http.Request, t api.T
 		}
 	}
 
-	changes, err := git.Compare(t.WorktreePath, p.DefaultBranch, snap.CommitSha, snap.TreeSha, since)
+	changes, err := git.Compare(r.Context(), t.WorktreePath, p.DefaultBranch, snap.CommitSha, snap.TreeSha, since)
 	if err != nil {
 		writeError(w, http.StatusInternalServerError, err)
 		return
@@ -97,7 +97,7 @@ func (s *Server) GetTaskDiff(w http.ResponseWriter, r *http.Request, taskID stri
 	if params.OldPath != nil {
 		oldPath = *params.OldPath
 	}
-	patch, err := git.FileDiff(t.WorktreePath, params.Base, params.Tree, params.Path, oldPath)
+	patch, err := git.FileDiff(r.Context(), t.WorktreePath, params.Base, params.Tree, params.Path, oldPath)
 	if err != nil {
 		writeError(w, http.StatusInternalServerError, err)
 		return

internal/server/files.go

@@ -102,7 +102,7 @@ func (s *Server) GetTaskDir(w http.ResponseWriter, r *http.Request, taskID strin
 	for _, e := range listing.Entries {
 		paths = append(paths, path.Join(real, e.Name))
 	}
-	ignored, err := git.Ignored(t.WorktreePath, paths)
+	ignored, err := git.Ignored(r.Context(), t.WorktreePath, paths)
 	if err != nil {
 		writeError(w, http.StatusInternalServerError, err)
 		return

internal/server/server.go

@@ -22,6 +22,7 @@ import (
 	"g.fc.run/ai/byre/internal/store"
 	"g.fc.run/ai/byre/internal/terminal"
 	"g.fc.run/ai/byre/internal/todo"
+	"g.fc.run/ai/byre/internal/trace"
 	"g.fc.run/ai/byre/internal/workflow"
 	"tailscale.com/client/local"
 	"tailscale.com/tsnet"
@@ -86,7 +87,7 @@ func New(dataDir string, portFirst int, ts *tsnet.Server, token string) (*Server
 		return nil, err
 	}
 	for _, p := range projects {
-		err = git.ConfigureNotesFetch(p.RepoPath)
+		err = git.ConfigureNotesFetch(context.Background(), p.RepoPath)
 		if err != nil {
 			slog.Error("configure notes fetch", "project", p.Id, "repo", p.RepoPath, "err", err)
 		}
@@ -131,7 +132,7 @@ func (s *Server) Handler() http.Handler {
 			writeError(w, http.StatusBadRequest, err)
 		},
 	})
-	return http.NewCrossOriginProtection().Handler(mux)
+	return timing(http.NewCrossOriginProtection().Handler(mux))
 }
 
 func (s *Server) LoopbackHandler() http.Handler {
@@ -167,7 +168,9 @@ func (s *Server) GetTailnet(w http.ResponseWriter, r *http.Request) {
 
 func (s *Server) identify(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		identified := trace.Start(r.Context(), "whois")
 		who, err := s.tailnet.WhoIs(r.Context(), r.RemoteAddr)
+		identified()
 		if err != nil {
 			writeError(w, http.StatusUnauthorized, fmt.Errorf("identify %s on the tailnet: %w", r.RemoteAddr, err))
 			return
@@ -301,12 +304,12 @@ func (s *Server) createProject(ctx context.Context, name, repoPath, createdBy st
 		return api.Project{}, fmt.Errorf("%w: name is required", agents.ErrInvalid)
 	}
 
-	info, err := git.Inspect(repoPath)
+	info, err := git.Inspect(ctx, repoPath)
 	if err != nil {
 		return api.Project{}, fmt.Errorf("%w: %w", agents.ErrInvalid, err)
 	}
 
-	err = git.ConfigureNotesFetch(info.Root)
+	err = git.ConfigureNotesFetch(ctx, info.Root)
 	if err != nil {
 		return api.Project{}, err
 	}
@@ -439,7 +442,7 @@ func (s *Server) GetTodo(w http.ResponseWriter, r *http.Request, projectID strin
 		return
 	}
 
-	src, found, err := git.ReadFile(p.RepoPath, p.DefaultBranch, todo.File)
+	src, found, err := git.ReadFile(r.Context(), p.RepoPath, p.DefaultBranch, todo.File)
 	if err != nil {
 		writeError(w, http.StatusInternalServerError, err)
 		return

internal/server/timing.go

@@ -0,0 +1,50 @@
+package server
+
+import (
+	"log/slog"
+	"net/http"
+	"time"
+
+	"g.fc.run/ai/byre/internal/trace"
+)
+
+const slowRequest = 200 * time.Millisecond
+
+type timedWriter struct {
+	http.ResponseWriter
+	start  time.Time
+	trace  *trace.Trace
+	status int
+}
+
+func (w *timedWriter) WriteHeader(status int) {
+	if w.status == 0 {
+		w.status = status
+		w.Header().Set("Server-Timing", w.trace.Header(time.Since(w.start)))
+	}
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *timedWriter) Write(b []byte) (int, error) {
+	if w.status == 0 {
+		w.WriteHeader(http.StatusOK)
+	}
+	return w.ResponseWriter.Write(b)
+}
+
+func (w *timedWriter) Unwrap() http.ResponseWriter {
+	return w.ResponseWriter
+}
+
+func timing(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		ctx, t := trace.New(r.Context())
+		tw := &timedWriter{ResponseWriter: w, start: time.Now(), trace: t}
+		next.ServeHTTP(tw, r.WithContext(ctx))
+		took := time.Since(tw.start)
+		if took < slowRequest || tw.status == http.StatusSwitchingProtocols || tw.Header().Get("Content-Type") == "text/event-stream" {
+			return
+		}
+		slog.Info("request slow", "method", r.Method, "path", r.URL.Path, "status", tw.status, "took", took, "spans", t.String())
+	})
+}