Distinguish TraceLogging events that share a name in the schema cache

[Chris Davis (chrdavis)]

Fixes #193.

TraceLogging events do not get a meaningful event id, so the schema cache key could not tell two events from the same provider apart. Adding the event name (#242) covered the common case, but a provider may log the same event name from several call sites with different fields. Those variants agree on provider, name, id, version, opcode, level and keyword, so they still collided and the first schema retrieved was used to decode all of them - silently shifting every field, and potentially reading past the end of the user data buffer.

The TraceLogging metadata is the schema, so hash it into the key. This keeps the cache effective for repeated events while separating variants, and costs no extra TdhGetEventInformation call. The hash is FNV-1a over a small blob; 0 is reserved to mean "no metadata".

Opt-in per provider

Hashing walks the whole metadata blob, so it costs time proportional to the size of the event. Only a handful of providers ever reuse an event name, so this is off by default and enabled per provider:

krabs::provider<> provider(guid);
provider.enable_trace_logging_full_schema_hashing();  // before trace.enable()
trace.enable(provider);

var provider = new Provider("Microsoft.Windows.AppLifeCycle.UI");
provider.EnableTraceLoggingFullSchemaHashing();
trace.Enable(provider);

provider<T> carries the flag, krabs::trace::enable() hands the provider's GUID to the trace's schema_locator, and get_event_schema_no_throw() only hashes the metadata for providers on that list. Providers that do not opt in take the same code path they did before this PR, so there is no added per-event cost for existing users. Manifest, MOF and WPP events are unaffected either way; they carry no TraceLogging metadata and their event id already identifies them uniquely. Kernel providers are excluded at compile time.

The opt-in list is a flat vector rather than a set: it is empty unless someone opts in, and a trace has a handful of providers at most, so scanning it beats hashing a GUID on every event. trace_context::schema_locator and trace::context_ lose their const qualifier so enable() can record the policy; callbacks still only ever see a const trace_context&.

Also fixed

Two defects in the metadata parsing this relies on:

• The name was read with an unbounded string_view constructor. A record whose name is not nul-terminated would read past the end of the extended data item. The search is now bounded by the metadata extent.

• The parser required the metadata Size field to exactly equal the extended data item size. Size describes the pseudo-structure and the item may be larger, so valid events lost their name and fell back to the ambiguous key. Size is now range-checked against the item instead.

And schema_key::operator=, which recursed until the stack was exhausted: the user-declared copy constructor and copy assignment suppress the implicit move operations, so the std::swap it used resolved back to operator= itself. It now assigns members directly and copies the incoming name into new storage before releasing the old, so the assigned key owns its name, as with the copy constructor. That holds even when the source borrows its name from the key being assigned to (key = schema_key(record, key.name)).

These three are unconditional - they are correctness fixes, independent of the opt-in.

Verification

• All 214 krabstests pass. New tests cover the opt-in and its propagation from the provider to the trace's schema_locator (7 tests), and schema_key::operator= ownership, including assignment from a key that borrows its name from the target (2 tests).
• examples/SchemaKeyCollisionRepro registers its own TraceLogging provider, emits two variants of one event name and consumes them with krabs. It exits 0 with the opt-in and 1 without it, so it doubles as a regression check for both halves of the behaviour.

[Matt Swann (swannman)]

Chris Davis (@chrdavis) thanks for submitting this! The problem you're solving makes sense - we have one concern about performance.

In the current model, the schema lookup cost for all TraceLogging events is the same; in the proposed change, the cost is proportional to the size of the event:

  ━━━━━━━━━━━━━━━━━━━━━  ━━━━━━━━  ━━━━━━━━━  ━━━━━━━━━━
   Manifest                13 ns      14 ns       ~1 ns
  ─────────────────────  ────────  ─────────  ──────────
   TraceLogging, 64 B      44 ns      89 ns      ~44 ns
  ─────────────────────  ────────  ─────────  ──────────
   TraceLogging, 256 B     46 ns     325 ns     ~279 ns
  ─────────────────────  ────────  ─────────  ──────────
   TraceLogging, 1 KiB     46 ns    1.27 µs    ~1.22 µs
  ─────────────────────  ────────  ─────────  ──────────
   TraceLogging, 4 KiB     46 ns    5.01 µs    ~4.97 µs

Would you rework this to be a per-provider policy that is opt-in?

[Matt Swann (swannman)]

Good approach, but let's make this opt-in on a per-provider basis. Thanks!

[Chris Davis (chrdavis)]

Matt Swann (@swannman) Thanks - reworked it into a per-provider opt-in in 636fbc9. It's off by default, so nothing changes for existing users:

krabs::provider<> provider(guid);
provider.enable_trace_logging_schema_disambiguation();  // before trace.enable()
trace.enable(provider);

var provider = new Provider("Microsoft.Windows.AppLifeCycle.UI");
provider.EnableTraceLoggingSchemaDisambiguation();
trace.Enable(provider);

provider<T> carries the flag, krabs::trace::enable() hands the provider's GUID to the trace's schema_locator, and get_event_schema_no_throw() only hashes the metadata for providers on that list. A provider that hasn't opted in takes exactly the code path it did before this PR, so the 44ns -> 5.01us you measured only applies to providers that ask for it. Kernel providers are excluded at compile time, and manifest/MOF/WPP events were never affected.

The opt-in list is a flat vector rather than a hash set deliberately: it's empty unless someone opts in, and a trace has a handful of providers at most, so the scan is cheaper than hashing a GUID on every event. The one visible consequence is that trace_context::schema_locator and trace::context_ are no longer const - callbacks still only ever see a const trace_context&.

The three correctness fixes in this PR (the unbounded name read, the over-strict Size check, and the infinite recursion in schema_key::operator=) stayed unconditional, since they're bugs rather than part of the feature.

All 212 krabstests pass, including 7 new ones for the opt-in, and examples/SchemaKeyCollisionRepro now exits 0 with the opt-in and 1 without it - so it covers both halves of the behaviour.

Happy to rename enable_trace_logging_schema_disambiguation if you'd prefer something shorter, and equally happy to drop the managed EnableTraceLoggingSchemaDisambiguation() wrapper from this PR if you'd rather keep it native-only for now.

[Matt Swann (swannman)]

Looking good! Found a potential memory corruption issue and added a few naming nits.

[Matt Swann (swannman)]

trace_logging_full_schema_hashing_enabled, similar changes elsewhere

[Chris Davis (chrdavis)]

Done in d9bf192 - trace_logging_full_schema_hashing_enabled(), on both provider<T> and schema_locator.

[Chris Davis (chrdavis)]

The backing member now follows suit as well: trace_logging_full_schema_hashing_enabled_ in 4c8ab69.

[Matt Swann (swannman)]

Approved with the most minor of nit comments if you'd be willing to do the rename?

[Matt Swann (swannman)]

nit: trace_logging_full_schema_hashing_enabled_, parallel to rundown_enabled_ above

[Chris Davis (chrdavis)]

Done in 4c8ab69 - renamed to trace_logging_full_schema_hashing_enabled_. Thanks for the review!