fix(office): stop agent heartbeat cooldowns from being silently ignored (#3512)

Co-authored-by: nova28 <17953305+nova28@users.noreply.github.com>
Co-authored-by: Carlos Florencio <carlosmflorencio@gmail.com>
This commit is contained in:
Henry
2026-09-11 04:31:01 +08:00
committed by GitHub
parent 03a383bb24
commit d29f35a7c2
10 changed files with 628 additions and 10 deletions
+18 -7
View File
@@ -151,9 +151,12 @@ func (l *heartbeatTaskLister) ListActiveTasksAtStep(
// 1. AgentInstance.Status — paused/stopped agents never receive
// heartbeats. (idle and working both pass; the runs scheduler's
// own checkout layer handles concurrency.)
// 2. CooldownSec since LastRunFinishedAt — when a run finished
// 2. CooldownSec (from agent_profiles) since
// office_agent_runtime.last_run_finished_at — when a run finished
// recently the gate suppresses heartbeats so the cooldown is
// respected end-to-end (heartbeat ≠ scheduler).
// respected end-to-end (heartbeat ≠ scheduler). This is a distinct
// column from agent_profiles' own same-named last_run_finished_at,
// which no Office write path stamps and must not be read here.
type heartbeatAgentRuntime struct {
office *officesqlite.Repository
}
@@ -175,11 +178,19 @@ func (r *heartbeatAgentRuntime) AllowFire(
case officemodels.AgentStatusPaused, officemodels.AgentStatusStopped:
return false, nil
}
if agent.LastRunFinishedAt != nil && agent.CooldownSec > 0 {
gateUntil := agent.LastRunFinishedAt.Add(time.Duration(agent.CooldownSec) * time.Second)
if now.Before(gateUntil) {
return false, nil
}
if agent.CooldownSec <= 0 {
return true, nil
}
runtime, err := r.office.GetAgentRuntime(ctx, agentID)
if err != nil {
return false, err
}
if runtime == nil || runtime.LastRunFinishedAt == nil {
return true, nil
}
gateUntil := runtime.LastRunFinishedAt.Add(time.Duration(agent.CooldownSec) * time.Second)
if now.Before(gateUntil) {
return false, nil
}
return true, nil
}
@@ -0,0 +1,227 @@
package backendapp
import (
"context"
"path/filepath"
"testing"
"time"
"github.com/jmoiron/sqlx"
"github.com/kandev/kandev/internal/agent/settings/store"
"github.com/kandev/kandev/internal/db"
"github.com/kandev/kandev/internal/office/models"
officesqlite "github.com/kandev/kandev/internal/office/repository/sqlite"
)
// newTestOfficeRepoForCron builds a real office SQLite repository (plus the
// shared agent_profiles schema owned by internal/agent/settings/store) so
// the cooldown gate regression test exercises the actual SELECT/UPDATE
// statements rather than a fake — this is a repository-column bug
// (reading the wrong table's last_run_finished_at), and a fake would
// hide exactly that class of defect.
func newTestOfficeRepoForCron(t *testing.T) (*officesqlite.Repository, *sqlx.DB) {
t.Helper()
dbConn, err := db.OpenSQLite(filepath.Join(t.TempDir(), "cron-cooldown.db"))
if err != nil {
t.Fatalf("open sqlite: %v", err)
}
database := sqlx.NewDb(dbConn, "sqlite3")
t.Cleanup(func() { _ = database.Close() })
_, cleanup, err := store.Provide(database, database, nil)
if err != nil {
t.Fatalf("agent settings store migrations: %v", err)
}
t.Cleanup(func() { _ = cleanup() })
repo, err := officesqlite.NewWithDB(database, database, nil)
if err != nil {
t.Fatalf("office migrations: %v", err)
}
// agent_profiles.agent_id is a FK into agents (CLI tool registrations);
// seed one so CreateAgentInstance's insert satisfies it.
now := time.Now().UTC()
if _, err := database.ExecContext(context.Background(),
`INSERT INTO agents (id, name, created_at, updated_at) VALUES (?, ?, ?, ?)`,
"agent-cli-tool", "cli-tool", now, now,
); err != nil {
t.Fatalf("seed agents row: %v", err)
}
return repo, database
}
// TestHeartbeatAgentRuntime_AllowFire_ReadsOfficeRuntimeCooldown is the
// regression test for the cooldown-gate defect: AllowFire must gate on
// office_agent_runtime.last_run_finished_at (the column
// Service.stampRunFinished actually maintains), not
// agent_profiles.last_run_finished_at (a same-named column inherited
// from the shared kanban agent-settings table that no Office write path
// ever stamps). Before the fix, AllowFire read the agent_profiles
// column, which stays NULL for Office agents, so the cooldown branch
// never triggered and every case below returned true regardless of the
// office_agent_runtime state.
func TestHeartbeatAgentRuntime_AllowFire_ReadsOfficeRuntimeCooldown(t *testing.T) {
repo, _ := newTestOfficeRepoForCron(t)
ctx := context.Background()
gate := &heartbeatAgentRuntime{office: repo}
agent := &models.AgentInstance{
ID: "agent-cooldown-1",
WorkspaceID: "ws-1",
Name: "cooldown-worker",
Role: models.AgentRoleWorker,
Status: models.AgentStatusIdle,
CooldownSec: 60,
}
if err := repo.CreateAgentInstance(ctx, agent); err != nil {
t.Fatalf("create agent: %v", err)
}
now := time.Now().UTC()
// Poison agent_profiles.last_run_finished_at with a value inside the
// 60s cooldown window (now - 5s), not outside it. If AllowFire were
// still reading this column instead of office_agent_runtime, this
// poisoned value alone would gate Case 1 below (no office_agent_runtime
// row yet, wants true) since it never changes across cases — proving
// the column is not consulted. Also confirms this column round-trips
// harmlessly and is not itself relied on by the fixed gate.
staleAgentProfilesValue := now.Add(-5 * time.Second)
agent.LastRunFinishedAt = &staleAgentProfilesValue
if err := repo.UpdateAgentInstance(ctx, agent); err != nil {
t.Fatalf("poison agent_profiles.last_run_finished_at: %v", err)
}
// Case 1: no office_agent_runtime row yet -> an agent that has never
// run is not gated by cooldown.
allowed, err := gate.AllowFire(ctx, agent.ID, now)
if err != nil {
t.Fatalf("AllowFire (no runtime row): %v", err)
}
if !allowed {
t.Error("AllowFire (no runtime row) = false, want true (never-run agent must not be gated)")
}
// Stamp office_agent_runtime.last_run_finished_at to "just now".
if err := repo.UpdateRuntimeLastRunFinished(ctx, agent.ID, now); err != nil {
t.Fatalf("stamp runtime: %v", err)
}
runtime, err := repo.GetAgentRuntime(ctx, agent.ID)
if err != nil || runtime == nil || runtime.LastRunFinishedAt == nil {
t.Fatalf("read stamped runtime: runtime=%+v, err=%v", runtime, err)
}
// Case 2: 30s into a 60s cooldown -> blocked.
allowed, err = gate.AllowFire(ctx, agent.ID, runtime.LastRunFinishedAt.Add(30*time.Second))
if err != nil {
t.Fatalf("AllowFire (within cooldown): %v", err)
}
if allowed {
t.Error("AllowFire (within cooldown) = true, want false")
}
// Case 3: exactly 60s after the stamp -> cooldown elapsed, allowed.
allowed, err = gate.AllowFire(ctx, agent.ID, runtime.LastRunFinishedAt.Add(60*time.Second))
if err != nil {
t.Fatalf("AllowFire (at cooldown boundary): %v", err)
}
if !allowed {
t.Error("AllowFire (at cooldown boundary) = false, want true")
}
}
func TestHeartbeatAgentRuntime_AllowFire_NullRuntimeTimestampAllows(t *testing.T) {
repo, database := newTestOfficeRepoForCron(t)
ctx := context.Background()
gate := &heartbeatAgentRuntime{office: repo}
agent := &models.AgentInstance{
ID: "agent-cooldown-null",
WorkspaceID: "ws-1",
Name: "null-timestamp-worker",
Role: models.AgentRoleWorker,
Status: models.AgentStatusIdle,
CooldownSec: 60,
}
if err := repo.CreateAgentInstance(ctx, agent); err != nil {
t.Fatalf("create agent: %v", err)
}
if err := repo.UpdateRuntimeLastRunFinished(ctx, agent.ID, time.Now().UTC()); err != nil {
t.Fatalf("stamp runtime: %v", err)
}
if _, err := database.ExecContext(ctx,
`UPDATE office_agent_runtime SET last_run_finished_at = NULL WHERE agent_id = ?`,
agent.ID,
); err != nil {
t.Fatalf("clear runtime timestamp: %v", err)
}
allowed, err := gate.AllowFire(ctx, agent.ID, time.Now().UTC())
if err != nil {
t.Fatalf("AllowFire (null runtime timestamp): %v", err)
}
if !allowed {
t.Error("AllowFire (null runtime timestamp) = false, want true")
}
}
func TestHeartbeatAgentRuntime_AllowFire_RuntimeLookupErrorBlocks(t *testing.T) {
repo, database := newTestOfficeRepoForCron(t)
ctx := context.Background()
gate := &heartbeatAgentRuntime{office: repo}
agent := &models.AgentInstance{
ID: "agent-cooldown-error",
WorkspaceID: "ws-1",
Name: "lookup-error-worker",
Role: models.AgentRoleWorker,
Status: models.AgentStatusIdle,
CooldownSec: 60,
}
if err := repo.CreateAgentInstance(ctx, agent); err != nil {
t.Fatalf("create agent: %v", err)
}
if _, err := database.ExecContext(ctx, `DROP TABLE office_agent_runtime`); err != nil {
t.Fatalf("drop runtime table: %v", err)
}
allowed, err := gate.AllowFire(ctx, agent.ID, time.Now().UTC())
if err == nil {
t.Fatal("AllowFire (runtime lookup error) returned nil error")
}
if allowed {
t.Error("AllowFire (runtime lookup error) = true, want false")
}
}
// TestHeartbeatAgentRuntime_AllowFire_ZeroCooldownSkipsRuntimeLookup
// pins the existing short-circuit: cooldown_sec <= 0 always allows
// firing without querying office_agent_runtime at all. The runtime
// table is dropped before the call, so an implementation that queries
// it anyway (instead of skipping) would surface as an error here
// rather than an unproven true.
func TestHeartbeatAgentRuntime_AllowFire_ZeroCooldownSkipsRuntimeLookup(t *testing.T) {
repo, database := newTestOfficeRepoForCron(t)
ctx := context.Background()
gate := &heartbeatAgentRuntime{office: repo}
agent := &models.AgentInstance{
ID: "agent-cooldown-2",
WorkspaceID: "ws-1",
Name: "no-cooldown-worker",
Role: models.AgentRoleWorker,
Status: models.AgentStatusIdle,
CooldownSec: 0,
}
if err := repo.CreateAgentInstance(ctx, agent); err != nil {
t.Fatalf("create agent: %v", err)
}
if _, err := database.ExecContext(ctx, `DROP TABLE office_agent_runtime`); err != nil {
t.Fatalf("drop office_agent_runtime: %v", err)
}
allowed, err := gate.AllowFire(ctx, agent.ID, time.Now().UTC())
if err != nil {
t.Fatalf("AllowFire queried office_agent_runtime despite cooldown_sec=0: %v", err)
}
if !allowed {
t.Error("AllowFire (cooldown_sec=0) = false, want true")
}
}
@@ -27,6 +27,9 @@ const (
// is treated as terminal. The run is marked failed with the verbatim
// error message, the consecutive-failure counter is incremented, and
// when it crosses the effective threshold the agent is auto-paused.
// It also stamps office_agent_runtime.last_run_finished_at the same as
// the completed/stopped paths, so cooldown_sec paces the agent's next
// heartbeat-driven fire regardless of why the previous run ended.
//
// No retry is scheduled — the user resolves via Resume session in the
// chat or Mark fixed in the inbox.
@@ -50,6 +53,7 @@ func (s *Service) HandleAgentFailure(
// here keeps the agent out of a stuck "working" even if the failure
// bookkeeping that follows errors out.
s.clearAgentWorking(ctx, run.AgentProfileID, run.ID)
s.stampRunFinished(ctx, run)
count, err := s.repo.IncrementAgentConsecutiveFailures(ctx, run.AgentProfileID)
if err != nil {
@@ -39,7 +39,6 @@ func TestSchedulerTick_AgentCompletedReleasesTaskCheckout(t *testing.T) {
t.Fatalf("register subscribers: %v", err)
}
beforePublish := time.Now().UTC()
agent := &models.AgentInstance{
ID: "profile-checkout-release",
WorkspaceID: "ws-1",
@@ -113,7 +112,11 @@ func TestSchedulerTick_AgentCompletedReleasesTaskCheckout(t *testing.T) {
// TestSchedulerTick_AgentFailedReleasesTaskCheckout is the failure-path
// counterpart: HandleAgentFailure calls repo.MarkRunFailed directly
// (not Service.FailRun / transitionRunTerminal), so it needs the same
// checkout-release treatment as the completion path.
// checkout-release treatment as the completion path. It also covers the
// cooldown-stamp parity gap: HandleAgentFailure must stamp
// office_agent_runtime.last_run_finished_at the same as the
// completed/stopped paths do, so a below-threshold failing agent is
// still paced by cooldown_sec on its next heartbeat-driven fire.
func TestSchedulerTick_AgentFailedReleasesTaskCheckout(t *testing.T) {
mock := &mockTaskStarter{}
svc := newTestService(t, service.ServiceOptions{TaskStarter: mock})
@@ -169,6 +172,7 @@ func TestSchedulerTick_AgentFailedReleasesTaskCheckout(t *testing.T) {
"error_message": "boom",
"agent_profile_id": agent.ID,
})
beforePublish := time.Now().UTC()
if err := eb.Publish(ctx, events.AgentFailed, event); err != nil {
t.Fatalf("publish agent failed: %v", err)
}
@@ -180,6 +184,17 @@ func TestSchedulerTick_AgentFailedReleasesTaskCheckout(t *testing.T) {
if !ok {
t.Fatal("expected task checkout to be released after AgentFailed, but another agent still cannot check it out")
}
runtime, err := svc.GetAgentRuntimeForTest(ctx, agent.ID)
if err != nil {
t.Fatalf("get agent runtime: %v", err)
}
if runtime == nil || runtime.LastRunFinishedAt == nil {
t.Fatal("expected last_run_finished_at to be stamped after AgentFailed, but it is still unset")
}
if runtime.LastRunFinishedAt.Before(beforePublish) {
t.Errorf("last_run_finished_at = %v, want at/after %v", runtime.LastRunFinishedAt, beforePublish)
}
}
// TestSchedulerTick_TasklessAgentCompletedStampsRuntime is the taskless-path
+81
View File
@@ -0,0 +1,81 @@
---
spec: docs/specs/office/agents.md
created: 2026-08-22
status: done
---
# Implementation Plan: Wire the Office agent cooldown gate
## Overview
PR #2902 fixed `office_agent_runtime.last_run_finished_at` to be stamped correctly on every
completed/stopped run (sync and async, task-bound and taskless), but explicitly scoped out two
follow-ups. This plan closes both, resolved together because they're the same underlying question
("what does the Office heartbeat cooldown gate mean?"):
1. **Wrong column.** `heartbeatAgentRuntime.AllowFire` (`internal/backendapp/cron.go`) reads
`agent_profiles.last_run_finished_at` — a column from the shared kanban agent-settings table
that no Office write path ever stamps — instead of `office_agent_runtime.last_run_finished_at`,
the column `Service.stampRunFinished` actually maintains. `agent.LastRunFinishedAt != nil` is
therefore always false and the cooldown branch never fires: Office heartbeat cooldown is
silently a no-op today, regardless of `cooldown_sec`.
2. **Missing stamp on failure.** `HandleAgentFailure` (`internal/office/service/failure.go`) marks
a run failed and releases its task checkout but never calls `stampRunFinished`. Once (1) is
fixed, a below-threshold failing agent would be exempt from cooldown pacing entirely (unlike a
successful or stopped run), letting a flapping agent retry with zero pacing until it crosses the
auto-pause threshold.
Resolved spec decision (see amendments below): cooldown paces **every** terminal run outcome for an
agent — completed, stopped, taskless-completed, and failed alike — uniformly. It is a run-pacing
mechanism, not a success tracker. The separate consecutive-failure counter / auto-pause threshold
remains the mechanism for stopping a chronically broken agent; cooldown only paces the failures that
happen before that threshold is reached.
Out of scope: removing or migrating the dead `agent_profiles.last_run_finished_at` column (bigger
blast radius across the shared kanban agent-settings table; not needed to fix the bug — the gate
just needs to stop reading it). No schema change. No frontend change.
## Spec amendments (already applied)
- `docs/specs/office/agents.md` — persistence-guarantees bullet for `office_agent_runtime` now
names the exact gate (`heartbeatAgentRuntime.AllowFire`), states which column it must read, and
explicitly calls out the `agent_profiles` same-named column as dead/not-authoritative.
- `docs/specs/office/runtime.md` — "Retry policy" section states that a terminal failure stamps the
cooldown timestamp same as success; a new persistence-guarantee bullet and a new GIVEN/WHEN/THEN
scenario cover it.
## Backend
### Task 01: Cooldown gate reads `office_agent_runtime`, not `agent_profiles` — done
`heartbeatAgentRuntime.AllowFire` currently gates on `agent.LastRunFinishedAt` (from
`office.GetAgentInstance`, i.e. `agent_profiles`). Change it to load the runtime row via
`office.GetAgentRuntime(ctx, agentID)` (already exists, returns `*officesqlite.RuntimeState` with
`LastRunFinishedAt *time.Time`, `nil, nil` when no row) and gate on that timestamp instead.
`agent.CooldownSec` still comes from `agent_profiles` (that field is actively written and unrelated
to this bug). No repository or schema change — `GetAgentRuntime` already exists and is already
exercised by other tests.
### Task 02: `HandleAgentFailure` stamps the cooldown timestamp — done
Add a `s.stampRunFinished(ctx, run)` call to `HandleAgentFailure` (`internal/office/service/failure.go`),
placed after `s.releaseTaskCheckoutForRun(ctx, run)` and before the consecutive-failure counter
work, mirroring the completed/stopped paths' ordering (finish/mark → release checkout → stamp).
`stampRunFinished` is already shared, idempotent, and no-ops safely on a nil run or empty
`AgentProfileID`; this task is a one-line call plus a test.
## Task waves
| Wave | Tasks | Parallel-safe |
|------|-------|----------------|
| 1 | 01, 02 | Yes — disjoint files (`internal/backendapp/cron.go` vs `internal/office/service/failure.go`), disjoint test files, no shared schema/migration/generated contract. |
Default `parallelism: sequential` in each task file per repo convention; the table above is a human
dispatch aid, not standing authorization to delegate to subagents.
## Validation
```bash
cd apps/backend && go test ./internal/backendapp/... ./internal/office/service/... ./internal/office/repository/sqlite/...
cd apps/backend && golangci-lint run ./internal/backendapp/... ./internal/office/service/... --timeout=5m
```
@@ -0,0 +1,136 @@
---
id: "01-cooldown-gate-column"
title: "Wire the heartbeat cooldown gate to office_agent_runtime"
status: done
wave: 1
depends_on: []
plan: "plan.md"
spec: "../../specs/office/agents.md"
---
# Task 01: Wire the heartbeat cooldown gate to `office_agent_runtime`
## Root cause
`heartbeatAgentRuntime.AllowFire` (`apps/backend/internal/backendapp/cron.go:160-184`) loads the
agent via `r.office.GetAgentInstance(ctx, agentID)` and gates on `agent.LastRunFinishedAt`. That
field is `models.AgentInstance.LastRunFinishedAt`, which maps to `agent_profiles.last_run_finished_at`
— a column owned by the shared kanban agent-settings store
(`internal/agent/settings/store/sqlite.go`). No Office write path ever sets that field (confirmed:
`grep -rn '\.LastRunFinishedAt\s*=' apps/backend/internal` outside test files matches nothing), so
it round-trips as whatever the row already had — effectively always NULL for Office agents. The gate
condition `agent.LastRunFinishedAt != nil && agent.CooldownSec > 0` is therefore always false and the
cooldown branch never executes.
PR #2902 correctly and centrally stamps `office_agent_runtime.last_run_finished_at` (via
`Service.stampRunFinished` -> `Repository.UpdateRuntimeLastRunFinished`) on every completed/stopped
run. That is the column the spec (`docs/specs/office/agents.md` persistence guarantees, and now this
plan's spec amendment) documents as the cooldown guard's source of truth. `office.GetAgentRuntime(ctx,
agentID)` (`internal/office/repository/sqlite/runtime.go:20`) already reads it and returns
`*RuntimeState{LastRunFinishedAt *time.Time}`, `nil, nil` when the agent has no runtime row yet.
## Acceptance
- `heartbeatAgentRuntime.AllowFire` gates on `office_agent_runtime.last_run_finished_at` (via
`office.GetAgentRuntime`), not `agent_profiles.last_run_finished_at`.
- `agent.CooldownSec` (from `agent_profiles`, via `GetAgentInstance`) is still the cooldown duration
source — unchanged.
- No runtime row (`GetAgentRuntime` returns `nil, nil`) or `LastRunFinishedAt == nil` on the runtime
row still allows firing (an agent that has never run is not gated) — same behavior as today, just
reading the right column.
- `CooldownSec <= 0` still skips the runtime lookup entirely and always allows firing — preserve the
existing short-circuit / avoid an unconditional extra query.
- Update the doc comment above `heartbeatAgentRuntime` (lines ~149-155) to name the column
explicitly instead of the generic "LastRunFinishedAt" it currently says.
## Regression test
Add `apps/backend/internal/backendapp/cron_test.go` (package `backendapp`, same package as
`cron.go` — `heartbeatAgentRuntime` is unexported). Follow the harness pattern already used in
`adapters_office_test.go`'s `newOfficeTaskAdapterHarness` (`db.OpenSQLite` + `officesqlite.NewWithDB`)
to build a real `*officesqlite.Repository` — this is a repository-column bug, so exercise the actual
SQL, not a fake.
Test (must fail before the fix, pass after):
1. Create an `AgentInstance` with `CooldownSec: 60`, `Status: idle`.
2. Stamp `office_agent_runtime.last_run_finished_at` to `time.Now().UTC()` via
`repo.UpdateRuntimeLastRunFinished(ctx, agent.ID, now)`.
3. Separately write a stale/irrelevant value into `agent_profiles.last_run_finished_at` for the same
agent (e.g. `repo.UpdateAgentInstance` with `LastRunFinishedAt: &tenMinutesAgo`, or raw SQL) to
prove the gate does not read that column — pre-fix this would make the test pass for the wrong
reason if the assertion only checked "blocked", so assert specifically that firing is blocked
despite `agent_profiles.last_run_finished_at` being far outside any cooldown window.
4. Call `(&heartbeatAgentRuntime{office: repo}).AllowFire(ctx, agent.ID, now.Add(30*time.Second))`
(30s into a 60s cooldown) and assert `false, nil`.
5. Call `AllowFire` again with `now.Add(61*time.Second)` and assert `true, nil` (cooldown elapsed).
6. A second case with no `office_agent_runtime` row at all (skip step 2) asserts `true, nil` —
never-run agents are not gated.
## Verification
```bash
cd apps/backend && go test ./internal/backendapp/... -run TestHeartbeatAgentRuntime -v
cd apps/backend && go test ./internal/backendapp/...
cd apps/backend && golangci-lint run ./internal/backendapp/... --new-from-rev=HEAD~1 --timeout=5m
```
## Files likely touched
- `apps/backend/internal/backendapp/cron.go`
- `apps/backend/internal/backendapp/cron_test.go` (new)
## Dependencies
None.
## Parallelism
Sequential. Marked parallel-safe with Task 02 at the plan level (disjoint files/tests, no shared
schema) but this repo's convention keeps `parallelism: sequential` as the per-task default; delegate
only on explicit user authorization.
## Inputs
- Spec: `docs/specs/office/agents.md` persistence-guarantees bullet (amended by this plan).
- Existing pattern: `apps/backend/internal/office/repository/sqlite/runtime_test.go` for
`GetAgentRuntime`/`UpdateRuntimeLastRunFinished` behavior; `adapters_office_test.go` for the
`backendapp`-package office-repo test harness.
## Risks
- `GetAgentInstance` and `GetAgentRuntime` are two separate queries per positive-cooldown
`AllowFire` call (previously one). The heartbeat handler calls the gate for each candidate task,
so the extra runtime query is per candidate task that reaches this gate. This remains a small
load for the heartbeat pass; do not attempt to fold the queries into a JOIN as part of this fix.
- Do not touch `agent_profiles.last_run_finished_at` itself (no migration, no field removal) — out
of scope per the plan; it's dead for Office cooldown purposes but may still round-trip harmlessly
through the shared kanban settings store.
## Output contract
Report the exact `AllowFire` behavior before/after, files changed, exact commands and results,
blockers/risks, then mark this task `done` and update its checkbox in `plan.md`.
## Completion report
- **Before**: `AllowFire` gated on `agent.LastRunFinishedAt` (`agent_profiles.last_run_finished_at`
via `GetAgentInstance`), a column no Office write path ever stamps — the cooldown branch never
fired. Reproduced by `TestHeartbeatAgentRuntime_AllowFire_ReadsOfficeRuntimeCooldown`, which failed
pre-fix with `AllowFire (within cooldown) = true, want false`.
- **After**: `AllowFire` short-circuits to `true` when `CooldownSec <= 0` (unchanged), otherwise loads
`office_agent_runtime` via `office.GetAgentRuntime` and gates on `runtime.LastRunFinishedAt`. No
runtime row, or a nil `LastRunFinishedAt`, still allows firing (never-run agent not gated).
`agent_profiles.last_run_finished_at` is no longer read by the gate at all.
- Files changed: `apps/backend/internal/backendapp/cron.go` (production fix + doc comment),
`apps/backend/internal/backendapp/cron_test.go` (new — two regression tests).
- Commands and results:
- `go test ./internal/backendapp/... -run TestHeartbeatAgentRuntime -v` — fails before the fix
(`within cooldown` case wrongly allows), passes after (both tests green).
- `go test ./internal/backendapp/...` — `ok` (all packages).
- `golangci-lint run ./internal/backendapp/... --new-from-rev=HEAD --timeout=5m` — `0 issues`.
- Blockers/risks: none. Confirmed two extra one-time setup steps needed in the test harness beyond
the plan's sketch: the shared `agent_profiles`/`agents` schema is owned by
`internal/agent/settings/store` (not the office or task repos), and `agent_profiles.agent_id` has a
FK into `agents` that required seeding one row — both are test-only harness details, no production
code implication.
@@ -0,0 +1,141 @@
---
id: "02-stamp-on-failure"
title: "Stamp last_run_finished_at on agent failure"
status: done
wave: 1
depends_on: []
plan: "plan.md"
spec: "../../specs/office/runtime.md"
---
# Task 02: Stamp `last_run_finished_at` on agent failure
## Root cause / resolved decision
`HandleAgentFailure` (`apps/backend/internal/office/service/failure.go:29-66`) marks the run failed
(`MarkRunFailed`) and releases the task checkout (`releaseTaskCheckoutForRun`) but never calls
`stampRunFinished`. Flagged by Greptile on PR #2902
(https://github.com/kdlbs/kandev/pull/2902#discussion_r3832467867) and confirmed real by reading the
code. PR #2902 deliberately scoped its own fix to `AgentCompleted`/`AgentStopped` (and their taskless
variants) only.
Resolved via the spec amendment in this plan (`docs/specs/office/runtime.md` "Retry policy"):
cooldown paces every terminal run outcome uniformly, including failure. Rationale: `cooldown_sec`
is a run-pacing mechanism keyed on "time since this agent last ran," not a success tracker — the
column name (`last_run_finished_at`, not `last_success_finished_at`) and the pre-existing spec
language ("cooldown between agent runs") already point this way. Once Task 01 wires the gate
correctly, an unstamped failure path would leave a below-threshold failing agent completely exempt
from pacing (unlike success/stop), which is the opposite of the safe default: a flapping provider or
a misconfigured agent could re-fire immediately after every failure with zero pacing, burning
cost/tokens on repeated attempts before the separate consecutive-failure/auto-pause threshold (a
different, coarser mechanism — unaffected by this change) eventually kicks in.
Note `HandleAgentFailure` is only reached when `tryPostStartFallback` (the routing-dispatcher retry
path, gated on `run.ResolvedProviderID` via `markShortProviderCooldown`) returns `false` — i.e. only
for a genuinely terminal failure, not a provider-routing retry. Stamping here does not double up with
or interfere with that separate, already-cooldown-aware retry path.
## Acceptance
- `HandleAgentFailure` calls `s.stampRunFinished(ctx, run)`, placed after
`s.releaseTaskCheckoutForRun(ctx, run)` and before `IncrementAgentConsecutiveFailures`, mirroring
the completed/stopped paths' ordering (terminal-mark -> release checkout -> stamp).
- The shared `stampRunFinished` helper remains a no-op for `run == nil` or an empty
`run.AgentProfileID`. `HandleAgentFailure` itself still requires a non-nil run because it reads
`run.ID` before it calls the helper.
- No change to the consecutive-failure counter, auto-pause threshold, or auto-pause behavior — this
task only adds the cooldown stamp.
## Regression test
Extend the existing `TestSchedulerTick_AgentFailedReleasesTaskCheckout` in
`apps/backend/internal/office/service/scheduler_checkout_release_test.go` (does not currently assert
the runtime stamp — only checkout release) rather than duplicating its full setup in a new function.
Mirror the assertion already used by `TestSchedulerTick_AgentCompletedReleasesTaskCheckout` in the
same file:
1. Capture `beforePublish := time.Now().UTC()` immediately before publishing the
`events.AgentFailed` event, after setup and scheduler dispatch.
2. After the existing checkout-reacquisition assertion, add:
```go
runtime, err := svc.GetAgentRuntimeForTest(ctx, agent.ID)
if err != nil {
t.Fatalf("get agent runtime: %v", err)
}
if runtime == nil || runtime.LastRunFinishedAt == nil {
t.Fatal("expected last_run_finished_at to be stamped after AgentFailed, but it is still unset")
}
if runtime.LastRunFinishedAt.Before(beforePublish) {
t.Errorf("last_run_finished_at = %v, want at/after %v", runtime.LastRunFinishedAt, beforePublish)
}
```
3. Update the function's doc comment (currently states it is "the failure-path counterpart" only for
checkout release) to also note it now covers the cooldown-stamp parity.
This assertion must fail before the code change (no stamp call exists yet -> `runtime` is nil or
`LastRunFinishedAt` is nil) and pass after.
## Verification
```bash
cd apps/backend && go test ./internal/office/service/... -run TestSchedulerTick_AgentFailed -v
cd apps/backend && go test ./internal/office/service/...
cd apps/backend && golangci-lint run ./internal/office/service/... --new-from-rev=HEAD --timeout=5m
```
## Files likely touched
- `apps/backend/internal/office/service/failure.go`
- `apps/backend/internal/office/service/scheduler_checkout_release_test.go`
## Dependencies
None.
## Parallelism
Sequential. Marked parallel-safe with Task 01 at the plan level (disjoint files/tests, no shared
schema) but this repo's convention keeps `parallelism: sequential` as the per-task default; delegate
only on explicit user authorization.
## Inputs
- Spec: `docs/specs/office/runtime.md` "Retry policy" section and the new persistence-guarantee
bullet / scenario (amended by this plan).
- Existing pattern: `TestSchedulerTick_AgentCompletedReleasesTaskCheckout` and
`TestSchedulerTick_TasklessAgentCompletedStampsRuntime` in the same test file — both already
assert the identical `GetAgentRuntimeForTest` / `LastRunFinishedAt` shape for the success paths.
## Risks
- None expected — `stampRunFinished` is already shared, already covered by its own nil/empty-ID
guard, and already exercised by three other call sites. This is additive; no existing behavior
changes.
## Output contract
Report the exact before/after stamping behavior, files changed, exact commands and results,
blockers/risks, then mark this task `done` and update its checkbox in `plan.md`.
## Completion report
- **Before**: `HandleAgentFailure` marked the run failed and released the task checkout but never
called `stampRunFinished` — `office_agent_runtime.last_run_finished_at` stayed unset after a
failure, exempting a below-threshold failing agent from cooldown pacing entirely. Reproduced by
extending `TestSchedulerTick_AgentFailedReleasesTaskCheckout`, which failed pre-fix with
`expected last_run_finished_at to be stamped after AgentFailed, but it is still unset`.
- **After**: `HandleAgentFailure` calls `s.stampRunFinished(ctx, run)` immediately after
`s.releaseTaskCheckoutForRun(ctx, run)`, before the consecutive-failure counter logic — mirroring
the completed/stopped paths' ordering. No change to the counter, threshold, or auto-pause behavior.
- Files changed: `apps/backend/internal/office/service/failure.go` (one-line call + doc comment),
`apps/backend/internal/office/service/scheduler_checkout_release_test.go` (extended existing test
with `beforePublish` capture + runtime-stamp assertions, updated doc comment).
- Commands and results:
- `go test ./internal/office/service/... -run TestSchedulerTick_AgentFailed -v` — fails before the
fix (stamp assertion), passes after (all subtests green).
- `go test ./internal/office/service/...` — `ok`.
- `golangci-lint run ./internal/office/service/... --new-from-rev=HEAD --timeout=5m` — `0 issues`.
- Plan-level validation (`go test ./internal/backendapp/... ./internal/office/service/...
./internal/office/repository/sqlite/...`) — all `ok`.
- Blockers/risks: none. Behavior is additive and uses the already-shared, already-nil-safe
`stampRunFinished` helper exactly as planned.
+1 -1
View File
@@ -27,7 +27,7 @@ What survives a kandev backend restart:
- **Agent identity** persists in `agent_profiles` (Office rows: `workspace_id != '' AND deleted_at IS NULL`). Name, role, icon, `reports_to`, Office permissions, budget, concurrency/cooldown settings, skills, instructions, executor preference, and failure policy are durable on the stable identity. Startup profile reconciliation must not replace an Office agent's name with a generated model label.
- **Execution configuration** is referenced, not copied, for Office launches. The resolved `execution_profile_id` supplies the provider CLI, account environment, model, mode, ACP config options, CLI flags and permissions, passthrough behavior, and MCP configuration. Route attempts and sessions retain that ID for audit and restart recovery.
- **Runtime status** persists in `office_agent_runtime` (PK `agent_id`). On restart a `paused` agent stays `paused`, `pause_reason` (e.g. `"budget"`) is preserved, and `last_run_finished_at` is retained so the cooldown guard works across restarts.
- **Runtime status** persists in `office_agent_runtime` (PK `agent_id`). On restart a `paused` agent stays `paused`, `pause_reason` (e.g. `"budget"`) is preserved, and `last_run_finished_at` is retained so the cooldown guard works across restarts. The heartbeat cooldown gate (`heartbeatAgentRuntime.AllowFire` in `internal/backendapp/cron.go`) reads this `office_agent_runtime.last_run_finished_at` column together with `agent_profiles.cooldown_sec` to decide whether enough time has elapsed since the agent's last run. `agent_profiles` carries its own same-named `last_run_finished_at` column, inherited from the shared kanban agent-settings table — no Office write path stamps it, so it is not the cooldown source of truth and must not be read for gating. Every terminal run for an agent — completed, stopped, taskless-completed, or failed — stamps `office_agent_runtime.last_run_finished_at` via `Service.stampRunFinished`, so `cooldown_sec` paces the next heartbeat-driven fire uniformly regardless of outcome; see [Office Agent Runtime — Error Handling Contract](../requirements/runtime.md) for the failure-path detail.
- **Reconciliation at startup**: `infra.Reconciler.ReconcileAll` (called once during boot) drops `office_agent_runtime` rows whose `agent_id` no longer exists in `agent_profiles`, deletes `office_channels` and `office_budget_policies` rows that reference removed agents/projects, and seeds default routine triggers for routines without one. Reconciliation is best-effort: any sub-step that errors is logged but does not block boot.
- **Hire requests** persist as `pending_approval` agent rows plus an approval entry in the inbox. A restart mid-hire leaves the approval visible; the user can still approve or reject and the same activation/deletion paths run.
- **Instructions** (`AGENTS.md`, `HEARTBEAT.md`, `SOUL.md`, `TOOLS.md` and any custom files) live in the office DB (`office_agent_instructions`) as the source of truth. The exported copy under `~/.kandev/runtime/<workspace-slug>/instructions/<agentId>/` is regenerated from DB on every session preparation — losing or wiping this directory between runs has no observable effect.
@@ -68,6 +68,7 @@ A follow-up spec can introduce per-adapter classification once we have real usag
- No automatic retry. Every adapter error is terminal for the wakeup that produced it.
- The wakeup row is stamped with `status = failed` and `error_message`. No follow-up wakeup is queued from the failure path.
- Re-runs only happen via explicit user action: **Resume session** in chat, **Mark fixed** on an inbox entry, or task reassignment to a different agent.
- A terminal failure still stamps `office_agent_runtime.last_run_finished_at` — `HandleAgentFailure` calls the same `Service.stampRunFinished` helper the completed/stopped paths use. Cooldown is a run-pacing mechanism, not a success tracker: a below-threshold failing agent is paced by `cooldown_sec` on its next heartbeat-driven fire exactly as it would be after a success, so a flapping provider or a misconfigured agent cannot retry back-to-back with zero pacing and burn cost/tokens before hitting auto-pause. This applies uniformly across every task assigned to the agent, not just the one that just failed - `cooldown_sec` gates the agent's next heartbeat-triggered fire, regardless of which task last failed. It does not gate task assignment or manual resume: those go through the runs scheduler's `ClaimNextRun`/`ProcessRunGuard` path, which does not consult `last_run_finished_at`. The consecutive-failure counter and auto-pause threshold (below) are the separate, existing mechanism for stopping a chronically broken agent altogether; cooldown only paces the failures that happen before that threshold is reached.
### Inbox surfacing
@@ -288,6 +289,7 @@ Recovery and runtime-action authorization splits across three actors: human user
- **Capability snapshot on the run** (`runs.capabilities`, `runs.input_snapshot`): durable, written by `ContextBuilder.BuildAndPersist`. A re-issued JWT after restart uses the same capability set so the run keeps the permissions it was granted at claim time.
- **Agent JWT signing key**: process-local. Defaults to a random 32-byte key when the `KANDEV_AGENT_JWT_KEY` config is empty, in which case all in-flight JWTs are invalidated on restart and agents must mint fresh tokens on the next prompt cycle. Configurable for stable cross-restart JWTs.
- **`affected_tasks` snapshot on `agent_paused_after_failures`**: NOT recomputed when listed tasks are reassigned away. The snapshot is intentionally point-in-time so the user resolves the pause entry as a whole.
- **`office_agent_runtime.last_run_finished_at`**: durable. Stamped on every terminal run outcome for the agent, including failure - not just completion/stop - so the heartbeat cooldown gate paces the agent's next fire regardless of why the previous run ended. See [`office/agents.md`](../requirements/agents.md#persistence-guarantees) persistence guarantees for the gate itself.
- **`scheduled_retry` runs**: not produced in v1. Every adapter error is terminal; the wakeup is stamped `failed` with no follow-up scheduled. The `scheduled_retry` status is reserved for a future classifier.
See also: [Dynamic Agent Routing](../../agents/requirements/dynamic-agent-routing.md) for provider routing and [`office/scheduler.md`](../requirements/scheduler.md) for wakeup queue semantics and the staleness check that cancels superseded wakeups.
@@ -27,6 +27,7 @@ This design preserves the technical source detail for `REQ-OFFICE-RUNTIME-001` d
- **GIVEN** a `FAILED` session, **WHEN** the topbar / chat header re-renders, **THEN** the "Agent working for Xs" timer and spinner are not displayed because `isLiveSession` reads `FAILED` as non-live.
- **GIVEN** a failed run, **WHEN** the user opens the per-task chat, **THEN** a structured error entry appears at the failure timestamp with header "The agent stopped with an error.", a `Show details` collapsible revealing the raw adapter payload, and Resume session + Start fresh action buttons.
- **GIVEN** an agent whose `consecutive_failures` reaches its effective `failure_threshold`, **WHEN** the failing wakeup is recorded, **THEN** the agent is auto-paused (`pause_reason` set), the threshold-th failure does NOT create its own `agent_run_failed` entry, and any prior `agent_run_failed` entries for that agent are auto-dismissed and replaced with a single `agent_paused_after_failures` entry listing the affected tasks.
- **GIVEN** an agent below its failure threshold with `cooldown_sec > 0`, **WHEN** a run fails and `HandleAgentFailure` marks it terminal, **THEN** `office_agent_runtime.last_run_finished_at` is stamped the same as after a successful run, and the heartbeat gate blocks the agent's next fire (for any task) until `cooldown_sec` has elapsed.
- **GIVEN** an auto-paused agent, **WHEN** the scheduler tick attempts to claim one of its wakeups, **THEN** the wakeup is not claimed; behaviour is identical to a manually-paused agent.
- **GIVEN** an `agent_run_failed` inbox entry, **WHEN** the user clicks Mark fixed, **THEN** an `inbox_dismissals` row is inserted, the (task, agent) session is cleared from `FAILED` to `IDLE`, and a new wakeup is queued with reason `manual_resume_after_failure`.
- **GIVEN** an `agent_paused_after_failures` inbox entry, **WHEN** the user clicks Mark fixed, **THEN** the agent's `pause_reason` clears, `consecutive_failures` resets to zero, and a wakeup with reason `manual_resume_after_failure` is queued for every (task, agent) listed on the entry.