Do IEventRecord objects get reused?

[duckfez]

This is possibly a dumb question, and shows my noobness with C#.

I am trying to match up two different IEventRecord objects coming off of the same provider - basically matching up request and response. When I get the "request" event from ETW, I shove the IEventRecord reference into a container object and shove that container onto a Dictionary. When I get the "response" event, I pull the container back off of the Dictionary and attempt to re-assemble the pair.

What I seem to be observing is that the IEventRecord from the request gets overwritten by the IEventRecord from the response - that is they contain the same data in the end. Makes me think that ultimately the request and response are both referring to the exact same instance of IEventRecord in the end...

( Relatively experienced with C/C++, this is my first C# project so I could just be doing something wrong )

    class DNSRecord
    {
        public IEventRecord request;
        public IEventRecord response;
    }
        void OnEventRecord(IEventRecord record)
        {
           switch(record.Id)
            {
                case 256:
                    processRequest(record);
                    break;

                case 257:
                    processResponse(record);
                    break;

                default:  break;
            }

        }

        void processRequest(IEventRecord record)
        {
            DNSRecord r = new DNSRecord();
            r.request = record;

            events.Add("whee", r);
            printRecordDebug(events["whee"].request);
        }

        void processResponse(IEventRecord record)
        {
            DNSRecord r = events["whee"];            
            printRecordDebug(events["whee"].request);
            events.Remove("whee");
        }

[swannman]

Thanks for reaching out!

In processResponse should printRecordDebug be accessing .response rather than .request?

void processResponse(IEventRecord record)
{
    DNSRecord r = events["whee"];            
    printRecordDebug(events["whee"].request); // .response?
    events.Remove("whee");
}

[duckfez]

Hey Matt! I guess I left out the important part of what I was seeing .. Based on my code attemping to print the .request twice you'd expect to see the exact same object dumped twice, right?

What I actually get, though, is the content of .request changes inside of .processResponse to have the response's data in it. Almost like I'm just passing around many different references to the same underlying object...

Basically, I dump what should be the same IEventRecord object from two places and get two different outputs....

[swannman]

Could you share the entire VS solution (or a minimal repro) as an attachment?

[duckfez]

Here's the whole project/solution - https://github.com/duckfez/Thing. I really really really appreciate the second set of eyes!!

[duckfez]

My testing environment is a 2016 Server w/ DNS Service, using nslookup to trigger DNS requests against 127.0.0.1.

[duckfez]

@swannman I've been working on a better understanding and reproduction of this and have pretty compelling (to me) evidence that suggests that a reference to IEventRecord can't be safely saved and used later. Later ETW events will overwrite something that your IEventRecord points to (maybe down in the C++ API?).

       void OnEventRecord(IEventRecord record)
        {
            switch(record.Id)
            {
                case 256:
                    processRequest(record);
                    break;

                case 257:
                    processResponse(record);
                    break;

                default:  break;
            }            
        }

        void processRequest(IEventRecord record)
        {
            DNSRecord r = new DNSRecord();
            r.request = record;
            events.Add("whee", r);

            outfile.WriteLine($"during processRequest request.Id = {events["whee"].request.Id}");
        }

        void processResponse(IEventRecord record)
        {
            DNSRecord r = events["whee"];
            outfile.WriteLine($"during processResponse1 request.Id = {events["whee"].request.Id}");
            r.response = record;
            outfile.WriteLine($"during processResponse2 request.Id = {events["whee"].request.Id}");
            events.Remove("whee");
        }

You should expect (with the DNS ETW provider I'm testing on) that the request.Id should always be 256 - otherwise I'd not land in processRequest at all. But this updated version, here's what I'm seeing in the output:

Starting Up
during processRequest request.Id = 256
during processResponse1 request.Id = 257
during processResponse2 request.Id = 257

I'm going to continue trimming this down to the slimmest reproduction I can.

[swannman]

Thank you for sharing the repro! The behavior you are seeing matches my expectations:

• Each ETW trace session contains a circular buffer of EVENT_RECORD objects.
• Windows writes new records into the buffer and calls the trace session's EventRecordCallback.
• On the callback, Krabs receives a reference to an EVENT_RECORD and forwards that reference to subscribers.
  • In order to forward an event to a managed code subscriber, Krabs instantiates managed EventRecord and EventRecordMetadata objects that wrap the record data and metadata. These managed objects wrap a reference to the underlying EventRecord rather than making a copy of the record.
• When all subscribers have finished handling the event and execution returns from the callback, the EVENT_RECORD in the circular buffer is available for Windows to reuse.
• Future callbacks on the trace session may deliver Krabs a reference to the same memory address as a previous EVENT_RECORD, but the contents of the record will have been overwritten by a new event.

Krabs operates on references to the EVENT_RECORD for performance reasons -- instead of copying the entire event on each callback, we only copy the metadata or properties that the subscriber accesses through the EventRecord and EventRecordMetadata APIs.

If you need to preserve data from an ETW record beyond the lifetime of a given callback, the best-practice would be to copy the data you need into a new C# object (POCO). These objects are small and .NET garbage collection should manage them nicely.

Let me know if that helps!

[duckfez]

That explains the situation perfectly. Krabsetw is some pretty fine software now that I know how to use it right. Thanks again!