Release corrections round 3: redact candidate-lookup failures in logs (#104)

Co-authored-by: orchestrator-agent <20+orchestrator-agent@code.cubecraftcreations.com>

docs/ARCHITECTURE.md

@@ -240,7 +240,12 @@ automatic** (D-021).
   (kept in memory, so a restart means fetching the candidates again) at
   the `grounding_revision` it was searched at, so a candidate offered
   before any rename is refused even if the name is changed back; the
-  page's URL, which may carry a token, is never returned or cached.
+  page's URL, which may carry a token, is never returned or cached. An
+  unknown dinner is 404, recipe search not set up 409 `not_configured` and
+  a search failure 502 `search_failed`; any other failure, such as a
+  stored recipe that cannot be read, is 500, logged with a fixed reason
+  and the dinner id only — never a candidate's URL or dependency error
+  text.
   `POST /api/v1/dinners/{id}/ground` takes exactly one of `{candidate_id}`,
   `{recipe_url}` (both grounded with `GroundURL`, setting `grounded`) or `{manual: {ingredients[], steps[], minutes,
   method}}` (1–100 ingredient lines, up to 100 steps, each non-blank and at

internal/dinners/grounding.go

@@ -85,6 +85,11 @@ var ErrGroundTimeout = errors.New("dinners: grounding the recipe took too long")
 // logged.
 var ErrGroundFailed = errors.New("dinners: grounding the recipe failed")
 
+// ErrCandidatesFailed wraps any unexpected failure finding a dinner's
+// candidates. Its text may quote a candidate's URL and dependency errors,
+// so it is never logged.
+var ErrCandidatesFailed = errors.New("dinners: finding recipe candidates failed")
+
 // ErrArchived is grounding an archived dinner by hand.
 var ErrArchived = errors.New("dinner archived")
 
@@ -332,19 +337,24 @@ type offerSearch struct {
 // replace the dinner's earlier candidates: one not offered again no longer
 // grounds it. They ground it for offerLifetime, and not at all once it is
 // grounded by hand, renamed or archived, even while this search runs. A
-// search that fails wraps recipes.ErrSearchFailed.
+// missing dinner is ErrNotFound; any other failure wraps
+// ErrCandidatesFailed, and a search that fails also wraps
+// recipes.ErrSearchFailed.
 func (s *Service) Candidates(ctx context.Context, id string) ([]Candidate, error) {
 	// Tracked before the dinner is read: grounding, renaming or archiving
 	// it after the read keeps this search from storing what it found.
 	keep, done := s.trackOffers(id)
 	defer done()
 	row, err := s.get(ctx, id)
-	if err != nil {
+	if errors.Is(err, ErrNotFound) {
 		return nil, err
 	}
+	if err != nil {
+		return nil, fmt.Errorf("%w: dinner %s: %w", ErrCandidatesFailed, id, err)
+	}
 	offers, err := s.grounder.Candidates(ctx, row.Name, row.Name, MaxCandidates)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("%w: dinner %s: %w", ErrCandidatesFailed, id, err)
 	}
 	out := make([]Candidate, len(offers))
 	urls := make(map[string]string, len(offers))

internal/server/dinners.go

@@ -205,7 +205,8 @@ func actorOrFail(w http.ResponseWriter, r *http.Request, logger *slog.Logger) (a
 // an archived dinner is 409 dinner_archived and one changed while grounding
 // 409 ground_conflict. Any other grounding failure, by candidate, link or
 // manual recipe, wraps dinners.ErrGroundFailed and is 500, logged by reason
-// and dinner id only.
+// and dinner id only, as is any other failure finding candidates, which
+// wraps dinners.ErrCandidatesFailed.
 func writeDinnerError(w http.ResponseWriter, r *http.Request, logger *slog.Logger, action string, err error) {
 	var invalid *dinners.ValidationError
 	var dup *dinners.DuplicateError
@@ -231,6 +232,12 @@ func writeDinnerError(w http.ResponseWriter, r *http.Request, logger *slog.Logge
 		// logged.
 		logger.ErrorContext(r.Context(), action, "reason", "ground_failed", "dinner_id", chi.URLParam(r, "id"))
 		writeError(w, r, logger, http.StatusInternalServerError, "internal", "internal error")
+	case errors.Is(err, dinners.ErrCandidatesFailed):
+		// The error may quote a candidate's URL, which can carry a
+		// personal token, and dependency errors, so only the reason and
+		// dinner are logged.
+		logger.ErrorContext(r.Context(), action, "reason", "candidates_failed", "dinner_id", chi.URLParam(r, "id"))
+		writeError(w, r, logger, http.StatusInternalServerError, "internal", "internal error")
 	case errors.Is(err, dinners.ErrArchived):
 		writeError(w, r, logger, http.StatusConflict, "dinner_archived", "the dinner is archived")
 	case errors.Is(err, dinners.ErrGroundConflict):

internal/server/grounding_test.go

@@ -204,6 +204,57 @@ func TestGetRecipeCandidatesSearchFails(t *testing.T) {
 	}
 }
 
+// TestGetRecipeCandidatesStoredLookupFailure: a candidate whose stored
+// recipe cannot be read, or is stored incomplete, is a 500 logged by reason
+// and dinner id, never with the candidate's URL, which can carry a personal
+// token, or the database error.
+func TestGetRecipeCandidatesStoredLookupFailure(t *testing.T) {
+	t.Parallel()
+	const (
+		token = "personal-token-abc123"
+		host  = "secret-candidate.example"
+		page  = "https://" + host + "/curry?access_token=" + token
+	)
+	for _, tc := range []struct {
+		name, sabotage string
+		leaks          []string
+	}{
+		// Renaming a column the lookup selects fails the read.
+		{"lookup", `ALTER TABLE recipes RENAME COLUMN yield TO yield_gone`, []string{"no such column", "yield"}},
+		// A recipe stored without its photo, method or difficulty is
+		// incomplete.
+		{"incomplete", `INSERT INTO recipes (id, source_url, title, raw_jsonld, fetched_at, created_at, updated_at)
+			VALUES ('r-incomplete', '` + page + `', 'Curry', '{}', 'now', 'now', 'now')`, []string{"r-incomplete", "no photo"}},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			e := newDinnersEnv(t)
+			e.search.Results["Chicken curry"] = []recipes.Candidate{{URL: page}}
+			id := createDinner(t, e.h, `{"name":"Chicken curry"}`) // runner not started: stays pending
+			if _, err := e.st.Writer.ExecContext(t.Context(), tc.sabotage); err != nil {
+				t.Fatal(err)
+			}
+
+			rec, body := callDinners(t, e.h, http.MethodGet, dinnersPath+"/"+id+"/recipe-candidates", "")
+			if rec.Code != http.StatusInternalServerError || errorCode(body) != "internal" {
+				t.Errorf("GET = %d %s, want 500 internal", rec.Code, rec.Body)
+			}
+			logs := e.logs.String()
+			for _, secret := range append([]string{page, host, token, "access_token"}, tc.leaks...) {
+				if strings.Contains(rec.Body.String(), secret) {
+					t.Errorf("response contains %q: %s", secret, rec.Body)
+				}
+				if strings.Contains(logs, secret) {
+					t.Errorf("logs contain %q: %s", secret, logs)
+				}
+			}
+			if !strings.Contains(logs, "reason=candidates_failed") || !strings.Contains(logs, "dinner_id="+id) {
+				t.Errorf("logs = %q, want reason=candidates_failed and the dinner id", logs)
+			}
+		})
+	}
+}
+
 func TestPostGroundViaCandidate(t *testing.T) {
 	t.Parallel()
 	e := newDinnersEnv(t).withRecipes(t)