microsoft / krabsetw

KrabsETW provides a modern C++ wrapper and a .NET wrapper around the low-level ETW trace consumption functions.
Other
588 stars 147 forks source link

Rundown events for Kernel logger are broken #178

Closed mediantt closed 2 years ago

mediantt commented 2 years ago

I wrote some code to consume kernel logger Process events, expecting to receive rundown of currently running instances first, the way ETW usually works. Testing revealed however, that the number of rundown events is very small and varies greatly with each run:

void test_etw()
{
    krabs::kernel_trace             trace(L"test");
    krabs::kernel::process_provider processProvider;

    int N  = 0;
    int N3 = 0;

    processProvider.add_on_event_callback([&](const EVENT_RECORD& record,
                                                  const krabs::trace_context& trace_context) {
        printf("%d   \r", ++N);
        if ( record.EventHeader.EventDescriptor.Opcode == EVENT_TRACE_TYPE_DC_START ) {
            ++N3;
        }
    });

    trace.enable(processProvider);
    printf("starting trace, press a key to stop\n");

    std::thread thread([&trace]() {
        trace.start();
    });

    _getch();

    printf("stopping trace\n");
    trace.stop();
    thread.join();
    printf("total events: %d, process rundown events: %d\n", N, N3);
}

After some investigation I stumbled upon this piece of code, which seems to be the root cause:

        ::FILETIME now;
        GetSystemTimeAsFileTime(&now);
        ULONG status = ProcessTrace(&trace_.sessionHandle_, 1, &now, NULL);

https://github.com/microsoft/krabsetw/blob/master/krabs/krabs/etw.hpp#L348

Needless to say that without StartTime parameter process rundown events arrive correctly.

        ULONG status = ProcessTrace(&trace_.sessionHandle_, 1, NULL, NULL);

I wonder if specifying StartTime can at least be made optional, since the way it is written now rundown events simply do not work.