diff --git a/spindle/engines/microvm/read_cache_proxy.go b/spindle/engines/microvm/read_cache_proxy.go index cb0b3e3fc..c08bc7617 100644 --- a/spindle/engines/microvm/read_cache_proxy.go +++ b/spindle/engines/microvm/read_cache_proxy.go @@ -125,10 +125,28 @@ func (l *cidFilteredVsockListener) Accept() (net.Conn, error) { } } +func cacheURLForLog(raw string) string { + switch raw { + case "daemon", "local": + return raw + } + u, err := url.Parse(raw) + if err != nil { + return "" + } + redacted := *u + redacted.User = nil + redacted.RawQuery = "" + redacted.ForceQuery = false + redacted.Fragment = "" + redacted.RawFragment = "" + return redacted.String() +} + func parseCacheUpstreams(raw []string) ([]*url.URL, error) { upstreams := make([]*url.URL, 0, len(raw)) seen := make(map[string]struct{}, len(raw)) - for _, value := range raw { + for i, value := range raw { value = strings.TrimSpace(value) if value == "" { continue @@ -140,13 +158,13 @@ func parseCacheUpstreams(raw []string) ([]*url.URL, error) { parsed, err := url.Parse(value) if err != nil { - return nil, fmt.Errorf("parse URL %q: %w", value, err) + return nil, fmt.Errorf("invalid cache URL at index %d: %s", i, cacheURLForLog(value)) } if parsed.Scheme != "http" && parsed.Scheme != "https" { - return nil, fmt.Errorf("URL %q uses unsupported scheme %q", value, parsed.Scheme) + return nil, fmt.Errorf("cache URL at index %d (%s) uses unsupported scheme %q", i, cacheURLForLog(value), parsed.Scheme) } if parsed.Host == "" { - return nil, fmt.Errorf("URL %q is missing host", value) + return nil, fmt.Errorf("cache URL at index %d (%s) is missing host", i, cacheURLForLog(value)) } upstreams = append(upstreams, parsed) } @@ -420,8 +438,8 @@ func (t *parallelRacingTransport) RoundTrip(req *http.Request) (*http.Response, if res.err != nil { if !errors.Is(res.err, context.Canceled) { t.logger.Warn("upstream failed", - "path", req.URL.Path, - "error", res.err, + "path", sanitizeExternalText(req.URL.Path), + "error", sanitizeExternalText(res.err.Error()), ) } continue diff --git a/spindle/engines/microvm/read_cache_proxy_test.go b/spindle/engines/microvm/read_cache_proxy_test.go index 87b53f00d..10bdbb902 100644 --- a/spindle/engines/microvm/read_cache_proxy_test.go +++ b/spindle/engines/microvm/read_cache_proxy_test.go @@ -3,10 +3,14 @@ package microvm import ( + "context" + "errors" "io" "log/slog" + "net" "net/http" "net/http/httptest" + "net/url" "strings" "testing" "time" @@ -210,3 +214,38 @@ func TestCacheProxyRejectsUnsafeRequestShapes(t *testing.T) { t.Fatalf("rejected requests reached upstream %d times", hits) } } + +func TestCacheURLForLogRedactsCredentials(t *testing.T) { + got := cacheURLForLog("https://user:password@cache.example/base?token=secret#fragment") + if got != "https://cache.example/base" { + t.Fatalf("redacted URL = %q", got) + } +} + +func TestRedactURLsInTextStripsCredentialsAndSecrets(t *testing.T) { + got := redactURLsInText(`Put "https://user:password@cache.example/nar/abc.nar.xz?token=secret#frag": write: broken pipe`) + want := `Put "https://REDACTED@cache.example/nar/abc.nar.xz": write: broken pipe` + if got != want { + t.Fatalf("redacted text = %q, want %q", got, want) + } +} + +func TestRedactingErrorKeepsErrorChain(t *testing.T) { + wrapped := redactingError{err: &url.Error{ + Op: "Put", + URL: "https://user:password@cache.example/nar/abc.nar.xz?token=secret", + Err: context.DeadlineExceeded, + }} + + message := wrapped.Error() + if strings.Contains(message, "password") || strings.Contains(message, "token=secret") { + t.Fatalf("redacted error still leaks credentials: %q", message) + } + if !errors.Is(wrapped, context.DeadlineExceeded) { + t.Error("errors.Is(context.DeadlineExceeded) no longer matches") + } + var netErr net.Error + if !errors.As(wrapped, &netErr) { + t.Error("errors.As(net.Error) no longer matches") + } +} diff --git a/spindle/engines/microvm/upload_cache_nix_store.go b/spindle/engines/microvm/upload_cache_nix_store.go index 82ce20034..e87709cc2 100644 --- a/spindle/engines/microvm/upload_cache_nix_store.go +++ b/spindle/engines/microvm/upload_cache_nix_store.go @@ -29,7 +29,7 @@ func (execRunner) Run(ctx context.Context, name string, args ...string) error { cmd := exec.CommandContext(ctx, name, args...) out, err := cmd.CombinedOutput() if err != nil { - return fmt.Errorf("%s %s: %w\n%s", name, strings.Join(args, " "), err, string(out)) + return fmt.Errorf("%s failed: %w: %s", name, redactingError{err}, sanitizeExternalText(string(out))) } return nil } @@ -459,9 +459,9 @@ func (b *NixStoreUploadBackend) importStorePath(ctx context.Context, storePath s } args = append(args, storePath) - b.logger.Info("importing staged cache path", "target", b.targetStore, "storePath", storePath) + b.logger.Info("importing staged cache path", "target", cacheURLForLog(b.targetStore), "storePath", sanitizeExternalText(storePath)) if err := b.runner.Run(ctx, "nix", args...); err != nil { - return fmt.Errorf("nix copy to %s: %w", b.targetStore, err) + return fmt.Errorf("nix copy to %s: %w", cacheURLForLog(b.targetStore), err) } return nil } diff --git a/spindle/engines/microvm/upload_cache_proxy.go b/spindle/engines/microvm/upload_cache_proxy.go index cad543d52..140f00595 100644 --- a/spindle/engines/microvm/upload_cache_proxy.go +++ b/spindle/engines/microvm/upload_cache_proxy.go @@ -53,7 +53,7 @@ func StartUploadCacheProxy(ctx context.Context, cid uint32, uploadURL string, re if logger == nil { logger = slog.Default() } - logger = logger.With("where", "upload_cache_proxy", "cid", cid, "uploadURL", uploadURL) + logger = logger.With("where", "upload_cache_proxy", "cid", cid, "uploadURL", cacheURLForLog(uploadURL)) backend, err := newUploadCacheBackend(uploadURL, operatorCacheUpstreams(readUpstreams), stagingDir, logger, opts.TrustedPublicKeys...) if err != nil { @@ -103,7 +103,7 @@ func StartUploadCacheProxy(ctx context.Context, cid uint32, uploadURL string, re } }() - logger.Info("started upload cache proxy", "port", port, "target", uploadURL, "readUpstreams", len(readUpstreams)) + logger.Info("started upload cache proxy", "port", port, "target", cacheURLForLog(uploadURL), "readUpstreams", len(readUpstreams)) return proxy, nil } @@ -114,13 +114,13 @@ func newUploadCacheBackend(uploadURL string, readUpstreams []CacheUpstream, stag target, err := url.Parse(uploadURL) if err != nil { - return nil, fmt.Errorf("parse upload URL %q: %w", uploadURL, err) + return nil, fmt.Errorf("invalid upload URL %s", cacheURLForLog(uploadURL)) } switch target.Scheme { case "http", "https": if target.Host == "" { - return nil, fmt.Errorf("upload URL %q is missing host", uploadURL) + return nil, fmt.Errorf("upload URL %s is missing host", cacheURLForLog(uploadURL)) } return newHTTPUploadProxyBackend(target, readUpstreams, logger), nil @@ -132,11 +132,11 @@ func newUploadCacheBackend(uploadURL string, readUpstreams []CacheUpstream, stag case "daemon", "local": return newNixStoreUploadBackend(uploadURL, stagingDir, readUpstreams, logger, nil, trustedPublicKeys...) default: - return nil, fmt.Errorf("unsupported upload URL %q", uploadURL) + return nil, fmt.Errorf("unsupported upload URL %s", cacheURLForLog(uploadURL)) } default: - return nil, fmt.Errorf("upload URL %q uses unsupported scheme %q", uploadURL, target.Scheme) + return nil, fmt.Errorf("upload URL %s uses unsupported scheme %q", cacheURLForLog(uploadURL), target.Scheme) } } diff --git a/spindle/engines/microvm/upload_staging.go b/spindle/engines/microvm/upload_staging.go index 964dbfaeb..44879839e 100644 --- a/spindle/engines/microvm/upload_staging.go +++ b/spindle/engines/microvm/upload_staging.go @@ -14,14 +14,65 @@ import ( "net/url" "os" "path/filepath" + "regexp" "strings" "sync" "time" + "unicode" "tangled.org/core/spindle/observability" "tangled.org/core/spindle/quota" ) +func sanitizeExternalText(value string) string { + value = redactURLsInText(value) + const maxRunes = 256 + var b strings.Builder + count := 0 + for _, r := range value { + if count == maxRunes { + b.WriteString("…") + break + } + if unicode.IsControl(r) { + b.WriteRune('�') + } else { + b.WriteRune(r) + } + count++ + } + return b.String() +} + +var urlInTextRe = regexp.MustCompile(`[a-zA-Z][a-zA-Z0-9+.-]*://[^\s"'<>]+`) + +func redactURLsInText(value string) string { + return urlInTextRe.ReplaceAllStringFunc(value, redactURLToken) +} + +func redactURLToken(raw string) string { + trimmed := strings.TrimRight(raw, `.,;:!?)]}"'`) + suffix := raw[len(trimmed):] + parsed, err := url.Parse(trimmed) + if err != nil { + scheme, _, _ := strings.Cut(trimmed, "://") + return scheme + "://REDACTED" + suffix + } + if parsed.User != nil { + parsed.User = url.User("REDACTED") + } + parsed.RawQuery = "" + parsed.ForceQuery = false + parsed.Fragment = "" + parsed.RawFragment = "" + return parsed.String() + suffix +} + +type redactingError struct{ err error } + +func (e redactingError) Error() string { return redactURLsInText(e.err.Error()) } +func (e redactingError) Unwrap() error { return e.err } + type stagedNarVerifier interface { Verify(context.Context, string, string, []string, bool) error } @@ -99,7 +150,7 @@ func (s *stagingWrapper) ServeHTTP(w http.ResponseWriter, r *http.Request) { relPath, err := normalizeUploadCachePath(r.URL.Path) if err != nil { - s.logger.Warn("refusing upload cache request with unsafe path", "path", r.URL.Path, "error", err) + s.logger.Warn("refusing upload cache request with unsafe path", "path", sanitizeExternalText(r.URL.Path), "error", err) http.Error(w, "invalid path", http.StatusBadRequest) return } @@ -153,7 +204,7 @@ func (s *stagingWrapper) handlePutNar(w http.ResponseWriter, r *http.Request, re name := strings.TrimPrefix(relPath, "nar/") dst, err := s.stagingObjectPath(relPath) if err != nil { - s.logger.Warn("refusing nar upload with unsafe path", "name", name, "error", err) + s.logger.Warn("refusing nar upload with unsafe path", "name", sanitizeExternalText(name), "error", err) http.Error(w, "invalid nar path", http.StatusBadRequest) return } @@ -223,7 +274,7 @@ func (s *stagingWrapper) handlePutNar(w http.ResponseWriter, r *http.Request, re }) if err != nil { s.releaseOrTrack(reservationID) - s.logger.Warn("stage nar upload failed", "name", name, "error", err) + s.logger.Warn("stage nar upload failed", "name", sanitizeExternalText(name), "error", err) var maxErr *http.MaxBytesError if errors.As(err, &maxErr) { http.Error(w, "nar too large", http.StatusRequestEntityTooLarge) @@ -246,7 +297,7 @@ func (s *stagingWrapper) handlePutNar(w http.ResponseWriter, r *http.Request, re s.stagedNARs[dst] = stagedNar{size: written, reservationID: reservationID} delete(s.skippedNARs, relPath) - s.logger.Debug("staged nar", "name", name, "bytes", written) + s.logger.Debug("staged nar", "name", sanitizeExternalText(name), "bytes", written) w.WriteHeader(http.StatusOK) } @@ -261,37 +312,37 @@ func canonicalNarKey(raw string) (string, error) { func (s *stagingWrapper) handlePutNarinfo(w http.ResponseWriter, r *http.Request, relPath string) { body, err := io.ReadAll(io.LimitReader(r.Body, maxNarinfoSize+1)) if err != nil { - s.logger.Warn("read narinfo body failed", "path", relPath, "error", err) + s.logger.Warn("read narinfo body failed", "path", sanitizeExternalText(relPath), "error", err) http.Error(w, "upload failed", http.StatusBadRequest) return } if len(body) > maxNarinfoSize { - s.logger.Warn("narinfo body exceeds maximum size", "path", relPath, "bytes", len(body)) + s.logger.Warn("narinfo body exceeds maximum size", "path", sanitizeExternalText(relPath), "bytes", len(body)) http.Error(w, "narinfo too large", http.StatusBadRequest) return } info, err := parseNarinfo(bytes.NewReader(body)) if err != nil { - s.logger.Warn("refusing narinfo upload with invalid body", "path", relPath, "error", err) - http.Error(w, "invalid narinfo: "+err.Error(), http.StatusBadRequest) + s.logger.Warn("refusing narinfo upload with invalid body", "path", sanitizeExternalText(relPath), "error", sanitizeExternalText(err.Error())) + http.Error(w, "invalid narinfo", http.StatusBadRequest) return } storePathHash, _, err := parseStorePath(info.StorePath) if err != nil { - s.logger.Warn("refusing narinfo upload with invalid store path", "path", relPath, "store_path", info.StorePath, "error", err) + s.logger.Warn("refusing narinfo upload with invalid store path", "path", sanitizeExternalText(relPath), "store_path", sanitizeExternalText(info.StorePath), "error", err) http.Error(w, "invalid StorePath", http.StatusBadRequest) return } fileHash := strings.TrimSuffix(filepath.Base(relPath), ".narinfo") if fileHash != storePathHash { - s.logger.Warn("refusing narinfo upload with mismatched filename hash", "path", relPath, "store_path", info.StorePath) + s.logger.Warn("refusing narinfo upload with mismatched filename hash", "path", sanitizeExternalText(relPath), "store_path", sanitizeExternalText(info.StorePath)) http.Error(w, "narinfo filename does not match StorePath hash", http.StatusBadRequest) return } narKey, err := canonicalNarKey(info.URL) if err != nil { - s.logger.Warn("narinfo references invalid nar URL", "path", relPath, "url", info.URL, "error", err) + s.logger.Warn("narinfo references invalid nar URL", "path", sanitizeExternalText(relPath), "url", sanitizeExternalText(info.URL), "error", sanitizeExternalText(err.Error())) http.Error(w, "invalid nar URL", http.StatusBadRequest) return } @@ -304,13 +355,13 @@ func (s *stagingWrapper) handlePutNarinfo(w http.ResponseWriter, r *http.Request narPath, err := s.stagingObjectPath(narKey) if err != nil { - s.logger.Warn("narinfo references unsafe nar URL", "path", relPath, "url", info.URL, "error", err) + s.logger.Warn("narinfo references unsafe nar URL", "path", sanitizeExternalText(relPath), "url", sanitizeExternalText(info.URL), "error", err) http.Error(w, "invalid nar URL", http.StatusBadRequest) return } narFi, err := os.Stat(narPath) if err != nil { - s.logger.Warn("narinfo references missing nar", "path", relPath, "url", info.URL, "error", err) + s.logger.Warn("narinfo references missing nar", "path", sanitizeExternalText(relPath), "url", sanitizeExternalText(info.URL), "error", err) http.Error(w, "referenced nar does not exist", http.StatusBadRequest) return } @@ -324,20 +375,20 @@ func (s *stagingWrapper) handlePutNarinfo(w http.ResponseWriter, r *http.Request dst, err := s.stagingObjectPath(relPath) if err != nil { - s.logger.Warn("refusing narinfo upload with unsafe path", "path", relPath, "error", err) + s.logger.Warn("refusing narinfo upload with unsafe path", "path", sanitizeExternalText(relPath), "error", err) s.abortCleanup(staged.reservationID, narPath, "") http.Error(w, "invalid path", http.StatusBadRequest) return } if _, err := writeNarinfoFile(dst, body); err != nil { - s.logger.Warn("stage narinfo upload failed", "path", relPath, "error", err) + s.logger.Warn("stage narinfo upload failed", "path", sanitizeExternalText(relPath), "error", err) s.abortCleanup(staged.reservationID, narPath, dst) http.Error(w, "internal error", http.StatusInternalServerError) return } if s.verifier != nil { if err := s.verifier.Verify(r.Context(), s.stagingDir, info.StorePath, s.trustedPublicKeys, s.requireSignedUploads); err != nil { - s.logger.Warn("refusing untrusted cache upload", "store_path", info.StorePath, "error", err.Error()) + s.logger.Warn("refusing untrusted cache upload", "store_path", sanitizeExternalText(info.StorePath), "error", sanitizeExternalText(err.Error())) s.abortCleanup(staged.reservationID, narPath, dst) http.Error(w, "cache object failed integrity or signature verification", http.StatusBadRequest) return @@ -422,7 +473,7 @@ func (s *stagingWrapper) handlePutNarinfo(w http.ResponseWriter, r *http.Request } if pubErr != nil { - s.logger.Warn("backend publish failed", "error", pubErr, "nar_published", narPublished) + s.logger.Warn("backend publish failed", "error", sanitizeExternalText(pubErr.Error()), "nar_published", narPublished) if narPublished || s.isUncertain(pubErr) { s.removeStagedNar(narPath) _ = os.Remove(dst) @@ -434,7 +485,7 @@ func (s *stagingWrapper) handlePutNarinfo(w http.ResponseWriter, r *http.Request metrics.RecordCacheUpload(backendName, "failed") metrics.RecordCacheUploadBytes(backendName, "failed", narSize) } - http.Error(w, "publish failed: "+pubErr.Error(), http.StatusBadGateway) + http.Error(w, "publish failed", http.StatusBadGateway) return } @@ -487,13 +538,13 @@ func (s *stagingWrapper) publishHTTP(ctx context.Context, relPath string, body i resp, err := client.Do(req) if err != nil { - return err + return redactingError{err} } defer resp.Body.Close() if resp.StatusCode < 200 || resp.StatusCode >= 300 { respBody, _ := io.ReadAll(io.LimitReader(resp.Body, 1024)) - return publishStatusError{status: resp.StatusCode, body: string(respBody)} + return publishStatusError{status: resp.StatusCode, body: sanitizeExternalText(string(respBody))} } return nil @@ -528,12 +579,12 @@ func (s *stagingWrapper) isUncertain(err error) bool { func (s *stagingWrapper) stagingObjectPath(relPath string) (string, error) { if !isNarObjectPath(relPath) && !isNarinfoObjectPath(relPath) { - return "", fmt.Errorf("invalid cache object path %q", relPath) + return "", fmt.Errorf("invalid cache object path %q", sanitizeExternalText(relPath)) } local, err := filepath.Localize(relPath) if err != nil { - return "", fmt.Errorf("unsafe cache object path %q: %w", relPath, err) + return "", fmt.Errorf("unsafe cache object path %q: %w", sanitizeExternalText(relPath), err) } return filepath.Join(s.stagingDir, local), nil