Merge pull request #242 from kylereedmsft/tracelogging_support

Add support for parsing and caching TraceLogging events.

krabs/krabs/filtering/event_filter.hpp

@@ -61,7 +61,7 @@ namespace krabs {
          *   Given optional predicate will be applied to ETW API filtered results
          * </summary>
          */
-        event_filter(unsigned short event_id, filter_predicate predicate=nullptr);
+        event_filter(unsigned short event_id, filter_predicate predicate = nullptr);
 
         /**
          * <summary>

krabs/krabs/schema_locator.hpp

@@ -32,28 +32,88 @@ namespace krabs {
     struct schema_key
     {
         guid      provider;
+
+        /**
+         * Using a string_view for name so that keys can be constructed from
+         * EVENT_RECORD pointers without allocation. If the key instance is
+         * added to the cache, 'internalize_name' must be called first so that
+         * the name points to owned memory and doesn't dangle.
+         * Only events logged with the TraceLogger API will have a name set
+         * in the key because it's available as part of the EVENT_RECORD.
+         * Other events are uniquely distinguished by their event Id.
+         */
+        std::string_view name;
+
         uint16_t  id;
-        uint8_t   opcode;
         uint8_t   version;
+        uint8_t   opcode;
         uint8_t   level;
+        uint64_t  keyword;
 
-        schema_key(const EVENT_RECORD &record)
+    private:
+        /**
+         * See note on 'name', this is only set when internalized and
+         * provides memory ownership for the string_view.
+         */
+        std::unique_ptr<std::string> backing_name;
+
+    public:
+        schema_key(const EVENT_RECORD &record, std::string_view name)
             : provider(record.EventHeader.ProviderId)
+            , name(name)
             , id(record.EventHeader.EventDescriptor.Id)
+            , version(record.EventHeader.EventDescriptor.Version)
             , opcode(record.EventHeader.EventDescriptor.Opcode)
             , level(record.EventHeader.EventDescriptor.Level)
-            , version(record.EventHeader.EventDescriptor.Version) { }
+            , keyword(record.EventHeader.EventDescriptor.Keyword) { }
+
+        schema_key(const schema_key &rhs)
+            : provider(rhs.provider)
+            , name(rhs.name)
+            , id(rhs.id)
+            , version(rhs.version)
+            , opcode(rhs.opcode)
+            , level(rhs.level)
+            , keyword(rhs.keyword)
+        {
+            internalize_name();
+        }
+
+        schema_key& operator=(const schema_key &rhs)
+        {
+            schema_key temp(rhs);
+            std::swap(*this, temp);
+            return *this;
+        }
 
         bool operator==(const schema_key &rhs) const
         {
+            // NB: Compare 'name' last for perf. Do not compare 'backing_name'.
             return provider == rhs.provider &&
                    id == rhs.id &&
+                   version == rhs.version &&
                    opcode == rhs.opcode &&
                    level == rhs.level &&
-                   version == rhs.version;
+                   keyword == rhs.keyword &&
+                   name == rhs.name;
         }
 
         bool operator!=(const schema_key &rhs) const { return !(*this == rhs); }
+
+        /**
+         * <summary>
+         * Allocate the 'backing_name' and set 'name' to point at it. This must be
+         * called before adding the key to a cache so that the lifetime of the
+         * 'name' string_view matches the lifetime of the cached instance.
+         * </summary>
+         */
+        void internalize_name()
+        {
+            if (!name.empty()) {
+                backing_name = std::make_unique<std::string>(name);
+                name = *backing_name;
+            }
+        }
     };
 }
 
@@ -73,10 +133,12 @@ namespace std {
             size_t h = 2166136261;
 
             h ^= (h << 5) + (h >> 2) + std::hash<krabs::guid>()(key.provider);
+            h ^= (h << 5) + (h >> 2) + std::hash<std::string_view>()(key.name);
             h ^= (h << 5) + (h >> 2) + key.id;
-            h ^= (h << 5) + (h >> 2) + key.opcode;
             h ^= (h << 5) + (h >> 2) + key.version;
+            h ^= (h << 5) + (h >> 2) + key.opcode;
             h ^= (h << 5) + (h >> 2) + key.level;
+            h ^= (h << 5) + (h >> 2) + key.keyword;
 
             return h;
         }
