diff --git a/README.md b/README.md index 3862808..12bfe30 100644 --- a/README.md +++ b/README.md @@ -444,6 +444,13 @@ not reachable. It checks config parsing, local daemon socket health, validity, and representative peer grants when local metadata is available. Use `--json` for scripts. +Daemon logs are emitted through `tracing` and are controlled with standard +`RUST_LOG` filters. Local control requests log structured fields for command, +peer node, resource, capability, stream, and stable error code where those +fields apply. Logs intentionally classify requests instead of formatting full +payloads, so bearer tokens, private key paths, packet/message payloads, and +document JSON are not logged by the request tracer. + See `docs/automation-examples.md` for shell, Python JSON, and user-service automation examples. See `docs/conflict-semantics.md` for the current per-resource conflict behavior diff --git a/crates/geth-node/src/lib.rs b/crates/geth-node/src/lib.rs index 0b8eb39..c061983 100644 --- a/crates/geth-node/src/lib.rs +++ b/crates/geth-node/src/lib.rs @@ -682,7 +682,16 @@ pub async fn handle_request_async( node: &LocalNode, request: ControlRequest, ) -> Result { - match request { + let trace = control_request_trace_fields(&request); + tracing::info!( + command = trace.command, + peer_node = trace.peer_node.as_deref().unwrap_or(""), + resource = trace.resource.as_deref().unwrap_or(""), + capability = trace.capability.as_deref().unwrap_or(""), + stream = trace.stream.as_deref().unwrap_or(""), + "control request started" + ); + let result = match request { ControlRequest::PeerCardExport { out } => export_peer_card(node, out, true).await, ControlRequest::PeerPing { node: peer_node } => peer_ping(node, &peer_node).await, ControlRequest::PeerAuthCheck { @@ -824,6 +833,330 @@ pub async fn handle_request_async( } Ok(response) } + }; + match &result { + Ok(_) => tracing::info!( + command = trace.command, + peer_node = trace.peer_node.as_deref().unwrap_or(""), + resource = trace.resource.as_deref().unwrap_or(""), + capability = trace.capability.as_deref().unwrap_or(""), + stream = trace.stream.as_deref().unwrap_or(""), + "control request completed" + ), + Err(error) => tracing::warn!( + command = trace.command, + peer_node = trace.peer_node.as_deref().unwrap_or(""), + resource = trace.resource.as_deref().unwrap_or(""), + capability = trace.capability.as_deref().unwrap_or(""), + stream = trace.stream.as_deref().unwrap_or(""), + error_code = node_error_code(error), + %error, + "control request failed" + ), + } + result +} + +#[derive(Debug, PartialEq, Eq)] +struct ControlTraceFields { + command: &'static str, + peer_node: Option, + resource: Option, + capability: Option, + stream: Option, +} + +fn control_request_trace_fields(request: &ControlRequest) -> ControlTraceFields { + let mut trace = ControlTraceFields { + command: control_request_command(request), + peer_node: None, + resource: None, + capability: None, + stream: None, + }; + match request { + ControlRequest::PeerPing { node } + | ControlRequest::KeychainSync { node } + | ControlRequest::AuthSync { node } => { + trace.peer_node = Some(node.clone()); + } + ControlRequest::PeerAuthCheck { + node, + resource, + capability, + } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(resource.clone()); + trace.capability = Some(capability.clone()); + } + ControlRequest::CasRootSync { node, name, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:cas-tree:{name}")); + trace.capability = Some("cas.fetch".to_owned()); + trace.stream = Some(format!("cas-tree:{name}")); + } + ControlRequest::SyncNow { node } => { + trace.peer_node = node.clone(); + trace.stream = Some("all".to_owned()); + } + ControlRequest::NodeGrant { + node, + resource, + capability, + .. + } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(resource.clone()); + trace.capability = Some(capability.clone()); + } + ControlRequest::NodeRevokeGrant { resource, .. } => { + trace.resource = Some(resource.clone()); + } + ControlRequest::AuthExplain { + resource, + capability, + .. + } + | ControlRequest::AuthGrant { + resource, + capability, + .. + } => { + trace.resource = Some(resource.clone()); + trace.capability = Some(capability.clone()); + } + ControlRequest::AuthRevoke { resource, .. } + | ControlRequest::SecretCreate { resource } + | ControlRequest::SecretRotate { resource } + | ControlRequest::SecretBearerCreate { resource, .. } + | ControlRequest::SecretBearerChallenge { resource, .. } + | ControlRequest::SecretBearerProve { resource, .. } + | ControlRequest::SecretBearerVerify { resource, .. } + | ControlRequest::SecretBearerRevoke { resource, .. } + | ControlRequest::CasAddPrivate { resource, .. } + | ControlRequest::CasGetPrivate { resource, .. } => { + trace.resource = Some(resource.clone()); + } + ControlRequest::CasFetch { node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some("resource:cas:local".to_owned()); + trace.capability = Some("cas.fetch".to_owned()); + } + ControlRequest::SshCertSync { node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some("resource:ssh:certs".to_owned()); + trace.capability = Some("ssh_cert.sync".to_owned()); + trace.stream = Some("ssh-certs".to_owned()); + } + ControlRequest::SshRevocationSync { node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some("resource:ssh:revocations".to_owned()); + trace.capability = Some("ssh_revocation.sync".to_owned()); + trace.stream = Some("ssh-revocations".to_owned()); + } + ControlRequest::KvSet { name, key, .. } => { + trace.resource = Some(format!("resource:kv:{name}")); + trace.capability = Some(format!("kv.write_key:{key}")); + trace.stream = Some(format!("kv:{name}")); + } + ControlRequest::KvSync { node, name, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:kv:{name}")); + trace.capability = Some("kv.read".to_owned()); + trace.stream = Some(format!("kv:{name}")); + } + ControlRequest::KvCreate { name } | ControlRequest::KvGet { name, .. } => { + trace.resource = Some(format!("resource:kv:{name}")); + trace.stream = Some(format!("kv:{name}")); + } + ControlRequest::DbSync { node, name, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:db:{name}")); + trace.capability = Some("db.sync".to_owned()); + trace.stream = Some(format!("db:{name}")); + } + ControlRequest::DbAdd { name, .. } + | ControlRequest::DbStatus { name } + | ControlRequest::DbChanges { name, .. } => { + trace.resource = Some(format!("resource:db:{name}")); + trace.stream = Some(format!("db:{name}")); + } + ControlRequest::DocumentSync { node, name, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:document:{name}")); + trace.capability = Some("document.read".to_owned()); + trace.stream = Some(format!("document:{name}")); + } + ControlRequest::DocumentCreate { name } + | ControlRequest::DocumentStatus { name } + | ControlRequest::DocumentSet { name, .. } + | ControlRequest::DocumentGet { name } => { + trace.resource = Some(format!("resource:document:{name}")); + trace.stream = Some(format!("document:{name}")); + } + ControlRequest::PubsubPub { topic, node, .. } => { + trace.peer_node = node.clone(); + trace.resource = Some(format!("resource:pubsub:{topic}")); + trace.capability = Some("pubsub.publish".to_owned()); + trace.stream = Some(format!("pubsub:{topic}")); + } + ControlRequest::PubsubSub { topic, node, .. } => { + trace.peer_node = node.clone(); + trace.resource = Some(format!("resource:pubsub:{topic}")); + trace.capability = Some("pubsub.subscribe".to_owned()); + trace.stream = Some(format!("pubsub:{topic}")); + } + ControlRequest::PipeListen { name, node, .. } => { + trace.peer_node = node.clone(); + trace.resource = Some(format!("resource:pipe:{name}")); + trace.capability = Some("pipe.listen".to_owned()); + trace.stream = Some(format!("pipe:{name}")); + } + ControlRequest::PipeConnect { target, node, .. } + | ControlRequest::PipeSend { target, node, .. } => { + trace.peer_node = node.clone(); + trace.resource = Some(format!("resource:pipe:{target}")); + trace.capability = Some("pipe.connect".to_owned()); + trace.stream = Some(format!("pipe:{target}")); + } + ControlRequest::PipeTcpForward { + node, target_addr, .. + } + | ControlRequest::PipeTcpStream { + node, target_addr, .. + } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:pipe-tcp:{target_addr}")); + trace.capability = Some("pipe.forward".to_owned()); + trace.stream = Some("pipe-tcp".to_owned()); + } + ControlRequest::PipeUnixForward { + node, target_path, .. + } + | ControlRequest::PipeUnixStream { + node, target_path, .. + } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:pipe-unix:{}", target_path.display())); + trace.capability = Some("pipe.forward".to_owned()); + trace.stream = Some("pipe-unix".to_owned()); + } + ControlRequest::SshProxyConnect { node, .. } + | ControlRequest::SshProxyStream { node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some("resource:ssh-proxy:local".to_owned()); + trace.capability = Some("ssh_proxy.connect".to_owned()); + trace.stream = Some("ssh-proxy".to_owned()); + } + ControlRequest::SshAdminShell { node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some("resource:ssh-proxy:local".to_owned()); + trace.capability = Some("ssh_proxy.admin_shell".to_owned()); + trace.stream = Some("ssh-admin-shell".to_owned()); + } + ControlRequest::OverlaySend { name, node, .. } => { + trace.peer_node = Some(node.clone()); + trace.resource = Some(format!("resource:overlay:{name}")); + trace.capability = Some("overlay.route".to_owned()); + trace.stream = Some(format!("overlay:{name}")); + } + ControlRequest::OverlayUp { name, .. } => { + trace.resource = Some(format!("resource:overlay:{name}")); + trace.capability = Some("overlay.route".to_owned()); + trace.stream = Some(format!("overlay:{name}")); + } + _ => {} + } + trace +} + +fn control_request_command(request: &ControlRequest) -> &'static str { + match request { + ControlRequest::Status => "status", + ControlRequest::NodeId => "node-id", + ControlRequest::PeerCardExport { .. } => "peer.export", + ControlRequest::PeerCardImport { .. } => "peer.import", + ControlRequest::PeerCardList => "peer.list", + ControlRequest::PeerPing { .. } => "peer.ping", + ControlRequest::PeerAuthCheck { .. } => "peer.auth-check", + ControlRequest::ResourceList => "resource.list", + ControlRequest::ResourceCreate { .. } => "resource.create", + ControlRequest::KeychainSync { .. } => "keychain.sync", + ControlRequest::AuthSync { .. } => "auth.sync", + ControlRequest::SyncStatus => "sync.status", + ControlRequest::SyncNow { .. } => "sync.now", + ControlRequest::AuthExplain { .. } => "auth.explain", + ControlRequest::AuthGrant { .. } => "auth.grant", + ControlRequest::AuthRevoke { .. } => "auth.revoke", + ControlRequest::CasFetch { .. } => "cas.fetch", + ControlRequest::CasRootSync { .. } => "cas.root.sync", + ControlRequest::CasAddPrivate { .. } => "cas.add-private", + ControlRequest::CasGetPrivate { .. } => "cas.get-private", + ControlRequest::SshCertSync { .. } => "ssh.cert.sync", + ControlRequest::SshRevocationSync { .. } => "ssh.revocation.sync", + ControlRequest::KvCreate { .. } => "kv.create", + ControlRequest::KvSet { .. } => "kv.set", + ControlRequest::KvGet { .. } => "kv.get", + ControlRequest::KvSync { .. } => "kv.sync", + ControlRequest::DbAdd { .. } => "db.add", + ControlRequest::DbStatus { .. } => "db.status", + ControlRequest::DbChanges { .. } => "db.changes", + ControlRequest::DbSync { .. } => "db.sync", + ControlRequest::DocumentCreate { .. } => "document.create", + ControlRequest::DocumentStatus { .. } => "document.status", + ControlRequest::DocumentSet { .. } => "document.set", + ControlRequest::DocumentGet { .. } => "document.get", + ControlRequest::DocumentSync { .. } => "document.sync", + ControlRequest::PubsubPub { .. } => "pubsub.pub", + ControlRequest::PubsubSub { .. } => "pubsub.sub", + ControlRequest::PipeListen { .. } => "pipe.listen", + ControlRequest::PipeConnect { .. } => "pipe.connect", + ControlRequest::PipeSend { .. } => "pipe.send", + ControlRequest::PipeRecv { .. } => "pipe.recv", + ControlRequest::PipeTcpForward { .. } => "pipe.forward-tcp", + ControlRequest::PipeTcpStream { .. } => "pipe.tcp-stream", + ControlRequest::PipeUnixForward { .. } => "pipe.forward-unix", + ControlRequest::PipeUnixStream { .. } => "pipe.unix-stream", + ControlRequest::SshProxyConnect { .. } => "ssh.proxy", + ControlRequest::SshProxyStream { .. } => "ssh.proxy-stream", + ControlRequest::SshAdminShell { .. } => "ssh.admin-shell", + ControlRequest::OverlayStatus => "overlay.status", + ControlRequest::OverlayPlan { .. } => "overlay.plan", + ControlRequest::OverlayJoin { .. } => "overlay.join", + ControlRequest::OverlayLeave { .. } => "overlay.leave", + ControlRequest::OverlayInterfacePlan { .. } => "overlay.interface-plan", + ControlRequest::OverlayUp { .. } => "overlay.up", + ControlRequest::OverlayDown { .. } => "overlay.down", + ControlRequest::OverlayPeers { .. } => "overlay.peers", + ControlRequest::OverlaySend { .. } => "overlay.send", + ControlRequest::OverlayRecv { .. } => "overlay.recv", + ControlRequest::SecretStatus => "secret.status", + ControlRequest::SecretCreate { .. } => "secret.create", + ControlRequest::SecretRotate { .. } => "secret.rotate", + ControlRequest::SecretBearerCreate { .. } => "secret.bearer.create", + ControlRequest::SecretBearerList => "secret.bearer.list", + ControlRequest::SecretBearerChallenge { .. } => "secret.bearer.challenge", + ControlRequest::SecretBearerProve { .. } => "secret.bearer.prove", + ControlRequest::SecretBearerVerify { .. } => "secret.bearer.verify", + ControlRequest::SecretBearerRevoke { .. } => "secret.bearer.revoke", + ControlRequest::ModuleStub { .. } => "module.stub", + _ => "control.request", + } +} + +fn node_error_code(error: &NodeError) -> &'static str { + match error { + NodeError::Unauthorized(_) => "unauthorized", + NodeError::PeerNotFound(_) => "peer_not_found", + NodeError::IrohEndpointUnavailable => "iroh_endpoint_unavailable", + NodeError::KvNotFound(_) => "kv_not_found", + NodeError::DbNotFound(_) => "db_not_found", + NodeError::DocumentNotFound(_) => "document_not_found", + NodeError::Cas(_) => "cas_error", + NodeError::Store(_) => "store_error", + NodeError::Config(_) => "config_error", + NodeError::Codec(_) => "codec_error", + _ => "node_error", } } @@ -837,8 +1170,37 @@ async fn handle_stream(node: LocalNode, stream: UnixStream) -> Result<(), NodeEr bearer_secret, } = request { + tracing::info!( + command = "ssh.proxy-stream", + peer_node = %peer_node, + resource = "resource:ssh-proxy:local", + capability = "ssh_proxy.connect", + stream = "ssh-proxy", + "streaming control request started" + ); let stream = reader.into_inner(); - return handle_local_ssh_proxy_stream(node, &peer_node, bearer_secret, stream).await; + let result = handle_local_ssh_proxy_stream(node, &peer_node, bearer_secret, stream).await; + match &result { + Ok(_) => tracing::info!( + command = "ssh.proxy-stream", + peer_node = %peer_node, + resource = "resource:ssh-proxy:local", + capability = "ssh_proxy.connect", + stream = "ssh-proxy", + "streaming control request completed" + ), + Err(error) => tracing::warn!( + command = "ssh.proxy-stream", + peer_node = %peer_node, + resource = "resource:ssh-proxy:local", + capability = "ssh_proxy.connect", + stream = "ssh-proxy", + error_code = node_error_code(error), + %error, + "streaming control request failed" + ), + } + return result; } if let ControlRequest::PipeTcpStream { node: peer_node, @@ -846,9 +1208,40 @@ async fn handle_stream(node: LocalNode, stream: UnixStream) -> Result<(), NodeEr bearer_secret, } = request { + let resource = format!("resource:pipe-tcp:{target_addr}"); + tracing::info!( + command = "pipe.tcp-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-tcp", + "streaming control request started" + ); let stream = reader.into_inner(); - return handle_local_pipe_tcp_stream(node, &peer_node, target_addr, bearer_secret, stream) - .await; + let result = + handle_local_pipe_tcp_stream(node, &peer_node, target_addr, bearer_secret, stream) + .await; + match &result { + Ok(_) => tracing::info!( + command = "pipe.tcp-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-tcp", + "streaming control request completed" + ), + Err(error) => tracing::warn!( + command = "pipe.tcp-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-tcp", + error_code = node_error_code(error), + %error, + "streaming control request failed" + ), + } + return result; } if let ControlRequest::PipeUnixStream { node: peer_node, @@ -856,9 +1249,40 @@ async fn handle_stream(node: LocalNode, stream: UnixStream) -> Result<(), NodeEr bearer_secret, } = request { + let resource = format!("resource:pipe-unix:{}", target_path.display()); + tracing::info!( + command = "pipe.unix-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-unix", + "streaming control request started" + ); let stream = reader.into_inner(); - return handle_local_pipe_unix_stream(node, &peer_node, target_path, bearer_secret, stream) - .await; + let result = + handle_local_pipe_unix_stream(node, &peer_node, target_path, bearer_secret, stream) + .await; + match &result { + Ok(_) => tracing::info!( + command = "pipe.unix-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-unix", + "streaming control request completed" + ), + Err(error) => tracing::warn!( + command = "pipe.unix-stream", + peer_node = %peer_node, + resource = %resource, + capability = "pipe.forward", + stream = "pipe-unix", + error_code = node_error_code(error), + %error, + "streaming control request failed" + ), + } + return result; } let response = match handle_request_async(&node, request).await { Ok(response) => response, @@ -11451,6 +11875,37 @@ mod tests { assert_eq!(merged["remote"], true); } + #[test] + fn control_trace_fields_exclude_bearer_secrets() { + let trace = control_request_trace_fields(&ControlRequest::KvSync { + node: "node:peer".to_owned(), + name: "prefs".to_owned(), + bearer_secret: Some("private-token-value".to_owned()), + }); + assert_eq!(trace.command, "kv.sync"); + assert_eq!(trace.peer_node.as_deref(), Some("node:peer")); + assert_eq!(trace.resource.as_deref(), Some("resource:kv:prefs")); + assert_eq!(trace.capability.as_deref(), Some("kv.read")); + assert_eq!(trace.stream.as_deref(), Some("kv:prefs")); + assert!(!format!("{trace:?}").contains("private-token-value")); + } + + #[test] + fn node_error_codes_are_stable_for_common_tracing_failures() { + assert_eq!( + node_error_code(&NodeError::Unauthorized("missing grant".to_owned())), + "unauthorized" + ); + assert_eq!( + node_error_code(&NodeError::PeerNotFound("node:missing".to_owned())), + "peer_not_found" + ); + assert_eq!( + node_error_code(&NodeError::IrohEndpointUnavailable), + "iroh_endpoint_unavailable" + ); + } + #[derive(Debug, PartialEq, Eq)] enum RemoteGuardKind { Capability, diff --git a/docs/architecture.md b/docs/architecture.md index 8b230dc..e5ffbe0 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -158,6 +158,12 @@ daemon errors include a `next:` recovery line for missing peer cards, missing grants, missing resources, unavailable endpoints, and missing DB/KV/document registrations. +Daemon logs use structured `tracing` fields for local control requests: +`command`, `peer_node`, `resource`, `capability`, `stream`, and stable +`error_code` where applicable. The request tracer classifies requests instead of +formatting full payloads, so bearer tokens, private key paths, packet/message +payloads, and document JSON are not logged by that layer. + Host-opening paths are intentionally narrow. TCP pipe forwarding accepts only explicit loopback socket addresses on both the local listener and remote target; Unix pipe forwarding requires absolute paths without parent-directory diff --git a/docs/production-readiness-roadmap.md b/docs/production-readiness-roadmap.md index c868f8a..b192cea 100644 --- a/docs/production-readiness-roadmap.md +++ b/docs/production-readiness-roadmap.md @@ -271,11 +271,11 @@ Goal: make `geth` ergonomic and stable as a base layer for custom automation. Goal: make production failures diagnosable from the CLI and logs. -- `[ ]` Improve structured tracing. +- `[x]` Improve structured tracing. Acceptance criteria: - - `[ ]` Logs include fields for command, peer node, resource, capability, + - `[x]` Logs include fields for command, peer node, resource, capability, stream, cursor, and stable error code where applicable. - - `[ ]` Sensitive bearer tokens and private material are not logged. + - `[x]` Sensitive bearer tokens and private material are not logged. - `[x]` Expand health status. Acceptance criteria: