From ea5c105ff2d64612915ee86cb3b6df3495890ad2 Mon Sep 17 00:00:00 2001 From: rcourtman Date: Sun, 23 Aug 2026 06:33:30 +0100 Subject: [PATCH] Log refused actions and name the missed command-agent lookup A refused action plan, decision, or execution returned its 409 to the client and left no trace in the server journal, so every remote report of "Docker / Podman command agent is not connected" stalled on greps that could never match anything. Refusals now log one warn line with the resource, capability, and reason code, and the Docker command-agent resolver reports which lookup missed (stale enrollment token binding vs agent-id/hostname session), carried as an optional diagnostic detail on the readiness contract and in the refusal envelope. Refs #1728 --- .../v6/internal/subsystems/agent-lifecycle.md | 7 +- .../v6/internal/subsystems/api-contracts.md | 14 ++- .../internal/subsystems/storage-recovery.md | 5 ++ .../internal/subsystems/unified-resources.md | 7 +- internal/api/actions.go | 48 ++++++---- internal/api/contract_test.go | 14 +++ .../api/docker_container_action_executor.go | 16 ++-- .../docker_container_action_executor_test.go | 87 +++++++++++++++++++ internal/unifiedresources/capabilities.go | 4 + internal/unifiedresources/clone_test.go | 19 ++++ 10 files changed, 192 insertions(+), 29 deletions(-) diff --git a/docs/release-control/v6/internal/subsystems/agent-lifecycle.md b/docs/release-control/v6/internal/subsystems/agent-lifecycle.md index d91d48502..94ef5cc03 100644 --- a/docs/release-control/v6/internal/subsystems/agent-lifecycle.md +++ b/docs/release-control/v6/internal/subsystems/agent-lifecycle.md @@ -960,7 +960,12 @@ reconnect, substitute, or directly address an agent to make a stale container action executable. Backend resource payloads and plan-action readiness are the only supported lifecycle signal for that state. When a resource payload carries typed `actionReadiness`, lifecycle surfaces may display the reason but must not -treat it as reconnect authority or an alternate command grant. +treat it as reconnect authority or an alternate command grant. The optional +`detail` such an entry may carry (naming the missed enrollment-token or +session lookup) and the server-side warn log every availability refusal now +writes are the same API-owned diagnosis surface: they add no agent-visible +transport, and no surface gains reconnect, rebind, or command authority from +reading them. Assistant session rename through `PATCH /api/ai/sessions/{id}` follows that same browser-safe history boundary. Lifecycle surfaces, MCP adapters, and agents may display the updated title as human navigation metadata, but they diff --git a/docs/release-control/v6/internal/subsystems/api-contracts.md b/docs/release-control/v6/internal/subsystems/api-contracts.md index 7c3f05b83..fd81d7b36 100644 --- a/docs/release-control/v6/internal/subsystems/api-contracts.md +++ b/docs/release-control/v6/internal/subsystems/api-contracts.md @@ -2463,7 +2463,11 @@ a new API state machine, queue contract, or verification-accounting field. Resource payloads may expose the same executor-owned unavailable state as `actionReadiness[]` entries with stable `name`, `available`, `reasonCode`, and `reason` fields so browser and agent clients can explain disabled - actions without treating unavailable capabilities as executable. + actions without treating unavailable capabilities as executable. A readiness + entry may add an optional bounded `detail` naming the concrete lookup the + refusal was judged against (for example the stale enrollment token id, or + the agent-id / hostname session lookups that missed); `reason` stays the + stable operator-safe copy and clients must not branch on `detail` text. Action approval decisions are API-owned as a separate non-execution contract: `POST /api/actions/{id}/decision` may only record an `approved` or `rejected` decision against a persisted `pending_approval` @@ -4273,7 +4277,13 @@ canonical resource and then asks the optional executor-owned `ExecuteUnderPolicy`, so an automatic broker cannot bypass it. A resource that disappears remains `action_plan_drift`; an explicitly unavailable capability returns HTTP `409` with shared code `action_execution_unavailable` and bounded -`resourceId`, `capabilityName`, `reasonCode`, and `reason` details. Pulse +`resourceId`, `capabilityName`, `reasonCode`, and `reason` details, plus an +optional `detail` when the executor supplies a lookup diagnostic. Every +availability refusal rendered through that shared envelope — plan, decision, +and execution alike — also writes one server-side warn log line naming the +resource, capability, reason code, and diagnostic, because a refusal that +reaches the client as a toast while the server journal stays empty is +undiagnosable from a remote bug report (#1728). Pulse persists a terminal failed/no-effect audit and lifecycle event and publishes the normal completion notification. Executors without either optional checker, and checkers returning an empty readiness result, preserve the existing diff --git a/docs/release-control/v6/internal/subsystems/storage-recovery.md b/docs/release-control/v6/internal/subsystems/storage-recovery.md index a9408dd19..4b9d2746d 100644 --- a/docs/release-control/v6/internal/subsystems/storage-recovery.md +++ b/docs/release-control/v6/internal/subsystems/storage-recovery.md @@ -384,6 +384,11 @@ no new persisted state: it is read from live Patrol runtime status at snapshot time, not from the run history list or the run tally, records no run identity, provider configuration, or blocked-reason text, and is likewise not recovery coverage or storage-health proof. + +Availability-refusal warn logs and the optional `actionReadiness` `detail` +emitted through the shared `internal/api/` action handlers are likewise +process-log observability only: they create no persisted state, no storage or +recovery signal, and no backup, restore, or storage-health proof. First-party workflow starter activity recorded through shared `internal/api/` handlers, including Pro activation entry-point telemetry for the same operations-loop prompt, is likewise API/privacy/commercial activation evidence diff --git a/docs/release-control/v6/internal/subsystems/unified-resources.md b/docs/release-control/v6/internal/subsystems/unified-resources.md index dff41f2c8..58bc8c774 100644 --- a/docs/release-control/v6/internal/subsystems/unified-resources.md +++ b/docs/release-control/v6/internal/subsystems/unified-resources.md @@ -907,7 +907,12 @@ cannot create a browser mutation. `available=false`, a stable reason code such as `command_agent_disconnected`, and operator-safe copy. Frontend consumers may use that field to explain disabled controls, while `capabilities` remains - the executable action set. + the executable action set. The same readiness entry may carry an optional + `detail` naming which command-session lookup the refusal was judged against + (the immutable enrollment token binding versus the agent-id / hostname + session lookups); it is diagnostic copy for server logs and support + threads, `reason` remains the stable user-facing text, and consumers must + not branch on `detail` content. Proxmox VM and LXC lifecycle actions are also part of that governed resource contract. `resourceFromVM` and `resourceFromContainer` may advertise `start` only for stopped guests and `shutdown`, `reboot`, and `stop` only diff --git a/internal/api/actions.go b/internal/api/actions.go index 335c4936b..01c49bcbf 100644 --- a/internal/api/actions.go +++ b/internal/api/actions.go @@ -16,6 +16,7 @@ import ( "github.com/rcourtman/pulse-go-rewrite/internal/api/resourceapi" "github.com/rcourtman/pulse-go-rewrite/internal/mock" unified "github.com/rcourtman/pulse-go-rewrite/internal/unifiedresources" + "github.com/rs/zerolog/log" ) const maxActionPlanRequestBytes = 1 << 20 @@ -337,6 +338,32 @@ func (h *ResourceHandlers) HandleGetAction(w http.ResponseWriter, r *http.Reques } } +// writeActionExecutionUnavailable renders an availability refusal into the +// stable 409 contract and logs it. Refusals previously produced only a client +// toast while the server journal stayed empty, so remote reports of "command +// agent is not connected" were undiagnosable without source access (#1728). +func writeActionExecutionUnavailable(w http.ResponseWriter, refusal *actionlifecycle.AvailabilityRefusedError) { + reason := firstNonEmpty(refusal.Readiness.Reason, "action execution is unavailable") + details := map[string]string{ + "resourceId": refusal.ResourceID, + "capabilityName": refusal.CapabilityName, + "reasonCode": refusal.Readiness.ReasonCode, + "reason": reason, + } + detail := strings.TrimSpace(refusal.Readiness.Detail) + if detail != "" { + details["detail"] = detail + } + log.Warn(). + Str("resource_id", refusal.ResourceID). + Str("capability", refusal.CapabilityName). + Str("reason_code", refusal.Readiness.ReasonCode). + Str("reason", reason). + Str("detail", detail). + Msg("Action refused: capability is not currently executable") + writeJSONErrorWithDetails(w, http.StatusConflict, agentcapabilities.AgentErrCodeActionExecutionUnavailable, "Action execution is unavailable", details) +} + func writeActionPlanError(w http.ResponseWriter, err error) { var validationErr *actionplanner.ValidationError var notFound *actionlifecycle.ResourceNotFoundError @@ -362,12 +389,7 @@ func writeActionPlanError(w http.ResponseWriter, err error) { "resourceId": notFound.ResourceID, }) case errors.As(err, &unavailable): - writeJSONErrorWithDetails(w, http.StatusConflict, agentcapabilities.AgentErrCodeActionExecutionUnavailable, "Action execution is unavailable", map[string]string{ - "resourceId": unavailable.ResourceID, - "capabilityName": unavailable.CapabilityName, - "reasonCode": unavailable.Readiness.ReasonCode, - "reason": firstNonEmpty(unavailable.Readiness.Reason, "action execution is unavailable"), - }) + writeActionExecutionUnavailable(w, unavailable) case errors.Is(err, actionlifecycle.ErrRegistryUnavailable): writeJSONError(w, http.StatusInternalServerError, "resource_registry_unavailable", sanitizeErrorForClient(err, "Resource registry unavailable")) case errors.Is(err, actionlifecycle.ErrStoreUnavailable): @@ -578,12 +600,7 @@ func writeActionReadinessError(w http.ResponseWriter, err error) bool { var availabilityCheck *actionlifecycle.AvailabilityCheckError switch { case errors.As(err, &availability): - writeJSONErrorWithDetails(w, http.StatusConflict, agentcapabilities.AgentErrCodeActionExecutionUnavailable, "Action execution is unavailable", map[string]string{ - "resourceId": availability.ResourceID, - "capabilityName": availability.CapabilityName, - "reasonCode": availability.Readiness.ReasonCode, - "reason": firstNonEmpty(availability.Readiness.Reason, "action execution is unavailable"), - }) + writeActionExecutionUnavailable(w, availability) case errors.Is(err, unified.ErrActionPlanDrift): writeJSONError(w, http.StatusConflict, agentcapabilities.AgentErrCodeActionPlanDrift, "Action plan no longer matches the current resource contract; refresh the plan before continuing") case errors.Is(err, unified.ErrActionEmergencyStop): @@ -876,12 +893,7 @@ func writeActionExecuteError(w http.ResponseWriter, err error) { case errors.Is(err, actionlifecycle.ErrExecutorUnavailable): writeJSONError(w, http.StatusNotImplemented, agentcapabilities.AgentErrCodeActionExecutorUnavailable, "No action executor is configured for this API instance") case errors.As(err, &availability): - writeJSONErrorWithDetails(w, http.StatusConflict, agentcapabilities.AgentErrCodeActionExecutionUnavailable, "Action execution is unavailable", map[string]string{ - "resourceId": availability.ResourceID, - "capabilityName": availability.CapabilityName, - "reasonCode": availability.Readiness.ReasonCode, - "reason": firstNonEmpty(availability.Readiness.Reason, "action execution is unavailable"), - }) + writeActionExecutionUnavailable(w, availability) case errors.As(err, &persist): writeActionExecutionPersistError(w, err) case errors.As(err, &freshness): diff --git a/internal/api/contract_test.go b/internal/api/contract_test.go index f667ef96c..8d1ca65d0 100644 --- a/internal/api/contract_test.go +++ b/internal/api/contract_test.go @@ -21246,6 +21246,7 @@ func TestContract_ResourceActionReadinessPayloadShape(t *testing.T) { Available: false, ReasonCode: "command_agent_disconnected", Reason: "Docker / Podman command agent is not connected.", + Detail: "no live command session for agent agent-1 or hostname docker-host", }, }, }) @@ -21259,6 +21260,7 @@ func TestContract_ResourceActionReadinessPayloadShape(t *testing.T) { `"available":false`, `"reasonCode":"command_agent_disconnected"`, `"reason":"Docker / Podman command agent is not connected."`, + `"detail":"no live command session for agent agent-1 or hostname docker-host"`, } { if !strings.Contains(body, want) { t.Fatalf("resource action readiness payload missing %s: %s", want, body) @@ -21267,6 +21269,18 @@ func TestContract_ResourceActionReadinessPayloadShape(t *testing.T) { if strings.Contains(body, "InternalHandler") { t.Fatalf("resource payload leaked internal action handler: %s", body) } + bare, err := json.Marshal(unifiedresources.ResourceActionReadiness{ + Name: "restart", + Available: false, + ReasonCode: "command_agent_disconnected", + Reason: "Docker / Podman command agent is not connected.", + }) + if err != nil { + t.Fatalf("marshal readiness: %v", err) + } + if strings.Contains(string(bare), "detail") { + t.Fatalf("empty diagnostic detail must be omitted from the readiness payload: %s", bare) + } } func TestContract_ActionPreflightRefusalProjectsStableReadiness(t *testing.T) { diff --git a/internal/api/docker_container_action_executor.go b/internal/api/docker_container_action_executor.go index d3eac14fb..93505ef2c 100644 --- a/internal/api/docker_container_action_executor.go +++ b/internal/api/docker_container_action_executor.go @@ -337,10 +337,12 @@ func (e dockerContainerActionExecutor) CheckActionAvailable(ctx context.Context, if _, err := e.executableDockerContainerResource(ctx, resource, operation); err != nil { return unavailableDockerActionReadiness(operation, dockerActionUnavailableReasonCode(err), dockerActionUnavailableReason(err)) } - if _, err := e.connectedDockerCommandAgentID(ctx, resource); err != nil { - return unavailableDockerActionReadiness(operation, "command_agent_disconnected", "Docker / Podman command agent is not connected.") + agentID, connectErr := e.connectedDockerCommandAgentID(ctx, resource) + if connectErr != nil { + readiness := unavailableDockerActionReadiness(operation, "command_agent_disconnected", "Docker / Podman command agent is not connected.") + readiness.Detail = connectErr.Error() + return readiness } - agentID, _ := e.connectedDockerCommandAgentID(ctx, resource) if liveAgentOperationReceiptVersion(ctx, e.agents, agentID) != operationreceipt.ProtocolVersion { return unavailableDockerActionReadiness(operation, "operation_receipt_unsupported", "The Pulse agent on this host cannot run reviewed actions: it is on an older version, or its durable state directory is unavailable. Update the agent, or check the agent logs if it is already current, then retry.") } @@ -425,7 +427,7 @@ func (e dockerContainerActionExecutor) executableDockerContainerResource(_ conte func (e dockerContainerActionExecutor) connectedDockerCommandAgentID(ctx context.Context, resource unified.Resource) (string, error) { if e.agents == nil { - return "", fmt.Errorf("docker container command agent is not connected") + return "", fmt.Errorf("docker container command agent is not connected: no agent command server is configured") } if resource.Docker == nil { return "", fmt.Errorf("docker resource metadata missing") @@ -435,8 +437,8 @@ func (e dockerContainerActionExecutor) connectedDockerCommandAgentID(ctx context } // When telemetry names a token, it is the immutable session binding. Do // not fall back to a different identity or hostname after rotation. - if strings.TrimSpace(resource.Docker.TokenID) != "" { - return "", fmt.Errorf("docker container command agent is not connected") + if tokenID := strings.TrimSpace(resource.Docker.TokenID); tokenID != "" { + return "", fmt.Errorf("docker container command agent is not connected: no live command session for enrollment token %s (agent %q, hostname %q); a token-named resource never falls back to identity or hostname lookup", tokenID, strings.TrimSpace(resource.Docker.AgentID), strings.TrimSpace(resource.Docker.Hostname)) } if agentID := strings.TrimSpace(resource.Docker.AgentID); agentID != "" && isAgentCommandConnected(ctx, e.agents, agentID) { return agentID, nil @@ -447,7 +449,7 @@ func (e dockerContainerActionExecutor) connectedDockerCommandAgentID(ctx context return agentID, nil } } - return "", fmt.Errorf("docker container command agent is not connected") + return "", fmt.Errorf("docker container command agent is not connected: no live command session for agent %q or hostname %q", strings.TrimSpace(resource.Docker.AgentID), strings.TrimSpace(resource.Docker.Hostname)) } func unavailableDockerActionReadiness(operation, reasonCode, reason string) unified.ResourceActionReadiness { diff --git a/internal/api/docker_container_action_executor_test.go b/internal/api/docker_container_action_executor_test.go index f493970d5..f63d31072 100644 --- a/internal/api/docker_container_action_executor_test.go +++ b/internal/api/docker_container_action_executor_test.go @@ -671,3 +671,90 @@ func TestDockerContainerActionExecutorRefusesUpdateThroughLifecycleHandler(t *te t.Fatalf("readiness = %+v, want fail-closed for wrong handler", readiness) } } + +func TestDockerContainerActionAvailabilityDetailNamesMissedLookup(t *testing.T) { + now := time.Now().UTC() + request := unified.ActionRequest{ + RequestID: "req-detail", + ResourceID: "app-container:api", + CapabilityName: "restart", + Reason: "operator requested restart", + RequestedBy: "operator", + } + + resource := dockerContainerActionResource("app-container:api", "docker", "running", now) + h := newActionTestResourceHandlers(t, &config.Config{DataPath: t.TempDir()}) + h.SetStateProvider(resourceUnifiedSeedProvider{ + snapshot: models.StateSnapshot{LastUpdate: now}, + resources: []unified.Resource{resource}, + }) + executor := newDockerContainerActionExecutor(h, &fakeDockerActionAgentCommander{ + connected: map[string]bool{"agent-1": false}, + }).(dockerContainerActionExecutor) + + readiness := executor.CheckActionAvailable(context.Background(), request, resource) + if readiness.Available || readiness.ReasonCode != "command_agent_disconnected" || + readiness.Reason != "Docker / Podman command agent is not connected." { + t.Fatalf("identity-fallback readiness = %#v, want disconnected agent", readiness) + } + if !strings.Contains(readiness.Detail, `agent "agent-1"`) { + t.Fatalf("identity-fallback detail = %q, want the missed agent identity named", readiness.Detail) + } + + tokenResource := dockerContainerActionResource("app-container:api", "docker", "running", now) + tokenResource.Docker.TokenID = "rotated-token" + tokenResource.Docker.Hostname = "docker-host" + tokenExecutor := newDockerContainerActionExecutor(h, &scopedFakeDockerActionAgentCommander{ + fakeDockerActionAgentCommander: &fakeDockerActionAgentCommander{ + connected: map[string]bool{"agent-1": true}, + }, + tokenAgents: map[string]string{}, + }).(dockerContainerActionExecutor) + + readiness = tokenExecutor.CheckActionAvailable(context.Background(), request, tokenResource) + if readiness.Available || readiness.ReasonCode != "command_agent_disconnected" || + readiness.Reason != "Docker / Podman command agent is not connected." { + t.Fatalf("token-named readiness = %#v, want disconnected agent", readiness) + } + if !strings.Contains(readiness.Detail, "rotated-token") || + !strings.Contains(readiness.Detail, "never falls back") { + t.Fatalf("token-named detail = %q, want the stale token binding named", readiness.Detail) + } +} + +func TestHandlePlanActionRefusalEnvelopeCarriesDetail(t *testing.T) { + now := time.Now().UTC() + h := newActionTestResourceHandlers(t, &config.Config{DataPath: t.TempDir()}) + h.SetStateProvider(resourceUnifiedSeedProvider{ + snapshot: models.StateSnapshot{LastUpdate: now}, + resources: []unified.Resource{ + dockerContainerActionResource("app-container:api", "docker", "running", now), + }, + }) + h.SetActionExecutor(newDockerContainerActionExecutor(h, &fakeDockerActionAgentCommander{ + connected: map[string]bool{"agent-1": false}, + })) + + rec := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodPost, "/api/actions/plan", bytes.NewBufferString(`{ + "requestId":"req-refusal-detail", + "resourceId":"app-container:api", + "capabilityName":"restart", + "reason":"operator requested restart", + "requestedBy":"operator" + }`)) + h.HandlePlanAction(rec, actionHandlerTestRequest(req, "")) + + if rec.Code != http.StatusConflict { + t.Fatalf("plan status = %d, want %d, body=%s", rec.Code, http.StatusConflict, rec.Body.String()) + } + var envelope struct { + Details map[string]string `json:"details"` + } + if err := json.Unmarshal(rec.Body.Bytes(), &envelope); err != nil { + t.Fatalf("decode refusal envelope: %v", err) + } + if !strings.Contains(envelope.Details["detail"], `agent "agent-1"`) { + t.Fatalf("envelope detail = %q, want the missed agent identity named", envelope.Details["detail"]) + } +} diff --git a/internal/unifiedresources/capabilities.go b/internal/unifiedresources/capabilities.go index d3f556c13..4b9f71882 100644 --- a/internal/unifiedresources/capabilities.go +++ b/internal/unifiedresources/capabilities.go @@ -80,4 +80,8 @@ type ResourceActionReadiness struct { Available bool `json:"available"` ReasonCode string `json:"reasonCode,omitempty"` Reason string `json:"reason,omitempty"` + // Detail names the concrete lookup or identity the refusal was judged + // against (which token, agent id, or hostname missed). It feeds server + // logs and error envelopes; Reason stays the stable user-facing copy. + Detail string `json:"detail,omitempty"` } diff --git a/internal/unifiedresources/clone_test.go b/internal/unifiedresources/clone_test.go index 76b5b622e..6a9b6ab56 100644 --- a/internal/unifiedresources/clone_test.go +++ b/internal/unifiedresources/clone_test.go @@ -875,3 +875,22 @@ func TestClonedResourcesPreservePlatformAdmission(t *testing.T) { t.Fatalf("provider-owned host must not admit standalone after clone, got %+v", cloned) } } + +func TestCloneResource_PreservesActionReadinessDetail(t *testing.T) { + original := &Resource{ + ID: "app-container:api", + ActionReadiness: []ResourceActionReadiness{ + { + Name: "restart", + Available: false, + ReasonCode: "command_agent_disconnected", + Reason: "Docker / Podman command agent is not connected.", + Detail: "no live command session for agent agent-1 or hostname docker-host", + }, + }, + } + cloned := cloneResource(original) + if len(cloned.ActionReadiness) != 1 || cloned.ActionReadiness[0] != original.ActionReadiness[0] { + t.Fatalf("clone dropped action readiness diagnostics: %#v", cloned.ActionReadiness) + } +}