The object_manager_provider does not support DuplicateHandle events

[jstarink]

Summary

I am trying to track object creation, destruction and duplication on a live Windows 10 machine. According to the MOF definitions on MSDN, these events correspond to opcodes 32, 33 and 34 respectively:

• https://learn.microsoft.com/en-us/windows/win32/etw/obhandleevent
• https://learn.microsoft.com/en-us/windows/win32/etw/obhandleduplicateevent

According to the examples, object_manager_provider is the struct to go for when tracking these events. And indeed, I can receive and parse events with opcode 32 and 33. However, events with opcode 34 seem to never be reported by the callback. Am I missing something, should I enable some extra flags/options, or could this be a bug?

To Reproduce

I use the following source code, which is heavily inspired by the provided examples:

krabstest.cpp

#include <krabs.hpp>
#include <iostream>

// Mapping for process IDs to their image names.
std::map<uint32_t, std::string> process_names;

// Set of image names that we want to print out to the console.
std::set<std::string>           included_processes;


/**
 * Prints "[<pid> <image name>]: "
 */ 
void print_header(const EVENT_RECORD& record) 
{
    auto entry = process_names.find(record.EventHeader.ProcessId);
    auto process_name = entry != process_names.end() ? entry->second : "<unknown>";
    std::cout << "[" << std::dec << record.EventHeader.ProcessId << " " << process_name << "]: ";
}


int main()
{
    // Set up some processes to print output for.
    included_processes.insert("notepad.exe");
    included_processes.insert("TesterApp.exe");

    krabs::kernel_trace trace(L"My Trace");

    // In order to filter events by process name, we need to track all process start/stop events to translate IDs to names.
    krabs::kernel::process_provider process_provider;
    process_provider.add_on_event_callback([](const EVENT_RECORD& record, const krabs::trace_context& context) {
        // For maintaining the process_names mapping, we only care about start, end and DC start events.
        if (record.EventHeader.EventDescriptor.Opcode > 3)
            return;

        // Obtain schema.
        krabs::schema schema(record, context.schema_locator);
        krabs::parser parser(schema);

        // Parse out proc id and file name.
        auto processId = parser.parse<uint32_t>(L"ProcessId");
        auto imageName = parser.parse<std::string>(L"ImageFileName");

        // Update process_names mapping accordingly.
        switch (record.EventHeader.EventDescriptor.Opcode) {
            case 1: // Process start
            case 3: // Process DC Start
                process_names[processId] = imageName;
                break;

            case 2: // Process end
                process_names.erase(processId);
                break;
        }        
    });
    trace.enable(process_provider);

    // Set up the object ETW source.
    krabs::kernel::object_manager_provider ob_provider;    
    ob_provider.add_on_event_callback([](const EVENT_RECORD& record, const krabs::trace_context& context) 
    {
        // Should we print information for this process?
        auto processName = process_names.find(record.EventHeader.ProcessId);
        if (processName == process_names.end() || included_processes.find(processName->second) == included_processes.end()) {
            return;
        }

        // Obtain event data schema.
        krabs::schema schema(record, context.schema_locator);
        krabs::parser parser(schema);

        switch (record.EventHeader.EventDescriptor.Opcode) {
            case 32: // CreateHandle
                print_header(record);
                std::cout << "CreateHandle"
                    << "(Handle: " << std::hex << parser.parse<uint32_t>(L"Handle")
                    << ")" << std::endl;
                break;

            case 33: // CloseHandle
                print_header(record);
                std::cout << "CloseHandle"
                    << "(Handle: " << std::hex << parser.parse<uint32_t>(L"Handle")
                    << ")" << std::endl;
                break;

            case 34: // DuplicateHandle
                print_header(record);
                std::cout << "DuplicateHandle"
                    << "(SourceHandle: " << std::hex << parser.parse<uint32_t>(L"SourceHandle")
                    << ", TargetHandle: " << std::hex << parser.parse<uint32_t>(L"TargetHandle")
                    << ", TargetProcessId: " << std::hex << parser.parse<uint32_t>(L"TargetProcessId")
                    << ")" << std::endl;
                break;

            default:
                std::wcout << L"Unhandled object event " << schema.opcode_name() << std::endl;
                break;
        }
    });

    trace.enable(ob_provider);

    std::cout << "Starting trace...\n";
    trace.start();
}

