наблюдаемость: завершить базовый контур Community

Добавить структурированные журналы, метрики, трассировку и безопасный канал критических ошибок. Усилить границы рантайма, тесты, проверку зависимостей и сценарии развёртывания.

crates/crank-runtime/src/executor.rs

@@ -1,14 +1,16 @@
 use std::sync::Arc;
-use std::time::{Duration, Instant};
+use std::time::Instant;
 
 use crank_core::{
-    AdapterRegistry, CoordinationStateStore, ExecutionMode, InvocationStatus, MeteringEvent,
-    ResponseCacheStore, SharedMeteringSink, SharedProtocolAdapter,
+    AdapterRegistry, CoordinationStateStore, ExecutionMode, InvocationSource, InvocationStatus,
+    MeteringEvent, ResponseCacheStore, SharedMeteringSink, SharedProtocolAdapter,
 };
+use crank_trace::{ErrorCategory, Stage, StageOutcome};
+use metrics::Gauge;
 use serde_json::{Map, Value, json};
 use time::OffsetDateTime;
 use tokio::sync::{OwnedSemaphorePermit, Semaphore};
-use tracing::debug;
+use tracing::{Instrument, Span, debug};
 
 use crate::{
     AdapterResponse, PreparedRequest, ResolvedAuth, RuntimeError, RuntimeLimits, RuntimeOperation,
@@ -176,18 +178,31 @@ impl RuntimeExecutor {
         request: RuntimeExecutionRequest<'_>,
     ) -> Result<Value, RuntimeError> {
         log_runtime_event("unary.execute", request.operation, request.request_context);
-        let _permit = self.acquire_unary_permit(request.operation)?;
         let started_at = Instant::now();
-        let prepared_request = self.prepare_request(request.operation, request.input)?;
-        let prepared_request = apply_resolved_auth(prepared_request, request.resolved_auth);
-        let result = self
-            .execute_prepared(
+        let runtime_span = Stage::RuntimeExecute.span();
+        let result = async {
+            let _permit = self.acquire_unary_permit(request.operation)?;
+            let _inflight = RuntimeInFlightGuard::new();
+            let mapping_span = Stage::RuntimeArgumentsMap.span();
+            let prepared_request =
+                mapping_span.in_scope(|| self.prepare_request(request.operation, request.input));
+            record_runtime_result(&mapping_span, &prepared_request);
+            drop(mapping_span);
+            let prepared_request = prepared_request?;
+            let prepared_request = apply_resolved_auth(prepared_request, request.resolved_auth);
+            self.execute_prepared(
                 request.operation,
                 request.input,
                 prepared_request,
                 request.request_context,
             )
-            .await;
+            .await
+        }
+        .instrument(runtime_span.clone())
+        .await;
+        record_runtime_result(&runtime_span, &result);
+        drop(runtime_span);
+        record_execution_metrics(request.request_context, &result, started_at);
         self.record_metering(
             request.operation,
             request.request_context,
@@ -221,59 +236,132 @@ impl RuntimeExecutor {
         request_context: Option<&RuntimeRequestContext>,
     ) -> Result<Value, RuntimeError> {
         let mut prepared_request = prepared_request;
-        let idempotency_key =
-            crate::idempotency::prepare_idempotency(operation, input, &mut prepared_request)?;
-        crate::confirmation::confirm_operation(
-            self.coordination_store.as_deref(),
+        let idempotency_applicable = crate::idempotency::policy(operation).is_some();
+        let idempotency_key = match crate::idempotency::prepare_idempotency(
             operation,
             input,
-            request_context,
-        )
-        .await?;
-        if let Some(response) = self
-            .load_idempotent_adapter_response(
+            &mut prepared_request,
+        ) {
+            Ok(key) => key,
+            Err(error) if idempotency_applicable => {
+                let span = Stage::RuntimeIdempotency.span();
+                StageOutcome::Error.record(&span);
+                ErrorCategory::Idempotency.record(&span);
+                return Err(error);
+            }
+            Err(error) => return Err(error),
+        };
+
+        if crate::confirmation::is_applicable(operation) {
+            let approval_span = Stage::ApprovalCheck.span();
+            let approval_result = crate::confirmation::confirm_operation(
+                self.coordination_store.as_deref(),
                 operation,
+                input,
+                request_context,
+            )
+            .instrument(approval_span.clone())
+            .await;
+            match &approval_result {
+                Ok(()) => StageOutcome::Success.record(&approval_span),
+                Err(RuntimeError::ConfirmationRequired { .. }) => {
+                    StageOutcome::Required.record(&approval_span);
+                    ErrorCategory::Approval.record(&approval_span);
+                }
+                Err(error) => {
+                    StageOutcome::Error.record(&approval_span);
+                    runtime_error_category(error).record(&approval_span);
+                }
+            }
+            drop(approval_span);
+            approval_result?;
+        }
+
+        let idempotency = if idempotency_applicable {
+            let idempotency_span = Stage::RuntimeIdempotency.span();
+            let result = crate::idempotency::begin(
+                self.coordination_store.as_deref(),
+                operation,
+                input,
                 idempotency_key.as_deref(),
                 request_context,
             )
-            .await
-        {
-            let finalized_output = finalize_output(operation, &response)?;
-            operation.output_schema.validate_shape(&finalized_output)?;
-            return Ok(finalized_output);
+            .instrument(idempotency_span.clone())
+            .await;
+            match &result {
+                Ok(crate::idempotency::IdempotencyAction::Execute(_)) => {
+                    StageOutcome::Execute.record(&idempotency_span);
+                }
+                Ok(crate::idempotency::IdempotencyAction::Replay(_)) => {
+                    StageOutcome::Replay.record(&idempotency_span);
+                }
+                Ok(crate::idempotency::IdempotencyAction::Disabled) => {
+                    StageOutcome::Skipped.record(&idempotency_span);
+                }
+                Err(error) => {
+                    StageOutcome::Error.record(&idempotency_span);
+                    runtime_error_category(error).record(&idempotency_span);
+                }
+            }
+            drop(idempotency_span);
+            result?
+        } else {
+            crate::idempotency::IdempotencyAction::Disabled
+        };
+        if let crate::idempotency::IdempotencyAction::Replay(response) = &idempotency {
+            return transform_response(operation, response);
         }
 
-        let adapter_response = match self
+        let adapter_result = match self
             .load_cached_adapter_response(operation, &prepared_request, request_context)
             .await
         {
-            Some(response) => response,
+            Some(response) => Ok(response),
             None => {
                 let adapter_response = self
                     .execute_adapter(operation, prepared_request.clone(), request_context)
-                    .await?;
-                self.store_cached_adapter_response(
-                    operation,
-                    &prepared_request,
-                    request_context,
-                    &adapter_response,
-                )
-                .await;
-                self.store_idempotent_adapter_response(
-                    operation,
-                    idempotency_key.as_deref(),
-                    request_context,
-                    &adapter_response,
-                )
-                .await;
+                    .await;
+                if let Ok(response) = &adapter_response {
+                    self.store_cached_adapter_response(
+                        operation,
+                        &prepared_request,
+                        request_context,
+                        response,
+                    )
+                    .await;
+                }
                 adapter_response
             }
         };
-        let finalized_output = finalize_output(operation, &adapter_response)?;
-
-        operation.output_schema.validate_shape(&finalized_output)?;
-
-        Ok(finalized_output)
+        let adapter_response = match adapter_result {
+            Ok(response) => response,
+            Err(error) => {
+                if let crate::idempotency::IdempotencyAction::Execute(reservation) = &idempotency
+                    && let Some(store) = self.coordination_store.as_deref()
+                {
+                    let idempotency_span = Stage::RuntimeIdempotency.span();
+                    let cleanup_result =
+                        crate::idempotency::mark_outcome_unknown(store, operation, reservation)
+                            .instrument(idempotency_span.clone())
+                            .await;
+                    record_runtime_result(&idempotency_span, &cleanup_result);
+                }
+                return Err(error);
+            }
+        };
+        if let crate::idempotency::IdempotencyAction::Execute(reservation) = &idempotency
+            && let Some(store) = self.coordination_store.as_deref()
+        {
+            let idempotency_span = Stage::RuntimeIdempotency.span();
+            let completion_result =
+                crate::idempotency::complete(store, operation, reservation, &adapter_response)
+                    .instrument(idempotency_span.clone())
+                    .await;
+            record_runtime_result(&idempotency_span, &completion_result);
+            drop(idempotency_span);
+            completion_result?;
+        }
+        transform_response(operation, &adapter_response)
     }
 
     async fn record_metering<T>(
@@ -323,7 +411,6 @@ impl RuntimeExecutor {
         let prepared_request = adapter_prepared_request(
             operation,
             &prepared_request,
-            request_context,
             operation.execution_config.timeout_ms,
         );
         let adapter_context = adapter_request_context(request_context);
@@ -360,11 +447,11 @@ impl RuntimeExecutor {
         let cache_key = response_cache_key(operation, prepared_request, request_context)?;
         let cached = match response_cache.get(&cache_key).await {
             Ok(cached) => cached?,
-            Err(error) => {
+            Err(_) => {
                 debug!(
-                    operation_id = %operation.operation_id,
-                    cache_key,
-                    error = %error,
+                    name: "runtime.response_cache.read_failed",
+                    operation_id = operation.operation_id.as_str(),
+                    error_category = "response_cache",
                     "response cache lookup skipped"
                 );
                 return None;
@@ -373,11 +460,11 @@ impl RuntimeExecutor {
 
         match adapter_response_from_cached(cached) {
             Ok(response) => Some(response),
-            Err(error) => {
+            Err(_) => {
                 debug!(
-                    operation_id = %operation.operation_id,
-                    cache_key,
-                    error,
+                    name: "runtime.response_cache.decode_failed",
+                    operation_id = operation.operation_id.as_str(),
+                    error_category = "cached_response",
                     "cached response payload was invalid"
                 );
                 let _ = response_cache.delete(&cache_key).await;
@@ -412,87 +499,19 @@ impl RuntimeExecutor {
             return;
         };
 
-        if let Err(error) = response_cache
+        if response_cache
             .put(&cache_key, cached_response, cache_ttl)
             .await
+            .is_err()
         {
             debug!(
-                operation_id = %operation.operation_id,
-                cache_key,
-                error = %error,
+                name: "runtime.response_cache.write_failed",
+                operation_id = operation.operation_id.as_str(),
+                error_category = "response_cache",
                 "response cache write skipped"
             );
         }
     }
-
-    async fn load_idempotent_adapter_response(
-        &self,
-        operation: &RuntimeOperation,
-        idempotency_key: Option<&str>,
-        request_context: Option<&RuntimeRequestContext>,
-    ) -> Option<AdapterResponse> {
-        let response_cache = self.response_cache.as_ref()?;
-        let cache_key =
-            crate::idempotency::cache_key(operation, idempotency_key?, request_context)?;
-        let cached = match response_cache.get(&cache_key).await {
-            Ok(cached) => cached?,
-            Err(error) => {
-                debug!(
-                    operation_id = %operation.operation_id,
-                    cache_key,
-                    error = %error,
-                    "idempotency cache lookup skipped"
-                );
-                return None;
-            }
-        };
-
-        adapter_response_from_cached(cached).ok()
-    }
-
-    async fn store_idempotent_adapter_response(
-        &self,
-        operation: &RuntimeOperation,
-        idempotency_key: Option<&str>,
-        request_context: Option<&RuntimeRequestContext>,
-        adapter_response: &AdapterResponse,
-    ) {
-        let Some(response_cache) = self.response_cache.as_ref() else {
-            return;
-        };
-        if !(200..=299).contains(&adapter_response.status_code) {
-            return;
-        }
-        let Some(policy) = crate::idempotency::policy(operation) else {
-            return;
-        };
-        let Some(cache_key) = crate::idempotency::cache_key(
-            operation,
-            idempotency_key.unwrap_or_default(),
-            request_context,
-        ) else {
-            return;
-        };
-        let Some(cached_response) = cached_response_from_adapter(adapter_response) else {
-            return;
-        };
-
-        if let Err(error) = response_cache
-            .put(
-                &cache_key,
-                cached_response,
-                Duration::from_millis(policy.ttl_ms),
-            )
-            .await
-        {
-            debug!(
-                operation_id = %operation.operation_id,
-                cache_key,
-                error = %error,
-                "idempotency cache write skipped"
-            );
-        }
-    }
 }
 
 fn adapter_request_context(
@@ -552,14 +571,149 @@ fn finalize_output(
         .unwrap_or_else(|| Value::Object(Map::new())))
 }
 
+fn transform_response(
+    operation: &RuntimeOperation,
+    response: &AdapterResponse,
+) -> Result<Value, RuntimeError> {
+    let span = Stage::RuntimeResponseTransform.span();
+    let result = span.in_scope(|| {
+        let finalized_output = finalize_output(operation, response)?;
+        operation.output_schema.validate_shape(&finalized_output)?;
+        Ok(finalized_output)
+    });
+    match &result {
+        Ok(_) => StageOutcome::Success.record(&span),
+        Err(_) => {
+            StageOutcome::Error.record(&span);
+            ErrorCategory::Transformation.record(&span);
+        }
+    }
+    result
+}
+
+fn record_runtime_result<T>(span: &Span, result: &Result<T, RuntimeError>) {
+    match result {
+        Ok(_) => StageOutcome::Success.record(span),
+        Err(error) => {
+            StageOutcome::Error.record(span);
+            runtime_error_category(error).record(span);
+        }
+    }
+}
+
+fn runtime_error_category(error: &RuntimeError) -> ErrorCategory {
+    match error {
+        RuntimeError::Schema(_) => ErrorCategory::Schema,
+        RuntimeError::Mapping(_) | RuntimeError::InvalidPreparedRequest { .. } => {
+            ErrorCategory::Mapping
+        }
+        RuntimeError::RestAdapter(_)
+        | RuntimeError::ProtocolAdapter(_)
+        | RuntimeError::UnsupportedProtocol { .. }
+        | RuntimeError::UnsupportedExecutionMode { .. } => ErrorCategory::Upstream,
+        RuntimeError::ConcurrencyLimitExceeded { .. } => ErrorCategory::Concurrency,
+        RuntimeError::ConfirmationRequired { .. }
+        | RuntimeError::InvalidConfirmationToken { .. }
+        | RuntimeError::ConfirmationStoreUnavailable { .. } => ErrorCategory::Approval,
+        RuntimeError::IdempotencyStoreUnavailable { .. }
+        | RuntimeError::IdempotencyInProgress { .. }
+        | RuntimeError::IdempotencyConflict { .. }
+        | RuntimeError::IdempotencyOutcomeUnknown { .. } => ErrorCategory::Idempotency,
+        RuntimeError::MissingAuthProfile { .. }
+        | RuntimeError::MissingSecret { .. }
+        | RuntimeError::MissingSecretVersion { .. }
+        | RuntimeError::InvalidAuthSecretValue { .. }
+        | RuntimeError::SecretCrypto { .. } => ErrorCategory::Configuration,
+    }
+}
+
 fn try_acquire_limit(
     limiter: Arc<Semaphore>,
     kind: &'static str,
     limit: usize,
 ) -> Result<OwnedSemaphorePermit, RuntimeError> {
-    limiter
-        .try_acquire_owned()
-        .map_err(|_| RuntimeError::ConcurrencyLimitExceeded { kind, limit })
+    limiter.try_acquire_owned().map_err(|_| {
+        metrics::counter!(
+            "crank_runtime_limit_rejections_total",
+            "stage" => "concurrency"
+        )
+        .increment(1);
+        RuntimeError::ConcurrencyLimitExceeded { kind, limit }
+    })
+}
+
+fn record_execution_metrics<T>(
+    request_context: Option<&RuntimeRequestContext>,
+    result: &Result<T, RuntimeError>,
+    started_at: Instant,
+) {
+    let source = request_context
+        .and_then(RuntimeRequestContext::metering_context)
+        .map_or("internal", |context| match context.source {
+            InvocationSource::AdminTestRun => "admin_test_run",
+            InvocationSource::AgentToolCall => "agent_tool_call",
+        });
+    let (outcome, error_kind) = match result {
+        Ok(_) => ("success", "none"),
+        Err(error) => ("error", runtime_error_kind(error)),
+    };
+
+    metrics::counter!(
+        "crank_tool_invocations_total",
+        "source" => source,
+        "outcome" => outcome,
+        "error_kind" => error_kind
+    )
+    .increment(1);
+    metrics::histogram!(
+        "crank_tool_invocation_duration_seconds",
+        "source" => source,
+        "outcome" => outcome
+    )
+    .record(started_at.elapsed().as_secs_f64());
+}
+
+fn runtime_error_kind(error: &RuntimeError) -> &'static str {
+    match error {
+        RuntimeError::Schema(_) => "schema",
+        RuntimeError::Mapping(_) => "mapping",
+        RuntimeError::RestAdapter(_) => "rest_adapter",
+        RuntimeError::ProtocolAdapter(_) => "protocol_adapter",
+        RuntimeError::UnsupportedProtocol { .. } => "unsupported_protocol",
+        RuntimeError::UnsupportedExecutionMode { .. } => "unsupported_execution_mode",
+        RuntimeError::ConcurrencyLimitExceeded { .. } => "concurrency_limit",
+        RuntimeError::InvalidPreparedRequest { .. } => "invalid_prepared_request",
+        RuntimeError::ConfirmationRequired { .. } => "confirmation_required",
+        RuntimeError::InvalidConfirmationToken { .. } => "invalid_confirmation_token",
+        RuntimeError::ConfirmationStoreUnavailable { .. } => "confirmation_store",
+        RuntimeError::IdempotencyStoreUnavailable { .. } => "idempotency_store",
+        RuntimeError::IdempotencyInProgress { .. } => "idempotency_in_progress",
+        RuntimeError::IdempotencyConflict { .. } => "idempotency_conflict",
+        RuntimeError::IdempotencyOutcomeUnknown { .. } => "idempotency_outcome_unknown",
+        RuntimeError::MissingAuthProfile { .. } => "missing_auth_profile",
+        RuntimeError::MissingSecret { .. } => "missing_secret",
+        RuntimeError::MissingSecretVersion { .. } => "missing_secret_version",
+        RuntimeError::InvalidAuthSecretValue { .. } => "invalid_auth_secret",
+        RuntimeError::SecretCrypto { .. } => "secret_crypto",
+    }
+}
+
+struct RuntimeInFlightGuard {
+    gauge: Gauge,
+}
+
+impl RuntimeInFlightGuard {
+    fn new() -> Self {
+        let gauge = metrics::gauge!("crank_runtime_inflight");
+        gauge.increment(1.0);
+        Self { gauge }
+    }
+}
+
+impl Drop for RuntimeInFlightGuard {
+    fn drop(&mut self) {
+        self.gauge.decrement(1.0);
+    }
 }
 
 fn log_runtime_event(
@@ -567,19 +721,26 @@ fn log_runtime_event(
     operation: &RuntimeOperation,
     request_context: Option<&RuntimeRequestContext>,
 ) {
-    let request_id = request_context
-        .map(|context| context.request_id.as_str())
-        .unwrap_or_default();
-    let correlation_id = request_context
-        .map(|context| context.correlation_id.as_str())
-        .unwrap_or_default();
-
-    debug!(
-        stage,
-        operation_id = %operation.operation_id,
-        protocol = ?operation.protocol,
-        request_id,
-        correlation_id,
-        "runtime execution"
-    );
+    let protocol = match operation.protocol {
+        crank_core::Protocol::Rest => "rest",
+    };
+    if let Some(context) = request_context {
+        debug!(
+            name: "runtime.execution.stage_reached",
+            stage,
+            operation_id = operation.operation_id.as_str(),
+            protocol,
+            request_id = context.request_id.as_str(),
+            correlation_id = context.correlation_id.as_str(),
+            "runtime execution"
+        );
+    } else {
+        debug!(
+            name: "runtime.execution.stage_reached",
+            stage,
+            operation_id = operation.operation_id.as_str(),
+            protocol,
+            "runtime execution"
+        );
+    }
 }