From 2046d0ba860865b4be88cc19d106f6061a974540 Mon Sep 17 00:00:00 2001 From: bernie-g Date: Wed, 26 Aug 2026 15:25:49 -0400 Subject: [PATCH 1/3] fix(pam-rdp): stable acceptor certificate The acceptor generated a fresh self-signed certificate per session. mstsc opens a second connection after the user accepts the certificate dialog and compares the certificate it receives against the one just approved, so a per-session cert never matched and it aborted the second handshake with "an unexpected server authentication certificate was received from the remote computer". Generate it once per process instead. Also adds the logging that made this diagnosable: the crate depended on tracing but nothing installed a subscriber, so every event from the bridge and IronRDP was discarded and failures surfaced as a bare status code. The Rust error string now reaches Go and zerolog instead of a static sentinel. sspi is pinned to info in the default filter regardless of LOG_LEVEL; it logs serialized TSCredentials, which contain the injected password in cleartext, at debug and below. --- .../pam/handlers/rdp/bridge_cgo_shared.go | 28 +++++++ packages/pam/handlers/rdp/native/Cargo.lock | 36 ++++++++ packages/pam/handlers/rdp/native/Cargo.toml | 1 + .../handlers/rdp/native/include/rdp_bridge.h | 7 ++ .../pam/handlers/rdp/native/src/bridge.rs | 83 +++++++++++++++++-- packages/pam/handlers/rdp/native/src/ffi.rs | 55 ++++++++++++ packages/pam/handlers/rdp/native/src/lib.rs | 1 + .../pam/handlers/rdp/native/src/logging.rs | 69 +++++++++++++++ 8 files changed, 271 insertions(+), 9 deletions(-) create mode 100644 packages/pam/handlers/rdp/native/src/logging.rs diff --git a/packages/pam/handlers/rdp/bridge_cgo_shared.go b/packages/pam/handlers/rdp/bridge_cgo_shared.go index c454c833..2b415259 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,33 @@ 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 "" if +// there is none. The status code alone can't distinguish a protocol +// negotiation failure from a target connect failure. +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..a02cb386 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,12 @@ int32_t rdp_bridge_wait(uint64_t handle); int32_t rdp_bridge_cancel(uint64_t handle); int32_t rdp_bridge_free(uint64_t handle); +/* Copies the last session error into `buf` as a NUL-terminated string and + * returns the length written, excluding the NUL. 0 means no error recorded. + * Only meaningful after rdp_bridge_wait returned SESSION_ERROR/THREAD_PANIC. + * Truncates on a UTF-8 boundary when `buf_len` is too small. */ +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..69cd6c17 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(); + // One task, one current-thread runtime. Don't move a half onto its own + // runtime: the stream it returns is bound to that runtime's IO driver. 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,15 @@ async fn run_acceptor_half( acceptor_public_key, None, ) - .await - .context("acceptor: CredSSP")?; + .await; + // Logged either way: how long the client waited before giving up is + // the whole question when a strict client disconnects mid-CredSSP. + 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 +802,20 @@ 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 runs KDC discovery inline here rather than yielding it as a + // network request. On a current-thread runtime its DNS helper + // blocks the whole runtime thread (sspi dns.rs execute_future), + // which would stall the acceptor half sharing this thread. Timing + // each step is how we tell that apart from a slow peer. + 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 +823,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 +869,47 @@ where Ok(()) } +/// A synchronous sspi step longer than this monopolizes the runtime thread +/// and starves the acceptor half, so it is worth a louder log line. +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(); + +/// One certificate for the whole process, not one per session. mstsc opens a +/// second connection after the user accepts the certificate dialog and compares +/// the certificate it receives against the one it just approved; a per-session +/// cert never matched, so it aborted the second handshake with "an unexpected +/// server authentication certificate was received from the remote computer". +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 may both generate one; whichever lands first wins so that + // every session presents the same certificate. + 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..711e6796 100644 --- a/packages/pam/handlers/rdp/native/src/ffi.rs +++ b/packages/pam/handlers/rdp/native/src/ffi.rs @@ -165,6 +165,9 @@ struct BridgeEntry { // Set once the events channel has reported closed; subsequent polls // short-circuit to RDP_POLL_ENDED. events_ended: Mutex, + // Populated by wait() on failure. The status code alone can't say why a + // session died, so Go reads the message back via rdp_bridge_last_error. + last_error: Mutex>, } static HANDLES: LazyLock>> = @@ -212,6 +215,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 +260,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 +404,14 @@ pub extern "C" fn rdp_bridge_wait(handle: u64) -> i32 { } Ok(Err(e)) => { error!(handle, error = ?e, "rdp_bridge_wait: session failed"); + // anyhow's alternate Display renders the full context chain, + // which is where the useful detail lives. + 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 +419,52 @@ 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); + } +} + +/// Copies the last session error into `buf` as a NUL-terminated string and +/// returns the byte length written, excluding the NUL. Returns 0 when there is +/// no error, and RDP_BRIDGE_BAD_ARG / RDP_BRIDGE_INVALID_HANDLE on misuse. +/// Truncates on a UTF-8 boundary if `buf_len` is too small. +/// +/// # 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..d71a8779 --- /dev/null +++ b/packages/pam/handlers/rdp/native/src/logging.rs @@ -0,0 +1,69 @@ +//! Tracing subscriber for the bridge. The crate is linked into the Go CLI as +//! a staticlib, so nothing else installs a subscriber; without this every +//! `tracing` event here and inside IronRDP is discarded before it is +//! formatted, which is why bridge failures used to surface as a bare status +//! code with no output. + +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 rather than EnvFilter: same `target=level,target=level` + // syntax, without pulling a regex engine in for span-field matching we + // never use. + let targets = filter.parse::().unwrap_or_else(|_| { + Targets::new().with_target("infisical_rdp_bridge", LevelFilter::INFO) + }); + + let fmt_layer = tracing_subscriber::fmt::layer() + .with_writer(std::io::stderr) + .with_ansi(false) + .with_target(true) + // Thread names make it obvious which half a line came from. + .with_thread_names(true); + + // try_init (not init) so a host-installed subscriber wins instead of + // aborting the process. + let _ = tracing_subscriber::registry() + .with(fmt_layer) + .with(targets) + .try_init(); + }); +} + +/// Mirrors the Go CLI's LOG_LEVEL so `LOG_LEVEL=debug infisical ...` turns on +/// bridge and IronRDP protocol tracing without a second knob. IronRDP logs +/// each decoded PDU at debug/trace, which is what makes strict-client +/// negotiation failures diagnosable. +/// +/// sspi is deliberately pinned to `info` regardless of LOG_LEVEL: it logs +/// serialized TSCredentials, which contain the injected PAM password in +/// cleartext, at debug and below. Enabling it has to be a deliberate +/// `RUST_LOG=sspi=trace`, never a side effect of raising the general log level. +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") +} From 3270a0477b2bd17eac540a61ed32c88327ee233c Mon Sep 17 00:00:00 2001 From: bernie-g Date: Wed, 26 Aug 2026 15:30:07 -0400 Subject: [PATCH 2/3] chore(pam-rdp): trim comments --- .../pam/handlers/rdp/bridge_cgo_shared.go | 4 +-- .../handlers/rdp/native/include/rdp_bridge.h | 6 ++--- .../pam/handlers/rdp/native/src/bridge.rs | 25 +++++------------- packages/pam/handlers/rdp/native/src/ffi.rs | 13 ++++------ .../pam/handlers/rdp/native/src/logging.rs | 26 +++++-------------- 5 files changed, 22 insertions(+), 52 deletions(-) diff --git a/packages/pam/handlers/rdp/bridge_cgo_shared.go b/packages/pam/handlers/rdp/bridge_cgo_shared.go index 2b415259..87408fbd 100644 --- a/packages/pam/handlers/rdp/bridge_cgo_shared.go +++ b/packages/pam/handlers/rdp/bridge_cgo_shared.go @@ -119,9 +119,7 @@ func (b *Bridge) Wait() error { } } -// lastError returns the Rust-side failure detail recorded by Wait, or "" if -// there is none. The status code alone can't distinguish a protocol -// negotiation failure from a target connect failure. +// 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))) diff --git a/packages/pam/handlers/rdp/native/include/rdp_bridge.h b/packages/pam/handlers/rdp/native/include/rdp_bridge.h index a02cb386..cadf99c4 100644 --- a/packages/pam/handlers/rdp/native/include/rdp_bridge.h +++ b/packages/pam/handlers/rdp/native/include/rdp_bridge.h @@ -51,10 +51,8 @@ int32_t rdp_bridge_wait(uint64_t handle); int32_t rdp_bridge_cancel(uint64_t handle); int32_t rdp_bridge_free(uint64_t handle); -/* Copies the last session error into `buf` as a NUL-terminated string and - * returns the length written, excluding the NUL. 0 means no error recorded. - * Only meaningful after rdp_bridge_wait returned SESSION_ERROR/THREAD_PANIC. - * Truncates on a UTF-8 boundary when `buf_len` is too small. */ +/* 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 diff --git a/packages/pam/handlers/rdp/native/src/bridge.rs b/packages/pam/handlers/rdp/native/src/bridge.rs index 69cd6c17..b7610783 100644 --- a/packages/pam/handlers/rdp/native/src/bridge.rs +++ b/packages/pam/handlers/rdp/native/src/bridge.rs @@ -88,8 +88,8 @@ async fn run_mitm_native_inner( ); let acceptor_username = target.username.clone(); - // One task, one current-thread runtime. Don't move a half onto its own - // runtime: the stream it returns is bound to that runtime's IO driver. + // 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), @@ -641,8 +641,6 @@ async fn run_acceptor_half( None, ) .await; - // Logged either way: how long the client waited before giving up is - // the whole question when a strict client disconnects mid-CredSSP. let elapsed_ms = credssp_start.elapsed().as_millis(); match &result { Ok(_) => info!(elapsed_ms, "acceptor: CredSSP exchange finished"), @@ -808,11 +806,7 @@ where round += 1; let client_state: ClientState = { let mut generator = sequence.process_ts_request(ts_request); - // sspi runs KDC discovery inline here rather than yielding it as a - // network request. On a current-thread runtime its DNS helper - // blocks the whole runtime thread (sspi dns.rs execute_future), - // which would stall the acceptor half sharing this thread. Timing - // each step is how we tell that apart from a slow peer. + // 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()); @@ -869,8 +863,7 @@ where Ok(()) } -/// A synchronous sspi step longer than this monopolizes the runtime thread -/// and starves the acceptor half, so it is worth a louder log line. +/// 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) { @@ -888,11 +881,8 @@ type AcceptorTls = (Vec, Arc); static ACCEPTOR_TLS: OnceLock = OnceLock::new(); -/// One certificate for the whole process, not one per session. mstsc opens a -/// second connection after the user accepts the certificate dialog and compares -/// the certificate it receives against the one it just approved; a per-session -/// cert never matched, so it aborted the second handshake with "an unexpected -/// server authentication certificate was received from the remote computer". +/// 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()); @@ -901,8 +891,7 @@ fn acceptor_tls_material() -> Result { generate_acceptor_cert().context("generate acceptor cert")?; let config = Arc::new(build_acceptor_tls_config(certified_key).context("build acceptor TLS config")?); - // Racing sessions may both generate one; whichever lands first wins so that - // every session presents the same certificate. + // Racing sessions both generate one; the first to land wins. let _ = ACCEPTOR_TLS.set((public_key, config)); Ok(ACCEPTOR_TLS .get() diff --git a/packages/pam/handlers/rdp/native/src/ffi.rs b/packages/pam/handlers/rdp/native/src/ffi.rs index 711e6796..2b5216b0 100644 --- a/packages/pam/handlers/rdp/native/src/ffi.rs +++ b/packages/pam/handlers/rdp/native/src/ffi.rs @@ -165,8 +165,7 @@ struct BridgeEntry { // Set once the events channel has reported closed; subsequent polls // short-circuit to RDP_POLL_ENDED. events_ended: Mutex, - // Populated by wait() on failure. The status code alone can't say why a - // session died, so Go reads the message back via rdp_bridge_last_error. + // Set by wait() on failure; Go reads it back via rdp_bridge_last_error. last_error: Mutex>, } @@ -404,8 +403,7 @@ pub extern "C" fn rdp_bridge_wait(handle: u64) -> i32 { } Ok(Err(e)) => { error!(handle, error = ?e, "rdp_bridge_wait: session failed"); - // anyhow's alternate Display renders the full context chain, - // which is where the useful detail lives. + // {e:#} renders the full context chain. set_last_error(handle, format!("{e:#}")); RDP_BRIDGE_SESSION_ERROR } @@ -426,10 +424,9 @@ fn set_last_error(handle: u64, message: String) { } } -/// Copies the last session error into `buf` as a NUL-terminated string and -/// returns the byte length written, excluding the NUL. Returns 0 when there is -/// no error, and RDP_BRIDGE_BAD_ARG / RDP_BRIDGE_INVALID_HANDLE on misuse. -/// Truncates on a UTF-8 boundary if `buf_len` is too small. +/// 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 /// diff --git a/packages/pam/handlers/rdp/native/src/logging.rs b/packages/pam/handlers/rdp/native/src/logging.rs index d71a8779..596c318f 100644 --- a/packages/pam/handlers/rdp/native/src/logging.rs +++ b/packages/pam/handlers/rdp/native/src/logging.rs @@ -1,8 +1,5 @@ -//! Tracing subscriber for the bridge. The crate is linked into the Go CLI as -//! a staticlib, so nothing else installs a subscriber; without this every -//! `tracing` event here and inside IronRDP is discarded before it is -//! formatted, which is why bridge failures used to surface as a bare status -//! code with no output. +//! 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; @@ -20,9 +17,7 @@ pub fn init() { .filter(|v| !v.trim().is_empty()) .unwrap_or_else(default_directive); - // Targets rather than EnvFilter: same `target=level,target=level` - // syntax, without pulling a regex engine in for span-field matching we - // never use. + // Targets, not EnvFilter: same syntax without the regex dependency. let targets = filter.parse::().unwrap_or_else(|_| { Targets::new().with_target("infisical_rdp_bridge", LevelFilter::INFO) }); @@ -31,11 +26,9 @@ pub fn init() { .with_writer(std::io::stderr) .with_ansi(false) .with_target(true) - // Thread names make it obvious which half a line came from. .with_thread_names(true); - // try_init (not init) so a host-installed subscriber wins instead of - // aborting the process. + // try_init, not init: a host-installed subscriber should win, not panic. let _ = tracing_subscriber::registry() .with(fmt_layer) .with(targets) @@ -43,15 +36,10 @@ pub fn init() { }); } -/// Mirrors the Go CLI's LOG_LEVEL so `LOG_LEVEL=debug infisical ...` turns on -/// bridge and IronRDP protocol tracing without a second knob. IronRDP logs -/// each decoded PDU at debug/trace, which is what makes strict-client -/// negotiation failures diagnosable. +/// Mirrors the Go CLI's LOG_LEVEL so one knob covers both sides. /// -/// sspi is deliberately pinned to `info` regardless of LOG_LEVEL: it logs -/// serialized TSCredentials, which contain the injected PAM password in -/// cleartext, at debug and below. Enabling it has to be a deliberate -/// `RUST_LOG=sspi=trace`, never a side effect of raising the general log level. +/// 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() From 2256469a74031ac4af2f64ac258e58e49be60ad0 Mon Sep 17 00:00:00 2001 From: bernie-g Date: Wed, 26 Aug 2026 19:52:19 -0400 Subject: [PATCH 3/3] fix(pam-rdp): cap sspi logging under RUST_LOG overrides --- packages/pam/handlers/rdp/native/src/logging.rs | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/packages/pam/handlers/rdp/native/src/logging.rs b/packages/pam/handlers/rdp/native/src/logging.rs index 596c318f..7542a2fa 100644 --- a/packages/pam/handlers/rdp/native/src/logging.rs +++ b/packages/pam/handlers/rdp/native/src/logging.rs @@ -18,9 +18,14 @@ pub fn init() { .unwrap_or_else(default_directive); // Targets, not EnvFilter: same syntax without the regex dependency. - let targets = filter.parse::().unwrap_or_else(|_| { + 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)