Integration test: trace lifetime

src/native/etw_types.rs

@@ -9,7 +9,7 @@
 use crate::provider::event_filter::EventFilterDescriptor;
 use crate::provider::TraceFlags;
 use crate::trace::{CallbackData, TraceProperties, TraceTrait};
-use std::ffi::c_void;
+use std::ffi::{c_void, OsString};
 use std::fmt::Formatter;
 use std::marker::PhantomData;
 use std::sync::Arc;
@@ -20,6 +20,7 @@ use windows::Win32::System::Diagnostics::Etw;
 use windows::Win32::System::Diagnostics::Etw::EVENT_FILTER_DESCRIPTOR;
 use widestring::{U16CStr, U16CString};
 
+
 mod event_record;
 pub use event_record::EventRecord;
 
@@ -225,6 +226,11 @@ impl EventTraceProperties {
     pub fn trace_name_array(&self) -> &[u16] {
         &self.wide_trace_name
     }
+    pub fn name(&self) -> OsString {
+        widestring::U16CStr::from_slice_truncate(&self.wide_trace_name)
+            .map(|ws| ws.to_os_string())
+            .unwrap_or(OsString::from("<invalid name>"))
+    }
 }
 
 /// Newtype wrapper over an [EVENT_TRACE_LOGFILEW]

src/trace.rs

@@ -1,6 +1,7 @@
 //! ETW Tracing/Session abstraction
 //!
 //! Provides both a Kernel and User trace that allows to start an ETW session
+use std::ffi::OsString;
 use std::marker::PhantomData;
 use std::sync::atomic::{AtomicUsize, Ordering};
 use std::sync::Arc;
