fix(orchestrator): warn when auto-start is skipped for unresolved dependencies (#3724)
Co-authored-by: Carlos Florencio <carlosmflorencio@gmail.com>
This commit is contained in:
Benjamin
@@ -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
|
||||
|
||||
@@ -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) {
|
||||
|
||||
@@ -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.
|
||||
@@ -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.
|
||||
@@ -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)
|
||||
|
||||
@@ -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.
|
||||
@@ -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: `<eventName>: 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)
|
||||
Reference in New Issue
Block a user