chore(log): Include entity context in log message text for searchability

AGENTS.md

@@ -19,3 +19,20 @@ The codebase uses Hermit to manage toolchains. It is written in Go, and uses Jus
 Only add comments for relatively large blocks of code, 20+ lines or more, and ONLY if it is not obvious what the code is
 doing. ALWAYS add Go-style documentation comments for public variables/types/functions. If you do add comments, the
 comments should explain WHY something is happening, not WHAT is happening.
+
+## Logging Standards
+
+- Include identifying context in message text: `"Clone failed"` → `fmt.Sprintf("Clone failed for %s: %v", upstream, err)`
+- Use bare key-value pairs: `"error", err` not `slog.String("error", err.Error())`
+- Capitalize messages, never log sensitive data
+
+**Enriched loggers - avoid duplication:**
+```go
+// ❌ BAD - duplicating "org" field already in .With()
+logger := logging.FromContext(ctx).With("org", org)
+logger.DebugContext(ctx, "Using token", "org", org, "installation_id", installationID)
+
+// ✅ GOOD - add repeated fields to .With() early, don't duplicate
+logger := logging.FromContext(ctx).With("org", org, "installation_id", installationID)
+logger.DebugContext(ctx, "Using token")
+```

cmd/cachewd/main.go

@@ -3,7 +3,6 @@ package main
 import (
 	"context"
 	"fmt"
-	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -91,15 +90,15 @@ func main() {
 	kctx.FatalIfErrorf(err, "failed to create metrics client")
 	defer func() {
 		if err := metricsClient.Close(); err != nil {
-			logger.ErrorContext(ctx, "failed to close metrics client", "error", err)
+			logger.ErrorContext(ctx, fmt.Sprintf("Failed to close metrics client: %v", err), "error", err)
 		}
 	}()
 
 	if err := metricsClient.ServeMetrics(ctx); err != nil {
 		kctx.FatalIfErrorf(err, "failed to start metrics server")
 	}
 
-	logger.InfoContext(ctx, "Starting cachewd", slog.String("bind", globalConfig.Bind))
+	logger.InfoContext(ctx, fmt.Sprintf("Starting cachewd on %s", globalConfig.Bind), "bind", globalConfig.Bind)
 
 	server := newServer(ctx, mux, globalConfig.Bind, globalConfig.MetricsConfig)
 	err = server.ListenAndServe()

internal/cache/disk.go

@@ -2,6 +2,7 @@ package cache
 
 import (
 	"context"
+	"fmt"
 	"io"
 	"io/fs"
 	"log/slog"
@@ -297,11 +298,11 @@ func (d *Disk) evictionLoop(ctx context.Context) {
 			return
 		case <-ticker.C:
 			if err := d.evict(); err != nil {
-				d.logger.ErrorContext(ctx, "eviction failed", "error", err)
+				d.logger.ErrorContext(ctx, fmt.Sprintf("Cache eviction failed: %v", err), "error", err)
 			}
 		case <-d.runEviction:
 			if err := d.evict(); err != nil {
-				d.logger.ErrorContext(ctx, "eviction failed", "error", err)
+				d.logger.ErrorContext(ctx, fmt.Sprintf("Cache eviction failed: %v", err), "error", err)
 			}
 		}
 	}

internal/config/config.go

@@ -3,6 +3,7 @@ package config
 
 import (
 	"context"
+	"fmt"
 	"log/slog"
 	"math/big"
 	"net/http"
@@ -128,7 +129,7 @@ func Load(
 
 	cache := cache.MaybeNewTiered(ctx, caches)
 
-	logger.DebugContext(ctx, "Cache backend", "cache", cache)
+	logger.DebugContext(ctx, fmt.Sprintf("Cache backend initialized: %v", cache), "cache", cache)
 
 	// Second pass, instantiate strategies and bind them to the mux.
 	for _, block := range strategyCandidates {

internal/githubapp/tokens.go

@@ -72,24 +72,23 @@ func (tm *TokenManager) GetTokenForOrg(ctx context.Context, org string) (string,
 	if tm == nil {
 		return "", errors.New("token manager not initialized")
 	}
-	logger := logging.FromContext(ctx).With(slog.String("org", org))
-
 	installationID := tm.installations.GetInstallationID(org)
 	if installationID == "" {
 		return "", errors.Errorf("no GitHub App installation configured for org: %s", org)
 	}
 
+	logger := logging.FromContext(ctx).With("org", org, "installation_id", installationID)
+
 	tm.mu.RLock()
 	cached, exists := tm.tokens[org]
 	tm.mu.RUnlock()
 
 	if exists && time.Now().Add(tm.cacheConfig.RefreshBuffer).Before(cached.expiresAt) {
-		logger.DebugContext(ctx, "Using cached GitHub App token")
+		logger.DebugContext(ctx, fmt.Sprintf("Using cached GitHub App token for org %s", org))
 		return cached.token, nil
 	}
 
-	logger.DebugContext(ctx, "Fetching new GitHub App installation token",
-		slog.String("installation_id", installationID))
+	logger.DebugContext(ctx, fmt.Sprintf("Fetching new GitHub App installation token for org %s", org))
 
 	token, expiresAt, err := tm.fetchInstallationToken(ctx, installationID)
 	if err != nil {

internal/jobscheduler/jobs.go

@@ -124,7 +124,7 @@ func (q *RootScheduler) worker(ctx context.Context, id int) {
 	for {
 		select {
 		case <-ctx.Done():
-			logger.InfoContext(ctx, "Worker terminated")
+			logger.InfoContext(ctx, fmt.Sprintf("Scheduler worker %d terminated", id))
 			return
 
 		case <-q.workAvailable:
@@ -133,9 +133,9 @@ func (q *RootScheduler) worker(ctx context.Context, id int) {
 				continue
 			}
 			jlogger := logger.With("job", job.String())
-			jlogger.InfoContext(ctx, "Running job")
+			jlogger.InfoContext(ctx, fmt.Sprintf("Running job: %s", job.String()))
 			if err := job.run(ctx); err != nil {
-				jlogger.ErrorContext(ctx, "Job failed", "error", err)
+				jlogger.ErrorContext(ctx, fmt.Sprintf("Job failed (%s): %v", job.String(), err), "error", err)
 			}
 			q.markQueueInactive(job.queue)
 			q.workAvailable <- true

internal/metrics/metrics.go

@@ -178,9 +178,9 @@ func (c *Client) ServeMetrics(ctx context.Context) error {
 	}
 
 	go func() {
-		logger.InfoContext(ctx, "Starting Prometheus metrics server", "port", c.port)
+		logger.InfoContext(ctx, fmt.Sprintf("Starting Prometheus metrics server on port %d", c.port), "port", c.port)
 		if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-			logger.ErrorContext(ctx, "Metrics server error", "error", err)
+			logger.ErrorContext(ctx, fmt.Sprintf("Failed to serve metrics on port %d: %v", c.port, err), "port", c.port, "error", err)
 		}
 	}()
 
@@ -189,7 +189,7 @@ func (c *Client) ServeMetrics(ctx context.Context) error {
 		shutdownCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 		defer cancel()
 		if err := server.Shutdown(shutdownCtx); err != nil {
-			logger.ErrorContext(shutdownCtx, "Metrics server shutdown error", "error", err)
+			logger.ErrorContext(shutdownCtx, fmt.Sprintf("Failed to shutdown metrics server: %v", err), "error", err)
 		}
 	}()
 

internal/strategy/apiv1.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"fmt"
 	"io"
 	"log/slog"
 	"maps"
@@ -55,7 +56,7 @@ func (d *APIV1) statObject(w http.ResponseWriter, r *http.Request) {
 			http.Error(w, "Cache object not found", http.StatusNotFound)
 			return
 		}
-		d.httpError(w, http.StatusInternalServerError, err, "Failed to open cache object", slog.String("key", key.String()))
+		d.httpError(w, http.StatusInternalServerError, err, "Failed to open cache object", "key", key.String())
 		return
 	}
 
@@ -76,18 +77,18 @@ func (d *APIV1) getObject(w http.ResponseWriter, r *http.Request) {
 			http.Error(w, "Cache object not found", http.StatusNotFound)
 			return
 		}
-		d.httpError(w, http.StatusInternalServerError, err, "Failed to open cache object", slog.String("key", key.String()))
+		d.httpError(w, http.StatusInternalServerError, err, "Failed to open cache object", "key", key.String())
 		return
 	}
 
 	maps.Copy(w.Header(), headers)
 
 	_, err = io.Copy(w, cr)
 	if err != nil {
-		d.logger.Error("Failed to copy cache object to response", slog.String("error", err.Error()), slog.String("key", key.String()))
+		d.logger.Error(fmt.Sprintf("Failed to copy cache object to response (key: %s): %v", key.String(), err), "error", err, "key", key.String())
 	}
 	if cerr := cr.Close(); cerr != nil {
-		d.logger.Error("Failed to close cache reader", slog.String("error", cerr.Error()), slog.String("key", key.String()))
+		d.logger.Error(fmt.Sprintf("Failed to close cache reader (key: %s): %v", key.String(), cerr), "error", cerr, "key", key.String())
 	}
 }
 
@@ -113,7 +114,7 @@ func (d *APIV1) putObject(w http.ResponseWriter, r *http.Request) {
 
 	cw, err := d.cache.Create(r.Context(), key, headers, ttl)
 	if err != nil {
-		d.httpError(w, http.StatusInternalServerError, err, "Failed to create cache writer", slog.String("key", key.String()))
+		d.httpError(w, http.StatusInternalServerError, err, "Failed to create cache writer", "key", key.String())
 		return
 	}
 
@@ -141,7 +142,7 @@ func (d *APIV1) deleteObject(w http.ResponseWriter, r *http.Request) {
 			http.Error(w, "Cache object not found", http.StatusNotFound)
 			return
 		}
-		d.httpError(w, http.StatusInternalServerError, err, "Failed to delete cache object", slog.String("key", key.String()))
+		d.httpError(w, http.StatusInternalServerError, err, "Failed to delete cache object", "key", key.String())
 		return
 	}
 }
@@ -159,12 +160,12 @@ func (d *APIV1) getStats(w http.ResponseWriter, r *http.Request) {
 
 	w.Header().Set("Content-Type", "application/json")
 	if err := json.NewEncoder(w).Encode(stats); err != nil {
-		d.logger.Error("Failed to encode stats response", slog.String("error", err.Error()))
+		d.logger.Error(fmt.Sprintf("Failed to encode stats response: %v", err), "error", err)
 	}
 }
 
 func (d *APIV1) httpError(w http.ResponseWriter, code int, err error, message string, args ...any) {
-	args = append(args, slog.String("error", err.Error()))
+	args = append(args, "error", err)
 	d.logger.Error(message, args...)
 	http.Error(w, message, code)
 }

internal/strategy/artifactory.go

@@ -90,9 +90,9 @@ func (a *Artifactory) registerPathBased(ctx context.Context, target *url.URL, hd
 
 	pattern := "GET " + a.prefix + "/"
 	mux.Handle(pattern, hdlr)
-	a.logger.InfoContext(ctx, "Registered Artifactory path-based route",
-		slog.String("prefix", a.prefix),
-		slog.String("target", target.String()))
+	a.logger.InfoContext(ctx, fmt.Sprintf("Registered Artifactory path-based route: %s -> %s", a.prefix, target.String()),
+		"prefix", a.prefix,
+		"target", target.String())
 }
 
 // registerHostBased registers host-based routing patterns for the configured hosts.
@@ -103,9 +103,9 @@ func (a *Artifactory) registerHostBased(ctx context.Context, hosts []string, hdl
 	for _, host := range hosts {
 		pattern := "GET " + host + "/"
 		mux.Handle(pattern, hdlr)
-		a.logger.InfoContext(ctx, "Registered Artifactory host-based route",
-			slog.String("pattern", pattern),
-			slog.String("target", a.target.String()))
+		a.logger.InfoContext(ctx, fmt.Sprintf("Registered Artifactory host-based route: %s -> %s", pattern, a.target.String()),
+			"pattern", pattern,
+			"target", a.target.String())
 	}
 }
 

internal/strategy/git/backend.go

@@ -3,6 +3,7 @@ package git
 import (
 	"bytes"
 	"context"
+	"fmt"
 	"log/slog"
 	"net/http"
 	"net/http/cgi" //nolint:gosec // CVE-2016-5386 only affects Go < 1.6.3
@@ -77,9 +78,9 @@ func (s *Strategy) serveFromBackend(w http.ResponseWriter, r *http.Request, repo
 		handler.ServeHTTP(w, r2)
 
 		if stderrBuf.Len() > 0 {
-			logger.ErrorContext(r.Context(), "git http-backend error",
-				slog.String("stderr", stderrBuf.String()),
-				slog.String("path", backendPath))
+			logger.ErrorContext(r.Context(), fmt.Sprintf("Git http-backend error for path %s: %s", backendPath, stderrBuf.String()),
+				"stderr", stderrBuf.String(),
+				"path", backendPath)
 		}
 
 		return nil

internal/strategy/git/bundle.go

@@ -3,7 +3,7 @@ package git
 import (
 	"bytes"
 	"context"
-	"log/slog"
+	"fmt"
 	"net/http"
 	"os/exec"
 	"time"
@@ -16,10 +16,10 @@ import (
 )
 
 func (s *Strategy) generateAndUploadBundle(ctx context.Context, repo *gitclone.Repository) error {
-	logger := logging.FromContext(ctx)
 	upstream := repo.UpstreamURL()
+	logger := logging.FromContext(ctx).With("upstream", upstream)
 
-	logger.InfoContext(ctx, "Bundle generation started", slog.String("upstream", upstream))
+	logger.InfoContext(ctx, fmt.Sprintf("Bundle generation started: %s", upstream))
 
 	cacheKey := cache.NewKey(upstream + ".bundle")
 
@@ -48,10 +48,10 @@ func (s *Strategy) generateAndUploadBundle(ctx context.Context, repo *gitclone.R
 		return nil
 	}), "generate bundle")
 	if err != nil {
-		logger.ErrorContext(ctx, "Bundle generation failed", slog.String("upstream", upstream), slog.String("error", err.Error()))
+		logger.ErrorContext(ctx, fmt.Sprintf("Bundle generation failed for %s: %v", upstream, err), "error", err)
 		return err
 	}
 
-	logger.InfoContext(ctx, "Bundle generation completed", slog.String("upstream", upstream))
+	logger.InfoContext(ctx, fmt.Sprintf("Bundle generation completed: %s", upstream))
 	return nil
 }