Orchestration completion and failure are logged and counted before the commit #60

Summary

process_orchestration_item writes the "Orchestration completed" and "Orchestration failed" log lines, and records the completion and failure metrics, before it calls ack_orchestration_item. When the commit is rejected, the logs and the metrics describe something that did not happen.

Where

• Logs and metrics:

  duroxide/src/runtime/dispatchers/orchestration.rs

  Lines 741 to 893 in 6a45886

  	// Log orchestration completion/failure and record metrics
  	if let Some(ref status) = metadata.status {
  	// Use actual orchestration name from work item, not metadata (which may be "unknown")
  	let orch_name = if workitem_reader.has_orchestration_name() {
  	workitem_reader.orchestration_name.as_str()
  	} else {
  	"unknown"
  	};
  	let version = metadata.orchestration_version.as_deref().unwrap_or(&version);
  	let event_count = history_mgr.full_history_len();
  	match status.as_str() {
  	"Completed" => {
  	tracing::debug!(
  	target: "duroxide::runtime",
  	instance_id = %instance,
  	execution_id = %execution_id_for_ack,
  	orchestration_name = %orch_name,
  	orchestration_version = %version,
  	worker_id = %worker_id,
  	history_events = %event_count,
  	"Orchestration completed"
  	);
  	// Record completion metrics with labels
  	self.record_orchestration_completion_with_labels(
  	orch_name,
  	version,
  	"success",
  	duration_seconds,
  	turn_count,
  	event_count as u64,
  	);
  	// Decrement active orchestrations (truly completed)
  	self.decrement_active_orchestrations();
  	}
  	"Failed" => {
  	// Extract error type from history_delta to determine log level
  	let (error_type, error_category) = history_delta_snapshot
  	.iter()
  	.find_map(|event| {
  	if let EventKind::OrchestrationFailed { details } = &event.kind {
  	let category = details.category();
  	let error_type = match category {
  	"infrastructure" => "infrastructure_error",
  	"configuration" => "config_error",
  	"application" => "app_error",
  	_ => "unknown",
  	};
  	Some((error_type, category))
  	} else {
  	None
  	}
  	})
  	.unwrap_or(("unknown", "unknown"));
  	// Only log as ERROR for infrastructure/configuration errors
  	// Application errors are expected business logic failures
  	match error_category {
  	"infrastructure" | "configuration" => {
  	tracing::error!(
  	target: "duroxide::runtime",
  	instance_id = %instance,
  	execution_id = %execution_id_for_ack,
  	orchestration_name = %orch_name,
  	orchestration_version = %version,
  	worker_id = %worker_id,
  	history_events = %event_count,
  	error_type = %error_category,
  	error = metadata.output.as_deref().unwrap_or("unknown"),
  	"Orchestration failed"
  	);
  	}
  	"application" => {
  	tracing::warn!(
  	target: "duroxide::runtime",
  	instance_id = %instance,
  	execution_id = %execution_id_for_ack,
  	orchestration_name = %orch_name,
  	orchestration_version = %version,
  	worker_id = %worker_id,
  	history_events = %event_count,
  	error_type = %error_category,
  	error = metadata.output.as_deref().unwrap_or("unknown"),
  	"Orchestration failed (application error)"
  	);
  	}
  	_ => {
  	tracing::error!(
  	target: "duroxide::runtime",
  	instance_id = %instance,
  	execution_id = %execution_id_for_ack,
  	orchestration_name = %orch_name,
  	orchestration_version = %version,
  	worker_id = %worker_id,
  	history_events = %event_count,
  	error_type = %error_category,
  	error = metadata.output.as_deref().unwrap_or("unknown"),
  	"Orchestration failed (unknown error type)"
  	);
  	}
  	}
  	// Record failure metrics with labels
  	self.record_orchestration_failure_with_labels(orch_name, version, error_type, error_category);
  	// Also record completion with failed status for duration tracking
  	self.record_orchestration_completion_with_labels(
  	orch_name,
  	version,
  	"failed",
  	duration_seconds,
  	turn_count,
  	event_count as u64,
  	);
  	// Decrement active orchestrations (terminal failure)
  	self.decrement_active_orchestrations();
  	}
  	"ContinuedAsNew" => {
  	tracing::debug!(
  	target: "duroxide::runtime",
  	instance_id = %instance,
  	execution_id = %execution_id_for_ack,
  	orchestration_name = %orch_name,
  	orchestration_version = %version,
  	worker_id = %worker_id,
  	history_events = %event_count,
  	"Orchestration continued as new"
  	);
  	// Record continue-as-new metric
  	self.record_continue_as_new(orch_name, execution_id_for_ack);
  	// Record completion with continue-as-new status
  	self.record_orchestration_completion_with_labels(
  	orch_name,
  	version,
  	"continuedAsNew",
  	duration_seconds,
  	turn_count,
  	event_count as u64,
  	);
  	// NOTE: Do NOT decrement active_orchestrations on continue-as-new!
  	// The orchestration is still active, just starting a new execution.
  	// The increment for the new execution will happen when the ContinueAsNew
  	// message is processed (above in the is_continue_as_new branch).
  	}
  	_ => {}
  	}
  	}

• The commit comes after them:

  duroxide/src/runtime/dispatchers/orchestration.rs

  Lines 949 to 961 in 6a45886

  	// Robust ack with basic retry on any provider error
  	match self
  	.ack_orchestration_with_changes(
  	lock_token,
  	execution_id_for_ack,
  	history_mgr.delta().to_vec(),
  	worker_items,
  	orchestrator_items,
  	metadata,
  	cancelled_activities,
  	)
  	.await
  	{

• The same holds for the start metric and the active gauge on a first turn:

  duroxide/src/runtime/dispatchers/orchestration.rs

  Lines 670 to 681 in 6a45886

  	// Record orchestration start metric
  	let initiated_by = if workitem_reader.is_continue_as_new {
  	"continueAsNew"
  	} else {
  	"client"
  	};
  	self.record_orchestration_start(&workitem_reader.orchestration_name, &version, initiated_by);
  	// Increment active orchestrations gauge ONLY for brand new orchestrations
  	if history_mgr.is_full_history_empty() && !workitem_reader.is_continue_as_new {
  	self.increment_active_orchestrations();
  	}

Effects

• A turn that lost its lock still logs Orchestration failed at ERROR, or Orchestration completed. Its commit is then rejected with Invalid lock token. An operator sees an error for an instance that is healthy.
• record_orchestration_completion_with_labels, record_orchestration_failure_with_labels and record_continue_as_new count a turn that was not committed. The turn that commits later is counted again.
• decrement_active_orchestrations runs twice for one instance, so the active gauge drifts down.

How this was checked

Read in the code. A local reproduction of a lost lock showed the log pattern: the turn logged Orchestration failed at ERROR, and the next line was ack_orchestration_item failed with non-retryable error with Invalid lock token.

Suggested fix

Write the terminal logs and record the metrics after a successful commit. PR #49 does this for the poison path. This is the same change for the normal path.

Tracked in #55.