Fix Schema cache for manifest-free events using EventName (n4r1b#120)

* Add event_name to Schema to differentia events in manifest-free providers

* Add Keyword to event_record

* Add test for TraceLogging with multiple events

* Remove unnecessary TODO comment

* Disable flaky tlg test

Author: n4r1b

Cargo.toml

@@ -47,3 +47,4 @@ log = "0.4"
 env_logger = "0.11" # used in examples
 serde_json = "1.0"
 flexbuffers = "2.0"
+tracelogging = "1.2"

src/native/etw_types/event_record.rs

@@ -4,6 +4,7 @@ use windows::core::GUID;
 use windows::Win32::System::Diagnostics::Etw::EVENT_RECORD;
 
 use crate::native::etw_types::extended_data::EventHeaderExtendedDataItem;
+use crate::native::ExtendedDataItem;
 
 use super::EVENT_HEADER_FLAG_32_BIT_HEADER;
 
@@ -65,6 +66,11 @@ impl EventRecord {
         self.0.EventHeader.EventDescriptor.Level
     }
 
+    /// The `Keyword` field from the wrapped `EVENT_RECORD`
+    pub fn keyword(&self) -> u64 {
+        self.0.EventHeader.EventDescriptor.Keyword
+    }
+
     /// The `Flags` field from the wrapped `EVENT_RECORD`
     pub fn event_flags(&self) -> u16 {
         self.0.EventHeader.Flags
@@ -154,4 +160,22 @@ impl EventRecord {
             )
         }
     }
+
+    /// Returns the `eventName` for manifest-free events
+    pub fn event_name(&self) -> String {
+        if self.event_id() != 0 {
+            return String::new();
+        }
+
+        if let Some(ExtendedDataItem::TraceLogging(name)) = self
+            .extended_data()
+            .iter()
+            .find(|ext_data| ext_data.is_tlg())
+            .map(|ext_data| ext_data.to_extended_data_item())
+        {
+            name
+        } else {
+            String::new()
+        }
+    }
 }

src/native/etw_types/extended_data.rs

@@ -1,16 +1,17 @@
 //! A module to handle Extended Data from ETW traces
 
+use std::{ffi::CStr, mem};
 use windows::core::GUID;
 use windows::Win32::Security::SID;
 use windows::Win32::System::Diagnostics::Etw::{
     EVENT_EXTENDED_ITEM_RELATED_ACTIVITYID, EVENT_EXTENDED_ITEM_TS_ID,
 };
 use windows::Win32::System::Diagnostics::Etw::{
     EVENT_HEADER_EXTENDED_DATA_ITEM, EVENT_HEADER_EXT_TYPE_EVENT_KEY,
-    EVENT_HEADER_EXT_TYPE_INSTANCE_INFO, EVENT_HEADER_EXT_TYPE_PROCESS_START_KEY,
-    EVENT_HEADER_EXT_TYPE_RELATED_ACTIVITYID, EVENT_HEADER_EXT_TYPE_SID,
-    EVENT_HEADER_EXT_TYPE_STACK_TRACE32, EVENT_HEADER_EXT_TYPE_STACK_TRACE64,
-    EVENT_HEADER_EXT_TYPE_TS_ID,
+    EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL, EVENT_HEADER_EXT_TYPE_INSTANCE_INFO,
+    EVENT_HEADER_EXT_TYPE_PROCESS_START_KEY, EVENT_HEADER_EXT_TYPE_RELATED_ACTIVITYID,
+    EVENT_HEADER_EXT_TYPE_SID, EVENT_HEADER_EXT_TYPE_STACK_TRACE32,
+    EVENT_HEADER_EXT_TYPE_STACK_TRACE64, EVENT_HEADER_EXT_TYPE_TS_ID,
 };
 
 // These types are returned by our public API. Let's use their re-exported versions
