Event Trace for Windows (ETW) FileName in File events missing

Question

I am trying to do some work with ETW in C#. Some raw events require a sort of 'aggregation' performed on them to obtain the full data in each event. This action takes information from some events and fills it in others.

This action can be performed on the output file of the ETW framework however I need to perform it dynamically in the real time of event apperance. I managed to perform this for the registry events and their missing "KeyName" values thanks to the answers in this thread.

I could not however find any information that would allow me to interpret the ETW file events to figure out the "FileName" attribute in each event.

Does anyone know how the FileIO events should be interpreted to obtain missing "FileNames" in each event? Are there any resources on this topic that I might have missed?

Ps. I am sorry if this question is unclear.

Answer 1

You might be missing FileRundown events. Normally, KernelTraceEventParserState keeps a dictionary which maps FileObject/FileKey to FileName. KernelTraceEventParser configures various hooks to fill this dictionary. The first problems are cleanup and delete events that remove file names from the dictionary before your hook is called. For other events, the problem is that you miss FileKey mappings for processes that were running before your trace started. And I haven't found a way to force the rundown events to run at the begging of the session. The only workaround I can propose is to run a short trace session with DiskIO | DiskFileIO keywords enabled and prepare your file key map. Later, in the main session, update it when you receive the FileIO/Create event. You may check a post on my blog to learn more details.

Below, I paste the F# code I used to test FileIO events. I hope it will help you with your scenario.

open System
open System.Threading
open Microsoft.Diagnostics.Tracing
open Microsoft.Diagnostics.Tracing.Parsers
open Microsoft.Diagnostics.Tracing.Session
open System.Collections.Generic
open Microsoft.Diagnostics.Tracing.Parsers.Kernel

type NtKeywords = KernelTraceEventParser.Keywords
type ClrKeywords = ClrTraceEventParser.Keywords

let rundownFileKeyMap sessionName =
    use session = new TraceEventSession(sessionName)

    let traceFlags = NtKeywords.DiskFileIO ||| NtKeywords.DiskIO
    session.EnableKernelProvider(traceFlags, NtKeywords.None) |> ignore

    let fileKeyMap = Dictionary<uint64, string>()
    session.Source.Kernel.add_FileIOFileRundown(fun ev -> fileKeyMap.[ev.FileKey] <- ev.FileName)

    use cts = new CancellationTokenSource(TimeSpan.FromSeconds(2.0))
    use _r = cts.Token.Register(fun _ -> session.Stop() |> ignore)

    session.Source.Process() |> ignore

    fileKeyMap

let processEvent (fileObjectAndKeyMap : Dictionary<uint64, string>) (ev : TraceEvent) =
    let opcode = int32(ev.Opcode)

    let fileKey =
        let i = ev.PayloadIndex("FileKey")
        if i >= 0 then ev.PayloadValue(i) :?> uint64 else 0UL
    let fileObject =
        let i = ev.PayloadIndex("FileObject")
        if i >= 0 then ev.PayloadValue(i) :?> uint64 else 0UL

    let path = 
        if opcode = 64 (* create *) then
            let ev = ev :?> FileIOCreateTraceData
            let fileName = ev.FileName
            fileObjectAndKeyMap.[fileObject] <- fileName
            fileName
        else
            let chooser k =
                match fileObjectAndKeyMap.TryGetValue(k) with
                | (true, s) -> Some s
                | (false, _) -> None
            seq { fileKey; fileObject } 
            |> Seq.tryPick chooser 
            |> Option.defaultValue "n/a"

    printfn "%d %s (%d) (%s) [%d.%d] (%s) key: 0x%X object: 0x%X '%s'" 
        (uint32(ev.EventIndex)) ev.EventName opcode (ev.GetType().Name) 
        ev.ProcessID ev.ThreadID ev.ProcessName fileKey fileObject path

[<EntryPoint>]
let main _ =
    let sessionName = sprintf "mytrace-%d" DateTime.UtcNow.Ticks

    use session = new TraceEventSession(sessionName)

    let traceFlags = NtKeywords.FileIOInit
    let stackFlags = NtKeywords.None
    session.EnableKernelProvider(traceFlags, stackFlags) |> ignore

    printf "Collecting rundown events..."
    let fileObjectAndKeyMap = rundownFileKeyMap (sprintf "%s_rundown" sessionName)
    printfn "done"
    printfn "Key map size: %d" fileObjectAndKeyMap.Count

    use _sub = session.Source.Kernel.Observe(fun s -> s.StartsWith("FileIO", StringComparison.Ordinal))
               |> Observable.subscribe (processEvent fileObjectAndKeyMap)

    Console.CancelKeyPress.Add(fun ev -> ev.Cancel <- true; session.Stop() |> ignore)

    session.Source.Process() |> ignore

    printfn "Key map size: %d" fileObjectAndKeyMap.Count
    0