fix(operations): expired-plan replay + declared lane timeouts + measured pin TTL (issue #192)

.gds/bundle.lock.yaml

@@ -4,14 +4,14 @@ schema_version: 1
 bundle:
   version: "0.9.7-dev"
   release_sequence: 0
-  source_tree_digest: "sha256:4ef1a44ed62126887d79d92366bfa5717e667f6dc120653f404cf67af1951a66"
-  digest: "sha256:096d982e79fa540447861ac9a09399b5b6ccb8296ac1401a0dbea5327a313347"
+  source_tree_digest: "sha256:86106022a9d268cbf92facb4b37f483d3a9e54e4286c9a2d2e0f322dbf8031c5"
+  digest: "sha256:d455f8eb189678391db807db5355c001d4034f2361b7376f8773dbd5ab8ac7d5"
 
 projection:
-  input_digest: "sha256:e1265a9c8ae3e836cb424c1fe9643e8b7b5c179120acb90e1ceed1c68da981b3"
-  output_digest: "sha256:4df46e053c6facae0ff05ec6d3aa41bf825101652bccde246f5943e891675355"
+  input_digest: "sha256:e285c5b042cc7063f98a9a5f0d9ef4c01f04e95f7e322990733d2091a9a6dec5"
+  output_digest: "sha256:c44ea2fe00938863c53a093c1229740a3af1f34f9cffe25195c660de508c80f1"
   files:
     - path: ".gds/compiled-policy.json"
       digest: "sha256:9f498788bdc34e52a0ab793c536e0e6a7b360c2e1a20446cbf03ed51986cdc6f"
     - path: ".github/workflows/gds-ci.yml"
-      digest: "sha256:a6c62e15759f55b957731b4a1ba8ad1bd401f1d9717c71f02dd6932c96e4b25b"
+      digest: "sha256:c00a0da0ba94629cf9858de9e7094fb40f892285e8896ca70723cc4701660be2"

.github/workflows/gds-ci.yml

@@ -1,8 +1,8 @@
 # GENERATED FILE - DO NOT EDIT DIRECTLY
 # generator: gds
 # bundle: 0.9.7-dev
-# source-tree-digest: sha256:4ef1a44ed62126887d79d92366bfa5717e667f6dc120653f404cf67af1951a66
-# input-digest: sha256:e1265a9c8ae3e836cb424c1fe9643e8b7b5c179120acb90e1ceed1c68da981b3
+# source-tree-digest: sha256:86106022a9d268cbf92facb4b37f483d3a9e54e4286c9a2d2e0f322dbf8031c5
+# input-digest: sha256:e285c5b042cc7063f98a9a5f0d9ef4c01f04e95f7e322990733d2091a9a6dec5
 # output-digest: sha256:4ef1ee2fcc42927eaedef9c85f7b421f87e5cc75ff7055ef520216a00f7d4b74
 # edit-source:
 #   - .gds/repository.yaml

core/app/module_pin.go

@@ -6,6 +6,7 @@ import (
 	"errors"
 	"path/filepath"
 	"strings"
+	"time"
 
 	"github.com/NDDev-OpenNetwork/github-device-sync/core/canonicaljson"
 	"github.com/NDDev-OpenNetwork/github-device-sync/core/compiler"
@@ -49,6 +50,10 @@ type ModulePinPlanData struct {
 type modulePinContext struct {
 	assessment  ModulePinAssessment
 	observation operations.Observation
+	// verificationDuration is the measured cost of the module's declared lanes
+	// at the target commit. Apply re-runs the same lanes before mutating, so
+	// the plan's lifetime must account for what it costs to re-prove itself.
+	verificationDuration time.Duration
 }
 
 type modulePinObserver struct {
@@ -97,7 +102,16 @@ func (services *Services) PlanModuleUpdatePin(
 	if err != nil {
 		return domain.InternalError("gds module update-pin plan", err)
 	}
-	plan, err := operations.NewPlan(planID, now, now.Add(projectionPlanLifetime), operations.PlanInput{
+	// The plan must outlive what it costs to re-prove it. Apply runs the same
+	// module verification up to twice -- once before the first mutation and
+	// once per step -- so a wall-clock lifetime sized for a read-only plan
+	// expired mid-verification on real modules (GDS issue 192). Three times
+	// the measured lane cost covers both re-runs plus one retry.
+	lifetime := projectionPlanLifetime
+	if derived := 3*current.verificationDuration + projectionPlanLifetime; derived > lifetime {
+		lifetime = derived
+	}
+	plan, err := operations.NewPlan(planID, now, now.Add(lifetime), operations.PlanInput{
 		Operation: "update-module-pin",
 		Actor:     operations.Actor{Type: "agent-session", SessionID: options.SessionID},
 		Preconditions: []operations.Precondition{{
@@ -372,8 +386,10 @@ func (services *Services) modulePinContext(
 	if len(verificationFindings) != 0 {
 		return modulePinContext{}, verificationFindings
 	}
+	// Zero command timeout: no operator bound exists on this path, so a lane's
+	// declared `verification.timeouts` applies before the engine default.
 	verification, runFindings := services.runModuleLanes(
-		ctx, moduleRoot, verificationPlan, defaultModuleCommandTimeout,
+		ctx, moduleRoot, verificationPlan, 0,
 	)
 	if len(runFindings) != 0 {
 		return modulePinContext{}, runFindings
@@ -409,13 +425,20 @@ func (services *Services) modulePinContext(
 	if err != nil {
 		return modulePinContext{}, []domain.Finding{modulePinFinding("GDS_MODULE_PIN_FINGERPRINT_FAILED", err.Error())}
 	}
+	var verificationDuration time.Duration
+	for _, lane := range verification.Lanes {
+		for _, command := range lane.Commands {
+			verificationDuration += time.Duration(command.DurationMS) * time.Millisecond
+		}
+	}
 	return modulePinContext{
 		assessment: ModulePinAssessment{
 			ConsumerID: consumer.Repository.ID, ModuleID: moduleAnchor.Repository.ID,
 			ConsumerRoot: consumerInfo.WorktreeRoot, ModuleRoot: moduleRoot,
 			GitmodulesName: gitmodulesName, GitlinkPath: submodule.Path,
 			ExpectedOldOID: submodule.GitlinkOID, TargetOID: targetOID, TargetRef: targetRef, Artifact: artifact,
 		},
+		verificationDuration: verificationDuration,
 		observation: operations.Observation{
 			RepositoryID: consumer.Repository.ID, HeadOID: consumerStatus.Head.OID,
 			WorktreeFingerprint: fingerprint, ManifestDigest: consumerManifestDigest,

core/app/module_verify.go

@@ -100,10 +100,6 @@ func (services *Services) VerifyModules(
 		paths[submodule.Name] = submodule.Path
 	}
 
-	timeout := options.CommandTimeout
-	if timeout <= 0 {
-		timeout = defaultModuleCommandTimeout
-	}
 	selected := strings.TrimSpace(options.Module)
 	data := ModuleVerifyData{Modules: []ModuleVerification{}}
 	matched := false
@@ -149,7 +145,7 @@ func (services *Services) VerifyModules(
 		if len(plan.Lanes) == 0 {
 			continue
 		}
-		report, runFindings := services.runModuleLanes(ctx, modulePath, plan, timeout)
+		report, runFindings := services.runModuleLanes(ctx, modulePath, plan, options.CommandTimeout)
 		findings = append(findings, runFindings...)
 		data.Modules = append(data.Modules, report)
 	}
@@ -173,11 +169,15 @@ func (services *Services) VerifyModules(
 // module: it never touches their checkout, their branch or their index. It is
 // removed on every path out, including failure, because a stray registration in
 // somebody else's Git store is a worse outcome than an unverified lane.
+// commandTimeout is the operator-chosen bound (zero when unset). An explicit
+// bound wins over the module's declared per-lane `verification.timeouts`,
+// which in turn win over the engine default -- the declaration exists because
+// the module knows its own verification cost better than a global constant.
 func (services *Services) runModuleLanes(
 	ctx context.Context,
 	modulePath string,
 	plan moduleworkflow.VerificationPlan,
-	timeout time.Duration,
+	commandTimeout time.Duration,
 ) (report ModuleVerification, findings []domain.Finding) {
 	report = ModuleVerification{
 		GitmodulesName: plan.GitmodulesName, Path: plan.Path,
@@ -229,11 +229,19 @@ func (services *Services) runModuleLanes(
 	}
 	registered = true
 
+	fallback := commandTimeout
+	if fallback <= 0 {
+		fallback = defaultModuleCommandTimeout
+	}
 	for _, lane := range plan.Lanes {
 		laneReport := LaneReport{Lane: lane.Lane, Commands: []CommandReport{}}
 		failed := false
+		laneTimeout := fallback
+		if commandTimeout <= 0 && lane.TimeoutSeconds > 0 {
+			laneTimeout = time.Duration(lane.TimeoutSeconds) * time.Second
+		}
 		for _, declared := range lane.Commands {
-			result := runDeclaredCommand(ctx, checkout, declared, timeout)
+			result := runDeclaredCommand(ctx, checkout, declared, laneTimeout)
 			laneReport.Commands = append(laneReport.Commands, result)
 			if result.CleanupPending {
 				preserve = true

core/cli/root.go

@@ -2839,11 +2839,16 @@ func (executor *executor) doctorCommand() *cobra.Command {
 }
 
 // laneCommandTimeout is the default deadline for commands that execute another
-// repository's declared verification lanes rather than reading state. Two
-// minutes is right for a read and far too short for a command that runs a
-// module's test suite twice -- once to plan, once to re-observe before the
-// mutation -- which is how a working `module update-pin` came to look broken.
-const laneCommandTimeout = 20 * time.Minute
+// repository's declared verification lanes rather than reading state. An
+// update-pin apply runs the module's suite twice -- once to plan, once to
+// re-observe before the mutation -- so this bound must cover two full
+// verification passes plus the mutation itself. Twenty minutes expired
+// mid-verify on a real module and surfaced as GDS_STALE_PLAN, which read as a
+// changed repository rather than a deadline (issue 192). Two hours is not a
+// latency budget: each declared command is bounded individually by the
+// module's verification.timeouts or the per-command default, so this only
+// stops a runaway operation. An explicit --timeout always wins.
+const laneCommandTimeout = 2 * time.Hour
 
 func (executor *executor) run(
 	command *cobra.Command,

core/domain/repository.go

@@ -102,6 +102,27 @@ type VerificationPolicy struct {
 	// alternative, inferring a gate from the commands beside it, would produce a
 	// confident answer with nothing behind it.
 	RequiredContexts []string `json:"required_contexts,omitempty" yaml:"required_contexts,omitempty"`
+	// Timeouts bounds how long one declared command in a lane may run before
+	// it is reported as timed out rather than failed, in seconds per lane.
+	// A module knows its own verification cost; without a way to declare it,
+	// a suite that legitimately exceeds the engine default can only flake --
+	// which is exactly what a pinned module's gitlink apply hit when its test
+	// lane re-ran under load. Zero or absent means the engine default.
+	Timeouts VerificationTimeouts `json:"timeouts,omitempty" yaml:"timeouts,omitempty"`
+}
+
+type VerificationTimeouts struct {
+	Bootstrap     int64 `json:"bootstrap,omitempty" yaml:"bootstrap,omitempty"`
+	Lint          int64 `json:"lint,omitempty" yaml:"lint,omitempty"`
+	Typecheck     int64 `json:"typecheck,omitempty" yaml:"typecheck,omitempty"`
+	Test          int64 `json:"test,omitempty" yaml:"test,omitempty"`
+	Build         int64 `json:"build,omitempty" yaml:"build,omitempty"`
+	Compatibility int64 `json:"compatibility,omitempty" yaml:"compatibility,omitempty"`
+	Package       int64 `json:"package,omitempty" yaml:"package,omitempty"`
+	Fast          int64 `json:"fast,omitempty" yaml:"fast,omitempty"`
+	PRRequired    int64 `json:"pr-required,omitempty" yaml:"pr-required,omitempty"`
+	Full          int64 `json:"full,omitempty" yaml:"full,omitempty"`
+	Release       int64 `json:"release,omitempty" yaml:"release,omitempty"`
 }
 
 type VerificationCommands struct {

core/module/verify.go

@@ -26,6 +26,9 @@ type LaneSelection struct {
 	// lanes need rather than proving anything itself. Its failure is a different
 	// statement: the check could not be attempted, not that the module failed it.
 	Prerequisite bool `json:"prerequisite,omitempty"`
+	// TimeoutSeconds bounds one command in this lane, as the module declared it.
+	// Zero selects the executor's default.
+	TimeoutSeconds int64 `json:"timeout_seconds,omitempty"`
 }
 
 // VerificationPlan is what a single module owes, read from its own anchor.
@@ -56,6 +59,25 @@ func lanesByName(commands domain.VerificationCommands) map[string][]string {
 	}
 }
 
+// timeoutsByName mirrors lanesByName: `verification.timeouts` uses the same
+// lane vocabulary as `verification.commands`, so both mappings live side by
+// side and cannot drift apart unnoticed.
+func timeoutsByName(timeouts domain.VerificationTimeouts) map[string]int64 {
+	return map[string]int64{
+		"bootstrap":     timeouts.Bootstrap,
+		"lint":          timeouts.Lint,
+		"typecheck":     timeouts.Typecheck,
+		"test":          timeouts.Test,
+		"build":         timeouts.Build,
+		"compatibility": timeouts.Compatibility,
+		"package":       timeouts.Package,
+		"fast":          timeouts.Fast,
+		"pr-required":   timeouts.PRRequired,
+		"full":          timeouts.Full,
+		"release":       timeouts.Release,
+	}
+}
+
 // PlanVerification reads what a module declares it owes.
 //
 // A lane named by `verification.required` that carries no commands is reported
@@ -74,6 +96,7 @@ func PlanVerification(
 	}
 	findings := []domain.Finding{}
 	available := lanesByName(anchor.Verification.Commands)
+	timeouts := timeoutsByName(anchor.Verification.Timeouts)
 
 	// `bootstrap` is the one lane `schemas/v1/repository.schema.json` keeps out
 	// of `verification.required`, and until now nothing selected it, so a module
@@ -87,6 +110,7 @@ func PlanVerification(
 	if bootstrap := available["bootstrap"]; len(bootstrap) != 0 {
 		plan.Lanes = append(plan.Lanes, LaneSelection{
 			Lane: "bootstrap", Commands: bootstrap, Prerequisite: true,
+			TimeoutSeconds: timeouts["bootstrap"],
 		})
 	}
 
@@ -138,7 +162,9 @@ func PlanVerification(
 			})
 			continue
 		}
-		plan.Lanes = append(plan.Lanes, LaneSelection{Lane: lane, Commands: commands})
+		plan.Lanes = append(plan.Lanes, LaneSelection{
+			Lane: lane, Commands: commands, TimeoutSeconds: timeouts[lane],
+		})
 	}
 	return plan, findings
 }

core/operations/engine.go

@@ -213,32 +213,10 @@ func (engine *Engine) apply(
 		return ApplyResult{}, err
 	}
 	now := engine.now()
-	if !plan.ExpiresAt.After(now) {
-		if transitionErr := engine.Store.TransitionPlan(ctx, planID, "planned", "stale"); transitionErr != nil {
-			return ApplyResult{}, newError(
-				"GDS_PLAN_EXPIRY_RECORD_FAILED", domain.ExitInternal,
-				"Expired plan could not be marked stale.", transitionErr,
-			)
-		}
-		return ApplyResult{PlanID: planID, Status: "stale"}, newError(
-			"GDS_PLAN_EXPIRED", domain.ExitStale,
-			"Plan expired before apply and no action handler was called.", nil,
-		)
-	}
-	if plan.RequiresApproval() {
-		if engine.RequireSignedApprovals && signed == nil {
-			return ApplyResult{PlanID: planID, Status: "planned"}, newError(
-				"GDS_SIGNED_APPROVAL_REQUIRED", domain.ExitApproval,
-				"This mutation requires a signed approval bound to the exact plan.", nil,
-			)
-		}
-		if signed == nil && validateApprovalReference(approvalReference) != nil {
-			return ApplyResult{PlanID: planID, Status: "planned"}, newError(
-				"GDS_APPROVAL_REQUIRED", domain.ExitApproval,
-				"This plan requires approval before apply.", nil,
-			)
-		}
-	}
+	// A presented signed approval is verified before any answer is derived
+	// from the journal: a request carrying an invalid signature must fail
+	// closed even when the plan already produced an operation, so the reply
+	// can never read as though that signature authorized something.
 	var signedDigest string
 	if signed != nil {
 		if engine.ApprovalVerifier == nil {
@@ -264,6 +242,58 @@ func (engine *Engine) apply(
 		if err != nil {
 			return ApplyResult{}, err
 		}
+	}
+	// A recorded operation replays before expiry or enablement are consulted:
+	// the mutation (or its refusal) already happened and re-reading the
+	// journal is idempotent. Without this ordering, an applied plan past its
+	// lifetime reports "expired" -- or an expiry-record failure -- instead of
+	// its actual result, and a signed plan can never replay at all because
+	// its one-shot enablement was consumed by the recorded operation.
+	if existing, loadErr := engine.Store.GetOperationByPlan(ctx, planID); loadErr == nil {
+		return engine.replayApply(ctx, existing)
+	} else if !errors.Is(loadErr, state.ErrNotFound) {
+		return ApplyResult{}, newError(
+			"GDS_OPERATION_LOOKUP_FAILED", domain.ExitInternal,
+			"Existing operation state could not be inspected.", loadErr,
+		)
+	}
+	if !plan.ExpiresAt.After(now) {
+		// No operation ever consumed this plan, so its terminal truth is
+		// stale. Write that as durable bookkeeping: it must survive a caller
+		// deadline that died during an earlier re-observation, like every
+		// other terminal journal in this engine, and it must tolerate having
+		// been written already -- an earlier expired apply may have recorded
+		// the same state. Either way the answer to this apply is identical.
+		if record.Status == "planned" || record.Status == "approved" {
+			if transitionErr := engine.Store.TransitionPlan(
+				context.WithoutCancel(ctx), planID, record.Status, "stale",
+			); transitionErr != nil {
+				return ApplyResult{}, newError(
+					"GDS_PLAN_EXPIRY_RECORD_FAILED", domain.ExitInternal,
+					"Expired plan could not be marked stale.", transitionErr,
+				)
+			}
+		}
+		return ApplyResult{PlanID: planID, Status: "stale"}, newError(
+			"GDS_PLAN_EXPIRED", domain.ExitStale,
+			"Plan expired before apply and no action handler was called.", nil,
+		)
+	}
+	if plan.RequiresApproval() {
+		if engine.RequireSignedApprovals && signed == nil {
+			return ApplyResult{PlanID: planID, Status: "planned"}, newError(
+				"GDS_SIGNED_APPROVAL_REQUIRED", domain.ExitApproval,
+				"This mutation requires a signed approval bound to the exact plan.", nil,
+			)
+		}
+		if signed == nil && validateApprovalReference(approvalReference) != nil {
+			return ApplyResult{PlanID: planID, Status: "planned"}, newError(
+				"GDS_APPROVAL_REQUIRED", domain.ExitApproval,
+				"This plan requires approval before apply.", nil,
+			)
+		}
+	}
+	if signed != nil {
 		enablement, enableErr := engine.Store.GetPlanEnablement(ctx, "enablement:"+signed.ApprovalID)
 		enablementProblem := ""
 		switch {
@@ -292,14 +322,6 @@ func (engine *Engine) apply(
 			)
 		}
 	}
-	if existing, loadErr := engine.Store.GetOperationByPlan(ctx, planID); loadErr == nil {
-		return engine.replayApply(ctx, existing)
-	} else if !errors.Is(loadErr, state.ErrNotFound) {
-		return ApplyResult{}, newError(
-			"GDS_OPERATION_LOOKUP_FAILED", domain.ExitInternal,
-			"Existing operation state could not be inspected.", loadErr,
-		)
-	}
 	if record.Status != "planned" {
 		return ApplyResult{}, newError(
 			"GDS_PLAN_STATE_CONFLICT", domain.ExitConflict,