diff --git a/packages/pam/handlers/rdp/bridge_cgo_shared.go b/packages/pam/handlers/rdp/bridge_cgo_shared.go index c454c833..87408fbd 100644 --- a/packages/pam/handlers/rdp/bridge_cgo_shared.go +++ b/packages/pam/handlers/rdp/bridge_cgo_shared.go @@ -17,6 +17,8 @@ import ( "net" "time" "unsafe" + + "github.com/rs/zerolog/log" ) func (p *RDPProxy) HandleConnection(ctx context.Context, clientConn net.Conn) error { @@ -83,6 +85,11 @@ func (p *RDPProxy) handleConnectionWith(ctx context.Context, clientConn net.Conn case err := <-waitErr: if err != nil && !errors.Is(err, ErrInvalidHandle) { cancelDrain() + log.Error(). + Err(err). + Str("sessionId", p.config.SessionID). + Str("target", fmt.Sprintf("%s:%d", p.config.TargetHost, p.config.TargetPort)). + Msg("RDP bridge session failed") return fmt.Errorf("rdp proxy: session: %w", err) } return nil @@ -103,12 +110,31 @@ func (b *Bridge) Wait() error { case C.RDP_BRIDGE_INVALID_HANDLE: return ErrInvalidHandle case C.RDP_BRIDGE_SESSION_ERROR, C.RDP_BRIDGE_THREAD_PANIC: + if msg := b.lastError(); msg != "" { + return fmt.Errorf("%w: %s", ErrSessionFailed, msg) + } return ErrSessionFailed default: return fmt.Errorf("rdp bridge: wait returned unexpected status %d", int32(rc)) } } +// lastError returns the Rust-side failure detail recorded by Wait, or "". +func (b *Bridge) lastError() string { + const bufLen = 4096 + buf := (*C.char)(C.malloc(C.size_t(bufLen))) + if buf == nil { + return "" + } + defer C.free(unsafe.Pointer(buf)) + + n := C.rdp_bridge_last_error(C.uint64_t(b.handle), buf, C.size_t(bufLen)) + if n <= 0 { + return "" + } + return C.GoStringN(buf, C.int(n)) +} + // Cancel is idempotent and safe from any goroutine. func (b *Bridge) Cancel() error { rc := C.rdp_bridge_cancel(C.uint64_t(b.handle)) diff --git a/packages/pam/handlers/rdp/native/Cargo.lock b/packages/pam/handlers/rdp/native/Cargo.lock index edfc4a04..f7f69d6a 100644 --- a/packages/pam/handlers/rdp/native/Cargo.lock +++ b/packages/pam/handlers/rdp/native/Cargo.lock @@ -1322,6 +1322,7 @@ dependencies = [ "tokio-rustls", "tokio-util", "tracing", + "tracing-subscriber", "x509-cert", ] @@ -1550,6 +1551,12 @@ dependencies = [ "cpufeatures", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "leb128fmt" version = "0.1.0" @@ -2627,6 +2634,15 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -2874,6 +2890,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "time" version = "0.3.47" @@ -3080,6 +3105,17 @@ dependencies = [ "once_cell", ] +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "sharded-slab", + "thread_local", + "tracing-core", +] + [[package]] name = "try-lock" version = "0.2.5" diff --git a/packages/pam/handlers/rdp/native/Cargo.toml b/packages/pam/handlers/rdp/native/Cargo.toml index 52ef126c..81e6a7d6 100644 --- a/packages/pam/handlers/rdp/native/Cargo.toml +++ b/packages/pam/handlers/rdp/native/Cargo.toml @@ -30,6 +30,7 @@ rcgen = "0.13" anyhow = "1" tracing = "0.1" +tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "registry"] } # Bundle zlib into the .a so cross-compile linkers don't need system -lz # per target arch. Pulled in transitively via flate2 (winscard -> sspi). diff --git a/packages/pam/handlers/rdp/native/include/rdp_bridge.h b/packages/pam/handlers/rdp/native/include/rdp_bridge.h index e325818a..cadf99c4 100644 --- a/packages/pam/handlers/rdp/native/include/rdp_bridge.h +++ b/packages/pam/handlers/rdp/native/include/rdp_bridge.h @@ -4,6 +4,7 @@ #ifndef INFISICAL_RDP_BRIDGE_H #define INFISICAL_RDP_BRIDGE_H +#include #include #ifdef __cplusplus @@ -50,6 +51,10 @@ int32_t rdp_bridge_wait(uint64_t handle); int32_t rdp_bridge_cancel(uint64_t handle); int32_t rdp_bridge_free(uint64_t handle); +/* Writes the last session error into `buf` NUL-terminated and returns its + * length excluding the NUL. 0 means none. Truncates on a UTF-8 boundary. */ +int32_t rdp_bridge_last_error(uint64_t handle, char *buf, size_t buf_len); + /* Poll return codes (distinct number space from the bridge status codes * above; consumed by rdp_bridge_poll_event only). */ #define RDP_POLL_OK 0 diff --git a/packages/pam/handlers/rdp/native/src/bridge.rs b/packages/pam/handlers/rdp/native/src/bridge.rs index f9dde70e..b7610783 100644 --- a/packages/pam/handlers/rdp/native/src/bridge.rs +++ b/packages/pam/handlers/rdp/native/src/bridge.rs @@ -4,7 +4,7 @@ use std::borrow::Cow; use std::sync::atomic::{AtomicU64, Ordering}; -use std::sync::Arc; +use std::sync::{Arc, OnceLock}; use std::time::{Duration, Instant}; use anyhow::{Context, Result}; @@ -80,7 +80,16 @@ async fn run_mitm_native_inner( // 0.23 needs an explicit provider when more than one is compiled in. let _ = rustls::crypto::ring::default_provider().install_default(); + info!( + target_host = %target.host, + target_port = target.port, + has_domain = target.domain.is_some(), + "bridge: starting native MITM session" + ); + let acceptor_username = target.username.clone(); + // Don't split these across runtimes: the streams they return are bound to + // the runtime that created them. let (acceptor_output, connector_output) = tokio::try_join!( run_acceptor_half(client_tcp, acceptor_username), run_connector_half(target), @@ -582,11 +591,7 @@ async fn run_acceptor_half( client_tcp: TcpStream, username: String, ) -> Result<(ErasedStream, bytes::BytesMut)> { - let (acceptor_public_key, _cert_der, certified_key) = - generate_acceptor_cert().context("generate acceptor cert")?; - let server_tls = - build_acceptor_tls_config(certified_key).context("build acceptor TLS config")?; - let server_tls = Arc::new(server_tls); + let (acceptor_public_key, server_tls) = acceptor_tls_material()?; let acceptor_framed = ironrdp_tokio::TokioFramed::new(client_tcp); let expected_creds = AcceptorCredentials { @@ -626,7 +631,8 @@ async fn run_acceptor_half( }; if acceptor.should_perform_credssp() { - ironrdp_acceptor::accept_credssp( + let credssp_start = Instant::now(); + let result = ironrdp_acceptor::accept_credssp( &mut acceptor_framed, &mut acceptor, &mut ReqwestNetworkClient::new(), @@ -634,8 +640,13 @@ async fn run_acceptor_half( acceptor_public_key, None, ) - .await - .context("acceptor: CredSSP")?; + .await; + let elapsed_ms = credssp_start.elapsed().as_millis(); + match &result { + Ok(_) => info!(elapsed_ms, "acceptor: CredSSP exchange finished"), + Err(e) => warn!(elapsed_ms, error = ?e, "acceptor: CredSSP failed"), + } + result.context("acceptor: CredSSP")?; } info!("acceptor: CredSSP complete"); @@ -789,11 +800,16 @@ where .context("CredsspSequence::init")?; let mut buf = WriteBuf::new(); + let mut round = 0usize; loop { + round += 1; let client_state: ClientState = { let mut generator = sequence.process_ts_request(ts_request); + // sspi does KDC discovery inline here and blocks the runtime thread. + let mut step_start = Instant::now(); let mut state = generator.start(); + log_sspi_step(round, "start", step_start.elapsed()); loop { match state { GeneratorState::Suspended(request) => { @@ -801,7 +817,9 @@ where .send(&request) .await .context("CredSSP network request")?; + step_start = Instant::now(); state = generator.resume(Ok(response)); + log_sspi_step(round, "resume", step_start.elapsed()); } GeneratorState::Completed(result) => { break result.map_err(|e| anyhow::anyhow!("CredSSP process: {e:?}"))?; @@ -845,6 +863,42 @@ where Ok(()) } +/// Past this, an sspi step is blocking the runtime thread, not just being slow. +const SSPI_STEP_STALL_WARN: Duration = Duration::from_millis(250); + +fn log_sspi_step(round: usize, phase: &'static str, elapsed: Duration) { + if elapsed >= SSPI_STEP_STALL_WARN { + warn!( + round, + phase, + elapsed_ms = elapsed.as_millis(), + "connector: sspi step blocked the runtime thread" + ); + } +} + +type AcceptorTls = (Vec, Arc); + +static ACCEPTOR_TLS: OnceLock = OnceLock::new(); + +/// Once per process, not per session: mstsc reconnects after the certificate +/// dialog and rejects a cert that differs from the one the user approved. +fn acceptor_tls_material() -> Result { + if let Some(existing) = ACCEPTOR_TLS.get() { + return Ok(existing.clone()); + } + let (public_key, _cert_der, certified_key) = + generate_acceptor_cert().context("generate acceptor cert")?; + let config = + Arc::new(build_acceptor_tls_config(certified_key).context("build acceptor TLS config")?); + // Racing sessions both generate one; the first to land wins. + let _ = ACCEPTOR_TLS.set((public_key, config)); + Ok(ACCEPTOR_TLS + .get() + .expect("acceptor TLS material set") + .clone()) +} + pub(crate) fn generate_acceptor_cert() -> Result<(Vec, Vec, rcgen::CertifiedKey)> { use x509_cert::der::Decode; diff --git a/packages/pam/handlers/rdp/native/src/ffi.rs b/packages/pam/handlers/rdp/native/src/ffi.rs index 0ff061ea..2b5216b0 100644 --- a/packages/pam/handlers/rdp/native/src/ffi.rs +++ b/packages/pam/handlers/rdp/native/src/ffi.rs @@ -165,6 +165,8 @@ struct BridgeEntry { // Set once the events channel has reported closed; subsequent polls // short-circuit to RDP_POLL_ENDED. events_ended: Mutex, + // Set by wait() on failure; Go reads it back via rdp_bridge_last_error. + last_error: Mutex>, } static HANDLES: LazyLock>> = @@ -212,6 +214,7 @@ fn spawn_session( domain: Option, flow: SessionFlow, ) -> anyhow::Result { + crate::logging::init(); client_tcp.set_nonblocking(true)?; let cancel = CancellationToken::new(); let cancel_for_thread = cancel.clone(); @@ -256,6 +259,7 @@ fn spawn_session( join: Mutex::new(Some(join)), events_rx: Mutex::new(Some(events_rx)), events_ended: Mutex::new(false), + last_error: Mutex::new(None), })) } @@ -399,10 +403,13 @@ pub extern "C" fn rdp_bridge_wait(handle: u64) -> i32 { } Ok(Err(e)) => { error!(handle, error = ?e, "rdp_bridge_wait: session failed"); + // {e:#} renders the full context chain. + set_last_error(handle, format!("{e:#}")); RDP_BRIDGE_SESSION_ERROR } Err(_) => { error!(handle, "rdp_bridge_wait: session thread panicked"); + set_last_error(handle, "session thread panicked".to_owned()); RDP_BRIDGE_THREAD_PANIC } }, @@ -410,6 +417,51 @@ pub extern "C" fn rdp_bridge_wait(handle: u64) -> i32 { } } +fn set_last_error(handle: u64, message: String) { + let handles = HANDLES.lock().expect("HANDLES poisoned"); + if let Some(entry) = handles.get(&handle) { + *entry.last_error.lock().expect("last_error poisoned") = Some(message); + } +} + +/// Writes the last session error into `buf` as a NUL-terminated string and +/// returns its length excluding the NUL. 0 means no error. Truncates on a +/// UTF-8 boundary. +/// +/// # Safety +/// +/// `buf` must be writable for `buf_len` bytes. +#[no_mangle] +pub unsafe extern "C" fn rdp_bridge_last_error( + handle: u64, + buf: *mut c_char, + buf_len: usize, +) -> i32 { + if buf.is_null() || buf_len == 0 { + return RDP_BRIDGE_BAD_ARG; + } + let handles = HANDLES.lock().expect("HANDLES poisoned"); + let Some(entry) = handles.get(&handle) else { + return RDP_BRIDGE_INVALID_HANDLE; + }; + let guard = entry.last_error.lock().expect("last_error poisoned"); + let Some(message) = guard.as_deref() else { + unsafe { *buf = 0 }; + return 0; + }; + + let mut end = message.len().min(buf_len - 1); + while end > 0 && !message.is_char_boundary(end) { + end -= 1; + } + let bytes = &message.as_bytes()[..end]; + unsafe { + std::ptr::copy_nonoverlapping(bytes.as_ptr(), buf.cast::(), end); + *buf.add(end) = 0; + } + i32::try_from(end).unwrap_or(i32::MAX) +} + #[no_mangle] pub extern "C" fn rdp_bridge_cancel(handle: u64) -> i32 { let handles = HANDLES.lock().expect("HANDLES poisoned"); diff --git a/packages/pam/handlers/rdp/native/src/lib.rs b/packages/pam/handlers/rdp/native/src/lib.rs index 13bf0bfe..1958bba5 100644 --- a/packages/pam/handlers/rdp/native/src/lib.rs +++ b/packages/pam/handlers/rdp/native/src/lib.rs @@ -7,4 +7,5 @@ pub mod cap_filter; pub mod config; pub mod events; pub mod ffi; +pub mod logging; pub mod rdcleanpath; diff --git a/packages/pam/handlers/rdp/native/src/logging.rs b/packages/pam/handlers/rdp/native/src/logging.rs new file mode 100644 index 00000000..7542a2fa --- /dev/null +++ b/packages/pam/handlers/rdp/native/src/logging.rs @@ -0,0 +1,62 @@ +//! Tracing subscriber for the bridge. Linked into the Go CLI as a staticlib, +//! so nothing else installs one and without this every event is discarded. + +use std::sync::Once; + +use tracing_subscriber::filter::{LevelFilter, Targets}; +use tracing_subscriber::layer::SubscriberExt as _; +use tracing_subscriber::util::SubscriberInitExt as _; + +static INIT: Once = Once::new(); + +/// Idempotent; safe to call from every FFI entry point. +pub fn init() { + INIT.call_once(|| { + let filter = std::env::var("RUST_LOG") + .ok() + .filter(|v| !v.trim().is_empty()) + .unwrap_or_else(default_directive); + + // Targets, not EnvFilter: same syntax without the regex dependency. + let mut targets = filter.parse::().unwrap_or_else(|_| { + Targets::new().with_target("infisical_rdp_bridge", LevelFilter::INFO) + }); + // A bare `RUST_LOG=debug` sets the default for every target, sspi + // included, so cap it unless the caller named sspi themselves. + if !targets.iter().any(|(target, _)| target.starts_with("sspi")) { + targets = targets.with_target("sspi", LevelFilter::INFO); + } + + let fmt_layer = tracing_subscriber::fmt::layer() + .with_writer(std::io::stderr) + .with_ansi(false) + .with_target(true) + .with_thread_names(true); + + // try_init, not init: a host-installed subscriber should win, not panic. + let _ = tracing_subscriber::registry() + .with(fmt_layer) + .with(targets) + .try_init(); + }); +} + +/// Mirrors the Go CLI's LOG_LEVEL so one knob covers both sides. +/// +/// sspi stays at `info` whatever LOG_LEVEL says: it logs the injected password +/// in cleartext at debug and below, so enabling it must be deliberate. +fn default_directive() -> String { + let level = std::env::var("LOG_LEVEL") + .unwrap_or_default() + .trim() + .to_ascii_lowercase(); + let level = match level.as_str() { + "trace" => "trace", + "debug" => "debug", + "warn" | "warning" => "warn", + "error" => "error", + "fatal" => "error", + _ => "info", + }; + format!("infisical_rdp_bridge={level},ironrdp={level},sspi=info") +}