Monitoring registry activity with ETW

If you are working on Windows, you know that the registry is a crucial component of this system. It contains lots of system and application configuration data. Apps use the registry to access some of the in-memory OS data. Therefore, monitoring the registry activity is one of the essential parts of the troubleshooting process. Fortunately, we have several tools to help us with this task, Process Monitor being probably the most popular one. In this post, though, I am going to prove that we could use ETW for this purpose as well.

A brief introduction to the registry paths

The way how the registry stores its data is quite complicated. I will focus only on the parts required to understand the ETW data, so if you would like to dig deeper, check the awesome Windows Internals book. When we think of the registry structure, we usually imagine the Regedit panel with subtrees under a few root keys:

The root key names, such as HKEY_LOCAL_MACHINE (or HKLM), translate internally to paths understandable by the Windows object manager. For example, HKLM would become \Registry\Machine. The \Registry part references a kernel key object that we can find using, for example, WinObjEx64:

When an application tries to access a registry path, the object manager forwards the call to the configuration manager. The configuration manager parses the path and returns a handle to a key object. Each key object points to its corresponding key control block (KCB). This KCB could be shared with other key objects as the configuration manager allocates exactly one KCB for a given registry path. Additionally, each KCB has a reference count, which reflects the number of key objects referencing it. Let’s see this in action while also recording the ETW events.

Registry events

We will use the simple code below to create and later delete a registry key with a string value:

let subkey = "Software\\LowLevelDesign"

use hkcu = RegistryKey.OpenBaseKey(RegistryHive.CurrentUser, RegistryView.Default)
do 
    use mytraceKey = hkcu.CreateSubKey(subkey)
    mytraceKey.SetValue("start", DateTime.UtcNow.ToString(), RegistryValueKind.String)

Console.WriteLine("Press enter to delete the key...")
Console.ReadLine() |> ignore

hkcu.DeleteSubKeyTree(subkey)

In a moment, I will explain why I am creating the LowLevelDesign key in a separate using scope. But first, let’s check the ETW trace for these operations:

