trace_lifetime.rs

//! Test that traces are started and stopped as expected

use std::process::Command;

use ferrisetw::provider::Provider;
use ferrisetw::schema_locator::SchemaLocator;
use ferrisetw::trace::RealTimeTraceTrait;
use ferrisetw::trace::TraceTrait;
use ferrisetw::trace::UserTrace;
use ferrisetw::EventRecord;

#[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 => trace_builder.start_and_process().unwrap(),
    };

    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) {
    for _attempt in 0..3 {
        let output = Command::new("logman")
            .arg("query")
            .arg("-ets")
            .output()
            .unwrap();

        let stdout_u8 = output.stdout;
        let stdout = String::from_utf8_lossy(&stdout_u8);
        let status = output.status;

        let res = stdout
            .split('\n')
            .any(|line| line.contains(ascii_part_of_the_trace_name));

        if status.success() {
            if res != expected {
                println!("logman output (returned {}): {}", status, stdout);
                unreachable!();
            }
        } else {
            // Not sure why, but logman sometimes fails to list current traces (with "The GUID passed was not recognized as valid by a WMI data provider.")
            println!("logman hit an error (returned {}).", status);
            println!("logman output: {}", stdout);
            println!("Let's try again");
            std::thread::sleep(std::time::Duration::from_millis(100));
        }
    }
}