As a test application, I have a basic program that creates a new file object, duplicates it 10 times, then closes all duplicated handles, and finally closes the main handle.

testerapp.cpp

#include <Windows.h>
#include <iostream>

int main()
{
    std::cin.get(); // activate the krabs log before pressing enter to clearly see which handles are belonging to the following code.

    auto handle = CreateFile(L"file.txt", GENERIC_READ | GENERIC_WRITE, 0, NULL, CREATE_ALWAYS, 0, NULL);
    std::cout << "Opened file (" << std::hex << handle << ")" << std::endl;

    const size_t duplicate_count = 10;
    auto duplicates = new HANDLE[duplicate_count];
    for (size_t i = 0; i < duplicate_count; i++) {
        !DuplicateHandle(
            GetCurrentProcess(),
            handle,
            GetCurrentProcess(),
            &duplicates[i],
            0,
            TRUE,
            DUPLICATE_SAME_ACCESS
        );

        std::cout << "Duplicated file (" << std::hex << duplicates[i] << ")" << std::endl;
    }

    for (size_t i = 0; i < duplicate_count; i++) {
        CloseHandle(duplicates[i]);
        std::cout << "Closed duplicated file (" << std::hex << duplicates[i] << ")" << std::endl;
    }

    CloseHandle(handle);

    std::cout << "Closed main handle file (" << std::hex << handle << ")" << std::endl;

    std::cin.get();
}

When running this with admin rights on a Windows 10 Pro N x64 machine, version 22H2, build 19045.3086, I only get the following output:

Notice how a single file object creation (12c) is directly followed up by 11 handle closure events, without any report of the file handle being duplicated.

Additional Context

It is maybe worth mentioning that other libraries that consume ETW events do seem to be able to report on object duplication. For example, using Microsoft.Diagnostics.Tracing.TraceEvent of the perfview project, reporting on handle duplication works fine:

[jstarink]

Update: If it may be of any help, when I inspect errors using add_on_error_callback, I get the following message for every duplicate handle event (34):

Could not find the schema: status_code=1168 provider_id=89497f50-effe-4440-8cf2-ce6b1cdcaca7 event_id=0

I suppose 1168 refers to ERROR_NOT_FOUND. It seems krabs cannot obtain the schema for this type of event.

[jdu2600]

or could this be a bug?

I think it's a bug. Probably in code I contributed. 😅

[swannman]

@jstarink thank you for the detailed repro steps! I was able to repro this locally - looks like it may actually be a bug in Windows.

The ETW provider gives us an EVENT_RECORD with record.EventHeader.EventDescriptor.Version of 0x03. TdhGetEventInformation returns ERROR_NOT_FOUND when we try to look up the schema for this event. However, if I manually set the Version to 0x02 the schema lookup succeeds!

I'll reach out to the Windows team to see how to get this fixed.

[jstarink]

Thanks for getting back to this. I came to the same conclusion after debugging the issue myself, but thought my understanding of TdhGetEventInformation was simply incorrect.

In case anyone else encounters this problem, as a temporary workaround, I have been using this code to parse out the MOF data manually:

ob_provider.add_on_event_callback([](const EVENT_RECORD& record, const krabs::trace_context& context) 
{
    /* ... */
    switch (record.EventHeader.EventDescriptor.Opcode)
    {
        /* ... */

    case 34: // DuplicateHandle
        char* data = (char*)record.UserData;

        auto object_pointer = *(uint64_t*) data; data += sizeof(uint64_t);
        auto source_handle = *(uint32_t*) data; data += sizeof(uint32_t);
        auto target_handle = *(uint32_t*) data; data += sizeof(uint32_t);
        auto target_pid = *(uint32_t*) data; data += sizeof(uint32_t);
        auto object_type = *(uint16_t*) data; data += sizeof(uint16_t);

        /* ... */
        break;
    }
});

This seems to have worked well enough for my use-cases. Looking forward to proper support for this however :).