fix: review fixes for webhook and auto mode (#8)

Clear available_* only when the deployed ref equals it, drop the unused
poll source, stop leaking internal errors to CI, use the request-scoped
logger, validate X-Request-ID, re-read jobs once after the timeout,
report refused when no target ref exists, and tidy UI, deploy and docs.

internal/master/model/model.go

@@ -56,7 +56,7 @@ type Service struct {
 	// AvailableRef is the newest ref a webhook or poll reported for this
 	// service; "" if none, or if a later job already deployed it.
 	AvailableRef    string
-	AvailableSource string // SourceWebhook or SourcePoll; "" when AvailableRef is empty
+	AvailableSource string // SourceWebhook; "" when AvailableRef is empty
 	AvailableAt     *time.Time
 	FirstSeenAt     time.Time
 	UpdatedAt       time.Time
@@ -72,13 +72,12 @@ const (
 // Sources of an available ref.
 const (
 	SourceWebhook = "webhook"
-	SourcePoll    = "poll"
 )
 
 // Available is a newer ref reported for a service.
 type Available struct {
 	Ref    string
-	Source string // SourceWebhook or SourcePoll
+	Source string // SourceWebhook
 	At     time.Time
 }
 

internal/master/store/jobs.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"strings"
 	"time"
 
 	"github.com/jackc/pgx/v5"
@@ -187,9 +188,10 @@ func (s *Store) JobProgress(ctx context.Context, agentID, jobID int64, chunk str
 // agentID: status, error, output (replacing what progress assembled),
 // started_at (the agent's, or the existing one if the agent sent none),
 // finished_at; to_ref = f.Ref when set. On success it also sets the
-// service's desired_ref = f.Ref and clears its available ref if that was
-// reported no later than the job was created (the job then deployed the
-// newest version), in the same transaction. Returns false if no
+// service's desired_ref = f.Ref and clears its available ref when that is
+// the ref the job was created for (ignoring any @digest) and was reported no
+// later than the job was created (that version is now running), in the same
+// transaction. Returns false if no
 // such active job belongs to agentID.
 func (s *Store) FinishJob(ctx context.Context, agentID, jobID int64, f model.JobFinish) (bool, error) {
 	tx, err := s.pool.Begin(ctx)
@@ -206,14 +208,17 @@ func (s *Store) FinishJob(ctx context.Context, agentID, jobID int64, f model.Job
 	}
 	var serviceID int64
 	var createdAt time.Time
+	var requestedRef string
+	// requested is the job's to_ref as it was created, before f.Ref overwrites it.
 	err = tx.QueryRow(ctx, `
-		UPDATE update_jobs SET
+		UPDATE update_jobs j SET
 			status = $3, error = $4, output = $5, output_truncated = $6,
-			to_ref = CASE WHEN $7::text <> '' THEN $7::text ELSE to_ref END,
-			started_at = COALESCE($8, started_at), finished_at = $9
-		WHERE id = $1 AND agent_id = $2 AND status IN ('queued', 'running')
-		RETURNING service_id, created_at`,
-		jobID, agentID, string(f.Status), f.Error, f.Output, f.OutputTruncated, f.Ref, startedAt, f.FinishedAt).Scan(&serviceID, &createdAt)
+			to_ref = CASE WHEN $7::text <> '' THEN $7::text ELSE j.to_ref END,
+			started_at = COALESCE($8, j.started_at), finished_at = $9
+		FROM (SELECT id, to_ref FROM update_jobs WHERE id = $1) requested
+		WHERE j.id = requested.id AND j.agent_id = $2 AND j.status IN ('queued', 'running')
+		RETURNING j.service_id, j.created_at, requested.to_ref`,
+		jobID, agentID, string(f.Status), f.Error, f.Output, f.OutputTruncated, f.Ref, startedAt, f.FinishedAt).Scan(&serviceID, &createdAt, &requestedRef)
 	if errors.Is(err, pgx.ErrNoRows) {
 		return false, nil
 	}
@@ -221,12 +226,13 @@ func (s *Store) FinishJob(ctx context.Context, agentID, jobID int64, f model.Job
 		return false, fmt.Errorf("finish job: %w", err)
 	}
 	if f.Status == model.JobSucceeded {
+		requestedRef, _, _ = strings.Cut(requestedRef, "@")
 		if _, err := tx.Exec(ctx, `
 			UPDATE services SET desired_ref = $2,
-				available_ref    = CASE WHEN available_at <= $3 THEN '' ELSE available_ref END,
-				available_source = CASE WHEN available_at <= $3 THEN '' ELSE available_source END,
-				available_at     = CASE WHEN available_at <= $3 THEN NULL ELSE available_at END
-			WHERE id = $1`, serviceID, f.Ref, createdAt); err != nil {
+				available_ref    = CASE WHEN available_ref = $4 AND available_at <= $3 THEN '' ELSE available_ref END,
+				available_source = CASE WHEN available_ref = $4 AND available_at <= $3 THEN '' ELSE available_source END,
+				available_at     = CASE WHEN available_ref = $4 AND available_at <= $3 THEN NULL ELSE available_at END
+			WHERE id = $1`, serviceID, f.Ref, createdAt, requestedRef); err != nil {
 			return false, fmt.Errorf("finish job: desired ref: %w", err)
 		}
 	}

internal/master/store/migrations/0003_webhook.sql

@@ -1,6 +1,6 @@
 ALTER TABLE services ADD COLUMN available_ref    text NOT NULL DEFAULT '';
 ALTER TABLE services ADD COLUMN available_source text NOT NULL DEFAULT ''
-    CHECK (available_source IN ('', 'webhook', 'poll'));
+    CHECK (available_source IN ('', 'webhook'));
 ALTER TABLE services ADD COLUMN available_at     timestamptz;
 
 CREATE INDEX services_by_image_repo ON services (image_repo) WHERE removed_at IS NULL;

internal/master/store/webhook_integration_test.go

@@ -88,18 +88,20 @@ func TestUpsertKeepsUpdateMode(t *testing.T) {
 	assert.Equal(t, model.ModeAuto, got.UpdateMode)
 }
 
-func TestFinishJob_ClearsAvailableOnlyWhenJobIsNewer(t *testing.T) {
+func TestFinishJob_ClearsAvailableOnlyWhenThatVersionWasDeployed(t *testing.T) {
 	succeed := model.JobFinish{Status: model.JobSucceeded, Ref: "r:2@sha256:d", StartedAt: t0, FinishedAt: t0}
 	tests := []struct {
-		name        string
-		availableAt time.Time // job is created at t0
-		finish      model.JobFinish
-		wantCleared bool
+		name         string
+		availableRef string
+		availableAt  time.Time // job is created at t0 for r:2
+		finish       model.JobFinish
+		wantCleared  bool
 	}{
-		{"suggestion before the job", t0.Add(-time.Minute), succeed, true},
-		{"suggestion at the same instant", t0, succeed, true},
-		{"suggestion after the job was created", t0.Add(time.Minute), succeed, false},
-		{"failed job keeps the suggestion", t0.Add(-time.Minute),
+		{"same ref, suggestion before the job", "r:2", t0.Add(-time.Minute), succeed, true},
+		{"same ref, suggestion at the same instant", "r:2", t0, succeed, true},
+		{"same ref, suggestion after the job was created", "r:2", t0.Add(time.Minute), succeed, false},
+		{"different ref keeps the suggestion", "r:3", t0.Add(-time.Minute), succeed, false},
+		{"failed job keeps the suggestion", "r:2", t0.Add(-time.Minute),
 			model.JobFinish{Status: model.JobFailed, Error: "boom", StartedAt: t0, FinishedAt: t0}, false},
 	}
 	for _, tt := range tests {
@@ -107,8 +109,10 @@ func TestFinishJob_ClearsAvailableOnlyWhenJobIsNewer(t *testing.T) {
 			s := openTestStore(t)
 			ctx := context.Background()
 			agent, svc := jobFixture(t, s, "a")
-			require.NoError(t, s.SetAvailable(ctx, svc, model.Available{Ref: "r:2", Source: model.SourceWebhook, At: tt.availableAt}))
-			j, err := s.CreateJob(ctx, newJob(svc, agent))
+			require.NoError(t, s.SetAvailable(ctx, svc, model.Available{Ref: tt.availableRef, Source: model.SourceWebhook, At: tt.availableAt}))
+			nj := newJob(svc, agent)
+			nj.ToRef = "r:2"
+			j, err := s.CreateJob(ctx, nj)
 			require.NoError(t, err)
 
 			ok, err := s.FinishJob(ctx, agent, j.ID, tt.finish)
@@ -122,7 +126,7 @@ func TestFinishJob_ClearsAvailableOnlyWhenJobIsNewer(t *testing.T) {
 				assert.Empty(t, got.AvailableSource)
 				assert.Nil(t, got.AvailableAt)
 			} else {
-				assert.Equal(t, "r:2", got.AvailableRef)
+				assert.Equal(t, tt.availableRef, got.AvailableRef)
 				assert.Equal(t, model.SourceWebhook, got.AvailableSource)
 				assert.NotNil(t, got.AvailableAt)
 			}

internal/master/web/server_test.go

@@ -616,7 +616,7 @@ func TestOverview_ShowsModeToggleAndAvailableBadge(t *testing.T) {
 		assert.Contains(t, body, `name="return" value="overview"`, path)
 		assert.Contains(t, body, `class="badge badge-update" title="gitea.shcizo.se/shcizo/slusk:1.5.0"`, path)
 		assert.Contains(t, body, `<input type="hidden" name="mode" value="manual">`, "auto services toggle to manual: "+path)
-		assert.Contains(t, body, `disabled title="`+model.ReasonSelf+`"`, "blocked manual services get a disabled button: "+path)
+		assert.Contains(t, body, `disabled>Make auto</button> <span class="muted">`+model.ReasonSelf+`</span>`, "blocked manual services get a disabled button: "+path)
 	}
 }
 

internal/master/web/templates/overview.html

@@ -24,7 +24,7 @@
             {{if eq .UpdateMode "auto"}}<input type="hidden" name="mode" value="manual">
             <button type="submit">Make manual</button>
             {{else}}<input type="hidden" name="mode" value="auto">
-            <button type="submit"{{if .AutoBlocked}} disabled title="{{.AutoBlocked}}"{{end}}>Make auto</button>{{end}}
+            <button type="submit"{{if .AutoBlocked}} disabled{{end}}>Make auto</button>{{if .AutoBlocked}} <span class="muted">{{.AutoBlocked}}</span>{{end}}{{end}}
           </form>
         </td>
       </tr>

internal/master/web/views.go

@@ -22,7 +22,8 @@ type serviceRow struct {
 
 // groupServices groups machine-bound services per agent and Swarm services
 // in one group, keeping the store's order (machines first, Swarm last).
-// autoBlocked returns the reason a service cannot be set to auto, or "".
+// autoBlocked is called for every service and returns the reason it cannot be
+// set to auto, or "" when it can.
 func groupServices(services []model.Service, autoBlocked func(model.Service) string) []serviceGroup {
 	var groups []serviceGroup
 	index := map[string]int{}

internal/master/webhook/webhook.go

@@ -33,10 +33,17 @@ const maxBodyBytes = 64 << 10
 // no broker signal arrives (signals to a slow subscriber can be dropped).
 const defaultPollEvery = 5 * time.Second
 
+// finalReadTimeout bounds the last read of pending jobs after the wait ends.
+const finalReadTimeout = 2 * time.Second
+
 // tagPattern is Docker's tag grammar. It keeps spaces, colons and "@" out of
 // the ref the agent is asked to deploy.
 var tagPattern = regexp.MustCompile(`^[A-Za-z0-9_][A-Za-z0-9_.-]{0,127}$`)
 
+// requestIDPattern limits a caller-supplied X-Request-ID to what is safe to
+// echo in a header and write to the log.
+var requestIDPattern = regexp.MustCompile(`^[A-Za-z0-9._-]{1,128}$`)
+
 // Result statuses.
 const (
 	statusSucceeded = "succeeded"
@@ -121,7 +128,7 @@ type response struct {
 func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	started := h.now()
 	requestID := r.Header.Get("X-Request-ID")
-	if requestID == "" {
+	if !requestIDPattern.MatchString(requestID) {
 		requestID = newRequestID()
 	}
 	w.Header().Set("X-Request-ID", requestID)
@@ -175,7 +182,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	resp := response{RequestID: requestID, Image: req.Image, Tag: req.Tag, Matched: len(services)}
 	pending := map[int]int64{} // index into resp.Results -> job ID
 	for _, svc := range services {
-		res, job := h.handle(work, svc, req.Tag, started)
+		res, job := h.handle(work, svc, req.Tag, started, log)
 		resp.Results = append(resp.Results, res)
 		if job != nil {
 			pending[len(resp.Results)-1] = job.ID
@@ -201,7 +208,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 // handle records the available ref on svc and, in auto mode, starts an update.
 // It returns the result and, if the job is still active, that job.
-func (h *Handler) handle(ctx context.Context, svc model.Service, tag string, started time.Time) (result, *model.Job) {
+func (h *Handler) handle(ctx context.Context, svc model.Service, tag string, started time.Time, log *slog.Logger) (result, *model.Job) {
 	res := result{ServiceID: svc.ID, Service: svc.DisplayName(), Kind: string(svc.Kind), Mode: svc.UpdateMode}
 
 	// The ref is built from the service's own repo, never from the request
@@ -212,13 +219,14 @@ func (h *Handler) handle(ctx context.Context, svc model.Service, tag string, sta
 	} else {
 		ref = jobs.FollowedRef(svc.ActualRef)
 	}
+	if ref == "" {
+		return h.finish(res, statusRefused, "no tag given and the service follows no tag", started), nil
+	}
 	res.ToRef = ref
-	if ref != "" {
-		err := h.store.SetAvailable(ctx, svc.ID, model.Available{Ref: ref, Source: model.SourceWebhook, At: h.now()})
-		if err != nil {
-			h.log.Error("webhook_set_available_failed", "service_id", svc.ID, "error", err)
-			return h.finish(res, statusFailed, "could not record available version: "+err.Error(), started), nil
-		}
+	err := h.store.SetAvailable(ctx, svc.ID, model.Available{Ref: ref, Source: model.SourceWebhook, At: h.now()})
+	if err != nil {
+		log.Error("webhook_set_available_failed", "service_id", svc.ID, "error", err)
+		return h.finish(res, statusFailed, "could not record available version", started), nil
 	}
 	if svc.UpdateMode != model.ModeAuto {
 		return h.finish(res, statusMarked, "", started), nil
@@ -233,8 +241,8 @@ func (h *Handler) handle(ctx context.Context, svc model.Service, tag string, sta
 		h.setJob(&res, job)
 		return h.finish(res, statusBusy, err.Error(), started), nil
 	case err != nil:
-		h.log.Error("webhook_start_failed", "service_id", svc.ID, "error", err)
-		return h.finish(res, statusFailed, err.Error(), started), nil
+		log.Error("webhook_start_failed", "service_id", svc.ID, "error", err)
+		return h.finish(res, statusFailed, "could not start job", started), nil
 	}
 	h.setJob(&res, job)
 	if job.Active() {
@@ -280,6 +288,11 @@ func (h *Handler) wait(parent context.Context, sub <-chan events.Topic, resp *re
 	for len(pending) > 0 {
 		select {
 		case <-ctx.Done():
+			// A job may have finished while the timer fired: look once more,
+			// on a context that outlives the request.
+			final, stop := context.WithTimeout(context.WithoutCancel(parent), finalReadTimeout)
+			h.readPending(final, resp, pending, started, log)
+			stop()
 			for i := range pending {
 				resp.Results[i] = h.finish(resp.Results[i], statusTimeout, "still running when the request timed out", started)
 			}
@@ -290,16 +303,22 @@ func (h *Handler) wait(parent context.Context, sub <-chan events.Topic, resp *re
 			}
 		case <-ticker.C:
 		}
-		for i, id := range pending {
-			job, err := h.store.GetJob(ctx, id)
-			if err != nil {
-				log.Warn("webhook_get_job_failed", "job_id", id, "error", err)
-				continue
-			}
-			if !job.Active() {
-				h.resolveJob(&resp.Results[i], job, started)
-				delete(pending, i)
-			}
+		h.readPending(ctx, resp, pending, started, log)
+	}
+}
+
+// readPending re-reads every pending job and resolves the ones that are done.
+func (h *Handler) readPending(ctx context.Context, resp *response, pending map[int]int64,
+	started time.Time, log *slog.Logger) {
+	for i, id := range pending {
+		job, err := h.store.GetJob(ctx, id)
+		if err != nil {
+			log.Warn("webhook_get_job_failed", "job_id", id, "error", err)
+			continue
+		}
+		if !job.Active() {
+			h.resolveJob(&resp.Results[i], job, started)
+			delete(pending, i)
 		}
 	}
 }

internal/master/webhook/webhook_test.go

@@ -289,10 +289,14 @@ func TestAvailableRefWithoutTag(t *testing.T) {
 			e := newEnv(t, compose(1, model.ModeManual, tt.actualRef))
 			rec := e.post(`{"image":"` + slusk + `"}`)
 			assert.Equal(t, 200, rec.Code)
+			r := decode(t, rec).Results[0]
 			if tt.wantRef == "" {
 				assert.Empty(t, e.store.avail)
+				assert.Equal(t, statusRefused, r.Status)
+				assert.Equal(t, "no tag given and the service follows no tag", r.Error)
 				return
 			}
+			assert.Equal(t, statusMarked, r.Status)
 			require.Len(t, e.store.avail, 1)
 			assert.Equal(t, tt.wantRef, e.store.avail[0].a.Ref)
 		})
@@ -302,18 +306,56 @@ func TestAvailableRefWithoutTag(t *testing.T) {
 func TestAutoDigestOnlyServiceWithoutTagIsRefused(t *testing.T) {
 	svc := compose(1, model.ModeAuto, slusk+"@sha256:old")
 	e := newEnv(t, svc)
-	e.jobs.errFor[1] = &model.NotUpdatableError{Reason: model.ReasonNoTag}
 
 	rec := e.post(`{"image":"` + slusk + `"}`)
 
 	assert.Equal(t, 200, rec.Code)
 	assert.Empty(t, e.store.avail)
-	calls := e.jobs.startCalls()
-	require.Len(t, calls, 1)
-	assert.Empty(t, calls[0].req.Ref, "no request tag and nothing followed: the job layer decides")
+	assert.Empty(t, e.jobs.startCalls(), "no target ref: nothing to start")
 	r := decode(t, rec).Results[0]
 	assert.Equal(t, statusRefused, r.Status)
-	assert.Equal(t, model.ReasonNoTag, r.Error)
+	assert.Equal(t, "no tag given and the service follows no tag", r.Error)
+}
+
+func TestValidTags(t *testing.T) {
+	for _, tag := range []string{"latest", "1.2.3-rc.1", "v1_2", strings.Repeat("a", 128)} {
+		e := newEnv(t, compose(1, model.ModeManual, slusk+":1"))
+		rec := e.post(`{"image":"` + slusk + `","tag":"` + tag + `"}`)
+		assert.Equal(t, 200, rec.Code, tag)
+		require.Len(t, e.store.avail, 1, tag)
+		assert.Equal(t, slusk+":"+tag, e.store.avail[0].a.Ref)
+	}
+	e := newEnv(t, compose(1, model.ModeManual, slusk+":1"))
+	rec := e.post(`{"image":"` + slusk + `","tag":"` + strings.Repeat("a", 129) + `"}`)
+	assert.Equal(t, 400, rec.Code)
+}
+
+func TestUnsafeRequestIDIsReplaced(t *testing.T) {
+	for _, id := range []string{"has space", "bad/slash", strings.Repeat("a", 129)} {
+		e := newEnv(t, compose(1, model.ModeManual, slusk+":1"))
+		rec := e.post(`{"image":"`+slusk+`"}`, "X-Request-ID", id)
+		got := rec.Header().Get("X-Request-ID")
+		assert.NotEqual(t, id, got)
+		assert.Regexp(t, `^[0-9a-f]{32}$`, got)
+	}
+	e := newEnv(t, compose(1, model.ModeManual, slusk+":1"))
+	rec := e.post(`{"image":"`+slusk+`"}`, "X-Request-ID", strings.Repeat("a", 128))
+	assert.Equal(t, strings.Repeat("a", 128), rec.Header().Get("X-Request-ID"))
+}
+
+func TestJobFinishedJustBeforeTimeoutIsNotReportedAsTimeout(t *testing.T) {
+	e := newEnv(t, compose(1, model.ModeAuto, slusk+":1.4.2"))
+	e.h.cfg.Timeout = 200 * time.Millisecond
+	e.h.pollEvery = time.Hour // only the final read after the deadline can see the result
+	go func() {
+		assert.Eventually(t, func() bool { return len(e.jobs.startCalls()) == 1 }, time.Second, time.Millisecond)
+		e.store.setJob(model.Job{ID: 1, Status: model.JobSucceeded}) // no Publish
+	}()
+
+	rec := e.post(`{"image":"` + slusk + `"}`)
+
+	assert.Equal(t, 200, rec.Code)
+	assert.Equal(t, statusSucceeded, decode(t, rec).Results[0].Status)
 }
 
 func TestAutoJobTargetIsBuiltFromServiceRepo(t *testing.T) {