@@ -117,6 +118,7 @@ pub trait TraceTrait: private::PrivateTraceTrait + Sized {
     fn trace_handle(&self) -> TraceHandle;
 
     // These utilities should be implemented for every trace
+    fn trace_name(&self) -> OsString;
     fn events_handled(&self) -> usize;
 
     // The following are default implementations, that work on both user and kernel traces
@@ -152,6 +154,10 @@ impl TraceTrait for UserTrace {
         self.trace_handle
     }
 
+    fn trace_name(&self) -> OsString {
+        self.properties.name()
+    }
+
     fn events_handled(&self) -> usize {
         self.callback_data.events_handled()
     }
@@ -167,6 +173,10 @@ impl TraceTrait for KernelTrace {
         self.trace_handle
     }
 
+    fn trace_name(&self) -> OsString {
+        self.properties.name()
+    }
+
     fn events_handled(&self) -> usize {
         self.callback_data.events_handled()
     }

tests/trace_lifetime.rs

@@ -0,0 +1,152 @@
+//! Test that traces are started and stopped as expected
+
+use std::process::Command;
+
+use ferrisetw::provider::Provider;
+use ferrisetw::native::etw_types::EventRecord;
+use ferrisetw::schema_locator::SchemaLocator;
+use ferrisetw::trace::UserTrace;
+use ferrisetw::trace::TraceTrait;
+
+
+#[derive(Clone, Copy, Debug)]
+enum HowToProcess {
+    StartOnly,
+    ProcessFromHandle,
+    StartAndProcess,
+}
+
+#[test]
+fn trace_lifetime() {
+    // List of (names to request, ASCII part to look for)
+    const NAME_EXAMPLES: [(&str, &str); 4] = [
+        ("simple-trace-name", "simple-trace-name"),
+        ("998877",            "998877"),
+        ("My Ütf-8 tråce",    "tf-8 tr"),
+        ("My Ütf-8 tråce name, that has quite a løøøøøøøøøøøøøøøøøøøøøng name, 😎 a very λονɣ name indeed (which is even longer than TRACE_NAME_MAX_CHARS). My Ütf-8 tråce name, that has quite a løøøøøøøøøøøøøøøøøøøøøng name, 😎 a very λονɣ name indeed (which is even longer than TRACE_NAME_MAX_CHARS).", "that has quite a"),
+    ];
+
+    const HOW_TO_PROCESS: [HowToProcess; 3] = [
+        HowToProcess::StartOnly,
+        HowToProcess::ProcessFromHandle,
+        HowToProcess::StartAndProcess,
+    ];
+
+    // Setup: make sure no trace is still running from an older interrupted test
+    for (requested_trace_name, _ascii_part_to_look_for) in NAME_EXAMPLES {
+        let _output = Command::new("logman")
+        .arg("stop")
+        .arg("-ets")
+        .arg(requested_trace_name)
+        .output()
+        .unwrap();
+    }
+
+    for provider_count in 0..2 {
+        for (requested_trace_name, ascii_part_to_look_for) in NAME_EXAMPLES {
+            for explicit_stop in [true, false] {
+                for how_to_process in HOW_TO_PROCESS {
+                    test_wordpad_trace(
+                        provider_count,
+                        requested_trace_name,
+                        ascii_part_to_look_for,
+                        explicit_stop,
+                        how_to_process);
+
+                    // Regardless of whether we explicitly stopped it, trace has been dropped and must no longer run
+                    assert_trace_exists(&ascii_part_to_look_for, false);
+                }
+            }
+        }
+    }
+}
+
+fn test_wordpad_trace(
+    provider_count: usize,
+    requested_trace_name: &str,
+    ascii_part_of_the_trace_name: &str,
+    explicit_stop: bool,
+    how_to_process: HowToProcess
+) {
+    println!("Testing a trace with {} providers, processed as {:?}, stopped:{}, name contains {}...", provider_count, how_to_process, explicit_stop, ascii_part_of_the_trace_name);
+
+    // Create a provider
+    let mut provider_builder = Provider
+        ::by_guid("54FFD262-99FE-4576-96E7-1ADB500370DC"); // Microsoft-Windows-Wordpad
+    for _i in 0..provider_count {
+        provider_builder = provider_builder.add_callback(|_record: &EventRecord, _locator: &SchemaLocator| {})
+    }
+    let wordpad_provider = provider_builder.build();
+    assert_trace_exists(requested_trace_name, false);
+
+
+    // Create a trace
+    let trace_builder = UserTrace::new()
+        .named(String::from(requested_trace_name))
+        .enable(wordpad_provider);
+
+    let trace = match how_to_process {
+        HowToProcess::StartOnly => {
+            let (trace, _handle) = trace_builder.start().unwrap();
+            trace // the trace is running, but not processing anything
+        },
+        HowToProcess::ProcessFromHandle => {
+            let (trace, handle) = trace_builder.start().unwrap();
+            std::thread::spawn(move || UserTrace::process_from_handle(handle));
+            trace
+        },
+        HowToProcess::StartAndProcess => {
+            let trace = trace_builder.start_and_process().unwrap();
+            trace
+        }
+    };
+
+    let actual_trace_name = trace.trace_name().to_string_lossy().to_string();
+    assert!(actual_trace_name.contains(ascii_part_of_the_trace_name));
+    assert_trace_exists(ascii_part_of_the_trace_name, true);
+
+    if explicit_stop {
+        trace.stop().unwrap();
+        assert_trace_exists(ascii_part_of_the_trace_name, false);
+    }
+}
+
+/// Call `logman` and check if the expected trace is part of the output
+///
+/// This is limited to the ASCII part of the trace name, because Windows really sucks when it comes to encodings from sub processes (codepage issues, etc.)
+#[track_caller]
+fn assert_trace_exists(ascii_part_of_the_trace_name: &str, expected: bool) -> bool {
+    let output_u8 = Command::new("logman")
+        .arg("query")
+        .arg("-ets")
+        .output()
+        .unwrap()
+        .stdout;
+
+    let output = String::from_utf8_lossy(&output_u8);
+
+    // let current_codepage = unsafe {
+    //     windows::Win32::Globalization::GetACP()
+    // };
+    // let current_encoding = codepage::to_encoding(current_codepage as u16).unwrap();
+    // let (output, _, _) = current_encoding.decode(&output_u8);
+
+    let res = output
+        .split('\n')
+        .any(|line| {
+            let val = line.contains(&ascii_part_of_the_trace_name);
+            // if val {
+            //     println!("  = {}", line);
+            // } else {
+            //     println!("  . {}", line);
+            // }
+            val
+        });
+
+    if res != expected {
+        println!("logman output: {}", output);
+        assert!(false);
+    }
+
+    res
+}