diff --git a/AGENTS.md b/AGENTS.md index fdacc57..0f78ffc 100644 --- a/AGENTS.md +++ b/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") +``` diff --git a/cmd/cachewd/main.go b/cmd/cachewd/main.go index 59efcbc..1676ad2 100644 --- a/cmd/cachewd/main.go +++ b/cmd/cachewd/main.go @@ -3,7 +3,6 @@ package main import ( "context" "fmt" - "log/slog" "net" "net/http" "os" @@ -91,7 +90,7 @@ 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) } }() @@ -99,7 +98,7 @@ func main() { 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() diff --git a/internal/cache/disk.go b/internal/cache/disk.go index 10ca9e2..59fb11b 100644 --- a/internal/cache/disk.go +++ b/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) } } } diff --git a/internal/config/config.go b/internal/config/config.go index 52762cf..4cf3ef9 100644 --- a/internal/config/config.go +++ b/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 { diff --git a/internal/githubapp/tokens.go b/internal/githubapp/tokens.go index 9eefaec..086bf56 100644 --- a/internal/githubapp/tokens.go +++ b/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 { diff --git a/internal/jobscheduler/jobs.go b/internal/jobscheduler/jobs.go index 03c45e7..633e073 100644 --- a/internal/jobscheduler/jobs.go +++ b/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 diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 37edb95..97204a2 100644 --- a/internal/metrics/metrics.go +++ b/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) } }() diff --git a/internal/strategy/apiv1.go b/internal/strategy/apiv1.go index d92b0b9..7daeebb 100644 --- a/internal/strategy/apiv1.go +++ b/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,7 +77,7 @@ 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 } @@ -84,10 +85,10 @@ func (d *APIV1) getObject(w http.ResponseWriter, r *http.Request) { _, 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) } diff --git a/internal/strategy/artifactory.go b/internal/strategy/artifactory.go index 08c105c..db6206c 100644 --- a/internal/strategy/artifactory.go +++ b/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()) } } diff --git a/internal/strategy/git/backend.go b/internal/strategy/git/backend.go index 9b0dd8d..511222f 100644 --- a/internal/strategy/git/backend.go +++ b/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 diff --git a/internal/strategy/git/bundle.go b/internal/strategy/git/bundle.go index 115609f..0442e49 100644 --- a/internal/strategy/git/bundle.go +++ b/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 } diff --git a/internal/strategy/git/git.go b/internal/strategy/git/git.go index 57cffc3..692d092 100644 --- a/internal/strategy/git/git.go +++ b/internal/strategy/git/git.go @@ -6,6 +6,7 @@ import ( "context" "crypto/sha256" "encoding/hex" + "fmt" "io" "log/slog" "net/http" @@ -95,7 +96,7 @@ func New( existing, err := s.cloneManager.DiscoverExisting(ctx) if err != nil { logger.WarnContext(ctx, "Failed to discover existing clones", - slog.String("error", err.Error())) + "error", err) } for _, repo := range existing { if s.config.BundleInterval > 0 { @@ -124,14 +125,14 @@ func New( // Inject token as Basic auth with "x-access-token" username req.SetBasicAuth("x-access-token", token) logger.DebugContext(req.Context(), "Injecting GitHub App auth into upstream request", - slog.String("org", org)) + "org", org) } } } }, Transport: s.httpClient.Transport, ErrorHandler: func(w http.ResponseWriter, r *http.Request, err error) { - logging.FromContext(r.Context()).ErrorContext(r.Context(), "Upstream request failed", slog.String("error", err.Error())) + logging.FromContext(r.Context()).ErrorContext(r.Context(), fmt.Sprintf("Upstream request failed: %v", err), "error", err) w.WriteHeader(http.StatusBadGateway) }, } @@ -164,10 +165,10 @@ func (s *Strategy) handleRequest(w http.ResponseWriter, r *http.Request) { host := r.PathValue("host") pathValue := r.PathValue("path") - logger.DebugContext(ctx, "Git request", - slog.String("method", r.Method), - slog.String("host", host), - slog.String("path", pathValue)) + logger.DebugContext(ctx, fmt.Sprintf("Git request: %s %s%s", r.Method, host, pathValue), + "method", r.Method, + "host", host, + "path", pathValue) if strings.HasSuffix(pathValue, "/bundle") { s.handleBundleRequest(w, r, host, pathValue) @@ -183,7 +184,10 @@ func (s *Strategy) handleRequest(w http.ResponseWriter, r *http.Request) { isReceivePack := service == "git-receive-pack" || strings.HasSuffix(pathValue, "/git-receive-pack") if isReceivePack { - logger.DebugContext(ctx, "Forwarding write operation to upstream") + logger.DebugContext(ctx, fmt.Sprintf("Forwarding write operation to upstream: %s %s%s", r.Method, host, pathValue), + slog.String("method", r.Method), + slog.String("host", host), + slog.String("path", pathValue)) s.forwardToUpstream(w, r, host, pathValue) return } @@ -193,8 +197,9 @@ func (s *Strategy) handleRequest(w http.ResponseWriter, r *http.Request) { repo, err := s.cloneManager.GetOrCreate(ctx, upstreamURL) if err != nil { - logger.ErrorContext(ctx, "Failed to get or create clone", - slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Failed to get or create clone for %s: %v", upstreamURL, err), + "upstream", upstreamURL, + "error", err) http.Error(w, "Internal server error", http.StatusInternalServerError) return } @@ -206,8 +211,9 @@ func (s *Strategy) handleRequest(w http.ResponseWriter, r *http.Request) { case gitclone.StateReady: if isInfoRefs { if err := s.ensureRefsUpToDate(ctx, repo); err != nil { - logger.WarnContext(ctx, "Failed to ensure refs up to date", - slog.String("error", err.Error())) + logger.WarnContext(ctx, fmt.Sprintf("Failed to ensure refs up to date for %s: %v", repo.UpstreamURL(), err), + "upstream", repo.UpstreamURL(), + "error", err) } } s.maybeBackgroundFetch(repo) @@ -215,7 +221,8 @@ func (s *Strategy) handleRequest(w http.ResponseWriter, r *http.Request) { case gitclone.StateCloning, gitclone.StateEmpty: if state == gitclone.StateEmpty { - logger.DebugContext(ctx, "Starting background clone, forwarding to upstream") + logger.DebugContext(ctx, fmt.Sprintf("Starting background clone for %s, forwarding to upstream", repo.UpstreamURL()), + "upstream", repo.UpstreamURL()) s.scheduler.Submit(repo.UpstreamURL(), "clone", func(ctx context.Context) error { s.startClone(ctx, repo) return nil @@ -276,8 +283,8 @@ func (s *Strategy) cleanupSpools(upstreamURL string) { if rp != nil { if err := rp.Close(); err != nil { logging.FromContext(s.ctx).WarnContext(s.ctx, "Failed to clean up spools", - slog.String("upstream", upstreamURL), - slog.String("error", err.Error())) + "upstream", upstreamURL, + "error", err) } } } @@ -289,7 +296,7 @@ func (s *Strategy) serveWithSpool(w http.ResponseWriter, r *http.Request, host, key, err := SpoolKeyForRequest(pathValue, r) if err != nil { logger.WarnContext(ctx, "Failed to compute spool key, forwarding to upstream", - slog.String("error", err.Error())) + "error", err) s.forwardToUpstream(w, r, host, pathValue) return } @@ -302,15 +309,15 @@ func (s *Strategy) serveWithSpool(w http.ResponseWriter, r *http.Request, host, spool, isWriter, err := rp.GetOrCreate(key) if err != nil { logger.WarnContext(ctx, "Failed to create spool, forwarding to upstream", - slog.String("error", err.Error())) + "error", err) s.forwardToUpstream(w, r, host, pathValue) return } if isWriter { logger.DebugContext(ctx, "Spooling upstream response", - slog.String("key", key), - slog.String("upstream", upstreamURL)) + "key", key, + "upstream", upstreamURL) tw := NewSpoolTeeWriter(w, spool) s.forwardToUpstream(tw, r, host, pathValue) spool.MarkComplete() @@ -319,24 +326,24 @@ func (s *Strategy) serveWithSpool(w http.ResponseWriter, r *http.Request, host, if spool.Failed() { logger.DebugContext(ctx, "Spool failed, forwarding to upstream", - slog.String("key", key)) + "key", key) s.forwardToUpstream(w, r, host, pathValue) return } logger.DebugContext(ctx, "Serving from spool", - slog.String("key", key), - slog.String("upstream", upstreamURL)) + "key", key, + "upstream", upstreamURL) if err := spool.ServeTo(w); err != nil { if errors.Is(err, ErrSpoolFailed) { logger.DebugContext(ctx, "Spool failed before response started, forwarding to upstream", - slog.String("key", key)) + "key", key) s.forwardToUpstream(w, r, host, pathValue) return } - logger.WarnContext(ctx, "Spool read failed mid-stream", - slog.String("key", key), - slog.String("error", err.Error())) + logger.WarnContext(ctx, fmt.Sprintf("Spool read failed mid-stream for key %s: %v", key, err), + "key", key, + "error", err) } } @@ -358,8 +365,8 @@ func (s *Strategy) serveCachedArtifact(w http.ResponseWriter, r *http.Request, h logger := logging.FromContext(ctx) logger.DebugContext(ctx, artifact+" request", - slog.String("host", host), - slog.String("path", pathValue)) + "host", host, + "path", pathValue) pathValue = strings.TrimSuffix(pathValue, "/"+artifact) repoPath := ExtractRepoPath(pathValue) @@ -370,13 +377,14 @@ func (s *Strategy) serveCachedArtifact(w http.ResponseWriter, r *http.Request, h if err != nil { if errors.Is(err, os.ErrNotExist) { logger.DebugContext(ctx, artifact+" not found in cache", - slog.String("upstream", upstreamURL)) + "upstream", upstreamURL) http.NotFound(w, r) return } - logger.ErrorContext(ctx, "Failed to open "+artifact+" from cache", - slog.String("upstream", upstreamURL), - slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Failed to open %s from cache for %s: %v", artifact, upstreamURL, err), + "artifact", artifact, + "upstream", upstreamURL, + "error", err) http.Error(w, "Internal server error", http.StatusInternalServerError) return } @@ -390,9 +398,10 @@ func (s *Strategy) serveCachedArtifact(w http.ResponseWriter, r *http.Request, h _, err = io.Copy(w, reader) if err != nil { - logger.ErrorContext(ctx, "Failed to stream "+artifact, - slog.String("upstream", upstreamURL), - slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Failed to stream %s for %s: %v", artifact, upstreamURL, err), + "artifact", artifact, + "upstream", upstreamURL, + "error", err) } } @@ -400,8 +409,8 @@ func (s *Strategy) startClone(ctx context.Context, repo *gitclone.Repository) { logger := logging.FromContext(ctx) logger.InfoContext(ctx, "Starting clone", - slog.String("upstream", repo.UpstreamURL()), - slog.String("path", repo.Path())) + "upstream", repo.UpstreamURL(), + "path", repo.Path()) err := repo.Clone(ctx) @@ -410,15 +419,15 @@ func (s *Strategy) startClone(ctx context.Context, repo *gitclone.Repository) { s.cleanupSpools(repo.UpstreamURL()) if err != nil { - logger.ErrorContext(ctx, "Clone failed", - slog.String("upstream", repo.UpstreamURL()), - slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Clone failed for %s: %v", repo.UpstreamURL(), err), + "upstream", repo.UpstreamURL(), + "error", err) return } logger.InfoContext(ctx, "Clone completed", - slog.String("upstream", repo.UpstreamURL()), - slog.String("path", repo.Path())) + "upstream", repo.UpstreamURL(), + "path", repo.Path()) if s.config.BundleInterval > 0 { s.scheduleBundleJobs(repo) @@ -448,13 +457,13 @@ func (s *Strategy) backgroundFetch(ctx context.Context, repo *gitclone.Repositor } logger.DebugContext(ctx, "Fetching updates", - slog.String("upstream", repo.UpstreamURL()), - slog.String("path", repo.Path())) + "upstream", repo.UpstreamURL(), + "path", repo.Path()) if err := repo.Fetch(ctx); err != nil { - logger.ErrorContext(ctx, "Fetch failed", - slog.String("upstream", repo.UpstreamURL()), - slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Fetch failed for %s: %v", repo.UpstreamURL(), err), + "upstream", repo.UpstreamURL(), + "error", err) } } diff --git a/internal/strategy/git/integration_test.go b/internal/strategy/git/integration_test.go index e6b6d88..cd45f14 100644 --- a/internal/strategy/git/integration_test.go +++ b/internal/strategy/git/integration_test.go @@ -31,7 +31,7 @@ func testServerWithLogging(ctx context.Context, handler http.Handler) *httptest. wrapper := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { logger := logging.FromContext(ctx).With("request", fmt.Sprintf("%s %s", r.Method, r.RequestURI)) r = r.WithContext(logging.ContextWithLogger(r.Context(), logger)) - logger.Debug("Request received") + logger.Debug(fmt.Sprintf("Request received: %s %s", r.Method, r.RequestURI)) handler.ServeHTTP(w, r) }) return httptest.NewServer(wrapper) diff --git a/internal/strategy/git/proxy.go b/internal/strategy/git/proxy.go index ecacbc4..88b1d1a 100644 --- a/internal/strategy/git/proxy.go +++ b/internal/strategy/git/proxy.go @@ -1,7 +1,7 @@ package git import ( - "log/slog" + "fmt" "net/http" "github.com/block/cachew/internal/logging" @@ -10,10 +10,10 @@ import ( func (s *Strategy) forwardToUpstream(w http.ResponseWriter, r *http.Request, host, pathValue string) { logger := logging.FromContext(r.Context()) - logger.DebugContext(r.Context(), "Forwarding to upstream", - slog.String("method", r.Method), - slog.String("host", host), - slog.String("path", pathValue)) + logger.DebugContext(r.Context(), fmt.Sprintf("Forwarding to upstream: %s %s%s", r.Method, host, pathValue), + "method", r.Method, + "host", host, + "path", pathValue) s.proxy.ServeHTTP(w, r) } diff --git a/internal/strategy/git/snapshot.go b/internal/strategy/git/snapshot.go index 9d294fc..0edd00d 100644 --- a/internal/strategy/git/snapshot.go +++ b/internal/strategy/git/snapshot.go @@ -2,7 +2,7 @@ package git import ( "context" - "log/slog" + "fmt" "net/http" "time" @@ -15,10 +15,10 @@ import ( ) func (s *Strategy) generateAndUploadSnapshot(ctx context.Context, repo *gitclone.Repository) error { - logger := logging.FromContext(ctx) upstream := repo.UpstreamURL() + logger := logging.FromContext(ctx).With("upstream", upstream) - logger.InfoContext(ctx, "Snapshot generation started", slog.String("upstream", upstream)) + logger.InfoContext(ctx, fmt.Sprintf("Snapshot generation started: %s", upstream)) cacheKey := cache.NewKey(upstream + ".snapshot") ttl := 7 * 24 * time.Hour @@ -26,11 +26,11 @@ func (s *Strategy) generateAndUploadSnapshot(ctx context.Context, repo *gitclone err := errors.Wrap(snapshot.Create(ctx, s.cache, cacheKey, repo.Path(), ttl, excludePatterns), "create snapshot") if err != nil { - logger.ErrorContext(ctx, "Snapshot generation failed", slog.String("upstream", upstream), slog.String("error", err.Error())) + logger.ErrorContext(ctx, fmt.Sprintf("Snapshot generation failed for %s: %v", upstream, err), "error", err) return err } - logger.InfoContext(ctx, "Snapshot generation completed", slog.String("upstream", upstream)) + logger.InfoContext(ctx, fmt.Sprintf("Snapshot generation completed: %s", upstream)) return nil } diff --git a/internal/strategy/github_releases.go b/internal/strategy/github_releases.go index 5add55b..64cbece 100644 --- a/internal/strategy/github_releases.go +++ b/internal/strategy/github_releases.go @@ -4,7 +4,6 @@ import ( "context" "encoding/json" "fmt" - "log/slog" "net/http" "slices" @@ -95,8 +94,8 @@ func (g *GitHubReleases) newGitHubRequest(ctx context.Context, url, accept, org token, err := g.tokenManager.GetTokenForOrg(ctx, org) if err != nil { logging.FromContext(ctx).WarnContext(ctx, "Failed to get GitHub App token, falling back to static token", - slog.String("org", org), - slog.String("error", err.Error())) + "org", org, + "error", err) } else if token != "" { req.Header.Set("Authorization", "Bearer "+token) } @@ -117,15 +116,15 @@ func (g *GitHubReleases) downloadRelease(ctx context.Context, org, repo, release isPrivate := slices.Contains(g.config.PrivateOrgs, org) logger := logging.FromContext(ctx).With( - slog.String("org", org), - slog.String("repo", repo), - slog.String("release", release), - slog.String("file", file)) + "org", org, + "repo", repo, + "release", release, + "file", file) realURL := fmt.Sprintf("https://github.com/%s/%s/releases/download/%s/%s", org, repo, release, file) if !isPrivate { // Public release - use direct download URL - logger.DebugContext(ctx, "Using public download URL") + logger.DebugContext(ctx, fmt.Sprintf("Using public download URL for %s/%s/%s", org, repo, file)) req, err := http.NewRequestWithContext(ctx, http.MethodGet, realURL, nil) if err != nil { return nil, httputil.Errorf(http.StatusInternalServerError, "create download request") @@ -134,7 +133,7 @@ func (g *GitHubReleases) downloadRelease(ctx context.Context, org, repo, release } // Use GitHub API to get release info and find the asset - logger.DebugContext(ctx, "Using GitHub API for private release") + logger.DebugContext(ctx, fmt.Sprintf("Using GitHub API for private release %s/%s:%s", org, repo, release)) apiURL := fmt.Sprintf("https://api.github.com/repos/%s/%s/releases/tags/%s", org, repo, release) req, err := g.newGitHubRequest(ctx, apiURL, "application/vnd.github+json", org) if err != nil { @@ -170,11 +169,11 @@ func (g *GitHubReleases) downloadRelease(ctx context.Context, org, repo, release } } if assetURL == "" { - logger.ErrorContext(ctx, "Asset not found in release", slog.Int("assets_count", len(releaseInfo.Assets))) + logger.ErrorContext(ctx, fmt.Sprintf("Asset not found in release (found %d assets)", len(releaseInfo.Assets)), "assets_count", len(releaseInfo.Assets)) return nil, httputil.Errorf(http.StatusNotFound, "asset %s not found in release %s", file, release) } - logger.DebugContext(ctx, "Found asset in release", slog.String("asset_url", assetURL)) + logger.DebugContext(ctx, fmt.Sprintf("Found asset in release: %s", assetURL), "asset_url", assetURL) // Create request for the asset download req, err = g.newGitHubRequest(ctx, assetURL, "application/octet-stream", org) diff --git a/internal/strategy/gomod/private_fetcher.go b/internal/strategy/gomod/private_fetcher.go index 955a979..d7d8d49 100644 --- a/internal/strategy/gomod/private_fetcher.go +++ b/internal/strategy/gomod/private_fetcher.go @@ -37,8 +37,8 @@ func newPrivateFetcher(logger *slog.Logger, cloneManager *gitclone.Manager) *pri } func (p *privateFetcher) Query(ctx context.Context, path, query string) (version string, t time.Time, err error) { - logger := p.logger.With(slog.String("module", path), slog.String("query", query)) - logger.DebugContext(ctx, "Private fetcher: Query") + logger := p.logger.With("module", path, "query", query) + logger.DebugContext(ctx, fmt.Sprintf("Private fetcher query for module %s: %s", path, query)) gitURL := p.modulePathToGitURL(path) @@ -60,8 +60,8 @@ func (p *privateFetcher) Query(ctx context.Context, path, query string) (version } func (p *privateFetcher) List(ctx context.Context, path string) (versions []string, err error) { - logger := p.logger.With(slog.String("module", path)) - logger.DebugContext(ctx, "Private fetcher: List") + logger := p.logger.With("module", path) + logger.DebugContext(ctx, fmt.Sprintf("Private fetcher list for module %s", path)) gitURL := p.modulePathToGitURL(path) repo, err := p.cloneManager.GetOrCreate(ctx, gitURL) @@ -82,8 +82,8 @@ func (p *privateFetcher) List(ctx context.Context, path string) (versions []stri } func (p *privateFetcher) Download(ctx context.Context, path, version string) (info, mod, zip io.ReadSeekCloser, err error) { - logger := p.logger.With(slog.String("module", path), slog.String("version", version)) - logger.DebugContext(ctx, "Private fetcher: Download") + logger := p.logger.With("module", path, "version", version) + logger.DebugContext(ctx, fmt.Sprintf("Private fetcher download for module %s version %s", path, version)) gitURL := p.modulePathToGitURL(path) repo, err := p.cloneManager.GetOrCreate(ctx, gitURL) diff --git a/internal/strategy/handler/handler.go b/internal/strategy/handler/handler.go index 4056329..f303b87 100644 --- a/internal/strategy/handler/handler.go +++ b/internal/strategy/handler/handler.go @@ -1,6 +1,7 @@ package handler import ( + "fmt" "io" "log/slog" "maps" @@ -102,7 +103,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { cacheKeyStr := h.cacheKeyFunc(r) key := cache.NewKey(cacheKeyStr) - logger.DebugContext(r.Context(), "Processing request", slog.String("cache_key", cacheKeyStr)) + logger.DebugContext(r.Context(), fmt.Sprintf("Processing request for cache key: %s", cacheKeyStr), "cache_key", cacheKeyStr) if h.serveCached(w, r, key, logger) { return @@ -121,18 +122,18 @@ func (h *Handler) serveCached(w http.ResponseWriter, r *http.Request, key cache. return false } - logger.DebugContext(r.Context(), "Cache hit") + logger.DebugContext(r.Context(), fmt.Sprintf("Cache hit for key: %s", key.String()), "cache_key", key.String()) defer cr.Close() maps.Copy(w.Header(), headers) if _, err := io.Copy(w, cr); err != nil { - logger.ErrorContext(r.Context(), "Failed to stream from cache", slog.String("error", err.Error())) - httputil.ErrorResponse(w, r, http.StatusInternalServerError, "Failed to stream from cache", "error", err.Error()) + logger.ErrorContext(r.Context(), fmt.Sprintf("Failed to stream from cache (key: %s): %v", key.String(), err), "cache_key", key.String(), "error", err) + httputil.ErrorResponse(w, r, http.StatusInternalServerError, "Failed to stream from cache", "error", err) } return true } func (h *Handler) fetchAndCache(w http.ResponseWriter, r *http.Request, key cache.Key, logger *slog.Logger) { - logger.DebugContext(r.Context(), "Cache miss, fetching from upstream") + logger.DebugContext(r.Context(), fmt.Sprintf("Cache miss for key: %s, fetching from upstream", key.String()), "cache_key", key.String()) upstreamReq, err := h.transformFunc(r) if err != nil { @@ -147,7 +148,7 @@ func (h *Handler) fetchAndCache(w http.ResponseWriter, r *http.Request, key cach } defer func() { if closeErr := resp.Body.Close(); closeErr != nil { - logger.ErrorContext(r.Context(), "Failed to close response body", slog.String("error", closeErr.Error())) + logger.ErrorContext(r.Context(), fmt.Sprintf("Failed to close response body: %v", closeErr), "error", closeErr) } }() @@ -162,7 +163,7 @@ func (h *Handler) fetchAndCache(w http.ResponseWriter, r *http.Request, key cach func (h *Handler) streamNonOKResponse(w http.ResponseWriter, resp *http.Response, logger *slog.Logger) { w.WriteHeader(resp.StatusCode) if _, err := io.Copy(w, resp.Body); err != nil { - logger.ErrorContext(resp.Request.Context(), "Failed to stream error response", slog.String("error", err.Error())) + logger.ErrorContext(resp.Request.Context(), fmt.Sprintf("Failed to stream error response (status %d): %v", resp.StatusCode, err), "status_code", resp.StatusCode, "error", err) } } @@ -185,10 +186,10 @@ func (h *Handler) streamAndCache(w http.ResponseWriter, r *http.Request, key cac maps.Copy(w.Header(), resp.Header) if _, err := io.Copy(w, pr); err != nil { - logger.ErrorContext(r.Context(), "Failed to stream response", slog.String("error", err.Error())) + logger.ErrorContext(r.Context(), fmt.Sprintf("Failed to stream response: %v", err), "error", err) } if closeErr := pr.Close(); closeErr != nil { - logger.ErrorContext(r.Context(), "Failed to close pipe", slog.String("error", closeErr.Error())) + logger.ErrorContext(r.Context(), fmt.Sprintf("Failed to close pipe: %v", closeErr), "error", closeErr) } } diff --git a/internal/strategy/hermit.go b/internal/strategy/hermit.go index 52f1fbc..02b1438 100644 --- a/internal/strategy/hermit.go +++ b/internal/strategy/hermit.go @@ -2,6 +2,7 @@ package strategy import ( "context" + "fmt" "log/slog" "net/http" "net/url" @@ -60,11 +61,11 @@ func NewHermit(ctx context.Context, config HermitConfig, _ jobscheduler.Schedule isInternalRedirect := config.GitHubBaseURL == defaultGitHubBaseURL s.redirectHandler = s.createRedirectHandler(isInternalRedirect, c) mux.Handle("GET /hermit/github.com/{path...}", s.redirectHandler) - logger.InfoContext(ctx, "Hermit strategy initialized", - slog.String("github_base_url", config.GitHubBaseURL), - slog.Bool("internal_redirect", isInternalRedirect)) + logger.InfoContext(ctx, fmt.Sprintf("Hermit strategy initialized with GitHub base URL: %s", config.GitHubBaseURL), + "github_base_url", config.GitHubBaseURL, + "internal_redirect", isInternalRedirect) } else { - logger.InfoContext(ctx, "Hermit strategy initialized") + logger.InfoContext(ctx, "Hermit strategy initialized without GitHub base URL") } return s, nil @@ -95,7 +96,7 @@ func (s *Hermit) createRedirectHandler(isInternalRedirect bool, c cache.Cache) h return s.buildGitHubURL(r) }). Transform(func(r *http.Request) (*http.Request, error) { - s.logger.DebugContext(r.Context(), "Redirect handler called for GitHub release") + s.logger.DebugContext(r.Context(), fmt.Sprintf("Redirect handler called for GitHub release: %s", r.PathValue("path")), "path", r.PathValue("path")) return s.buildRedirectRequest(r) }) } diff --git a/internal/strategy/host.go b/internal/strategy/host.go index afa4f8a..44cfea1 100644 --- a/internal/strategy/host.go +++ b/internal/strategy/host.go @@ -82,7 +82,7 @@ func (d *Host) buildTargetURL(r *http.Request) *url.URL { targetURL, err := url.Parse(d.target.String()) if err != nil { - d.logger.Error("Failed to parse target URL", "error", err.Error(), "target", d.target.String()) + d.logger.Error(fmt.Sprintf("Failed to parse target URL: %v", err), "error", err, "target", d.target.String()) return &url.URL{} } targetURL.Path = path