diff --git a/apps/backend/internal/orchestrator/event_handlers_dependencies.go b/apps/backend/internal/orchestrator/event_handlers_dependencies.go index 3199fb1924..05c2edfcee 100644 --- a/apps/backend/internal/orchestrator/event_handlers_dependencies.go +++ b/apps/backend/internal/orchestrator/event_handlers_dependencies.go @@ -54,7 +54,7 @@ func (s *Service) dependencyBlocksAutoStart(ctx context.Context, taskID, eventNa return true, true } if isBlocked { - s.logger.Debug(eventName+": task has unresolved dependencies; skipping auto-start", + s.logger.Warn(eventName+": task has unresolved dependencies; skipping auto-start", zap.String("task_id", taskID), zap.String("blocked_reason", reason)) } return isBlocked, false diff --git a/apps/backend/internal/orchestrator/event_handlers_dependencies_test.go b/apps/backend/internal/orchestrator/event_handlers_dependencies_test.go index 4dc3091ef1..627efbe9f1 100644 --- a/apps/backend/internal/orchestrator/event_handlers_dependencies_test.go +++ b/apps/backend/internal/orchestrator/event_handlers_dependencies_test.go @@ -1,8 +1,11 @@ package orchestrator import ( + "context" "testing" + "go.uber.org/zap/zapcore" + "github.com/kandev/kandev/internal/task/models" taskservice "github.com/kandev/kandev/internal/task/service" ) @@ -44,6 +47,45 @@ func TestResolutionLaunchesOnlyTasksWithARecordedIntent(t *testing.T) { } } +// TestDependencyBlocksAutoStartWarnsOnBlockedSkip is the regression test for +// issue #3720: the blocked verdict was logged at Debug, invisible at the +// default INFO level, so operators saw tasks sit on an auto-start step with +// no launch and no log. A deliberate skip of an auto-start is +// operator-visible by definition and must warn, matching the lookup-error +// path right above it. +// +// Expected pre-fix failure: the only matching entry is at Debug, so the +// WarnLevel filter finds none. +func TestDependencyBlocksAutoStartWarnsOnBlockedSkip(t *testing.T) { + ctx := context.Background() + repo := setupTestRepo(t) + svc := createTestService(repo, newMockStepGetter(), newMockTaskRepo()) + log, logs := observedTestLogger(t) + svc.logger = log + svc.SetTaskDependencyReader(&launchDependencyReader{blocked: true}) + + const taskID = "task-blocked-skip" + const eventName = "task.workflow_step_entered" + blocked, gateErrored := svc.dependencyBlocksAutoStart(ctx, taskID, eventName) + if !blocked || gateErrored { + t.Fatalf("blocked = %v, gateErrored = %v; want true, false", blocked, gateErrored) + } + + entries := logs. + FilterMessage(eventName + ": task has unresolved dependencies; skipping auto-start"). + FilterLevelExact(zapcore.WarnLevel).All() + if len(entries) != 1 { + t.Fatalf("blocked-skip WARN logs = %#v, want exactly one", entries) + } + fields := entries[0].ContextMap() + if got := fields["task_id"]; got != taskID { + t.Fatalf("task_id = %v, want %q", got, taskID) + } + if got := fields["blocked_reason"]; got != "pending" { + t.Fatalf("blocked_reason = %v, want \"pending\"", got) + } +} + // The failure reason compared in the resolution path must be the exported // constant, not a local copy that can drift out of sync silently. func TestFailedReasonUsesTheExportedConstant(t *testing.T) { diff --git a/docs/plans/dependency-gate-skip-visibility/plan.md b/docs/plans/dependency-gate-skip-visibility/plan.md new file mode 100644 index 0000000000..81a61bb0be --- /dev/null +++ b/docs/plans/dependency-gate-skip-visibility/plan.md @@ -0,0 +1,100 @@ +--- +created: 2026-09-16 +status: implemented +requirements: + - REQ-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001 +system_design: + - ../../specs/tasks/system-design/dependency-gate-skip-visibility.md +legacy_specs: [] +--- + +# Implementation Plan: Dependency Gate Skip Visibility + +## Overview + +The dependency gate correctly skips automated launches for tasks with +unresolved dependencies, but the blocked verdict was logged at Debug, which is +invisible at the default INFO level. Operators saw tasks sit on an auto-start +step (`on_enter: auto_start_agent`) with no launch, no error, and no log line, +which is indistinguishable from a broken launcher. One work order raises the +blocked-skip log to WARN and proves it with a regression test. + +## Evidence and root cause + +Issue #3720 records a recovery session where nine kanban tasks sat on an +auto-start step with zero sessions and zero error output. Every task had +pending `task_blockers` edges and the gate was correctly skipping the launch, +silently. The lookup-error path in `dependencyBlocksAutoStart` already logs at +WARN; only the genuine blocked verdict used Debug. Root cause is at +`apps/backend/internal/orchestrator/event_handlers_dependencies.go`: the +`isBlocked` branch's `s.logger.Debug` call. + +## Scope + +### In scope + +- One log-level change on the blocked verdict: Debug to WARN. +- Keeping the existing `task_id` and `blocked_reason` fields and the + event-prefixed message unchanged. +- A regression test asserting the WARN entry for a genuine block. + +### Out of scope + +- Gate semantics, fail-closed reads, and launch-token handling. +- Board or dashboard indicators for dependency-blocked tasks. +- Log-level changes on any other path. + +## Technical approach + +Change `s.logger.Debug` to `s.logger.Warn` in the `isBlocked` branch of +`dependencyBlocksAutoStart`. The log contract is specified by +[Dependency Gate Skip Visibility](../../specs/tasks/system-design/dependency-gate-skip-visibility.md): +the message keeps the caller's event-name prefix, and the structured fields +keep `task_id` and `blocked_reason`. No behavior change accompanies the level. + +## Tests + +- `TestDependencyBlocksAutoStartWarnsOnBlockedSkip` in + `apps/backend/internal/orchestrator/event_handlers_dependencies_test.go` + filters the observed zap log for the blocked-skip message at exactly + `WarnLevel` and asserts one entry whose `task_id` and `blocked_reason` fields + match the blocked reader (REQ-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.1). +- The unblocked and lookup-error paths are not asserted in this file. + +## Work orders + +- [x] [Task 01: Warn on blocked auto-start skip](task-01-warn-on-blocked-skip.md) + +## Verification + +Run from the repository root. + +```bash +(cd apps/backend && go test ./internal/orchestrator -run 'TestDependency|TestResolution' -count=1) +(cd apps/backend && gofmt -l internal/orchestrator) +(cd apps/backend && go vet ./internal/orchestrator) +python3 scripts/list-docs.py validate +python3 scripts/lint-spec-files.py --all +git diff --check +``` + +## Verification results + +Implementation and verification completed. The blocked verdict now logs at +WARN with the event-prefixed message, `task_id`, and `blocked_reason`; the +lookup-error path and its WARN entry are unchanged. + +- Focused gate tests: passed. +- Full `internal/orchestrator` package tests: passed. +- `gofmt` and `go vet` on the package: clean. +- Specification catalog validation and specification lint: passed. + +## Risks + +- A blocked task that sits on an auto-start step for a long time logs one WARN + per gate evaluation. Evaluations happen on discrete events, not a poll, so + the volume is bounded by board activity. + +## Documentation impact + +Backend log level only. Public documentation is unchanged. diff --git a/docs/plans/dependency-gate-skip-visibility/task-01-warn-on-blocked-skip.md b/docs/plans/dependency-gate-skip-visibility/task-01-warn-on-blocked-skip.md new file mode 100644 index 0000000000..9879ff2c95 --- /dev/null +++ b/docs/plans/dependency-gate-skip-visibility/task-01-warn-on-blocked-skip.md @@ -0,0 +1,105 @@ +--- +id: "01-warn-on-blocked-skip" +title: "Warn on blocked auto-start skip" +status: done +wave: 1 +depends_on: [] +plan: "plan.md" +requirements: + - REQ-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001 +acceptance_criteria: + - AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.1 + - AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.2 +system_design: + - ../../specs/tasks/system-design/dependency-gate-skip-visibility.md +--- + +# Task 01: Warn on Blocked Auto-Start Skip + +## Summary + +The dependency gate's genuine blocked verdict is logged at WARN instead of +Debug, so an operator running at the default INFO level sees why an automated +launch did not happen. + +## In scope + +- The one-word level change on the `isBlocked` branch of + `dependencyBlocksAutoStart`. +- The regression test asserting the WARN entry and its structured fields. + +## Out of scope + +- Gate semantics, fail-closed reads, launch-token handling, and any UI change. +- The lookup-error path, which already logs at WARN. + +## Acceptance + +- A blocked task evaluated by any automated launch path emits one WARN entry + whose message names the triggering event and whose fields carry `task_id` + and `blocked_reason`. +- A task that passes the gate emits no blocked-skip WARN entry. + +## Implementation sequence + +1. Add `TestDependencyBlocksAutoStartWarnsOnBlockedSkip` against the observed + logger and confirm it fails against the Debug logging. +2. Change `s.logger.Debug` to `s.logger.Warn` in the `isBlocked` branch and + confirm the test passes. +3. Run the package suite and the documentation validators. + +## Verification + +Run from the repository root. + +```bash +(cd apps/backend && go test ./internal/orchestrator -run 'TestDependency|TestResolution' -count=1) +(cd apps/backend && gofmt -l internal/orchestrator) +(cd apps/backend && go vet ./internal/orchestrator) +python3 scripts/list-docs.py validate +python3 scripts/lint-spec-files.py --all +git diff --check +``` + +## Files likely touched + +- `apps/backend/internal/orchestrator/event_handlers_dependencies.go` +- `apps/backend/internal/orchestrator/event_handlers_dependencies_test.go` + +## Dependencies + +None. + +## Risks + +None beyond the bounded per-evaluation log volume noted in the plan. + +## Parallelism + +`sequential` + +## Inputs + +- Requirement acceptance criteria in + `docs/specs/tasks/requirements/dependency-gate-skip-visibility.md`. +- Log contract in + `docs/specs/tasks/system-design/dependency-gate-skip-visibility.md`. +- Gate call sites in `event_handlers_workflow.go` and `session_launch.go`. + +## Results + +Implemented the level change and the regression test. The observed-logger test +filters for the blocked-skip message at exactly `WarnLevel`, asserts a single +entry, and checks the `task_id` and `blocked_reason` fields; it was verified +red against the pre-fix Debug logging before the fix. This test covers the +blocked path. The unblocked and lookup-error paths are not asserted in this +file. + +- `go test ./internal/orchestrator -run 'TestDependency|TestResolution' -count=1`: + passed. +- `go test ./internal/orchestrator -count=1`: passed. +- `gofmt -l internal/orchestrator`: empty. +- `go vet ./internal/orchestrator`: clean. +- `python3 scripts/list-docs.py validate`: passed. +- `python3 scripts/lint-spec-files.py --all`: passed. +- `git diff --check`: passed. diff --git a/docs/specs/tasks/README.md b/docs/specs/tasks/README.md index b7bb439b74..339c80a0e2 100644 --- a/docs/specs/tasks/README.md +++ b/docs/specs/tasks/README.md @@ -112,6 +112,7 @@ signals, and task-scoped scheduling contracts. - [Task-create dependency selector refinement](requirements/task-dependencies-create-dialog-dependency-selector.md) - [Edit task dependencies](requirements/task-dependency-detail-editing.md) - [Task Dependencies and Auto-Start Chains](requirements/task-dependencies.md) +- [Dependency Gate Skip Visibility](requirements/dependency-gate-skip-visibility.md) - [Session Launch Repository Resolution](requirements/launch-repository-resolution.md) - [Task Launch Failure Recovery](requirements/task-launch-failure-recovery.md) - [Worktree metadata recovery](requirements/worktree-metadata-recovery.md) @@ -190,6 +191,7 @@ signals, and task-scoped scheduling contracts. - [Resume prompt queue](system-design/resume-prompt-queue.md) - [Session Delete Preserves Task Workspaces](system-design/session-delete-resource-cleanup.md) - [Task Dependencies and Auto-Start Chains](system-design/task-dependencies.md) +- [Dependency Gate Skip Visibility](system-design/dependency-gate-skip-visibility.md) - [Edit task dependencies](system-design/task-dependency-detail-editing.md) - [Session Launch Repository Resolution](system-design/launch-repository-resolution.md) - [Task Launch Failure Recovery](system-design/task-launch-failure-recovery.md) diff --git a/docs/specs/tasks/requirements/dependency-gate-skip-visibility.md b/docs/specs/tasks/requirements/dependency-gate-skip-visibility.md new file mode 100644 index 0000000000..557f5d24c4 --- /dev/null +++ b/docs/specs/tasks/requirements/dependency-gate-skip-visibility.md @@ -0,0 +1,57 @@ +--- +status: active +system: tasks +created: 2026-09-16 +owners: + - kandev +--- +# Dependency Gate Skip Visibility Requirements + +## Overview + +A task that reaches an automated launch path while it still has unresolved +dependencies is deliberately not started. That deliberate skip must be visible +in backend logs at the default level, so an operator can tell a working +dependency gate from a broken launcher without session surgery or a restart. + +## Requirements + +### REQ-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001: Dependency gate skip visibility + +**Intent:** Every automated-launch skip caused by unresolved task dependencies +is observable by operators at the default backend log level. + +#### Acceptance criteria + +- **AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.1:** When an automated launch + path skips a launch because the task has unresolved dependencies, the backend + shall log a WARN-level entry whose message identifies the triggering event + and whose structured fields carry `task_id` and the dependency + `blocked_reason`. +- **AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.2:** A task that passes the + dependency gate shall produce no blocked-skip WARN entry, so the WARN level + stays reserved for genuine dependency skips instead of noise on every + automated launch. + +## Scenarios + +- **GIVEN** a task whose dependency gate reports blocked, **WHEN** the task + enters a workflow step with `on_enter: auto_start_agent`, **THEN** the + backend emits one WARN entry naming the step-enter event, carrying the task + and the blocked reason, and starts no session. +- **GIVEN** a task whose dependency gate reports blocked, **WHEN** WIP queue + promotion or an automated session launch reaches the gate, **THEN** the same + blocked-skip WARN entry is emitted for that event. +- **GIVEN** a task with no unresolved dependencies, **WHEN** any automated + launch path runs, **THEN** no blocked-skip WARN entry is emitted. +- **GIVEN** a dependency read that fails, **WHEN** the gate fails closed, + **THEN** the existing lookup-failure WARN entry (with the read error) is + emitted instead of the blocked-skip entry. + +## Out of scope + +- Gate semantics: the blocked verdict, the fail-closed read behavior, and + launch-token handling remain owned by + [Task Dependencies and Auto-Start Chains](task-dependencies.md). +- Board or dashboard indicators for dependency-blocked tasks. +- Log-level changes on paths other than the dependency gate. diff --git a/docs/specs/tasks/system-design/dependency-gate-skip-visibility.md b/docs/specs/tasks/system-design/dependency-gate-skip-visibility.md new file mode 100644 index 0000000000..0129777a2f --- /dev/null +++ b/docs/specs/tasks/system-design/dependency-gate-skip-visibility.md @@ -0,0 +1,72 @@ +--- +status: current +system: tasks +requirements: + - REQ-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001 +created: 2026-09-16 +owners: + - kandev +--- +# Dependency Gate Skip Visibility System Design + +## Purpose and boundaries + +This design owns the backend log contract for automated launches that the +dependency gate deliberately skips. A skipped auto-start is exceptional and +operator-visible by definition: a task moved onto an auto-start step and did +not launch. The skip is therefore logged at WARN, matching the gate's adjacent +lookup-failure path. + +Gate semantics, the fail-closed read behavior, and launch-token handling are +owned by [Task Dependencies and Auto-Start Chains](task-dependencies.md). This +design changes only the observability of the genuine blocked verdict; it adds +no endpoint, feature flag, database column, or user-facing copy. + +## Requirement mapping + +| Criterion | Design section | +| --- | --- | +| AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.1 | Blocked-skip log contract | +| AC-TASKS-DEPENDENCY-GATE-SKIP-VISIBILITY-001.2 | Non-blocking paths | + +## Blocked-skip log contract + +`dependencyBlocksAutoStart` in `internal/orchestrator` is the single gate +consulted by every automated launch path: step entry +(`task.workflow_step_entered`), WIP queue promotion (`task.queue_promoted`), +and automated session launch (`session.launch`). The caller's event name is +passed in and prefixes the log message, so one log site identifies which path +skipped the launch. + +When the gate's read succeeds and reports blocked, the service logs one WARN +entry through its structured zap logger: + +- Message: `: task has unresolved dependencies; skipping auto-start`. +- Fields: `task_id` (string) and `blocked_reason` (string, the gate's reason + such as `pending` or the failed-predecessor reason). + +A read error keeps the existing separate WARN entry (`dependency lookup +failed; skipping auto-start`, with the error field) and the fail-closed +return; it is not conflated with the genuine-block entry because the blocked +reason differs from a read error. No launch, error surface, or task-state +change accompanies the blocked-skip entry: the task simply stays where it is +until its dependencies resolve. + +## Non-blocking paths + +A task that passes the gate logs nothing at this site. The WARN level is +reserved for the exceptional skip so ordinary launches do not train operators +to ignore warnings. Debug-level detail for unrelated gate decisions stays at +Debug. + +## Verification + +`TestDependencyBlocksAutoStartWarnsOnBlockedSkip` in +`event_handlers_dependencies_test.go` drives the gate with a blocked reader, +asserts exactly one WARN entry with the event-prefixed message, and checks the +`task_id` and `blocked_reason` fields. This test covers the blocked path. +The unblocked and lookup-error paths are not asserted in this file. + +## Implementation Plans + +- [Dependency gate skip visibility](../../../plans/dependency-gate-skip-visibility/plan.md)