@@ -28,7 +29,7 @@ pub struct EventHeaderExtendedDataItem(EVENT_HEADER_EXTENDED_DATA_ITEM);
 /// See <https://docs.microsoft.com/en-us/windows/win32/api/relogger/ns-relogger-event_header_extended_data_item>
 #[derive(Debug)]
 pub enum ExtendedDataItem {
-    /// Unexpected or invalid (or not implemented yet in Ferrisetw) extended data type
+    /// Unexpected, invalid or not implemented yet
     Unsupported,
     /// Related activity identifier
     RelatedActivityId(GUID),
@@ -41,9 +42,8 @@ pub enum ExtendedDataItem {
     StackTrace32(EVENT_EXTENDED_ITEM_STACK_TRACE32),
     /// Call stack (if the event is captured on a 64-bit computer)
     StackTrace64(EVENT_EXTENDED_ITEM_STACK_TRACE64),
-    // TODO: implement them, but the documentation does not clearly define what they are supposed to contain
-    // /// TraceLogging event metadata information
-    // SchemaTl,
+    /// TraceLogging event metadata information
+    TraceLogging(String),
     // /// Provider traits data
     // /// (for example traits set through EventSetInformation(EventProviderSetTraits) or specified through EVENT_DATA_DESCRIPTOR_TYPE_PROVIDER_METADATA)
     // ProvTraits,
@@ -61,7 +61,12 @@ impl EventHeaderExtendedDataItem {
         self.0.ExtType
     }
 
+    pub fn is_tlg(&self) -> bool {
+        self.0.ExtType as u32 == EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL
+    }
+
     /// Returns this extended data as a variant of a Rust enum.
+    // TODO: revisit this function
     pub fn to_extended_data_item(&self) -> ExtendedDataItem {
         let data_ptr = self.0.DataPtr as *const std::ffi::c_void;
         if data_ptr.is_null() {
@@ -109,7 +114,83 @@ impl EventHeaderExtendedDataItem {
                 ExtendedDataItem::EventKey(unsafe { *data_ptr })
             }
 
+            EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL => {
+                ExtendedDataItem::TraceLogging(unsafe { self.get_event_name().unwrap_or_default() })
+            }
+
             _ => ExtendedDataItem::Unsupported,
         }
     }
+
+    ///
+    /// This function will parse the `_tlgEventMetadata_t` to retrieve the EventName
+    ///
+    /// For more info see `_tlgEventMetadata_t` in `TraceLoggingProvider.h` (Windows SDK)
+    ///
+    /// ```cpp
+    /// struct _tlgEventMetadata_t
+    /// {
+    ///     UINT8 Type; // = _TlgBlobEvent4
+    ///     UCHAR Channel;
+    ///     UCHAR Level;
+    ///     UCHAR Opcode;
+    ///     ULONGLONG Keyword;
+    ///     UINT16 RemainingSize; // = sizeof(RemainingSize + Tags + EventName + Fields)
+    ///     UINT8 Tags[]; // 1 or more bytes. Read until you hit a byte with high bit unset.
+    ///     char EventName[sizeof("eventName")]; // UTF-8 nul-terminated event name
+    ///     for each field {
+    ///         char FieldName[sizeof("fieldName")];
+    ///         UINT8 InType;
+    ///         UINT8 OutType;
+    ///         UINT8 Tags[];
+    ///         UINT16 ValueCount;
+    ///         UINT16 TypeInfoSize;
+    ///         char TypeInfo[TypeInfoSize];
+    ///     }
+    /// }
+    /// ```
+    ///
+    ///  We are only interested on `EventName` so we will only consider the first three members.
+    ///
+    /// # Safety
+    ///
+    /// As per the MS header 'This structure may change in future revisions of this header.'  
+    /// **Keep an eye on it!**
+    ///
+    // TODO: Make this function more robust
+    unsafe fn get_event_name(&self) -> Option<String> {
+        const TAGS_SIZE: usize = 1;
+        debug_assert!(self.is_tlg());
+
+        let mut data_ptr = self.0.DataPtr as *const u8;
+        if data_ptr.is_null() {
+            return None;
+        }
+
+        let size = data_ptr.read_unaligned() as u16;
+        data_ptr = data_ptr.add(mem::size_of::<u16>());
+
+        let mut n = 0;
+        while n < size {
+            // Read until you hit a byte with high bit unset.
+            let tag = data_ptr.read_unaligned();
+            data_ptr = data_ptr.add(TAGS_SIZE);
+
+            if tag & 0b1000_0000 == 0 {
+                break;
+            }
+
+            n += 1;
+        }
+
+        // If debug let's assert here since this is a case we want to investigate
+        debug_assert!(n != size);
+        if n == size {
+            return None;
+        }
+
+        Some(String::from(
+            CStr::from_ptr(data_ptr as *const _).to_string_lossy(),
+        ))
+    }
 }

src/schema_locator.rs

@@ -50,6 +50,13 @@ struct SchemaKey {
     //       see https://github.com/microsoft/krabsetw/issues/195
     opcode: u8,
     level: u8,
+    //
+    // From MS documentation `evntprov.h`
+    // For manifest-free events (i.e. TraceLogging), Event.Id and Event.Version are not useful
+    // and should be ignored. Use Event name, level, keyword, and opcode for event filtering and
+    // identification.
+    //
+    event_name: String,
 }
 
 impl SchemaKey {
@@ -60,6 +67,7 @@ impl SchemaKey {
             opcode: event.opcode(),
             version: event.version(),
             level: event.level(),
+            event_name: event.event_name(),
         }
     }
 }