4065.7271 (21776.18288) Registry/Open [0xFFFFAE0C9795E860] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\Software\LowLevelDesign' [0] -> 0 (0.01540)
4066.5557 (21776.18288) Registry/Open [0xFFFFAE0C9795E860] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\Software\LowLevelDesign' [0] -> 0 (0.00850)
4066.5796 Registry/KCBCreate [0xFFFFAE0CC1544D20] <- '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN'
4066.6179 (21776.18288) Registry/Create [0xFFFFAE0C9795E860] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\Software\LowLevelDesign' [0] -> 0 (0.10650)
4070.3576 (21776.18288) Registry/SetValue [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN\start' [0] -> 0 (0.02800)
4070.3731 (21776.18288) Registry/Close [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN' [0] -> 0 (0.00020)

<Enter pressed>

144250.1876 (21776.18288) Registry/Open [0xFFFFAE0C9795E860] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\Software\LowLevelDesign' [0] -> 0 (0.02720)
144250.2030 (21776.18288) Registry/Query [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN' [0] -> 0 (0.00430)
144250.2135 (21776.18288) Registry/Close [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN' [0] -> 0 (0.00010)
144250.7885 (21776.18288) Registry/Open [0xFFFFAE0C9795E860] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\Software\LowLevelDesign' [0] -> 0 (0.00860)
144250.9071 (21776.18288) Registry/Delete [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN' [0] -> 0 (0.06300)
144250.9087 (21776.18288) Registry/Close [0xFFFFAE0CC1544D20] = '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN' [0] -> 0 (0.00020)
144250.9118 Registry/KCBDelete [0xFFFFAE0CC1544D20] <- '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN'

If you look at the paths in the trace, you will immediately see that ETW uses the “kernel” registry paths (starting with \Registry). As the LowLevelDesign registry key didn’t exist when the app started, the configuration manager needed to create it. That’s the KCBCreate event we see in the trace:

4066.5796 Registry/KCBCreate [0xFFFFAE0CC1544D20] <- '\REGISTRY\USER\S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN'

We can confirm that the address is indeed a valid KCB address in WinDbg:

lkd> !reg kcb 0xFFFFAE0CC1544D20

Key              : \REGISTRY\USER\S-S-1-5-21-435461841-1121519493-2341496315-1001\SOFTWARE\LOWLEVELDESIGN
RefCount         : 0x0000000000000000
Flags            : DelayedClose, CompressedName,
ExtFlags         :
Parent           : 0xffffae0c9ac26600
KeyHive          : 0xffffae0c9a174000
KeyCell          : 0xed9160 [cell index]
TotalLevels      : 5
LayerHeight      : 0
MaxNameLen       : 0x0
MaxValueNameLen  : 0xa
MaxValueDataLen  : 0x28
LastWriteTime    : 0x 1d6760a:0x8c2420e6
KeyBodyListHead  : 0xffffae0cc1544d98 0xffffae0cc1544d98
SubKeyCount      : 0
Owner            : 0x0000000000000000
KCBLock          : 0xffffae0cc1544e18
KeyLock          : 0xffffae0cc1544e28

When I closed all the handles and deleted the LowLevelDesign key, the kernel emitted the KCBDelete key. Interestingly, when I created and deleted the LowLevelDesign key without disposing of mytraceKey, the KCBDelete event was missing. Also, the LowLevelDesign KCB address was soon reused by another key. That’s why I placed the using scope in the original code. Let’s look in the tracing application code and explain other hex values from the trace.

KCBs, registry key names, and the trace session

All registry ETW events have the same format, but the meaning of the KeyName property is different for various OpCodes. To correctly resolve key names in “regular” registry events, we need to analyze the KCB events first. For KCBs opened/created during the trace session, we should receive a KCBCreate event. From this event, we need to save the FileName with its corresponding KeyHandle. To acquire FileNames for KCBs that were opened before our trace session started, we need to run a rundown session. This procedure is very similar to what I did for the FileIORundown events in the previous post. Sample code looks as follows:

let regHandleToKeyName = Dictionary<uint64, string>()

let processKCBCreateEvent (ev : RegistryTraceData) =
    printfn "%.4f %s [0x%X] <- '%s'" ev.TimeStampRelativeMSec ev.EventName ev.KeyHandle ev.KeyName 
    regHandleToKeyName.[ev.KeyHandle] <- ev.KeyName

let processKCBDeleteEvent (ev : RegistryTraceData) =
    printfn "%.4f %s [0x%X] <- '%s'" ev.TimeStampRelativeMSec ev.EventName ev.KeyHandle ev.KeyName 
    regHandleToKeyName.Remove(ev.KeyHandle) |> ignore

let runRundownSession sessionName =
    printf "Starting rundown session %s" sessionName
    use session = new TraceEventSession(sessionName)

    let traceFlags = NtKeywords.Registry

    session.EnableKernelProvider(traceFlags, NtKeywords.None) |> ignore

    // Accessing the source enables kernel provider so must be run after the EnableKernelProvider call
    makeKernelParserStateless session.Source
    session.Source.Kernel.add_RegistryKCBRundownBegin(Action<_>(processKCBCreateEvent))
    session.Source.Kernel.add_RegistryKCBRundownEnd(Action<_>(processKCBCreateEvent))

    // Rundown session lasts 2 secs - make it longer, if required
    use cts = new CancellationTokenSource(TimeSpan.FromSeconds(2.0))
    use _r = cts.Token.Register(fun _ -> session.Stop() |> ignore)

    session.Source.Process() |> ignore

Now, when a registry event has a non-zero KeyHandle value, we need to look up the parent path in the regHandleToKeyName dictionary and prepend it to the KeyName value from the event payload. Finally, for the “key-value” events (such as EVENT_TRACE_TYPE_REGSETVALUE), the KeyName property is, in fact, a value name. Fortunately, the RegistryTraceData class fixes this confusion by providing a ValueName property. We only need to make sure we use it for valid events. Below, you may find sample code for handling the “regular” registry events:

let filter (ev : RegistryTraceData) =
    ev.ProcessID = pid || ev.ProcessID = -1

let getFullKeyName keyHandle eventKeyName =
    let baseKeyName =
        match regHandleToKeyName.TryGetValue(keyHandle) with
        | (true, name) -> name
        | (false, _) -> ""
    Path.Combine(baseKeyName, eventKeyName)

let processKeyEvent (ev : RegistryTraceData) =
    if filter ev then
        let keyName = getFullKeyName ev.KeyHandle ev.KeyName
        printfn "%.4f (%d.%d) %s [0x%X] = '%s' [%d] -> %d (%.5f)" 
            ev.TimeStampRelativeMSec ev.ProcessID ev.ThreadID ev.EventName 
            ev.KeyHandle keyName ev.Index ev.Status ev.ElapsedTimeMSec

let processValueEvent (ev : RegistryTraceData) =
    if filter ev then
        let keyName = getFullKeyName ev.KeyHandle ev.ValueName
        printfn "%.4f (%d.%d) %s [0x%X] = '%s' [%d] -> %d (%.5f)" 
            ev.TimeStampRelativeMSec ev.ProcessID ev.ThreadID ev.EventName 
            ev.KeyHandle keyName ev.Index ev.Status ev.ElapsedTimeMSec

And the full tracer sample is available in my blog samples repository. Remember to run the code as Admin.