@@ -92,6 +154,14 @@ namespace krabs {
      */
     std::unique_ptr<char[]> get_event_schema_from_tdh(const EVENT_RECORD &);
 
+    /**
+     * <summary>
+     * Returns a string_view to the event name if the specified event was logged
+     * with the TraceLogger API otherwise returns an empty string_view.
+     * </summary>
+     */
+    std::string_view get_trace_logger_event_name(const EVENT_RECORD &);
+
     /**
      * <summary>
      * Fetches and caches schemas from TDH.
@@ -117,18 +187,91 @@ namespace krabs {
     // Implementation
     // ------------------------------------------------------------------------
 
+    inline std::string_view get_trace_logger_event_name(const EVENT_RECORD & record)
+    {
+        /**
+         * This implements part of the parsing that TDH would normally do so that
+         * a schema_key can be built without calling TDH (which is expensive).
+         * Here's pseudo code from the TraceLogger header describing the layout.
+         *
+         * // EventMetadata:
+         * // This pseudo-structure is the layout of the "event metadata" referenced by
+         * // EVENT_DATA_DESCRIPTOR_TYPE_EVENT_METADATA.
+         * // It provides the event's name, event tags, and field information.
+         * struct EventMetadata // Variable-length pseudo-structure, byte-aligned, tightly-packed.
+         * {
+         *     UINT16 Size; // = sizeof(EventMetadata)
+         *     UINT8 Extension[]; // 1 or more bytes. Read until you hit a byte with high bit unset.
+         *     char Name[]; // UTF-8 nul-terminated event name
+         *     FieldMetadata Fields[]; // 0 or more field definitions.
+         * };
+         */
+
+        char* metadataPtr = nullptr;
+        USHORT metadataSize = 0;
+
+        // Look for a TraceLogger event schema in the extended data.
+        for (USHORT i = 0; i < record.ExtendedDataCount; ++i) {
+            auto& dataItem = record.ExtendedData[i];
+            if (dataItem.ExtType == EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL) {
+                metadataSize = dataItem.DataSize;
+                metadataPtr = (char*)dataItem.DataPtr;
+                break;
+            }
+        }
+
+        // Didn't find one or it was too small.
+        if (metadataPtr == nullptr || metadataSize < sizeof(USHORT)) {
+            return {};
+        }
+
+        // Ensure that the sizes match to prevent reading off the buffer.
+        USHORT structSize = *(USHORT*)metadataPtr;
+        if (structSize != metadataSize) {
+            return {};
+        }
+
+        // Skipping over the 'Extension' field of the block to find the name offset.
+        // Per code comment: Read until you hit a byte with high bit unset.
+        USHORT nameOffset = sizeof(USHORT);
+        while (nameOffset < structSize) {
+            char c = *(metadataPtr + nameOffset);
+            nameOffset++; // NB: always consume the character.
+
+            // High-bit set?
+            if ((c & 0x80) != 0x80) {
+                break;
+            }
+        }
+
+        // Ensure the offset found is valid.
+        if (nameOffset >= structSize) {
+            return {};
+        }
+
+        return {metadataPtr + nameOffset};
+    }
+
     inline const PTRACE_EVENT_INFO schema_locator::get_event_schema(const EVENT_RECORD &record) const
     {
-        // check the cache
-        auto key = schema_key(record);
-        auto& buffer = cache_[key];
+        auto eventName = get_trace_logger_event_name(record);
+        auto key = schema_key(record, eventName);
 
-        if (!buffer) {
-            auto temp = get_event_schema_from_tdh(record);
-            buffer.swap(temp);
+        // Check the cache...
+        auto it = cache_.find(key);
+        if (it != cache_.end()) {
+            return (PTRACE_EVENT_INFO)it->second.get();
         }
 
-        return (PTRACE_EVENT_INFO)(buffer.get());
+        // Cache miss. Fetch the schema...
+        auto buffer = get_event_schema_from_tdh(record);
+        auto returnVal = (PTRACE_EVENT_INFO)buffer.get();
+
+        // Add the new instance to the cache.
+        // NB: key's 'internalize_name' gets called by the cctor here.
+        cache_.emplace(key, std::move(buffer));
+
+        return returnVal;
     }
 
     inline std::unique_ptr<char[]> get_event_schema_from_tdh(const EVENT_RECORD &record)

krabs/krabs/testing/record_builder.hpp

@@ -83,6 +83,7 @@ namespace krabs { namespace testing {
             size_t version,
             size_t opcode = 0,
             size_t level = 0,
+            size_t keyword = 0,
             bool trim_string_null_terminator = false);
 
         /**
@@ -180,6 +181,7 @@ namespace krabs { namespace testing {
         const size_t version_;
         const size_t opcode_;
         const size_t level_;
+        const size_t keyword_;
         EVENT_HEADER header_;
         std::vector<record_property_thunk> properties_;
         bool trim_string_null_terminator_;
@@ -214,19 +216,22 @@ namespace krabs { namespace testing {
         size_t version,
         size_t opcode,
         size_t level,
+        size_t keyword,
         bool trim_string_null_terminator)
     : providerId_(providerId)
     , id_(id)
     , version_(version)
     , opcode_(opcode)
     , level_(level)
+    , keyword_(keyword)
     , trim_string_null_terminator_(trim_string_null_terminator)
     {
         ZeroMemory(&header_, sizeof(EVENT_HEADER));
         header_.EventDescriptor.Id      = static_cast<USHORT>(id_);
         header_.EventDescriptor.Version = static_cast<UCHAR>(version_);
         header_.EventDescriptor.Opcode  = static_cast<UCHAR>(opcode_);
         header_.EventDescriptor.Level   = static_cast<UCHAR>(level_);
+        header_.EventDescriptor.Keyword = static_cast<ULONGLONG>(keyword_);
         memcpy(&header_.ProviderId, (const GUID *)&providerId_, sizeof(GUID));
     }