src/trace/callback_data.rs

@@ -9,8 +9,6 @@ use crate::schema_locator::SchemaLocator;
 use crate::trace::RealTimeTraceTrait;
 use crate::EtwCallback;
 
-pub use crate::native::etw_types::LoggingMode;
-
 /// Data used by callbacks when the trace is running
 // NOTE: this structure is accessed in an unsafe block in a separate thread (see the `trace_callback_thunk` function)
 //       Thus, this struct must not be mutated (outside of interior mutability and/or using Mutex and other synchronization mechanisms) when the associated trace is running.

tests/tlg.rs

@@ -0,0 +1,123 @@
+use tracelogging as tlg;
+
+use ferrisetw::parser::Parser;
+use ferrisetw::provider::Provider;
+use ferrisetw::schema_locator::SchemaLocator;
+use ferrisetw::trace::TraceTrait;
+use ferrisetw::trace::UserTrace;
+use ferrisetw::EventRecord;
+
+mod utils;
+use utils::{Status, TestKind};
+
+const EVENT1_COUNT: u32 = 1;
+const EVENT2_COUNT: u32 = 5;
+const TEST_STRING_VALUE: &'static str = "TestString";
+const PROVIDER_NAME: &'static str = "ferrisETW.TraceLoggingTest";
+
+tlg::define_provider!(FERRIS_PROVIDER, "ferrisETW.TraceLoggingTest");
+
+#[ignore]
+#[test]
+fn tlg_tests() {
+    unsafe {
+        FERRIS_PROVIDER.register();
+    }
+
+    let binding = tlg::Guid::from_name(PROVIDER_NAME).to_utf8_bytes();
+    let guid = std::str::from_utf8(&binding).unwrap();
+
+    tlg_multiple_events(guid);
+
+    FERRIS_PROVIDER.unregister();
+}
+
+fn generate_tlg_events() {
+    for _i in 0..EVENT1_COUNT {
+        tlg::write_event!(
+            FERRIS_PROVIDER,
+            "Event1",
+            level(Warning),
+            keyword(0x13),
+            str8("String", TEST_STRING_VALUE),
+        );
+    }
+
+    for i in 0..EVENT2_COUNT {
+        tlg::write_event!(
+            FERRIS_PROVIDER,
+            "Event2",
+            level(Informational),
+            keyword(0x6),
+            u32("Integer", &i),
+        );
+    }
+}
+
+fn tlg_multiple_events(provider_guid: &str) {
+    let passed = Status::new(TestKind::ExpectSuccess);
+    let notifier = passed.notifier();
+
+    let mut event1_count = 0;
+    let mut event2_count = 0;
+
+    let tlg_provider = Provider::by_guid(provider_guid)
+        .add_callback(
+            move |record: &EventRecord, schema_locator: &SchemaLocator| {
+                let schema = schema_locator.event_schema(record).unwrap();
+                let parser = Parser::create(record, &schema);
+
+                // Test event_name function is working as expected & we can handle multiple
+                // different events.
+                if record.event_name() == "Event1" {
+                    println!(
+                        "Received Event1({}) from ferrisETW.TraceLoggingTest",
+                        event1_count
+                    );
+
+                    assert_eq!(record.level(), tlg::Level::Warning.as_int());
+                    assert_eq!(record.keyword(), 0x13);
+
+                    // Tracelogging crate sets OutTypeUtf8 for str8 which we don't handle at the
+                    // moment.
+                    let _data = parser.try_parse::<String>("String");
+                    // assert!(data.is_ok());
+                    // assert_eq!(data, TEST_STRING_VALUE);
+
+                    event1_count = event1_count + 1;
+                } else if record.event_name() == "Event2" {
+                    println!(
+                        "Received Event2({}) from ferrisETW.TraceLoggingTest",
+                        event2_count
+                    );
+
+                    assert_eq!(record.level(), tlg::Level::Informational.as_int());
+                    assert_eq!(record.keyword(), 0x6);
+
+                    let data = parser.try_parse::<u32>("Integer");
+
+                    assert!(data.is_ok());
+                    assert_eq!(data.unwrap(), event2_count);
+
+                    event2_count = event2_count + 1;
+                }
+
+                if event1_count == EVENT1_COUNT && event2_count == EVENT2_COUNT {
+                    notifier.notify_success();
+                }
+            },
+        )
+        .build();
+
+    let tlg_trace = UserTrace::new()
+        .enable(tlg_provider)
+        .start_and_process()
+        .unwrap();
+
+    generate_tlg_events();
+
+    passed.assert_passed();
+    assert!(tlg_trace.events_handled() > 0);
+    tlg_trace.stop().unwrap();
+    println!("tlg_multiple_events passed");
+}