Merge pull request #66 from daladim/more_integration_tests

More integration tests

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;
@@ -225,6 +225,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/dns.rs

@@ -62,8 +62,11 @@ fn simple_user_dns_trace() {
 fn test_event_id_filter() {
     let passed1 = Status::new(TestKind::ExpectSuccess);
     let passed2 = Status::new(TestKind::ExpectNoFailure);
+    let passed3 = Status::new(TestKind::ExpectSuccess);
+
     let notifier1 = passed1.notifier();
     let notifier2 = passed2.notifier();
+    let notifier3 = passed3.notifier();
 
     let filter = EventFilter::ByEventIds(vec![EVENT_ID_DNS_QUERY_COMPLETED]);
 
@@ -78,6 +81,12 @@ fn test_event_id_filter() {
                 notifier2.notify_failure();
             }
         })
+        .add_callback(move |record: &EventRecord, _schema_locator: &SchemaLocator| {
+            // This secondary callback basically tests all callbacks are run
+            if record.event_id() == EVENT_ID_DNS_QUERY_COMPLETED {
+                notifier3.notify_success();
+            }
+        })
         .build();
 
     let _trace = UserTrace::new()
@@ -89,6 +98,7 @@ fn test_event_id_filter() {
 
     passed1.assert_passed();
     passed2.assert_passed();
+    passed3.assert_passed();
     // Not calling .stop() here, let's just rely on the `impl Drop`
 
     println!("test_event_id_filter passed");

tests/trace_lifetime.rs

@@ -0,0 +1,141 @@
+//! 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 res = output
+        .split('\n')
+        .any(|line| {
+            let val = line.contains(&ascii_part_of_the_trace_name);
+            val
+        });
+
+    if res != expected {
+        println!("logman output: {}", output);
+        assert!(false);
+    }
+
+    res
+}