diff --git a/api/native/Cargo.toml b/api/native/Cargo.toml index 3425a030b..91d03e739 100644 --- a/api/native/Cargo.toml +++ b/api/native/Cargo.toml @@ -14,6 +14,7 @@ azihsm_api.workspace = true open-enum.workspace = true parking_lot.workspace = true tracing.workspace = true +tracing-subscriber = { features = ["env-filter", "fmt"], workspace = true } zerocopy = { features = ["derive"], workspace = true } [features] diff --git a/api/native/doc/chapter_11_diagnostics.md b/api/native/doc/chapter_11_diagnostics.md new file mode 100644 index 000000000..bd04989ce --- /dev/null +++ b/api/native/doc/chapter_11_diagnostics.md @@ -0,0 +1,78 @@ +# Diagnostics + +## File-Based Tracing + +The native API library uses Rust's `tracing` framework internally for structured logging across the entire SDK stack, from the API layer down through the DDI. +By default no trace output is emitted, but it can be directed to a file by setting environment variables before loading the library. + +This is useful for diagnosing failures in any host process that loads `azihsm_api_native` (e.g., the OpenSSL provider, C/C++ test binaries, or custom applications). + +### Environment Variables + +| Variable | Required | Description | +|----------|----------|-------------| +| `AZIHSM_NATIVEAPI_TRACE_FILE` | Yes | File path for trace output. When set, a tracing subscriber is installed on the first API call. | +| `AZIHSM_NATIVEAPI_TRACE_FILE_APPEND` | No | Set to `1` to append to an existing file. If unset or any other value, the file is truncated on each run. | +| `RUST_LOG` | No | Controls the trace filter level. Defaults to `info`. Accepts standard `tracing` filter syntax (see below). | + +### Trace Filter Syntax + +The `RUST_LOG` variable accepts directives in the format used by [`tracing-subscriber`'s `EnvFilter`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html). +A few examples: + +| Value | Effect | +|-------|--------| +| `debug` | All crates at DEBUG level and above | +| `trace` | All crates at TRACE level (most verbose) | +| `info` | All crates at INFO level (the default) | +| `azihsm_api=debug,azihsm_ddi_mock=info` | DEBUG for the API, INFO for the mock DDI, WARN for others | + +### Usage Example + +```bash +# Linux +export AZIHSM_NATIVEAPI_TRACE_FILE=/tmp/azihsm_trace.log +export RUST_LOG=debug +./my_application + +# Inspect the trace +head -50 /tmp/azihsm_trace.log +``` + +```powershell +# Windows (PowerShell) +$env:AZIHSM_NATIVEAPI_TRACE_FILE = "$env:TEMP\azihsm_trace.log" +$env:RUST_LOG = "debug" +.\my_application.exe + +# Inspect the trace +Get-Content $env:AZIHSM_NATIVEAPI_TRACE_FILE | Select-Object -First 50 +``` + +### Output Format + +Each line in the trace file contains a structured event with the following fields: + +* **Timestamp** — UTC wall-clock time (e.g., `2026-06-12T17:13:42.223204Z`) +* **Level** — `TRACE`, `DEBUG`, `INFO`, `WARN`, or `ERROR` +* **Thread ID** — Identifies the originating thread (e.g., `ThreadId(01)`) +* **Span context** — Nested call chain showing the path through the SDK +* **Target** — The Rust module that emitted the event (e.g., `azihsm_api::partition`) +* **Message** — The log message and any structured fields + +Example output: + +```text +2026-06-12T17:13:42.223204Z INFO ThreadId(01) partition_info_list: azihsm_api::partition: enter +2026-06-12T17:13:42.224544Z DEBUG ThreadId(01) partition_info_list:dev_paths:dev_info_list{self=DdiMock}: azihsm_ddi_mock::ddi: Got DdiMock device info list size=1 +``` + +### Behavior Notes + +* Tracing initialization occurs exactly once, on the first API call. + Subsequent calls incur no overhead. +* If `AZIHSM_NATIVEAPI_TRACE_FILE` is not set, no subscriber is installed and there is no performance impact. +* If the trace file cannot be opened (e.g., invalid path or permission denied), the library silently continues without tracing. +* The trace subscriber is global to the process. + If another subscriber has already been installed (e.g., by the host application), the library's subscriber will not replace it. + diff --git a/api/native/src/lib.rs b/api/native/src/lib.rs index f031d325b..23f3683d2 100644 --- a/api/native/src/lib.rs +++ b/api/native/src/lib.rs @@ -35,6 +35,7 @@ mod session_props; #[path = "../../lib/src/shared_types.rs"] mod shared_types; mod str; +mod trace_file; mod utils; use std::ffi::c_void; @@ -200,6 +201,7 @@ static HANDLE_TABLE: LazyLock = LazyLock::new(HandleTable::default) pub(crate) fn abi_boundary Result<(), AzihsmStatus> + UnwindSafe>( f: F, ) -> AzihsmStatus { + let _ = std::panic::catch_unwind(trace_file::init_trace_file); match catch_unwind(f) { Ok(hr) => match hr { Ok(_) => AzihsmStatus::Success, diff --git a/api/native/src/trace_file.rs b/api/native/src/trace_file.rs new file mode 100644 index 000000000..d8e079daa --- /dev/null +++ b/api/native/src/trace_file.rs @@ -0,0 +1,206 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! File-based tracing initialization for the native API. +//! +//! When the environment variable `AZIHSM_NATIVEAPI_TRACE_FILE` is set to a file +//! path, this module installs a `tracing_subscriber` that writes all trace +//! output to that file. Initialization is idempotent and thread-safe thanks +//! to [`std::sync::Once`]. +//! +//! By default, the file is truncated on each run. +//! Set `AZIHSM_NATIVEAPI_TRACE_FILE_APPEND=1` to append instead. +//! +//! If the environment variable is not set, or if any step of the +//! initialization fails (file open, filter parse, subscriber install), the +//! function silently returns without installing a subscriber. + +use std::io::Write; +use std::sync::Once; + +use tracing_subscriber::EnvFilter; +use tracing_subscriber::fmt; +use tracing_subscriber::fmt::MakeWriter; +use tracing_subscriber::prelude::*; + +/// Name of the environment variable that controls file-based tracing. +const TRACE_FILE_ENV_VAR: &str = "AZIHSM_NATIVEAPI_TRACE_FILE"; + +/// Name of the environment variable that controls append mode. +/// When set to `"1"`, the trace file is opened in append mode so that +/// output from successive runs accumulates. Any other value (or unset) +/// causes the file to be truncated on each run. +const TRACE_FILE_APPEND_ENV_VAR: &str = "AZIHSM_NATIVEAPI_TRACE_FILE_APPEND"; + +/// Thread-safe, non-poisoning file writer for the tracing subscriber. +/// +/// Uses [`parking_lot::Mutex`] instead of [`std::sync::Mutex`] so that a +/// panic while holding the lock does not poison the mutex and silently +/// break all subsequent trace writes. +struct TraceFileWriter(parking_lot::Mutex); + +/// RAII guard returned by [`TraceFileWriter`] that implements [`Write`]. +struct TraceFileWriterGuard<'a>(parking_lot::MutexGuard<'a, std::fs::File>); + +impl Write for TraceFileWriterGuard<'_> { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.write(buf) + } + + fn flush(&mut self) -> std::io::Result<()> { + self.0.flush() + } +} + +impl<'a> MakeWriter<'a> for TraceFileWriter { + type Writer = TraceFileWriterGuard<'a>; + + fn make_writer(&'a self) -> Self::Writer { + TraceFileWriterGuard(self.0.lock()) + } +} + +/// Ensures file-based tracing is initialized exactly once. +/// +/// This function is safe to call from any thread and any number of times. +/// On the first call it checks `AZIHSM_NATIVEAPI_TRACE_FILE`: +/// +/// * If the variable is **not set**, no subscriber is installed. +/// * If it **is set**, the file is opened and a `tracing_subscriber::fmt` +/// subscriber is installed that writes timestamped, structured trace events +/// to the file. Timestamps are always in UTC. +/// +/// All errors are silently ignored so that tracing failures never affect +/// normal library operation. +pub(crate) fn init_trace_file() { + static ONCE: Once = Once::new(); + + ONCE.call_once(|| { + // If the env var is not set, do nothing. + let trace_path = match std::env::var(TRACE_FILE_ENV_VAR) { + Ok(p) if !p.is_empty() => p, + _ => return, + }; + + // Check whether append mode is requested. + let append = matches!(std::env::var(TRACE_FILE_APPEND_ENV_VAR).as_deref(), Ok("1")); + + // Attempt to open/create the trace file. + let mut opts = std::fs::OpenOptions::new(); + opts.create(true).write(true); + if append { + opts.append(true); + } else { + opts.truncate(true); + } + let file = match opts.open(&trace_path) { + Ok(f) => f, + Err(_) => return, + }; + let writer = TraceFileWriter(parking_lot::Mutex::new(file)); + + // Build an EnvFilter from RUST_LOG, defaulting to `info`. + let filter = match EnvFilter::try_from_default_env() { + Ok(f) => f, + Err(_) => match EnvFilter::try_new("info") { + Ok(f) => f, + Err(_) => return, + }, + }; + + // Build and install the subscriber. If `set_global_default` fails + // (e.g. another subscriber was already installed), silently ignore. + let subscriber = tracing_subscriber::registry().with(filter).with( + fmt::layer() + .with_writer(writer) + .with_ansi(false) + .with_timer(fmt::time::SystemTime) + .with_thread_ids(true) + .with_target(true) + .with_span_events(fmt::format::FmtSpan::FULL), + ); + + let _ = tracing::subscriber::set_global_default(subscriber); + }); +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Calling `init_trace_file` multiple times must never panic, regardless + /// of whether the env var is set. + #[test] + fn init_trace_file_is_idempotent() { + // Without the env var set, these are all no-ops. + init_trace_file(); + init_trace_file(); + init_trace_file(); + } + + /// Verifies that trace output is written to the file when the + /// environment variable is set. Runs as a subprocess so that the + /// `Once` guard and global subscriber don't interfere with other tests. + #[test] + fn trace_output_written_to_file() { + // Use a unique filename to avoid collisions when tests run in + // parallel or multiple jobs share the same temp directory. + let filename = format!( + "azihsm_nativeapi_trace_test_{}_{}.log", + std::process::id(), + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .map_or(0, |d| d.as_nanos()), + ); + let trace_path = std::env::temp_dir().join(filename); + let _ = std::fs::remove_file(&trace_path); + + // Re-invoke *this* test binary running only the helper test, with + // the trace env vars set. The helper emits a known marker event. + // The helper is #[ignore]d so it doesn't run as a no-op during + // normal test execution; --include-ignored allows us to invoke it. + let exe = std::env::current_exe().expect("current_exe should be available"); + let status = std::process::Command::new(&exe) + .arg("--exact") + .arg("trace_file::tests::trace_output_helper") + .arg("--nocapture") + .arg("--include-ignored") + .env(TRACE_FILE_ENV_VAR, &trace_path) + .env("RUST_LOG", "trace") + .status() + .expect("failed to spawn subprocess"); + + assert!(status.success(), "helper subprocess failed: {status}"); + + let contents = std::fs::read_to_string(&trace_path) + .expect("trace file should exist after the helper ran"); + + assert!( + contents.contains("trace_init_marker_event"), + "trace file should contain the marker event, but got:\n{contents}" + ); + + // Verify the first line starts with an RFC 3339 UTC timestamp + // (e.g. "2026-06-12T17:13:42.223204Z"). + let first_line = contents.lines().next().unwrap_or(""); + assert!( + first_line.len() > 30 + && first_line.as_bytes()[4] == b'-' + && first_line.as_bytes()[10] == b'T' + && first_line.contains("Z "), + "first line should start with an RFC 3339 UTC timestamp, but was:\n{first_line}" + ); + + let _ = std::fs::remove_file(&trace_path); + } + + /// Helper test invoked as a subprocess by `trace_output_written_to_file`. + /// Not meant to be run directly — it requires the trace env vars to be + /// set by the parent process. + #[ignore] + #[test] + fn trace_output_helper() { + init_trace_file(); + tracing::info!("trace_init_marker_event"); + } +}