diff --git a/docs/agent/session-model.md b/docs/agent/session-model.md index 3cd0c7b2..584ff8d4 100644 --- a/docs/agent/session-model.md +++ b/docs/agent/session-model.md @@ -619,6 +619,75 @@ not “what is the coding task ledger for this repo work?”. - Idle open-session reuse and explicit close for operator audit views - Aggregate stats for read-only audit APIs, with explicit bounded-scan coverage +### Generic model-ergonomics telemetry + +Model-visible **runtime** tool calls reuse the existing Action Audit event as the +durable/queryable sink for low-cardinality ergonomics telemetry. No second +telemetry table or recorder is created. The shared ToolRuntime kernel owns the +normal timer for a registered model-visible tool; the transport that already owns +the outer Action Audit row then finalizes one `summary.model_ergonomics` object +from the final model-facing ToolResult projection. A transport may use a bounded +fallback timer only after a runtime tool identity is established when MCP-only +validation rejects the call before kernel entry or the MCP hard dispatch timeout +prevents kernel completion. Batch items do not create generic invocation records, +and hidden/internal helpers do not start this telemetry. + +The version-1 generic record contains only: + +- `schema_version = 1`; +- registry-owned `tool_name` and closed/bounded `tool_category`; +- `success` and non-negative `duration_ms` for the outer invocation up to its + returned ToolResult/Job handoff; +- nullable `serialized_result_bytes`; +- nullable structured `error_kind`, `failure_kind`, `recovery_kind`, and + authoritative closed `execution_state` when present. + +`serialized_result_bytes` is the UTF-8 byte length of the exact final +model-facing ToolResult JSON object (`success`, `output`, and `error` only when +present), serialized with the normal serde JSON representation. It is not a +character count, Rust memory size, stdout/stderr estimate, database-row size, or +HTTP/JSON-RPC/MCP framing size. MCP finalizes the count from the final +`structuredContent` ToolResult after MCP-only image/resource framing, so bytes +removed from the model-facing ToolResult are not charged. If a registered +model-visible tool identity has already been established but the call is rejected +before any ToolResult exists (for example invalid arguments, insufficient scope, +or MCP wrapper validation), the invocation is still counted but +`serialized_result_bytes` is `null`; the transport-specific error envelope is +never substituted for a ToolResult. The MCP hard dispatch timeout is recorded the +same way with structured `error_kind = dispatch_hard_timeout` so stalled calls do +not disappear from failure/latency aggregates. +There is currently no +authoritative generic final-result truncation fact, so generic +`result_truncated` is deliberately **not** recorded; tool-specific truncation +fields keep their existing meanings. + +Classification consumes structured ToolResult fields only. It never derives a +kind from arbitrary English error prose. The generic record stores no tool +arguments, commands/argv/scripts/stdin/stdout/stderr, ToolResult body or error +prose, paths/cwd/project ids, query/file/clipboard/Computer contents, Session +message/prompt/answer bodies, credentials, native identities, or arbitrary user +text. Existing Action Audit correlation/attribution fields remain separate +pre-existing audit data; P1a does not copy them into `model_ergonomics`. + +`edit_tool_telemetry` remains the edit-specific structured tracing enrichment. +An edit invocation therefore has one generic Action Audit invocation record plus +its existing edit-specific enrichment, not two generic counts. Workflow Session +`tool_call_started` / `tool_call_finished` events remain a separate workflow +ledger and are not the persistence source for this aggregate ergonomics data. + +Telemetry is observation-only and failure-isolated. Failure to serialize the +bounded generic projection or to persist the Action Audit row is dropped/warned +without changing the tool's success, output, error, permission, execution state, +retry safety, Job lifecycle, or Computer authority. + +For dogfood analysis, read bounded Action Audit events through +`/api/audit/session` or query SQLite `action_events.summary_json`, select rows +with `summary.model_ergonomics`, and aggregate by `tool_name`. The raw bounded +records are sufficient for invocation/success counts, duration p50/p95, +serialized-result mean/high percentiles, and structured error/recovery-kind +distributions in later SQL/Python analysis; no dashboard or analytics service is +part of this contract. + ### Identity | Aspect | Contract | diff --git a/src/mcp.rs b/src/mcp.rs index b96b9a2e..d7d55e54 100644 --- a/src/mcp.rs +++ b/src/mcp.rs @@ -10,6 +10,9 @@ use crate::tool_runtime::kernel::{ check_runtime_tool_scope, HostFileImportTrust, ToolCallContext, ToolCallErrorStatus, ToolCallRequest as KernelToolCallRequest, ToolTransport, }; +use crate::tool_runtime::model_ergonomics_telemetry::{ + ModelErgonomicsRecord, ModelErgonomicsTimer, +}; use crate::tool_runtime::tool_definition::LOCAL_CODING_TOOL_NAMES; #[cfg(test)] use crate::tool_runtime::MAX_PROJECT_ARTIFACT_BYTES; @@ -2266,11 +2269,20 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) } else { None }; - let record_audit = |success: bool, status: StatusCode, error: Option| { + let record_audit = |success: bool, + status: StatusCode, + error: Option, + model_ergonomics: Option<&ModelErgonomicsRecord>| { if let Some((audit, tool, project)) = audit.as_ref() { + let mut summary = json!({ "transport": "mcp" }); + if let Some(telemetry) = + model_ergonomics.and_then(|record| serde_json::to_value(record).ok()) + { + summary["model_ergonomics"] = telemetry; + } let mut event = ActionAuditRecord::new(tool.clone(), success, status) .error(error) - .summary(json!({ "transport": "mcp" })); + .summary(summary); event.project = project.clone(); audit.record(event); } @@ -2291,6 +2303,16 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) // failure mode behind "MCP request never gets a reply"), converting a // silently dead HTTP request into an observable JSON-RPC error. let request_id = request.id.clone(); + // The shared kernel timer is authoritative for completed runtime calls. Keep + // one outer emergency timer only so the MCP hard-timeout path does not erase + // an otherwise established runtime invocation from ergonomics telemetry. + let mut hard_timeout_model_ergonomics = + if runtime.model_surface() == ModelSurface::CanonicalConnector { + None + } else { + tool_name.as_deref().and_then(ModelErgonomicsTimer::start) + }; + let mut model_ergonomics = None; let outcome = match tokio::time::timeout( MCP_DISPATCH_HARD_TIMEOUT, handle_mcp_request_with_lifecycle( @@ -2302,6 +2324,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) host_file_import_trust, window.identity.as_ref(), Some(&mut guard), + Some(&mut model_ergonomics), ), ) .await @@ -2330,10 +2353,16 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) Some(-32000), ); } + let timeout_model_ergonomics = hard_timeout_model_ergonomics.take().map(|timer| { + timer + .finish() + .record_for_pre_result_failure("dispatch_hard_timeout") + }); record_audit( false, StatusCode::INTERNAL_SERVER_ERROR, Some("mcp dispatch hard timeout".to_string()), + timeout_model_ergonomics.as_ref(), ); let estimated = estimate_json_bytes(&body); guard.response_serialized(500, estimated, Some(false), None, "dispatch_hard_timeout"); @@ -2396,6 +2425,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) .as_str() .map(str::to_string) }, + model_ergonomics.as_ref(), ); let estimated = estimate_json_bytes(&body); guard.response_serialized(200, estimated, Some(true), tool_success, "ok"); @@ -2403,7 +2433,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) guard.handler_returned(200, estimated, Some(true), tool_success, "ok"); } McpOutcome::ArtifactExportStream { id, plan } => { - record_audit(true, StatusCode::OK, None); + record_audit(true, StatusCode::OK, None, None); guard.response_serialized(200, None, Some(true), None, "artifact_export_stream"); res.status_code(StatusCode::OK); let _ = res.add_header("content-type", "application/json", true); @@ -2450,6 +2480,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) false, StatusCode::BAD_REQUEST, body["error"]["message"].as_str().map(str::to_string), + model_ergonomics.as_ref(), ); let estimated = estimate_json_bytes(&body); guard.response_serialized(400, estimated, Some(false), None, "bad_request"); @@ -2462,6 +2493,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) false, StatusCode::NOT_FOUND, body["error"]["message"].as_str().map(str::to_string), + model_ergonomics.as_ref(), ); let estimated = estimate_json_bytes(&body); guard.response_serialized(404, estimated, Some(false), None, "not_found"); @@ -2480,6 +2512,7 @@ pub async fn mcp_post(req: &mut Request, depot: &mut Depot, res: &mut Response) "insufficient scope: {}", required_scope.unwrap_or("unknown") )), + model_ergonomics.as_ref(), ); let estimated = estimate_json_bytes(&body); guard.response_serialized(403, estimated, Some(false), None, "forbidden"); @@ -2525,6 +2558,7 @@ async fn handle_mcp_request( HostFileImportTrust::Untrusted, None, None, + None, ) .await; match outcome { @@ -2547,6 +2581,7 @@ async fn handle_mcp_request_with_lifecycle( host_file_import_trust: HostFileImportTrust, window: Option<&crate::client_window::ClientWindow>, mut lifecycle: Option<&mut ToolRequestLifecycle>, + mut model_ergonomics_out: Option<&mut Option>, ) -> McpOutcome { let stateless_2026 = protocol_era == McpProtocolEra::Stateless2026; let artifact_export_resource_read = stateless_2026 @@ -2888,6 +2923,11 @@ async fn handle_mcp_request_with_lifecycle( ), )); } + // From here on, the MCP boundary has established a model-visible runtime + // tool identity. A few MCP-only validations still happen before the + // shared ToolRuntime kernel; preserve those failed attempts in generic + // telemetry without creating a second record for normal kernel calls. + let mut pre_kernel_model_ergonomics = ModelErgonomicsTimer::start(¶ms.name); let artifact_export_caller = if params.name == "export_project_artifact" { if !stateless_2026 || runtime.model_surface() != ModelSurface::FullOperatorRuntime { return McpOutcome::BadRequest(rpc_error( @@ -2899,11 +2939,21 @@ async fn handle_mcp_request_with_lifecycle( match mcp_artifact_export_caller_binding(auth) { Ok(caller) => Some(caller), Err(error) => { + if let (Some(slot), Some(timer)) = ( + model_ergonomics_out.as_deref_mut(), + pre_kernel_model_ergonomics.take(), + ) { + *slot = Some( + timer + .finish() + .record_for_pre_result_failure("invalid_arguments"), + ); + } return McpOutcome::BadRequest(rpc_error( id, -32602, format!("export_project_artifact cannot bind this caller: {error}"), - )) + )); } } } else { @@ -2994,6 +3044,16 @@ async fn handle_mcp_request_with_lifecycle( lc.dispatch_failed("invalid_arguments"); lc.dispatch_finished(false, Some(false), "invalid_arguments"); } + if let (Some(slot), Some(timer)) = ( + model_ergonomics_out.as_deref_mut(), + pre_kernel_model_ergonomics.take(), + ) { + *slot = Some( + timer + .finish() + .record_for_pre_result_failure("invalid_arguments"), + ); + } return McpOutcome::BadRequest(rpc_error(id, -32602, message)); } }; @@ -3015,6 +3075,7 @@ async fn handle_mcp_request_with_lifecycle( }, ) .await; + let model_ergonomics_completion = outcome.model_ergonomics; let result = match outcome.error_status { Some(ToolCallErrorStatus::InsufficientScope { required_scope, @@ -3024,6 +3085,13 @@ async fn handle_mcp_request_with_lifecycle( lc.dispatch_failed("forbidden"); lc.dispatch_finished(false, Some(false), "forbidden"); } + if let (Some(slot), Some(completion)) = ( + model_ergonomics_out.as_deref_mut(), + model_ergonomics_completion.as_ref(), + ) { + *slot = + Some(completion.record_for_pre_result_failure("insufficient_scope")); + } return scope_forbidden(auth, required_scope, description); } Some(ToolCallErrorStatus::InvalidArguments { message }) => { @@ -3031,6 +3099,12 @@ async fn handle_mcp_request_with_lifecycle( lc.dispatch_failed("invalid_arguments"); lc.dispatch_finished(false, Some(false), "invalid_arguments"); } + if let (Some(slot), Some(completion)) = ( + model_ergonomics_out.as_deref_mut(), + model_ergonomics_completion.as_ref(), + ) { + *slot = Some(completion.record_for_pre_result_failure("invalid_arguments")); + } return McpOutcome::BadRequest(rpc_error(id, -32602, message)); } None => outcome @@ -3065,14 +3139,22 @@ async fn handle_mcp_request_with_lifecycle( snapshot_resource_caller, ) }; - rpc_result( + let model_ergonomics = model_ergonomics_completion.as_ref().and_then(|completion| { + result + .get("structuredContent") + .and_then(|structured| completion.record_for_structured_content(structured)) + }); + if let Some(slot) = model_ergonomics_out.as_deref_mut() { + *slot = model_ergonomics; + } + return McpOutcome::Ok(rpc_result( id, if stateless_2026 { mcp_stateless_result(result, false) } else { result }, - ) + )); } "notifications/initialized" if !stateless_2026 => rpc_result(id, json!({})), _ => { diff --git a/src/mcp_tests/http_transport.rs b/src/mcp_tests/http_transport.rs index b802f3ee..c00339da 100644 --- a/src/mcp_tests/http_transport.rs +++ b/src/mcp_tests/http_transport.rs @@ -191,7 +191,7 @@ async fn mcp_tools_call_writes_a_summary_action_audit_row() { let (_tmp, db) = test_db(); let runtime = Arc::new(test_runtime_with_surface(ModelSurface::FullOperatorRuntime)); let service = Service::new(build_test_router(config, db.clone(), runtime)); - let resp = TestClient::post("http://localhost/mcp") + let mut resp = TestClient::post("http://localhost/mcp") .bearer_auth("secret") .json(&json!({ "jsonrpc": "2.0", @@ -202,6 +202,11 @@ async fn mcp_tools_call_writes_a_summary_action_audit_row() { .send(&service) .await; assert_eq!(resp.status_code, Some(StatusCode::OK)); + let body: Value = resp.take_json().await.unwrap(); + let structured = &body["result"]["structuredContent"]; + assert_eq!(structured["success"], true); + assert!(structured["error"].is_null()); + let expected_tool_result_bytes = serde_json::to_vec(structured).unwrap().len() as u64; // End the connection guard structurally inside the block: the awaited // requests below must not overlap it. @@ -226,10 +231,22 @@ async fn mcp_tools_call_writes_a_summary_action_audit_row() { assert_eq!(action, "toolsCall"); assert_eq!(operation, "list_tools"); assert_eq!(status, "success"); + let summary: Value = serde_json::from_str(&summary).unwrap(); + assert_eq!(summary["transport"], "mcp"); assert!( - !summary.contains("tools"), - "summary must not embed output: {summary}" + summary.get("output").is_none(), + "summary must not embed tool output: {summary}" ); + let telemetry = &summary["model_ergonomics"]; + assert_eq!(telemetry["tool_name"], "list_tools"); + assert_eq!(telemetry["tool_category"], "runtime"); + assert_eq!(telemetry["success"], true); + assert_eq!( + telemetry["serialized_result_bytes"].as_u64().unwrap(), + expected_tool_result_bytes, + "MCP telemetry must count the final structuredContent ToolResult, not JSON-RPC/content framing" + ); + assert!(telemetry["recovery_kind"].is_null()); // Non-tool methods stay out of the audit. let resp = TestClient::post("http://localhost/mcp") @@ -261,6 +278,85 @@ async fn mcp_tools_call_writes_a_summary_action_audit_row() { assert_eq!(count, 1); } +#[tokio::test] +async fn mcp_pre_result_invalid_arguments_still_records_generic_attempt() { + let config = test_config(Some("secret")); + let (_tmp, db) = test_db(); + let runtime = Arc::new(test_runtime_with_surface(ModelSurface::FullOperatorRuntime)); + let service = Service::new(build_test_router(config, db.clone(), runtime)); + let mut response = TestClient::post("http://localhost/mcp") + .bearer_auth("secret") + .json(&json!({ + "jsonrpc": "2.0", + "id": 101, + "method": "tools/call", + "params": {"name": "read_file", "arguments": {}} + })) + .send(&service) + .await; + assert_eq!(effective_status(&response), StatusCode::BAD_REQUEST); + let body: Value = response.take_json().await.unwrap(); + assert_eq!(body["error"]["code"], -32602); + + let summary: String = db + .conn_for_tests() + .query_row( + "SELECT summary_json FROM action_events WHERE operation = 'read_file'", + [], + |row| row.get(0), + ) + .unwrap(); + let summary: Value = serde_json::from_str(&summary).unwrap(); + let telemetry = &summary["model_ergonomics"]; + assert_eq!(telemetry["tool_name"], "read_file"); + assert_eq!(telemetry["success"], false); + assert_eq!(telemetry["error_kind"], "invalid_arguments"); + assert!(telemetry["serialized_result_bytes"].is_null()); +} + +#[tokio::test] +async fn mcp_pre_kernel_wrapper_validation_still_records_generic_attempt() { + let config = test_config(Some("secret")); + let (_tmp, db) = test_db(); + let runtime = Arc::new(test_runtime_with_surface(ModelSurface::FullOperatorRuntime)); + let service = Service::new(build_test_router(config, db.clone(), runtime)); + let mut arguments = json!({}); + arguments.as_object_mut().unwrap().insert( + crate::tool_runtime::sessions::TOOL_CALL_RECORDING_SESSION_ID_FIELD.to_string(), + json!(42), + ); + + let mut response = TestClient::post("http://localhost/mcp") + .bearer_auth("secret") + .json(&json!({ + "jsonrpc": "2.0", + "id": 102, + "method": "tools/call", + "params": {"name": "list_tools", "arguments": arguments} + })) + .send(&service) + .await; + assert_eq!(effective_status(&response), StatusCode::BAD_REQUEST); + let body: Value = response.take_json().await.unwrap(); + assert_eq!(body["error"]["code"], -32602); + + let summary: String = db + .conn_for_tests() + .query_row( + "SELECT summary_json FROM action_events WHERE operation = 'list_tools'", + [], + |row| row.get(0), + ) + .unwrap(); + let summary: Value = serde_json::from_str(&summary).unwrap(); + let telemetry = &summary["model_ergonomics"]; + assert_eq!(telemetry["tool_name"], "list_tools"); + assert_eq!(telemetry["tool_category"], "runtime"); + assert_eq!(telemetry["success"], false); + assert_eq!(telemetry["error_kind"], "invalid_arguments"); + assert!(telemetry["serialized_result_bytes"].is_null()); +} + fn seed_action_audit_pat(db: &crate::Database, user: &crate::models::UserRecord) -> String { let plaintext = crate::auth::generate_api_token(); let record = crate::models::ApiKeyRecord { diff --git a/src/runtime_http.rs b/src/runtime_http.rs index 8964ab3c..4b298477 100644 --- a/src/runtime_http.rs +++ b/src/runtime_http.rs @@ -4,6 +4,7 @@ use crate::tool_request_trace::{estimate_json_bytes, new_trace_id, ToolRequestLi use crate::tool_runtime::kernel::{ ToolCallContext, ToolCallErrorStatus, ToolCallRequest as KernelToolCallRequest, ToolTransport, }; +use crate::tool_runtime::model_ergonomics_telemetry::ModelErgonomicsCompletion; use crate::tool_runtime::sessions::TOOL_CALL_RECORDING_SESSION_ID_FIELD; use crate::tool_runtime::{ ListToolsOptions, ToolCall, ToolRuntime, TOOL_CALL_ARGUMENTS_FIELD, TOOL_CALL_PARAMS_FIELD, @@ -157,6 +158,7 @@ fn prepare_action_tools_call_response( tool: &str, project: Option, result: crate::tool_runtime::ToolResult, + model_ergonomics: Option<&ModelErgonomicsCompletion>, ) -> (StatusCode, crate::tool_runtime::ToolResult) { let status = if result.success { StatusCode::OK @@ -164,21 +166,43 @@ fn prepare_action_tools_call_response( StatusCode::BAD_REQUEST }; let audit_output = action_audit_output_for_tool(tool, &result.output); - let mut event = ActionAuditRecord::new(tool.to_string(), result.success, status) - .error(result.error.clone()) - .summary(json!({ - "output": audit_output, - })); - event.project = project; - audit.record(event); let response = if crate::config::action_compact_responses_enabled() { action_compact::compact_action_tool_result(tool, result) } else { result }; + let mut summary = json!({"output": audit_output}); + if let Some(telemetry) = model_ergonomics + .and_then(|completion| completion.record_for_tool_result(&response)) + .and_then(|record| serde_json::to_value(record).ok()) + { + summary["model_ergonomics"] = telemetry; + } + let mut event = ActionAuditRecord::new(tool.to_string(), response.success, status) + .error(response.error.clone()) + .summary(summary); + event.project = project; + audit.record(event); (status, response) } +fn record_action_tools_call_pre_result_failure( + audit: &ActionAudit, + tool: &str, + status: StatusCode, + model_ergonomics: Option<&ModelErgonomicsCompletion>, + error_kind: &'static str, +) { + let mut summary = json!({}); + if let Some(telemetry) = model_ergonomics + .map(|completion| completion.record_for_pre_result_failure(error_kind)) + .and_then(|record| serde_json::to_value(record).ok()) + { + summary["model_ergonomics"] = telemetry; + } + audit.record(ActionAuditRecord::new(tool.to_string(), false, status).summary(summary)); +} + #[handler] pub async fn tools_list(req: &mut Request, depot: &mut Depot, res: &mut Response) { let Some(runtime) = require_runtime(depot, res) else { @@ -289,12 +313,20 @@ pub async fn tools_call(req: &mut Request, depot: &mut Depot, res: &mut Response }, ) .await; + let model_ergonomics = outcome.model_ergonomics; match outcome.error_status { Some(ToolCallErrorStatus::InsufficientScope { required_scope, description, }) => { guard.dispatch_failed("insufficient_scope"); + record_action_tools_call_pre_result_failure( + &audit, + &tool, + StatusCode::FORBIDDEN, + model_ergonomics.as_ref(), + "insufficient_scope", + ); guard.dispatch_finished(false, Some(false), "insufficient_scope"); // Scope-denial body is rendered by the credential-aware helper; size not measured. guard.response_serialized(403, None, Some(false), Some(false), "insufficient_scope"); @@ -303,6 +335,13 @@ pub async fn tools_call(req: &mut Request, depot: &mut Depot, res: &mut Response } Some(ToolCallErrorStatus::InvalidArguments { message }) => { guard.dispatch_failed("invalid_arguments"); + record_action_tools_call_pre_result_failure( + &audit, + &tool, + StatusCode::BAD_REQUEST, + model_ergonomics.as_ref(), + "invalid_arguments", + ); guard.dispatch_finished(false, Some(false), "invalid_arguments"); guard.response_serialized(400, None, Some(false), Some(false), "invalid_arguments"); res.status_code(StatusCode::BAD_REQUEST); @@ -324,8 +363,13 @@ pub async fn tools_call(req: &mut Request, depot: &mut Depot, res: &mut Response } // Audit the tool-specific durable projection; optionally compact only the HTTP response body. // Trace size reflects what ChatGPT receives (post-compact when on). - let (status, response) = - prepare_action_tools_call_response(&audit, &tool, outcome.project, result); + let (status, response) = prepare_action_tools_call_response( + &audit, + &tool, + outcome.project, + result, + model_ergonomics.as_ref(), + ); let estimated = if guard.enabled() { serde_json::to_value(&response) .ok() diff --git a/src/runtime_http/tests/model_ergonomics_tests.rs b/src/runtime_http/tests/model_ergonomics_tests.rs new file mode 100644 index 00000000..e2e65a0d --- /dev/null +++ b/src/runtime_http/tests/model_ergonomics_tests.rs @@ -0,0 +1,216 @@ +use salvo::http::StatusCode; +use salvo::test::{ResponseExt, TestClient}; +use salvo::Service; +use serde_json::{json, Value}; +use std::sync::Arc; + +fn single_model_ergonomics( + db: &crate::Database, + action_session_id: &str, + expected_tool: &str, +) -> Value { + let events = db.list_action_events(action_session_id, 20).unwrap(); + assert_eq!( + events.len(), + 1, + "one outer tool call must create one ActionAudit row" + ); + assert_eq!(events[0].operation.as_deref(), Some(expected_tool)); + let summary: Value = serde_json::from_str(&events[0].summary_json).unwrap(); + summary + .get("model_ergonomics") + .cloned() + .unwrap_or_else(|| panic!("missing generic telemetry in summary: {summary}")) +} + +#[tokio::test] +async fn api_model_ergonomics_success_is_exact_and_queryable() { + let config = super::test_config(Some("secret")); + let (_db_tmp, db) = super::test_db(); + let project_tmp = tempfile::tempdir().unwrap(); + let runtime = Arc::new(super::runtime_with_local_project( + project_tmp.path(), + "demo", + )); + let service = Service::new(super::build_projects_router(config, db.clone(), runtime)); + + let mut response = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .add_header("x-action-session-id", "ergonomics-success", true) + .json(&json!({"tool": "tool_manifest", "intent": "audit"})) + .send(&service) + .await; + assert_eq!(super::effective_status(&response), StatusCode::OK); + let body: Value = response.take_json().await.unwrap(); + assert_eq!(body["success"], true); + + let telemetry = single_model_ergonomics(&db, "ergonomics-success", "tool_manifest"); + assert_eq!(telemetry["schema_version"], 1); + assert_eq!(telemetry["tool_name"], "tool_manifest"); + assert_eq!(telemetry["tool_category"], "runtime"); + assert_eq!(telemetry["success"], true); + assert!(telemetry["duration_ms"].as_u64().is_some()); + assert_eq!( + telemetry["serialized_result_bytes"].as_u64().unwrap(), + serde_json::to_vec(&body).unwrap().len() as u64, + "API telemetry must count the exact final ToolResult UTF-8 serialization" + ); + assert!(telemetry["error_kind"].is_null()); + assert!(telemetry["failure_kind"].is_null()); + assert!(telemetry["recovery_kind"].is_null()); + assert!(telemetry.get("result_truncated").is_none()); +} + +#[tokio::test] +async fn api_model_ergonomics_failure_uses_structured_kinds_without_private_text() { + let config = super::test_config(Some("secret")); + let (_db_tmp, db) = super::test_db(); + let project_tmp = tempfile::tempdir().unwrap(); + let runtime = Arc::new(super::runtime_with_local_project( + project_tmp.path(), + "demo", + )); + let service = Service::new(super::build_projects_router(config, db.clone(), runtime)); + let private_project = "PRIVATE-command-path-query-token"; + + let mut response = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .add_header("x-action-session-id", "ergonomics-failure", true) + .json(&json!({"tool": "project_overview", "project": private_project})) + .send(&service) + .await; + assert_eq!(super::effective_status(&response), StatusCode::BAD_REQUEST); + let body: Value = response.take_json().await.unwrap(); + assert_eq!(body["success"], false); + assert_eq!(body["output"]["error_kind"], "unknown_project"); + assert_eq!(body["output"]["recovery_kind"], "fix_input"); + + let telemetry = single_model_ergonomics(&db, "ergonomics-failure", "project_overview"); + assert_eq!(telemetry["success"], false); + assert_eq!(telemetry["error_kind"], "unknown_project"); + assert!(telemetry["failure_kind"].is_null()); + assert_eq!(telemetry["recovery_kind"], "fix_input"); + assert_eq!( + telemetry["serialized_result_bytes"].as_u64().unwrap(), + serde_json::to_vec(&body).unwrap().len() as u64 + ); + let serialized = serde_json::to_string(&telemetry).unwrap(); + for forbidden in [private_project, "command", "path", "query", "token"] { + assert!( + !serialized.contains(forbidden), + "generic telemetry leaked arbitrary/private text {forbidden}: {serialized}" + ); + } +} + +#[tokio::test] +async fn api_pre_result_invalid_arguments_still_counts_without_fabricated_bytes() { + let config = super::test_config(Some("secret")); + let (_db_tmp, db) = super::test_db(); + let project_tmp = tempfile::tempdir().unwrap(); + let runtime = Arc::new(super::runtime_with_local_project( + project_tmp.path(), + "demo", + )); + let service = Service::new(super::build_projects_router(config, db.clone(), runtime)); + + let mut response = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .add_header("x-action-session-id", "ergonomics-invalid", true) + .json(&json!({"tool": "read_file"})) + .send(&service) + .await; + assert_eq!(super::effective_status(&response), StatusCode::BAD_REQUEST); + let body: Value = response.take_json().await.unwrap(); + assert!(body["error"].is_string()); + + let telemetry = single_model_ergonomics(&db, "ergonomics-invalid", "read_file"); + assert_eq!(telemetry["success"], false); + assert_eq!(telemetry["error_kind"], "invalid_arguments"); + assert!(telemetry["serialized_result_bytes"].is_null()); + assert!(telemetry["failure_kind"].is_null()); + assert!(telemetry["recovery_kind"].is_null()); + assert!(telemetry["execution_state"].is_null()); +} + +#[tokio::test] +async fn api_batch_call_records_one_generic_outer_invocation() { + let config = super::test_config(Some("secret")); + let (_db_tmp, db) = super::test_db(); + let project_tmp = tempfile::tempdir().unwrap(); + let (runtime, registry) = super::register_import_agent_with_capabilities( + project_tmp.path(), + Some(crate::shell_protocol::ShellClientCapabilities { + file_read: true, + ..Default::default() + }), + ) + .await; + let executor = super::spawn_startup_agent_executor(registry); + let service = Service::new(super::build_projects_router(config, db.clone(), runtime)); + + let mut response = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .add_header("x-action-session-id", "ergonomics-batch", true) + .json(&json!({ + "tool": "read_files", + "project": "agent:importer:demo", + "items": [ + {"path": "missing-a.rs"}, + {"path": "missing-b.rs"} + ] + })) + .send(&service) + .await; + let status = super::effective_status(&response); + let body: Value = response.take_json().await.unwrap(); + executor.abort(); + + assert_eq!(status, StatusCode::OK, "{body}"); + assert_eq!(body["success"], true); + assert_eq!(body["output"]["items"].as_array().unwrap().len(), 2); + assert!(body["output"]["items"] + .as_array() + .unwrap() + .iter() + .all(|item| item["success"] == false)); + let telemetry = single_model_ergonomics(&db, "ergonomics-batch", "read_files"); + assert_eq!(telemetry["tool_name"], "read_files"); + assert_eq!(telemetry["success"], true); +} + +#[tokio::test] +async fn action_audit_sink_failure_never_changes_success_or_failure_tool_result() { + let config = super::test_config(Some("secret")); + let (_db_tmp, db) = super::test_db(); + let project_tmp = tempfile::tempdir().unwrap(); + let runtime = Arc::new(super::runtime_with_local_project( + project_tmp.path(), + "demo", + )); + let service = Service::new(super::build_projects_router(config, db.clone(), runtime)); + db.conn_for_tests() + .execute("DROP TABLE action_events", []) + .unwrap(); + + let mut success = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .json(&json!({"tool": "tool_manifest", "intent": "audit"})) + .send(&service) + .await; + assert_eq!(super::effective_status(&success), StatusCode::OK); + let success_body: Value = success.take_json().await.unwrap(); + assert_eq!(success_body["success"], true); + assert!(success_body["output"]["tools"].is_array()); + + let mut failure = TestClient::post("http://localhost/api/tools/call") + .bearer_auth("secret") + .json(&json!({"tool": "project_overview", "project": "missing-project"})) + .send(&service) + .await; + assert_eq!(super::effective_status(&failure), StatusCode::BAD_REQUEST); + let failure_body: Value = failure.take_json().await.unwrap(); + assert_eq!(failure_body["success"], false); + assert_eq!(failure_body["output"]["error_kind"], "unknown_project"); + assert_eq!(failure_body["output"]["recovery_kind"], "fix_input"); +} diff --git a/src/runtime_http_tests.rs b/src/runtime_http_tests.rs index bdf880fa..3ad3a15c 100644 --- a/src/runtime_http_tests.rs +++ b/src/runtime_http_tests.rs @@ -9,6 +9,8 @@ use std::time::Duration; mod import_http_tests; #[path = "runtime_http/tests/jobs_tests.rs"] mod jobs_tests; +#[path = "runtime_http/tests/model_ergonomics_tests.rs"] +mod model_ergonomics_tests; #[path = "runtime_http/tests/project_files_tests.rs"] mod project_files_tests; #[path = "runtime_http/tests/projects_tests.rs"] diff --git a/src/tool_runtime/kernel.rs b/src/tool_runtime/kernel.rs index 932c54a0..9b113c3e 100644 --- a/src/tool_runtime/kernel.rs +++ b/src/tool_runtime/kernel.rs @@ -1,3 +1,4 @@ +use super::model_ergonomics_telemetry::{ModelErgonomicsCompletion, ModelErgonomicsTimer}; use super::sessions::{ strip_tool_call_expectation_metadata, SessionTransport, ToolCallRecorderMetadata, }; @@ -76,6 +77,7 @@ pub(crate) struct ToolCallOutcome { pub(crate) result: Option, pub(crate) error_status: Option, pub(crate) project: Option, + pub(crate) model_ergonomics: Option, } pub(crate) fn check_runtime_tool_scope( @@ -139,6 +141,17 @@ impl ToolRuntime { &self, request: ToolCallRequest, context: ToolCallContext<'_>, + ) -> ToolCallOutcome { + let telemetry = ModelErgonomicsTimer::start(&request.tool_name); + let mut outcome = self.call_tool_with_context_inner(request, context).await; + outcome.model_ergonomics = telemetry.map(ModelErgonomicsTimer::finish); + outcome + } + + async fn call_tool_with_context_inner( + &self, + request: ToolCallRequest, + context: ToolCallContext<'_>, ) -> ToolCallOutcome { let recorder_metadata = ToolCallRecorderMetadata::from_arguments(&request.arguments); let concrete_arguments = strip_tool_call_expectation_metadata(request.arguments.clone()); @@ -162,6 +175,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } } @@ -183,6 +197,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } let recorder_project = self @@ -209,6 +224,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } } @@ -271,6 +287,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } } @@ -311,6 +328,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } if let Some(session_id) = context.session_id { @@ -364,6 +382,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } if let Some(denial) = self.sessions.guard_denial(session_id, &request.tool_name) { @@ -403,6 +422,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project: None, + model_ergonomics: None, }; } } @@ -414,6 +434,7 @@ impl ToolRuntime { result: None, error_status: Some(error_status), project: None, + model_ergonomics: None, }; } } @@ -449,6 +470,7 @@ impl ToolRuntime { result: None, error_status: Some(error_status), project: None, + model_ergonomics: None, }; } } @@ -488,6 +510,7 @@ impl ToolRuntime { result: None, error_status: Some(ToolCallErrorStatus::InvalidArguments { message }), project: None, + model_ergonomics: None, }; } }; @@ -601,6 +624,7 @@ impl ToolRuntime { result: Some(result), error_status: None, project, + model_ergonomics: None, } } diff --git a/src/tool_runtime/mod.rs b/src/tool_runtime/mod.rs index 2bb79873..4866b043 100644 --- a/src/tool_runtime/mod.rs +++ b/src/tool_runtime/mod.rs @@ -35,6 +35,7 @@ pub(crate) mod kernel; mod local_jobs; mod lsp_tools; pub(crate) mod metadata; +pub(crate) mod model_ergonomics_telemetry; pub(crate) mod observations; mod observe_jobs; mod patch; diff --git a/src/tool_runtime/model_ergonomics_telemetry.rs b/src/tool_runtime/model_ergonomics_telemetry.rs new file mode 100644 index 00000000..b7c2c759 --- /dev/null +++ b/src/tool_runtime/model_ergonomics_telemetry.rs @@ -0,0 +1,315 @@ +//! Privacy-bounded telemetry projection for model-visible runtime tool calls. +//! +//! This module owns no persistence. The shared tool kernel measures invocation +//! latency and transports finalize the record from the exact model-facing +//! `ToolResult` projection before attaching it to the existing Action Audit row. + +use super::tool_definition::model_visible_tool_definitions; +use super::{ToolResult, RECOVERY_KIND_VALUES}; +use serde::Serialize; +use serde_json::Value; +#[cfg(test)] +use std::time::Duration; +use std::time::Instant; + +const MAX_STRUCTURED_KIND_BYTES: usize = 64; + +#[derive(Debug)] +pub(crate) struct ModelErgonomicsTimer { + tool_name: &'static str, + tool_category: &'static str, + started: Instant, +} + +#[derive(Debug, Clone, Copy)] +pub(crate) struct ModelErgonomicsCompletion { + tool_name: &'static str, + tool_category: &'static str, + duration_ms: u64, +} + +#[derive(Debug, Clone, PartialEq, Eq, Serialize)] +pub(crate) struct ModelErgonomicsRecord { + pub(crate) schema_version: u8, + pub(crate) tool_name: &'static str, + pub(crate) tool_category: &'static str, + pub(crate) success: bool, + pub(crate) duration_ms: u64, + pub(crate) serialized_result_bytes: Option, + pub(crate) error_kind: Option, + pub(crate) failure_kind: Option, + pub(crate) recovery_kind: Option, + pub(crate) execution_state: Option, +} + +impl ModelErgonomicsTimer { + pub(crate) fn start(tool_name: &str) -> Option { + let definition = + model_visible_tool_definitions().find(|definition| definition.name == tool_name)?; + Some(Self { + tool_name: definition.name, + tool_category: definition.category, + started: Instant::now(), + }) + } + + pub(crate) fn finish(self) -> ModelErgonomicsCompletion { + let elapsed = self.started.elapsed(); + ModelErgonomicsCompletion { + tool_name: self.tool_name, + tool_category: self.tool_category, + duration_ms: elapsed.as_millis().min(u64::MAX as u128) as u64, + } + } + + #[cfg(test)] + fn finish_after(self, elapsed: Duration) -> ModelErgonomicsCompletion { + ModelErgonomicsCompletion { + tool_name: self.tool_name, + tool_category: self.tool_category, + duration_ms: elapsed.as_millis().min(u64::MAX as u128) as u64, + } + } +} + +impl ModelErgonomicsCompletion { + /// Finalize telemetry from the exact `ToolResult` value rendered by the API + /// transport. Serialization failure drops telemetry rather than affecting + /// the tool outcome. + pub(crate) fn record_for_tool_result( + &self, + result: &ToolResult, + ) -> Option { + let serialized_result_bytes = serde_json::to_vec(result).ok()?.len(); + Some(self.record_from_parts( + result.success, + &result.output, + Some(serialized_result_bytes), + )) + } + + /// Finalize telemetry from MCP `structuredContent`, which is the final + /// model-facing ToolResult projection after MCP-only image/resource framing. + /// The MCP content blocks and JSON-RPC envelope are intentionally excluded. + pub(crate) fn record_for_structured_content( + &self, + structured_content: &Value, + ) -> Option { + let success = structured_content.get("success")?.as_bool()?; + let output = structured_content.get("output")?; + let serialized_result_bytes = serde_json::to_vec(structured_content).ok()?.len(); + Some(self.record_from_parts(success, output, Some(serialized_result_bytes))) + } + + /// Record an invocation rejected after the kernel recognized a model-visible + /// tool but before any ToolResult existed. The byte field is intentionally + /// null rather than measuring a transport-specific error envelope. + pub(crate) fn record_for_pre_result_failure( + &self, + error_kind: &'static str, + ) -> ModelErgonomicsRecord { + let mut record = self.record_from_parts(false, &Value::Null, None); + record.error_kind = Some(error_kind.to_string()); + record + } + + fn record_from_parts( + &self, + success: bool, + output: &Value, + serialized_result_bytes: Option, + ) -> ModelErgonomicsRecord { + let (error_kind, failure_kind, recovery_kind) = if success { + (None, None, None) + } else { + ( + structured_kind(output, "error_kind"), + structured_kind(output, "failure_kind"), + recovery_kind(output), + ) + }; + ModelErgonomicsRecord { + schema_version: 1, + tool_name: self.tool_name, + tool_category: self.tool_category, + success, + duration_ms: self.duration_ms, + serialized_result_bytes: serialized_result_bytes + .map(|bytes| bytes.min(u64::MAX as usize) as u64), + error_kind, + failure_kind, + recovery_kind, + execution_state: execution_state(output), + } + } +} + +fn structured_kind(output: &Value, field: &str) -> Option { + let value = output.get(field)?.as_str()?.trim(); + if value.is_empty() + || value.len() > MAX_STRUCTURED_KIND_BYTES + || !value + .bytes() + .all(|byte| byte.is_ascii_lowercase() || byte.is_ascii_digit() || byte == b'_') + { + return None; + } + Some(value.to_string()) +} + +fn recovery_kind(output: &Value) -> Option { + let value = output.get("recovery_kind")?.as_str()?; + RECOVERY_KIND_VALUES + .contains(&value) + .then(|| value.to_string()) +} + +fn execution_state(output: &Value) -> Option { + let value = output.get("execution_state")?.as_str()?; + matches!( + value, + "not_started" + | "pending" + | "running" + | "started" + | "outcome_unknown" + | "completed" + | "cancelled" + | "timed_out" + ) + .then(|| value.to_string()) +} + +#[cfg(test)] +mod tests { + use super::*; + use serde_json::json; + + fn completion(tool_name: &str, duration_ms: u64) -> ModelErgonomicsCompletion { + ModelErgonomicsTimer::start(tool_name) + .expect("model-visible tool") + .finish_after(Duration::from_millis(duration_ms)) + } + + #[test] + fn success_record_uses_exact_utf8_tool_result_bytes() { + let result = ToolResult::ok(json!({"text": "中文", "count": 2})); + let record = completion("tool_manifest", 7) + .record_for_tool_result(&result) + .unwrap(); + let expected = serde_json::to_vec(&result).unwrap().len() as u64; + let chars = serde_json::to_string(&result).unwrap().chars().count() as u64; + assert_eq!(record.serialized_result_bytes, Some(expected)); + assert!( + expected > chars, + "UTF-8 multibyte text must count bytes, not chars" + ); + assert_eq!(record.duration_ms, 7); + assert!(record.success); + assert_eq!(record.tool_name, "tool_manifest"); + assert_eq!(record.tool_category, "runtime"); + assert_eq!(record.error_kind, None); + assert_eq!(record.failure_kind, None); + assert_eq!(record.recovery_kind, None); + } + + #[test] + fn failure_record_consumes_only_structured_recovery_fields() { + let private = "PRIVATE error prose /tmp/secret.rs token=abc search needle"; + let result = ToolResult::err_with_output( + private, + json!({ + "error_kind": "stale_surface", + "failure_kind": "not_started", + "recovery_kind": "reobserve", + "execution_state": "not_started", + "command": private, + "path": "/tmp/secret.rs", + "query": "search needle", + "message": private + }), + ); + let record = completion("computer_control", 3) + .record_for_tool_result(&result) + .unwrap(); + assert!(!record.success); + assert_eq!(record.error_kind.as_deref(), Some("stale_surface")); + assert_eq!(record.failure_kind.as_deref(), Some("not_started")); + assert_eq!(record.recovery_kind.as_deref(), Some("reobserve")); + assert_eq!(record.execution_state.as_deref(), Some("not_started")); + let telemetry = serde_json::to_string(&record).unwrap(); + for forbidden in [private, "/tmp/secret.rs", "search needle", "token=abc"] { + assert!( + !telemetry.contains(forbidden), + "telemetry leaked {forbidden}: {telemetry}" + ); + } + } + + #[test] + fn success_never_invents_failure_or_recovery_metadata() { + let result = ToolResult::ok(json!({ + "error_kind": "stale_surface", + "failure_kind": "outcome_unknown", + "recovery_kind": "retry_same" + })); + let record = completion("tool_manifest", 0) + .record_for_tool_result(&result) + .unwrap(); + assert_eq!(record.error_kind, None); + assert_eq!(record.failure_kind, None); + assert_eq!(record.recovery_kind, None); + } + + #[test] + fn invalid_structured_kinds_are_not_promoted_to_telemetry() { + let result = ToolResult::err_with_output( + "private prose", + json!({ + "error_kind": "PRIVATE arbitrary text / path", + "failure_kind": "x".repeat(MAX_STRUCTURED_KIND_BYTES + 1), + "recovery_kind": "blind_retry", + "execution_state": "maybe" + }), + ); + let record = completion("tool_manifest", 0) + .record_for_tool_result(&result) + .unwrap(); + assert_eq!(record.error_kind, None); + assert_eq!(record.failure_kind, None); + assert_eq!(record.recovery_kind, None); + assert_eq!(record.execution_state, None); + } + + #[test] + fn pre_result_failure_counts_invocation_without_fabricating_tool_result_bytes() { + let record = completion("read_file", 2).record_for_pre_result_failure("invalid_arguments"); + assert!(!record.success); + assert_eq!(record.error_kind.as_deref(), Some("invalid_arguments")); + assert_eq!(record.serialized_result_bytes, None); + assert_eq!(record.failure_kind, None); + assert_eq!(record.recovery_kind, None); + assert_eq!(record.execution_state, None); + } + + #[test] + fn hidden_tools_do_not_start_generic_model_usage_telemetry() { + assert!(ModelErgonomicsTimer::start("start_coding_task").is_none()); + assert!(ModelErgonomicsTimer::start("definitely_internal_helper").is_none()); + } + + #[test] + fn every_registered_model_visible_tool_has_generic_telemetry_identity() { + let specs = super::super::registered_tool_specs(); + assert!(!specs.is_empty()); + for spec in specs { + let timer = ModelErgonomicsTimer::start(&spec.name) + .unwrap_or_else(|| panic!("{} bypasses generic telemetry identity", spec.name)); + assert_ne!( + timer.tool_category, "other", + "{} has no bounded category", + spec.name + ); + } + } +} diff --git a/src/tool_runtime/tests/edit_tool_telemetry.rs b/src/tool_runtime/tests/edit_tool_telemetry.rs index e6e8834e..6eb649e6 100644 --- a/src/tool_runtime/tests/edit_tool_telemetry.rs +++ b/src/tool_runtime/tests/edit_tool_telemetry.rs @@ -108,6 +108,51 @@ async fn dispatch_records_edit_tool_usage_without_sensitive_args() { } } +#[tokio::test] +async fn kernel_generic_telemetry_and_edit_enrichment_each_emit_once() { + clear_test_edit_tool_usage(); + let runtime = test_runtime(); + let outcome = runtime + .call_tool_with_context( + super::super::kernel::ToolCallRequest { + tool_name: "write_project_file".to_string(), + arguments: json!({ + "project": "agent:oe:missing", + "path": "src/private.rs", + "content": "PRIVATE edit body", + "overwrite": true + }), + }, + super::super::kernel::ToolCallContext { + transport: super::super::kernel::ToolTransport::Api, + session_id: None, + auth: None, + window: None, + record_oauth_scope_denials: true, + host_file_import_trust: Default::default(), + }, + ) + .await; + let result = outcome.result.as_ref().expect("tool result"); + let generic = outcome + .model_ergonomics + .as_ref() + .expect("one generic model-visible completion") + .record_for_tool_result(result) + .expect("generic record"); + assert_eq!(generic.tool_name, "write_project_file"); + assert_eq!(generic.tool_category, "edit"); + assert_eq!(generic.success, result.success); + + let edit_events = take_test_edit_tool_usage(); + assert_eq!( + edit_events.len(), + 1, + "edit-specific enrichment must remain one event" + ); + assert_eq!(edit_events[0].tool_name, "write_project_file"); +} + #[tokio::test] async fn edit_tool_usage_does_not_change_session_ledger_shape() { clear_test_edit_tool_usage();