From 899181905d4eb329b6119593292ea761c897ce2e Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Wed, 12 Dec 2018 16:05:33 -0800 Subject: [PATCH 01/17] Add basic Go ETW implementation --- etw/etw.go | 7 ++++ etw/event.go | 54 +++++++++++++++++++++++++ etw/eventdata.go | 15 +++++++ etw/eventmetadata.go | 44 +++++++++++++++++++++ etw/logrus/hook.go | 78 ++++++++++++++++++++++++++++++++++++ etw/provider.go | 87 +++++++++++++++++++++++++++++++++++++++++ etw/sample/sample.go | 53 +++++++++++++++++++++++++ etw/zsyscall_windows.go | 69 ++++++++++++++++++++++++++++++++ 8 files changed, 407 insertions(+) create mode 100644 etw/etw.go create mode 100644 etw/event.go create mode 100644 etw/eventdata.go create mode 100644 etw/eventmetadata.go create mode 100644 etw/logrus/hook.go create mode 100644 etw/provider.go create mode 100644 etw/sample/sample.go create mode 100644 etw/zsyscall_windows.go diff --git a/etw/etw.go b/etw/etw.go new file mode 100644 index 0000000..e60a8fa --- /dev/null +++ b/etw/etw.go @@ -0,0 +1,7 @@ +package etw + +//go:generate go run $GOROOT/src/syscall/mksyscall_windows.go -output zsyscall_windows.go etw.go + +//sys eventRegister(providerId *windows.GUID, callback uintptr, callbackContext uintptr, providerHandle *providerHandle) (win32err error) = advapi32.EventRegister +//sys eventUnregister(providerHandle providerHandle) (win32err error) = advapi32.EventUnregister +//sys eventWriteTransfer(providerHandle providerHandle, descriptor *EventDescriptor, activityID *windows.GUID, relatedActivityID *windows.GUID, dataDescriptorCount uint32, dataDescriptors *eventDataDescriptor) (win32err error) = advapi32.EventWriteTransfer diff --git a/etw/event.go b/etw/event.go new file mode 100644 index 0000000..5639d0a --- /dev/null +++ b/etw/event.go @@ -0,0 +1,54 @@ +package etw + +type Channel uint8 + +const ( + ChannelTracelogging Channel = 11 +) + +type Level uint8 + +const ( + LevelAlways Level = iota + LevelCritical + LevelError + LevelWarning + LevelInfo + LevelVerbose +) + +type Event struct { + Descriptor *EventDescriptor + Metadata *EventMetadata + Data *EventData +} + +type EventDescriptor struct { + ID uint16 + Version uint8 + Channel Channel + Level Level + Opcode uint8 + Task uint16 + Keyword uint64 +} + +func NewEventDescriptor() *EventDescriptor { + return &EventDescriptor{ + ID: 0, + Version: 0, + Channel: ChannelTracelogging, + Level: LevelVerbose, + Opcode: 0, + Task: 0, + Keyword: 0, + } +} + +func NewEvent(name string, descriptor *EventDescriptor) *Event { + return &Event{ + Descriptor: descriptor, + Metadata: NewEventMetadata(name), + Data: &EventData{}, + } +} diff --git a/etw/eventdata.go b/etw/eventdata.go new file mode 100644 index 0000000..9fc5c4d --- /dev/null +++ b/etw/eventdata.go @@ -0,0 +1,15 @@ +package etw + +import ( + "bytes" + "encoding/binary" +) + +type EventData struct { + buffer bytes.Buffer +} + +func (ed *EventData) AddString(data string) { + binary.Write(&ed.buffer, binary.LittleEndian, []byte(data)) + binary.Write(&ed.buffer, binary.LittleEndian, byte(0)) +} diff --git a/etw/eventmetadata.go b/etw/eventmetadata.go new file mode 100644 index 0000000..9c480d6 --- /dev/null +++ b/etw/eventmetadata.go @@ -0,0 +1,44 @@ +package etw + +import ( + "bytes" + "encoding/binary" +) + +type InType byte + +const ( + InTypeNull InType = iota + InTypeUnicodeString + InTypeAnsiString + InTypeInt8 + InTypeUint8 + InTypeInt16 + InTypeUint16 + InTypeInt32 + InTypeUint32 + InTypeInt64 + InTypeUint64 + InTypeFloat + InTypeDouble + InTypeBool32 +) + +type EventMetadata struct { + buffer bytes.Buffer +} + +func NewEventMetadata(name string) *EventMetadata { + em := EventMetadata{} + binary.Write(&em.buffer, binary.LittleEndian, uint16(0)) // Length placeholder + binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Tags + binary.Write(&em.buffer, binary.LittleEndian, []byte(name)) // Event name + binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Null terminator for name + return &em +} + +func (em *EventMetadata) AddField(name string, inType InType) { + binary.Write(&em.buffer, binary.LittleEndian, []byte(name)) // Field name + binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Null terminator for name + binary.Write(&em.buffer, binary.LittleEndian, byte(inType)) // In type +} diff --git a/etw/logrus/hook.go b/etw/logrus/hook.go new file mode 100644 index 0000000..7fec697 --- /dev/null +++ b/etw/logrus/hook.go @@ -0,0 +1,78 @@ +package hook + +import ( + "fmt" + "reflect" + + "github.com/Microsoft/go-winio/etw" + "github.com/sirupsen/logrus" + + "golang.org/x/sys/windows" +) + +// Hook is a Logrus hook which logs received events to ETW. +type Hook struct { + provider *etw.Provider +} + +// NewHook registers a new ETW provider and returns a hook to log from it. +func NewHook(providerName string, providerID *windows.GUID) (*Hook, error) { + hook := Hook{} + + provider, err := etw.NewProvider(providerName, providerID, nil) + if err != nil { + return nil, err + } + hook.provider = provider + + return &hook, nil +} + +// Levels returns the set of levels that this hook wants to receive log entries +// for. +func (h *Hook) Levels() []logrus.Level { + return []logrus.Level{ + logrus.TraceLevel, + logrus.DebugLevel, + logrus.InfoLevel, + logrus.WarnLevel, + logrus.ErrorLevel, + logrus.FatalLevel, + logrus.PanicLevel, + } +} + +// Fire receives each Logrus entry as it is logged, and logs it to ETW. +func (h *Hook) Fire(e *logrus.Entry) error { + descriptor := etw.NewEventDescriptor() + + // We could try to map Logrus levels to ETW levels, but we would lose some + // fidelity as there are fewer ETW levels. So instead we use the level + // directly. + descriptor.Level = etw.Level(e.Level) + + event := etw.NewEvent("LogrusEntry", descriptor) + + event.Metadata.AddField("Message", etw.InTypeAnsiString) + event.Data.AddString(e.Message) + + for k, v := range e.Data { + switch reflect.TypeOf(v).Kind() { + case reflect.String: + event.Metadata.AddField(k, etw.InTypeAnsiString) + event.Data.AddString(v.(string)) + default: + event.Metadata.AddField(k, etw.InTypeAnsiString) + event.Data.AddString(fmt.Sprintf(" %v", reflect.TypeOf(v), v)) + } + } + + h.provider.WriteEvent(event) + + return nil +} + +// Close cleans up the hook and closes the ETW provider. +func (h *Hook) Close() error { + return h.provider.Close() +} diff --git a/etw/provider.go b/etw/provider.go new file mode 100644 index 0000000..47521eb --- /dev/null +++ b/etw/provider.go @@ -0,0 +1,87 @@ +package etw + +import ( + "bytes" + "encoding/binary" + "unsafe" + + "golang.org/x/sys/windows" +) + +type eventDataDescriptorType uint8 + +const ( + eventDataDescriptorTypeUserData eventDataDescriptorType = iota + eventDataDescriptorTypeEventMetadata + eventDataDescriptorTypeProviderMetadata +) + +type Provider struct { + handle providerHandle + metadata *bytes.Buffer +} + +type providerHandle windows.Handle + +type EnableCallback func(*windows.GUID, uint32, byte, uint64, uint64, uintptr) + +type eventDataDescriptor struct { + ptr uint64 + size uint32 + dataType eventDataDescriptorType + reserved1 uint8 + reserved2 uint16 +} + +func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buffer *bytes.Buffer) { + // Passing a pointer to Go-managed memory as part of a block of memory is risky since the GC doesn't know about it. + // If we find a better way to do this we should use it instead. + descriptor.ptr = uint64(uintptr(unsafe.Pointer(&buffer.Bytes()[0]))) + descriptor.size = uint32(buffer.Len()) + descriptor.dataType = dataType +} + +// NewProvider creates and registers a new provider. +func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provider, error) { + innerCallback := func(sourceID *windows.GUID, isEnabled uint32, level byte, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, _ uintptr) uintptr { + if callback != nil { + callback(sourceID, isEnabled, level, matchAnyKeyword, matchAllKeyword, filterData) + } + return 0 + } + + var providerHandle providerHandle + if err := eventRegister(id, windows.NewCallback(innerCallback), 0, &providerHandle); err != nil { + return nil, err + } + + var metadataBuffer bytes.Buffer + binary.Write(&metadataBuffer, binary.LittleEndian, uint16(0)) + binary.Write(&metadataBuffer, binary.LittleEndian, []byte(name)) + binary.Write(&metadataBuffer, binary.LittleEndian, byte(0)) + binary.LittleEndian.PutUint16(metadataBuffer.Bytes(), uint16(metadataBuffer.Len())) + + return &Provider{ + handle: providerHandle, + metadata: &metadataBuffer, + }, nil +} + +// Close unregisters the provider. +func (provider *Provider) Close() error { + return eventUnregister(provider.handle) +} + +// WriteEvent writes a single event to ETW, from this provider. +func (provider *Provider) WriteEvent(event *Event) error { + // Finalize the event metadata buffer by filling in the buffer length at the + // beginning. + binary.LittleEndian.PutUint16(event.Metadata.buffer.Bytes(), uint16(event.Metadata.buffer.Len())) + + var dataDescriptors [3]eventDataDescriptor + dataDescriptors[0].set(eventDataDescriptorTypeProviderMetadata, provider.metadata) + dataDescriptors[1].set(eventDataDescriptorTypeEventMetadata, &event.Metadata.buffer) + dataDescriptors[2].set(eventDataDescriptorTypeUserData, &event.Data.buffer) + + return eventWriteTransfer(provider.handle, event.Descriptor, nil, nil, 3, &dataDescriptors[0]) +} diff --git a/etw/sample/sample.go b/etw/sample/sample.go new file mode 100644 index 0000000..46850dc --- /dev/null +++ b/etw/sample/sample.go @@ -0,0 +1,53 @@ +// Shows a sample usage of the ETW logging package. +package main + +import ( + "bufio" + "fmt" + "os" + + "github.com/Microsoft/go-winio/etw" + "github.com/sirupsen/logrus" + + "golang.org/x/sys/windows" +) + +func callback(sourceID *windows.GUID, isEnabled uint32, level byte, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr) { + fmt.Printf("Callback: isEnabled=%d, level=%d, matchAnyKeyword=%d\n", isEnabled, level, matchAnyKeyword) +} + +func main() { + providerID := windows.GUID{0xdd2062c6, 0x5d1b, 0x4a0f, [8]uint8{0xbd, 0xb9, 0x22, 0x28, 0xbc, 0xb1, 0x07, 0x7c}} + + provider, err := etw.NewProvider("TestProvider", &providerID, callback) + if err != nil { + logrus.Error(err) + return + } + defer func() { + if err := provider.Close(); err != nil { + logrus.Error(err) + } + }() + + reader := bufio.NewReader(os.Stdin) + + fmt.Println("Press enter to log an event") + reader.ReadString('\n') + + event := etw.NewEvent("TestEvent", etw.NewEventDescriptor()) + event.Metadata.AddField("TestField", etw.InTypeAnsiString) + event.Data.AddString("Foo") + event.Metadata.AddField("TestField2", etw.InTypeAnsiString) + event.Data.AddString("Bar") + + if err := provider.WriteEvent(event); err != nil { + fmt.Println(err) + return + } + + fmt.Println("Event written") + + fmt.Println("Press enter to exit") + reader.ReadString('\n') +} diff --git a/etw/zsyscall_windows.go b/etw/zsyscall_windows.go new file mode 100644 index 0000000..5b044ca --- /dev/null +++ b/etw/zsyscall_windows.go @@ -0,0 +1,69 @@ +// Code generated by 'go generate'; DO NOT EDIT. + +package etw + +import ( + "syscall" + "unsafe" + + "golang.org/x/sys/windows" +) + +var _ unsafe.Pointer + +// Do the interface allocations only once for common +// Errno values. +const ( + errnoERROR_IO_PENDING = 997 +) + +var ( + errERROR_IO_PENDING error = syscall.Errno(errnoERROR_IO_PENDING) +) + +// errnoErr returns common boxed Errno values, to prevent +// allocations at runtime. +func errnoErr(e syscall.Errno) error { + switch e { + case 0: + return nil + case errnoERROR_IO_PENDING: + return errERROR_IO_PENDING + } + // TODO: add more here, after collecting data on the common + // error values see on Windows. (perhaps when running + // all.bat?) + return e +} + +var ( + modadvapi32 = windows.NewLazySystemDLL("advapi32.dll") + + procEventRegister = modadvapi32.NewProc("EventRegister") + procEventUnregister = modadvapi32.NewProc("EventUnregister") + procEventWriteTransfer = modadvapi32.NewProc("EventWriteTransfer") +) + +func eventRegister(providerId *windows.GUID, callback uintptr, callbackContext uintptr, providerHandle *providerHandle) (win32err error) { + r0, _, _ := syscall.Syscall6(procEventRegister.Addr(), 4, uintptr(unsafe.Pointer(providerId)), uintptr(callback), uintptr(callbackContext), uintptr(unsafe.Pointer(providerHandle)), 0, 0) + if r0 != 0 { + win32err = syscall.Errno(r0) + } + return +} + +func eventUnregister(providerHandle providerHandle) (win32err error) { + r0, _, _ := syscall.Syscall(procEventUnregister.Addr(), 1, uintptr(providerHandle), 0, 0) + if r0 != 0 { + win32err = syscall.Errno(r0) + } + return +} + +func eventWriteTransfer(providerHandle providerHandle, descriptor *EventDescriptor, activityID *windows.GUID, relatedActivityID *windows.GUID, dataDescriptorCount uint32, dataDescriptors *eventDataDescriptor) (win32err error) { + r0, _, _ := syscall.Syscall6(procEventWriteTransfer.Addr(), 6, uintptr(providerHandle), uintptr(unsafe.Pointer(descriptor)), uintptr(unsafe.Pointer(activityID)), uintptr(unsafe.Pointer(relatedActivityID)), uintptr(dataDescriptorCount), uintptr(unsafe.Pointer(dataDescriptors))) + if r0 != 0 { + win32err = syscall.Errno(r0) + } + return +} From 083046a6cdf51f15bf79d52acd601a3c3d145ac1 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Wed, 12 Dec 2018 18:20:51 -0800 Subject: [PATCH 02/17] Add comments --- etw/event.go | 53 +++++++++++++++++++++++++++++++++++--------- etw/eventdata.go | 8 +++++++ etw/eventmetadata.go | 7 ++++++ etw/provider.go | 18 ++++++++++----- 4 files changed, 70 insertions(+), 16 deletions(-) diff --git a/etw/event.go b/etw/event.go index 5639d0a..2a01d4f 100644 --- a/etw/event.go +++ b/etw/event.go @@ -1,13 +1,23 @@ package etw +// Channel represents the ETW logging channel that is used. It can be used by +// event consumers to give an event special treatment. type Channel uint8 const ( + // ChannelTracelogging is the default channel for tracelogging events. It is + // not required to be used for tracelogging, but will prevent decoding + // issues for these events on older operating systems. ChannelTracelogging Channel = 11 ) +// Level represents the ETW logging level. There are several predefined levels +// that are commonly used, but technically anything from 0-255 is allowed. +// Lower levels indicate more important events, and 0 indicates an event that +// will always be collected. type Level uint8 +// Predefined ETW log levels. const ( LevelAlways Level = iota LevelCritical @@ -17,15 +27,27 @@ const ( LevelVerbose ) +// Event represents a single ETW event. It can have field metadata and data +// added to it, and then be logged via a provider to actually send it to ETW. type Event struct { Descriptor *EventDescriptor Metadata *EventMetadata Data *EventData } +// NewEvent returns a new instance of an event object. +func NewEvent(name string, descriptor *EventDescriptor) *Event { + return &Event{ + Descriptor: descriptor, + Metadata: NewEventMetadata(name), + Data: &EventData{}, + } +} + +// EventDescriptor represents various metadata for an ETW event. type EventDescriptor struct { - ID uint16 - Version uint8 + id uint16 + version uint8 Channel Channel Level Level Opcode uint8 @@ -33,10 +55,12 @@ type EventDescriptor struct { Keyword uint64 } +// NewEventDescriptor returns an EventDescriptor initialized for use with +// tracelogging. func NewEventDescriptor() *EventDescriptor { return &EventDescriptor{ - ID: 0, - Version: 0, + id: 0, + version: 0, Channel: ChannelTracelogging, Level: LevelVerbose, Opcode: 0, @@ -45,10 +69,19 @@ func NewEventDescriptor() *EventDescriptor { } } -func NewEvent(name string, descriptor *EventDescriptor) *Event { - return &Event{ - Descriptor: descriptor, - Metadata: NewEventMetadata(name), - Data: &EventData{}, - } +// Identity returns the identity of the event. If the identity is not 0, it +// should uniquely identify the other event metadata (contained in +// EventDescriptor, and field metadata). Only the lower 24 bits of this value +// are relevant. +func (ed *EventDescriptor) Identity() uint32 { + return (uint32(ed.version) << 16) & uint32(ed.id) +} + +// SetIdentity sets the identity of the event. If the identity is not 0, it +// should uniquely identify the other event metadata (contained in +// EventDescriptor, and field metadata). Only the lower 24 bits of this value +// are relevant. +func (ed *EventDescriptor) SetIdentity(identity uint32) { + ed.id = uint16(identity) + ed.version = uint8(identity >> 16) } diff --git a/etw/eventdata.go b/etw/eventdata.go index 9fc5c4d..f847b9c 100644 --- a/etw/eventdata.go +++ b/etw/eventdata.go @@ -5,10 +5,18 @@ import ( "encoding/binary" ) +// EventData maintains a buffer which builds up the data for an ETW event. It +// needs to be paired with EventMetadata which describes the event. type EventData struct { buffer bytes.Buffer } +// NewEventData returns a new EventData with an empty buffer. +func NewEventData() *EventData { + return &EventData{} +} + +// AddString appends the data for a string to the end of the buffer. func (ed *EventData) AddString(data string) { binary.Write(&ed.buffer, binary.LittleEndian, []byte(data)) binary.Write(&ed.buffer, binary.LittleEndian, byte(0)) diff --git a/etw/eventmetadata.go b/etw/eventmetadata.go index 9c480d6..e4813c9 100644 --- a/etw/eventmetadata.go +++ b/etw/eventmetadata.go @@ -5,8 +5,10 @@ import ( "encoding/binary" ) +// InType indicates the type of data contained in the ETW event. type InType byte +// Various InType definitions for tracelogging. const ( InTypeNull InType = iota InTypeUnicodeString @@ -24,10 +26,14 @@ const ( InTypeBool32 ) +// EventMetadata maintains a buffer which builds up the metadatadata for an ETW +// event. It needs to be paired with EventData which describes the event. type EventMetadata struct { buffer bytes.Buffer } +// NewEventMetadata returns a new EventMetadata with event name and initial +// metadata written to the buffer. func NewEventMetadata(name string) *EventMetadata { em := EventMetadata{} binary.Write(&em.buffer, binary.LittleEndian, uint16(0)) // Length placeholder @@ -37,6 +43,7 @@ func NewEventMetadata(name string) *EventMetadata { return &em } +// AddField appends a single field to the end of the event metadata buffer. func (em *EventMetadata) AddField(name string, inType InType) { binary.Write(&em.buffer, binary.LittleEndian, []byte(name)) // Field name binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Null terminator for name diff --git a/etw/provider.go b/etw/provider.go index 47521eb..4c50278 100644 --- a/etw/provider.go +++ b/etw/provider.go @@ -16,6 +16,9 @@ const ( eventDataDescriptorTypeProviderMetadata ) +// Provider represents an ETW event provider. It is identified by a provider +// name and ID (GUID), which should always have a 1:1 mapping to each other +// (e.g. don't use multiple provider names with the same ID, or vice versa). type Provider struct { handle providerHandle metadata *bytes.Buffer @@ -23,6 +26,8 @@ type Provider struct { type providerHandle windows.Handle +// EnableCallback is the form of the callback function that receives provider +// enable/disable notifications from ETW. type EnableCallback func(*windows.GUID, uint32, byte, uint64, uint64, uintptr) type eventDataDescriptor struct { @@ -34,8 +39,9 @@ type eventDataDescriptor struct { } func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buffer *bytes.Buffer) { - // Passing a pointer to Go-managed memory as part of a block of memory is risky since the GC doesn't know about it. - // If we find a better way to do this we should use it instead. + // Passing a pointer to Go-managed memory as part of a block of memory is + // risky since the GC doesn't know about it. If we find a better way to do + // this we should use it instead. descriptor.ptr = uint64(uintptr(unsafe.Pointer(&buffer.Bytes()[0]))) descriptor.size = uint32(buffer.Len()) descriptor.dataType = dataType @@ -56,10 +62,10 @@ func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provi } var metadataBuffer bytes.Buffer - binary.Write(&metadataBuffer, binary.LittleEndian, uint16(0)) - binary.Write(&metadataBuffer, binary.LittleEndian, []byte(name)) - binary.Write(&metadataBuffer, binary.LittleEndian, byte(0)) - binary.LittleEndian.PutUint16(metadataBuffer.Bytes(), uint16(metadataBuffer.Len())) + binary.Write(&metadataBuffer, binary.LittleEndian, uint16(0)) // Write empty size for buffer (to update later) + binary.Write(&metadataBuffer, binary.LittleEndian, []byte(name)) // Provider name + binary.Write(&metadataBuffer, binary.LittleEndian, byte(0)) // Null terminator for name + binary.LittleEndian.PutUint16(metadataBuffer.Bytes(), uint16(metadataBuffer.Len())) // Update the size at the beginning of the buffer return &Provider{ handle: providerHandle, From bb628025f5bbb4298ba0036a101c6f6e3721d82d Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 13 Dec 2018 14:12:44 -0800 Subject: [PATCH 03/17] Clean up some types and comments --- etw/etw.go | 7 +++++++ etw/event.go | 12 +++++++----- etw/eventmetadata.go | 2 +- etw/provider.go | 20 +++++++++++++++++--- etw/sample/sample.go | 4 ++-- 5 files changed, 34 insertions(+), 11 deletions(-) diff --git a/etw/etw.go b/etw/etw.go index e60a8fa..da905ec 100644 --- a/etw/etw.go +++ b/etw/etw.go @@ -1,3 +1,10 @@ +// Package etw provides support for TraceLogging-based ETW (Event Tracing +// for Windows). TraceLogging is a format of ETW events that are self-describing +// (the event contains information on its own schema). This allows them to be +// decoded without needing a separate manifest with event information. The +// implementation here is based on the information found in +// TraceLoggingProvider.h in the Windows SDK, which implements TraceLogging as a +// set of C macros. package etw //go:generate go run $GOROOT/src/syscall/mksyscall_windows.go -output zsyscall_windows.go etw.go diff --git a/etw/event.go b/etw/event.go index 2a01d4f..bbf3172 100644 --- a/etw/event.go +++ b/etw/event.go @@ -5,10 +5,10 @@ package etw type Channel uint8 const ( - // ChannelTracelogging is the default channel for tracelogging events. It is - // not required to be used for tracelogging, but will prevent decoding + // ChannelTraceLogging is the default channel for TraceLogging events. It is + // not required to be used for TraceLogging, but will prevent decoding // issues for these events on older operating systems. - ChannelTracelogging Channel = 11 + ChannelTraceLogging Channel = 11 ) // Level represents the ETW logging level. There are several predefined levels @@ -56,12 +56,14 @@ type EventDescriptor struct { } // NewEventDescriptor returns an EventDescriptor initialized for use with -// tracelogging. +// TraceLogging. func NewEventDescriptor() *EventDescriptor { + // Standard TraceLogging events default to the TraceLogging channel, and + // verbose level. return &EventDescriptor{ id: 0, version: 0, - Channel: ChannelTracelogging, + Channel: ChannelTraceLogging, Level: LevelVerbose, Opcode: 0, Task: 0, diff --git a/etw/eventmetadata.go b/etw/eventmetadata.go index e4813c9..39e9909 100644 --- a/etw/eventmetadata.go +++ b/etw/eventmetadata.go @@ -8,7 +8,7 @@ import ( // InType indicates the type of data contained in the ETW event. type InType byte -// Various InType definitions for tracelogging. +// Various InType definitions for TraceLogging. const ( InTypeNull InType = iota InTypeUnicodeString diff --git a/etw/provider.go b/etw/provider.go index 4c50278..6bb23e3 100644 --- a/etw/provider.go +++ b/etw/provider.go @@ -26,9 +26,23 @@ type Provider struct { type providerHandle windows.Handle +// ProviderState informs the provider EnableCallback what action is being +// performed. +type ProviderState uint32 + +const ( + // ProviderStateDisable indicates the provider is being disabled. + ProviderStateDisable ProviderState = iota + // ProviderStateEnable indicates the provider is being enabled. + ProviderStateEnable + // ProviderStateCaptureState indicates the provider is having its current + // state snap-shotted. + ProviderStateCaptureState +) + // EnableCallback is the form of the callback function that receives provider // enable/disable notifications from ETW. -type EnableCallback func(*windows.GUID, uint32, byte, uint64, uint64, uintptr) +type EnableCallback func(*windows.GUID, ProviderState, Level, uint64, uint64, uintptr) type eventDataDescriptor struct { ptr uint64 @@ -49,9 +63,9 @@ func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buf // NewProvider creates and registers a new provider. func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provider, error) { - innerCallback := func(sourceID *windows.GUID, isEnabled uint32, level byte, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, _ uintptr) uintptr { + innerCallback := func(sourceID *windows.GUID, state ProviderState, level Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, _ uintptr) uintptr { if callback != nil { - callback(sourceID, isEnabled, level, matchAnyKeyword, matchAllKeyword, filterData) + callback(sourceID, state, level, matchAnyKeyword, matchAllKeyword, filterData) } return 0 } diff --git a/etw/sample/sample.go b/etw/sample/sample.go index 46850dc..3088412 100644 --- a/etw/sample/sample.go +++ b/etw/sample/sample.go @@ -12,8 +12,8 @@ import ( "golang.org/x/sys/windows" ) -func callback(sourceID *windows.GUID, isEnabled uint32, level byte, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr) { - fmt.Printf("Callback: isEnabled=%d, level=%d, matchAnyKeyword=%d\n", isEnabled, level, matchAnyKeyword) +func callback(sourceID *windows.GUID, state etw.ProviderState, level etw.Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr) { + fmt.Printf("Callback: isEnabled=%d, level=%d, matchAnyKeyword=%d\n", state, level, matchAnyKeyword) } func main() { From 62f7a6b7b94736df8544dd0b1bca7f4bd0e3045a Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 13 Dec 2018 14:26:45 -0800 Subject: [PATCH 04/17] Rearrange etw packages --- {etw => pkg/etw}/etw.go | 0 {etw => pkg/etw}/event.go | 0 {etw => pkg/etw}/eventdata.go | 0 {etw => pkg/etw}/eventmetadata.go | 0 {etw => pkg/etw}/provider.go | 0 {etw => pkg/etw}/sample/sample.go | 2 +- {etw => pkg/etw}/zsyscall_windows.go | 0 {etw/logrus => pkg/etwlogrus}/hook.go | 4 ++-- 8 files changed, 3 insertions(+), 3 deletions(-) rename {etw => pkg/etw}/etw.go (100%) rename {etw => pkg/etw}/event.go (100%) rename {etw => pkg/etw}/eventdata.go (100%) rename {etw => pkg/etw}/eventmetadata.go (100%) rename {etw => pkg/etw}/provider.go (100%) rename {etw => pkg/etw}/sample/sample.go (96%) rename {etw => pkg/etw}/zsyscall_windows.go (100%) rename {etw/logrus => pkg/etwlogrus}/hook.go (92%) diff --git a/etw/etw.go b/pkg/etw/etw.go similarity index 100% rename from etw/etw.go rename to pkg/etw/etw.go diff --git a/etw/event.go b/pkg/etw/event.go similarity index 100% rename from etw/event.go rename to pkg/etw/event.go diff --git a/etw/eventdata.go b/pkg/etw/eventdata.go similarity index 100% rename from etw/eventdata.go rename to pkg/etw/eventdata.go diff --git a/etw/eventmetadata.go b/pkg/etw/eventmetadata.go similarity index 100% rename from etw/eventmetadata.go rename to pkg/etw/eventmetadata.go diff --git a/etw/provider.go b/pkg/etw/provider.go similarity index 100% rename from etw/provider.go rename to pkg/etw/provider.go diff --git a/etw/sample/sample.go b/pkg/etw/sample/sample.go similarity index 96% rename from etw/sample/sample.go rename to pkg/etw/sample/sample.go index 3088412..f42f5ea 100644 --- a/etw/sample/sample.go +++ b/pkg/etw/sample/sample.go @@ -6,7 +6,7 @@ import ( "fmt" "os" - "github.com/Microsoft/go-winio/etw" + "github.com/Microsoft/go-winio/pkg/etw" "github.com/sirupsen/logrus" "golang.org/x/sys/windows" diff --git a/etw/zsyscall_windows.go b/pkg/etw/zsyscall_windows.go similarity index 100% rename from etw/zsyscall_windows.go rename to pkg/etw/zsyscall_windows.go diff --git a/etw/logrus/hook.go b/pkg/etwlogrus/hook.go similarity index 92% rename from etw/logrus/hook.go rename to pkg/etwlogrus/hook.go index 7fec697..230e6f8 100644 --- a/etw/logrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -1,10 +1,10 @@ -package hook +package etwlogrus import ( "fmt" "reflect" - "github.com/Microsoft/go-winio/etw" + "github.com/Microsoft/go-winio/pkg/etw" "github.com/sirupsen/logrus" "golang.org/x/sys/windows" From cd4b2fefe97ff737e712f59930ffd034962d06db Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 13 Dec 2018 17:23:55 -0800 Subject: [PATCH 05/17] Change from reflection to type switch in Logrus hook --- pkg/etw/eventmetadata.go | 3 ++- pkg/etwlogrus/hook.go | 6 +++--- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/pkg/etw/eventmetadata.go b/pkg/etw/eventmetadata.go index 39e9909..2539941 100644 --- a/pkg/etw/eventmetadata.go +++ b/pkg/etw/eventmetadata.go @@ -8,7 +8,8 @@ import ( // InType indicates the type of data contained in the ETW event. type InType byte -// Various InType definitions for TraceLogging. +// Various InType definitions for TraceLogging. These must match the definitions +// found in TraceLoggingProvider.h in the Windows SDK. const ( InTypeNull InType = iota InTypeUnicodeString diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 230e6f8..e13747c 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -57,10 +57,10 @@ func (h *Hook) Fire(e *logrus.Entry) error { event.Data.AddString(e.Message) for k, v := range e.Data { - switch reflect.TypeOf(v).Kind() { - case reflect.String: + switch v := v.(type) { + case string: event.Metadata.AddField(k, etw.InTypeAnsiString) - event.Data.AddString(v.(string)) + event.Data.AddString(v) default: event.Metadata.AddField(k, etw.InTypeAnsiString) event.Data.AddString(fmt.Sprintf(" %v", reflect.TypeOf(v), v)) From 98d07c865e82e75003b7a33d1c597bb22adb84d1 Mon Sep 17 00:00:00 2001 From: John Starks Date: Tue, 18 Dec 2018 18:20:29 -0800 Subject: [PATCH 06/17] Update pkg/etw/event.go Co-Authored-By: kevpar --- pkg/etw/event.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/etw/event.go b/pkg/etw/event.go index bbf3172..a67e62c 100644 --- a/pkg/etw/event.go +++ b/pkg/etw/event.go @@ -76,7 +76,7 @@ func NewEventDescriptor() *EventDescriptor { // EventDescriptor, and field metadata). Only the lower 24 bits of this value // are relevant. func (ed *EventDescriptor) Identity() uint32 { - return (uint32(ed.version) << 16) & uint32(ed.id) + return (uint32(ed.version) << 16) | uint32(ed.id) } // SetIdentity sets the identity of the event. If the identity is not 0, it From 35e42dab22c336c76ec6c5f9f2b328602161ca49 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Wed, 19 Dec 2018 01:38:48 -0800 Subject: [PATCH 07/17] Address PR feedback --- pkg/etw/event.go | 2 +- pkg/etw/eventdata.go | 5 ++--- pkg/etw/provider.go | 33 ++++++++++++++++----------------- 3 files changed, 19 insertions(+), 21 deletions(-) diff --git a/pkg/etw/event.go b/pkg/etw/event.go index bbf3172..a67e62c 100644 --- a/pkg/etw/event.go +++ b/pkg/etw/event.go @@ -76,7 +76,7 @@ func NewEventDescriptor() *EventDescriptor { // EventDescriptor, and field metadata). Only the lower 24 bits of this value // are relevant. func (ed *EventDescriptor) Identity() uint32 { - return (uint32(ed.version) << 16) & uint32(ed.id) + return (uint32(ed.version) << 16) | uint32(ed.id) } // SetIdentity sets the identity of the event. If the identity is not 0, it diff --git a/pkg/etw/eventdata.go b/pkg/etw/eventdata.go index f847b9c..ecd2ca9 100644 --- a/pkg/etw/eventdata.go +++ b/pkg/etw/eventdata.go @@ -2,7 +2,6 @@ package etw import ( "bytes" - "encoding/binary" ) // EventData maintains a buffer which builds up the data for an ETW event. It @@ -18,6 +17,6 @@ func NewEventData() *EventData { // AddString appends the data for a string to the end of the buffer. func (ed *EventData) AddString(data string) { - binary.Write(&ed.buffer, binary.LittleEndian, []byte(data)) - binary.Write(&ed.buffer, binary.LittleEndian, byte(0)) + ed.buffer.Write([]byte(data)) + ed.buffer.WriteByte(0) } diff --git a/pkg/etw/provider.go b/pkg/etw/provider.go index 6bb23e3..1853ce2 100644 --- a/pkg/etw/provider.go +++ b/pkg/etw/provider.go @@ -21,7 +21,7 @@ const ( // (e.g. don't use multiple provider names with the same ID, or vice versa). type Provider struct { handle providerHandle - metadata *bytes.Buffer + metadata []byte } type providerHandle windows.Handle @@ -52,17 +52,19 @@ type eventDataDescriptor struct { reserved2 uint16 } -func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buffer *bytes.Buffer) { +func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buffer []byte) { // Passing a pointer to Go-managed memory as part of a block of memory is // risky since the GC doesn't know about it. If we find a better way to do // this we should use it instead. - descriptor.ptr = uint64(uintptr(unsafe.Pointer(&buffer.Bytes()[0]))) - descriptor.size = uint32(buffer.Len()) + descriptor.ptr = uint64(uintptr(unsafe.Pointer(&buffer[0]))) + descriptor.size = uint32(len(buffer)) descriptor.dataType = dataType } // NewProvider creates and registers a new provider. func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provider, error) { + provider := &Provider{} + innerCallback := func(sourceID *windows.GUID, state ProviderState, level Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, _ uintptr) uintptr { if callback != nil { callback(sourceID, state, level, matchAnyKeyword, matchAllKeyword, filterData) @@ -70,21 +72,18 @@ func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provi return 0 } - var providerHandle providerHandle - if err := eventRegister(id, windows.NewCallback(innerCallback), 0, &providerHandle); err != nil { + if err := eventRegister(id, windows.NewCallback(innerCallback), 0, &provider.handle); err != nil { return nil, err } - var metadataBuffer bytes.Buffer - binary.Write(&metadataBuffer, binary.LittleEndian, uint16(0)) // Write empty size for buffer (to update later) - binary.Write(&metadataBuffer, binary.LittleEndian, []byte(name)) // Provider name - binary.Write(&metadataBuffer, binary.LittleEndian, byte(0)) // Null terminator for name - binary.LittleEndian.PutUint16(metadataBuffer.Bytes(), uint16(metadataBuffer.Len())) // Update the size at the beginning of the buffer + metadata := &bytes.Buffer{} + binary.Write(metadata, binary.LittleEndian, uint16(0)) // Write empty size for buffer (to update later) + metadata.WriteString(name) // Provider name + metadata.WriteByte(0) // Null terminator for name + binary.LittleEndian.PutUint16(metadata.Bytes(), uint16(metadata.Len())) // Update the size at the beginning of the buffer + provider.metadata = metadata.Bytes() - return &Provider{ - handle: providerHandle, - metadata: &metadataBuffer, - }, nil + return provider, nil } // Close unregisters the provider. @@ -100,8 +99,8 @@ func (provider *Provider) WriteEvent(event *Event) error { var dataDescriptors [3]eventDataDescriptor dataDescriptors[0].set(eventDataDescriptorTypeProviderMetadata, provider.metadata) - dataDescriptors[1].set(eventDataDescriptorTypeEventMetadata, &event.Metadata.buffer) - dataDescriptors[2].set(eventDataDescriptorTypeUserData, &event.Data.buffer) + dataDescriptors[1].set(eventDataDescriptorTypeEventMetadata, event.Metadata.buffer.Bytes()) + dataDescriptors[2].set(eventDataDescriptorTypeUserData, event.Data.buffer.Bytes()) return eventWriteTransfer(provider.handle, event.Descriptor, nil, nil, 3, &dataDescriptors[0]) } From dcfdf4a9f623f88a1451d4c27cd4ccefe08072cc Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Wed, 19 Dec 2018 01:42:44 -0800 Subject: [PATCH 08/17] Improve ETW callback support and track provider enable state --- pkg/etw/provider.go | 134 ++++++++++++++++++++++++++++++++++++++---- pkg/etwlogrus/hook.go | 4 ++ 2 files changed, 127 insertions(+), 11 deletions(-) diff --git a/pkg/etw/provider.go b/pkg/etw/provider.go index 1853ce2..4490b08 100644 --- a/pkg/etw/provider.go +++ b/pkg/etw/provider.go @@ -3,6 +3,7 @@ package etw import ( "bytes" "encoding/binary" + "sync" "unsafe" "golang.org/x/sys/windows" @@ -20,8 +21,14 @@ const ( // name and ID (GUID), which should always have a 1:1 mapping to each other // (e.g. don't use multiple provider names with the same ID, or vice versa). type Provider struct { - handle providerHandle - metadata []byte + handle providerHandle + metadata []byte + callback EnableCallback + index uint + enabled bool + level Level + keywordAny uint64 + keywordAll uint64 } type providerHandle windows.Handle @@ -61,18 +68,87 @@ func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buf descriptor.dataType = dataType } -// NewProvider creates and registers a new provider. -func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provider, error) { - provider := &Provider{} +// Because the provider callback function needs to be able to access the +// provider data when it is invoked by ETW, we need to keep provider data stored +// in a global map based on an index. The index is passed as the callback +// context to ETW. +type providerMap struct { + m map[uint]*Provider + i uint + lock sync.Mutex +} - innerCallback := func(sourceID *windows.GUID, state ProviderState, level Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, _ uintptr) uintptr { - if callback != nil { - callback(sourceID, state, level, matchAnyKeyword, matchAllKeyword, filterData) - } - return 0 +var providers = providerMap{ + m: make(map[uint]*Provider), +} + +func (p *providerMap) newProvider() *Provider { + p.lock.Lock() + defer p.lock.Unlock() + + i := p.i + p.i++ + + provider := &Provider{ + index: i, } - if err := eventRegister(id, windows.NewCallback(innerCallback), 0, &provider.handle); err != nil { + p.m[i] = provider + return provider +} + +func (p *providerMap) removeProvider(provider *Provider) { + p.lock.Lock() + defer p.lock.Unlock() + + delete(p.m, provider.index) +} + +func (p *providerMap) getProvider(index uint) *Provider { + p.lock.Lock() + defer p.lock.Unlock() + + return p.m[index] +} + +func providerCallback(sourceID *windows.GUID, state ProviderState, level Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, i uintptr) { + provider := providers.getProvider(uint(i)) + + switch state { + case ProviderStateDisable: + provider.enabled = false + case ProviderStateEnable: + provider.enabled = true + provider.level = level + provider.keywordAny = matchAnyKeyword + provider.keywordAll = matchAllKeyword + } + + if provider.callback != nil { + provider.callback(sourceID, state, level, matchAnyKeyword, matchAllKeyword, filterData) + } +} + +// providerCallbackAdapter acts as the first-level callback from the C/ETW side +// for provider notifications. Because Go has trouble with callback arguments of +// different size, it has only pointer-sized arguments, which are then cast to +// the appropriate types when calling providerCallback. +func providerCallbackAdapter(sourceID *windows.GUID, state uintptr, level uintptr, matchAnyKeyword uintptr, matchAllKeyword uintptr, filterData uintptr, i uintptr) uintptr { + providerCallback(sourceID, ProviderState(state), Level(level), uint64(matchAnyKeyword), uint64(matchAllKeyword), filterData, i) + return 0 +} + +// NewProvider creates and registers a new provider. +func NewProvider(name string, id *windows.GUID, callback EnableCallback) (provider *Provider, err error) { + provider = providers.newProvider() + defer func() { + if err != nil { + providers.removeProvider(provider) + } + }() + provider.callback = callback + + if err := eventRegister(id, windows.NewCallback(providerCallbackAdapter), uintptr(provider.index), &provider.handle); err != nil { return nil, err } @@ -88,9 +164,45 @@ func NewProvider(name string, id *windows.GUID, callback EnableCallback) (*Provi // Close unregisters the provider. func (provider *Provider) Close() error { + providers.removeProvider(provider) return eventUnregister(provider.handle) } +// IsEnabled calls IsEnabledForLevelAndKeywords with LevelAlways and all +// keywords set. +func (provider *Provider) IsEnabled() bool { + return provider.IsEnabledForLevelAndKeywords(LevelAlways, ^uint64(0)) +} + +// IsEnabledForLevel calls IsEnabledForLevelAndKeywords with the specified level +// and all keywords set. +func (provider *Provider) IsEnabledForLevel(level Level) bool { + return provider.IsEnabledForLevelAndKeywords(level, ^uint64(0)) +} + +// IsEnabledForLevelAndKeywords allows event producer code to check if there are +// any event sessions that are interested in an event, based on the event level +// and keywords. Although this check happens automatically in the ETW +// infrastructure, it can be useful to check if an event will actually be +// consumed before doing expensive work to build the event data. +func (provider *Provider) IsEnabledForLevelAndKeywords(level Level, keywords uint64) bool { + if !provider.enabled { + return false + } + + // ETW automatically sets the level to 255 if it is specified as 0, so we + // don't need to worry about the level=0 (all events) case. + if level > provider.level { + return false + } + + if keywords != 0 && (keywords&provider.keywordAny == 0 || keywords&provider.keywordAll != provider.keywordAll) { + return false + } + + return true +} + // WriteEvent writes a single event to ETW, from this provider. func (provider *Provider) WriteEvent(event *Event) error { // Finalize the event metadata buffer by filling in the buffer length at the diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index e13747c..6037388 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -44,6 +44,10 @@ func (h *Hook) Levels() []logrus.Level { // Fire receives each Logrus entry as it is logged, and logs it to ETW. func (h *Hook) Fire(e *logrus.Entry) error { + if !h.provider.IsEnabledForLevel(etw.Level(e.Level)) { + return + } + descriptor := etw.NewEventDescriptor() // We could try to map Logrus levels to ETW levels, but we would lose some From 824a366a22120aad1954f8d20ff62ddeff04da72 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Wed, 19 Dec 2018 01:52:09 -0800 Subject: [PATCH 09/17] Make etw package internal --- {pkg => internal}/etw/etw.go | 0 {pkg => internal}/etw/event.go | 0 {pkg => internal}/etw/eventdata.go | 0 {pkg => internal}/etw/eventmetadata.go | 0 {pkg => internal}/etw/provider.go | 0 {pkg => internal}/etw/sample/sample.go | 0 {pkg => internal}/etw/zsyscall_windows.go | 0 pkg/etwlogrus/hook.go | 4 ++-- 8 files changed, 2 insertions(+), 2 deletions(-) rename {pkg => internal}/etw/etw.go (100%) rename {pkg => internal}/etw/event.go (100%) rename {pkg => internal}/etw/eventdata.go (100%) rename {pkg => internal}/etw/eventmetadata.go (100%) rename {pkg => internal}/etw/provider.go (100%) rename {pkg => internal}/etw/sample/sample.go (100%) rename {pkg => internal}/etw/zsyscall_windows.go (100%) diff --git a/pkg/etw/etw.go b/internal/etw/etw.go similarity index 100% rename from pkg/etw/etw.go rename to internal/etw/etw.go diff --git a/pkg/etw/event.go b/internal/etw/event.go similarity index 100% rename from pkg/etw/event.go rename to internal/etw/event.go diff --git a/pkg/etw/eventdata.go b/internal/etw/eventdata.go similarity index 100% rename from pkg/etw/eventdata.go rename to internal/etw/eventdata.go diff --git a/pkg/etw/eventmetadata.go b/internal/etw/eventmetadata.go similarity index 100% rename from pkg/etw/eventmetadata.go rename to internal/etw/eventmetadata.go diff --git a/pkg/etw/provider.go b/internal/etw/provider.go similarity index 100% rename from pkg/etw/provider.go rename to internal/etw/provider.go diff --git a/pkg/etw/sample/sample.go b/internal/etw/sample/sample.go similarity index 100% rename from pkg/etw/sample/sample.go rename to internal/etw/sample/sample.go diff --git a/pkg/etw/zsyscall_windows.go b/internal/etw/zsyscall_windows.go similarity index 100% rename from pkg/etw/zsyscall_windows.go rename to internal/etw/zsyscall_windows.go diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 6037388..e64abf7 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -4,7 +4,7 @@ import ( "fmt" "reflect" - "github.com/Microsoft/go-winio/pkg/etw" + "github.com/Microsoft/go-winio/internal/etw" "github.com/sirupsen/logrus" "golang.org/x/sys/windows" @@ -45,7 +45,7 @@ func (h *Hook) Levels() []logrus.Level { // Fire receives each Logrus entry as it is logged, and logs it to ETW. func (h *Hook) Fire(e *logrus.Entry) error { if !h.provider.IsEnabledForLevel(etw.Level(e.Level)) { - return + return nil } descriptor := etw.NewEventDescriptor() From 82ad3816992a97d89fbc2cf50a33eff2b733edb4 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 20 Dec 2018 01:28:55 -0800 Subject: [PATCH 10/17] Add ETW support for out type and tags --- internal/etw/eventdata.go | 2 +- internal/etw/eventmetadata.go | 133 +++++++++++++++++++++++++++++++--- internal/etw/provider.go | 4 +- pkg/etwlogrus/hook.go | 6 +- 4 files changed, 130 insertions(+), 15 deletions(-) diff --git a/internal/etw/eventdata.go b/internal/etw/eventdata.go index ecd2ca9..7d62799 100644 --- a/internal/etw/eventdata.go +++ b/internal/etw/eventdata.go @@ -17,6 +17,6 @@ func NewEventData() *EventData { // AddString appends the data for a string to the end of the buffer. func (ed *EventData) AddString(data string) { - ed.buffer.Write([]byte(data)) + ed.buffer.WriteString(data) ed.buffer.WriteByte(0) } diff --git a/internal/etw/eventmetadata.go b/internal/etw/eventmetadata.go index 2539941..31ad41a 100644 --- a/internal/etw/eventmetadata.go +++ b/internal/etw/eventmetadata.go @@ -13,7 +13,7 @@ type InType byte const ( InTypeNull InType = iota InTypeUnicodeString - InTypeAnsiString + InTypeANSIString InTypeInt8 InTypeUint8 InTypeInt16 @@ -25,6 +25,52 @@ const ( InTypeFloat InTypeDouble InTypeBool32 + InTypeBinary + InTypeGUID + InTypePointerUnsupported + InTypeFileTime + InTypeSystemTime + InTypeSID + InTypeHexInt32 + InTypeHexInt64 + InTypeCountedString + InTypeCountedANSIString + InTypeStruct + InTypeCountedBinary +) + +// OutType specifies a hint to the event decoder for how the value should be +// formatted. +type OutType byte + +// Various OutType definitions for TraceLogging. These must match the +// definitions found in TraceLoggingProvider.h in the Windows SDK. +const ( + // OutTypeDefault indicates that the default formatting for the in type will + // be used by the event decoder. + OutTypeDefault OutType = iota + OutTypeNoPrint + OutTypeString + OutTypeBoolean + OutTypeHex + OutTypePID + OutTypeTID + OutTypePort + OutTypeIPv4 + OutTypeIPv6 + OutTypeSocketAddress + OutTypeXML + OutTypeJSON + OutTypeWin32Error + OutTypeNTStatus + OutTypeHResult + OutTypeFileTime + OutTypeSigned + OutTypeUnsigned + OutTypeUTF8 OutType = 35 + OutTypePKCS7WithTypeInfo OutType = 36 + OutTypeCodePointer OutType = 37 + OutTypeDateTimeUTC OutType = 38 ) // EventMetadata maintains a buffer which builds up the metadatadata for an ETW @@ -37,16 +83,85 @@ type EventMetadata struct { // metadata written to the buffer. func NewEventMetadata(name string) *EventMetadata { em := EventMetadata{} - binary.Write(&em.buffer, binary.LittleEndian, uint16(0)) // Length placeholder - binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Tags - binary.Write(&em.buffer, binary.LittleEndian, []byte(name)) // Event name - binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Null terminator for name + binary.Write(&em.buffer, binary.LittleEndian, uint16(0)) // Length placeholder + em.writeTags(0) + em.buffer.WriteString(name) + em.buffer.WriteByte(0) // Null terminator for name return &em } +type field struct { + name string + inType InType + outType OutType + tags uint32 +} + +func (em *EventMetadata) writeField(f field) { + em.buffer.WriteString(f.name) + em.buffer.WriteByte(0) // Null terminator for name + + if f.outType == OutTypeDefault && f.tags == 0 { + em.buffer.WriteByte(byte(f.inType)) + } else { + em.buffer.WriteByte(byte(f.inType | 128)) + if f.tags == 0 { + em.buffer.WriteByte(byte(f.outType)) + } else { + em.buffer.WriteByte(byte(f.outType | 128)) + em.writeTags(f.tags) + } + } +} + +func (em *EventMetadata) writeTags(tags uint32) { + tags &= 0xfffffff + + for { + val := tags >> 21 + + if tags&0x1fffff == 0 { + em.buffer.WriteByte(byte(val & 0x7f)) + return + } + + em.buffer.WriteByte(byte(val | 0x80)) + + tags <<= 7 + } +} + +type fieldOpt func(f *field) + +// WithOutType specifies the out type for the field. This value is used as a +// hint by the event decoder for how the field value should be formatted. If no +// out type is specified, a default formatting based on the in type will be +// used. +func WithOutType(outType OutType) fieldOpt { + return func(f *field) { + f.outType = outType + } +} + +// WithTags adds a tag to the field. Tags are 28-bit values that have meaning +// only to the event consumer. The top 4 bits of the value will be ignored. +// Multiple uses of this option will cause the tags to be OR'd together. +func WithTags(tags uint32) fieldOpt { + return func(f *field) { + f.tags |= tags + } +} + // AddField appends a single field to the end of the event metadata buffer. -func (em *EventMetadata) AddField(name string, inType InType) { - binary.Write(&em.buffer, binary.LittleEndian, []byte(name)) // Field name - binary.Write(&em.buffer, binary.LittleEndian, byte(0)) // Null terminator for name - binary.Write(&em.buffer, binary.LittleEndian, byte(inType)) // In type +func (em *EventMetadata) AddField(name string, inType InType, opts ...fieldOpt) { + f := field{ + name: name, + inType: inType, + } + + for _, opt := range opts { + opt(&f) + } + + em.writeField(f) } diff --git a/internal/etw/provider.go b/internal/etw/provider.go index 4490b08..5e6f65d 100644 --- a/internal/etw/provider.go +++ b/internal/etw/provider.go @@ -153,8 +153,8 @@ func NewProvider(name string, id *windows.GUID, callback EnableCallback) (provid } metadata := &bytes.Buffer{} - binary.Write(metadata, binary.LittleEndian, uint16(0)) // Write empty size for buffer (to update later) - metadata.WriteString(name) // Provider name + binary.Write(metadata, binary.LittleEndian, uint16(0)) // Write empty size for buffer (to update later) + metadata.WriteString(name) metadata.WriteByte(0) // Null terminator for name binary.LittleEndian.PutUint16(metadata.Bytes(), uint16(metadata.Len())) // Update the size at the beginning of the buffer provider.metadata = metadata.Bytes() diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index e64abf7..9a3c966 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -57,16 +57,16 @@ func (h *Hook) Fire(e *logrus.Entry) error { event := etw.NewEvent("LogrusEntry", descriptor) - event.Metadata.AddField("Message", etw.InTypeAnsiString) + event.Metadata.AddField("Message", etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) event.Data.AddString(e.Message) for k, v := range e.Data { switch v := v.(type) { case string: - event.Metadata.AddField(k, etw.InTypeAnsiString) + event.Metadata.AddField(k, etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) event.Data.AddString(v) default: - event.Metadata.AddField(k, etw.InTypeAnsiString) + event.Metadata.AddField(k, etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) event.Data.AddString(fmt.Sprintf(" %v", reflect.TypeOf(v), v)) } } From 50cf0baa2f426f35ed8141a20d89df626c122354 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 20 Dec 2018 14:05:36 -0800 Subject: [PATCH 11/17] Support auto-generation of ETW provider ID --- internal/etw/eventmetadata.go | 11 ++++++++ internal/etw/provider.go | 47 +++++++++++++++++++++++++++++++++-- internal/etw/sample/sample.go | 29 +++++++++++++++++---- pkg/etwlogrus/hook.go | 6 ++--- 4 files changed, 82 insertions(+), 11 deletions(-) diff --git a/internal/etw/eventmetadata.go b/internal/etw/eventmetadata.go index 31ad41a..cdcbfc8 100644 --- a/internal/etw/eventmetadata.go +++ b/internal/etw/eventmetadata.go @@ -114,13 +114,24 @@ func (em *EventMetadata) writeField(f field) { } } +// writeTags writes out the tags value to the event metadata. Tags is a 28-bit +// value, interpreted as bit flags, which are only relevant to the event +// consumer. The event consumer may choose to attribute special meaning to tags +// (e.g. 0x4 could mean the field contains PII). Tags are written as a series of +// bytes, each containing 7 bits of tag value, with the high bit set if there is +// more tag data in the following byte. This allows for a more compact +// representation when not all of the tag bits are needed. func (em *EventMetadata) writeTags(tags uint32) { + // Only use the top 28 bits of the tags value. tags &= 0xfffffff for { + // Tags are written with the most significant bits (e.g. 21-27) first. val := tags >> 21 if tags&0x1fffff == 0 { + // If there is no more data to write after this, write this value + // without the high bit set, and return. em.buffer.WriteByte(byte(val & 0x7f)) return } diff --git a/internal/etw/provider.go b/internal/etw/provider.go index 5e6f65d..880f17e 100644 --- a/internal/etw/provider.go +++ b/internal/etw/provider.go @@ -2,7 +2,9 @@ package etw import ( "bytes" + "crypto/sha1" "encoding/binary" + "strings" "sync" "unsafe" @@ -21,6 +23,7 @@ const ( // name and ID (GUID), which should always have a 1:1 mapping to each other // (e.g. don't use multiple provider names with the same ID, or vice versa). type Provider struct { + ID *windows.GUID handle providerHandle metadata []byte callback EnableCallback @@ -138,17 +141,57 @@ func providerCallbackAdapter(sourceID *windows.GUID, state uintptr, level uintpt return 0 } +// providerIDFromName generates a provider ID based on the provider name. It +// uses the same algorithm as used by .NET's EventSource class, which is based +// on RFC 4122. More information on the algorithm can be found here: +// https://blogs.msdn.microsoft.com/dcook/2015/09/08/etw-provider-names-and-guids/ +// The algorithm is roughly: +// Hash = Sha1(namespace + arg.ToUpper().ToUtf16be()) +// Guid = Hash[0..15], with Hash[7] tweaked according to RFC 4122 +func providerIDFromName(name string) (*windows.GUID, error) { + namespace := []byte{0x48, 0x2C, 0x2D, 0xB2, 0xC3, 0x90, 0x47, 0xC8, 0x87, 0xF8, 0x1A, 0x15, 0xBF, 0xC1, 0x30, 0xFB} + buffer := &bytes.Buffer{} + buffer.Write(namespace) + + nameUTF16, err := windows.UTF16FromString(strings.ToUpper(name)) + if err != nil { + return nil, err + } + // nameUTF16 includes a null terminator, which we don't want included in the + // hash. + binary.Write(buffer, binary.BigEndian, nameUTF16[:len(nameUTF16)-1]) + + sum := sha1.Sum(buffer.Bytes()) + sum[7] = (sum[7] & 0xf) | 0x50 + + return &windows.GUID{ + Data1: (uint32(sum[3]) << 24) | (uint32(sum[2]) << 16) | (uint32(sum[1]) << 8) | uint32(sum[0]), + Data2: (uint16(sum[5]) << 8) | uint16(sum[4]), + Data3: (uint16(sum[7]) << 8) | uint16(sum[6]), + Data4: [8]byte{sum[8], sum[9], sum[10], sum[11], sum[12], sum[13], sum[14], sum[15]}, + }, nil +} + +func NewProvider(name string, callback EnableCallback) (provider *Provider, err error) { + id, err := providerIDFromName(name) + if err != nil { + return nil, err + } + return NewProviderWithID(name, id, callback) +} + // NewProvider creates and registers a new provider. -func NewProvider(name string, id *windows.GUID, callback EnableCallback) (provider *Provider, err error) { +func NewProviderWithID(name string, id *windows.GUID, callback EnableCallback) (provider *Provider, err error) { provider = providers.newProvider() defer func() { if err != nil { providers.removeProvider(provider) } }() + provider.ID = id provider.callback = callback - if err := eventRegister(id, windows.NewCallback(providerCallbackAdapter), uintptr(provider.index), &provider.handle); err != nil { + if err := eventRegister(provider.ID, windows.NewCallback(providerCallbackAdapter), uintptr(provider.index), &provider.handle); err != nil { return nil, err } diff --git a/internal/etw/sample/sample.go b/internal/etw/sample/sample.go index f42f5ea..1b9d002 100644 --- a/internal/etw/sample/sample.go +++ b/internal/etw/sample/sample.go @@ -3,10 +3,12 @@ package main import ( "bufio" + "encoding/binary" + "encoding/hex" "fmt" "os" - "github.com/Microsoft/go-winio/pkg/etw" + "github.com/Microsoft/go-winio/internal/etw" "github.com/sirupsen/logrus" "golang.org/x/sys/windows" @@ -16,10 +18,25 @@ func callback(sourceID *windows.GUID, state etw.ProviderState, level etw.Level, fmt.Printf("Callback: isEnabled=%d, level=%d, matchAnyKeyword=%d\n", state, level, matchAnyKeyword) } +func guidToString(guid *windows.GUID) string { + data1 := make([]byte, 4) + binary.BigEndian.PutUint32(data1, guid.Data1) + data2 := make([]byte, 2) + binary.BigEndian.PutUint16(data2, guid.Data2) + data3 := make([]byte, 2) + binary.BigEndian.PutUint16(data3, guid.Data3) + return fmt.Sprintf( + "%s-%s-%s-%s-%s", + hex.EncodeToString(data1), + hex.EncodeToString(data2), + hex.EncodeToString(data3), + hex.EncodeToString(guid.Data4[:2]), + hex.EncodeToString(guid.Data4[2:])) +} + func main() { - providerID := windows.GUID{0xdd2062c6, 0x5d1b, 0x4a0f, [8]uint8{0xbd, 0xb9, 0x22, 0x28, 0xbc, 0xb1, 0x07, 0x7c}} + provider, err := etw.NewProvider("TestProvider", callback) - provider, err := etw.NewProvider("TestProvider", &providerID, callback) if err != nil { logrus.Error(err) return @@ -30,15 +47,17 @@ func main() { } }() + fmt.Println("Provider ID:", guidToString(provider.ID)) + reader := bufio.NewReader(os.Stdin) fmt.Println("Press enter to log an event") reader.ReadString('\n') event := etw.NewEvent("TestEvent", etw.NewEventDescriptor()) - event.Metadata.AddField("TestField", etw.InTypeAnsiString) + event.Metadata.AddField("TestField", etw.InTypeANSIString) event.Data.AddString("Foo") - event.Metadata.AddField("TestField2", etw.InTypeAnsiString) + event.Metadata.AddField("TestField2", etw.InTypeANSIString) event.Data.AddString("Bar") if err := provider.WriteEvent(event); err != nil { diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 9a3c966..294835a 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -6,8 +6,6 @@ import ( "github.com/Microsoft/go-winio/internal/etw" "github.com/sirupsen/logrus" - - "golang.org/x/sys/windows" ) // Hook is a Logrus hook which logs received events to ETW. @@ -16,10 +14,10 @@ type Hook struct { } // NewHook registers a new ETW provider and returns a hook to log from it. -func NewHook(providerName string, providerID *windows.GUID) (*Hook, error) { +func NewHook(providerName string) (*Hook, error) { hook := Hook{} - provider, err := etw.NewProvider(providerName, providerID, nil) + provider, err := etw.NewProvider(providerName, nil) if err != nil { return nil, err } From 7c26c75173d3cb859842ddde21505b0f1bbdfd54 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Fri, 21 Dec 2018 10:06:18 -0800 Subject: [PATCH 12/17] Add ETW support for arrays --- internal/etw/eventdata.go | 8 ++++++++ internal/etw/eventmetadata.go | 36 ++++++++++++++++++++++++++++++----- internal/etw/sample/sample.go | 7 +++++++ 3 files changed, 46 insertions(+), 5 deletions(-) diff --git a/internal/etw/eventdata.go b/internal/etw/eventdata.go index 7d62799..6296099 100644 --- a/internal/etw/eventdata.go +++ b/internal/etw/eventdata.go @@ -2,6 +2,7 @@ package etw import ( "bytes" + "encoding/binary" ) // EventData maintains a buffer which builds up the data for an ETW event. It @@ -20,3 +21,10 @@ func (ed *EventData) AddString(data string) { ed.buffer.WriteString(data) ed.buffer.WriteByte(0) } + +// This is mostly added for testing purposes, and will be removed later, as we +// shouldn't take a dependency on binary.Write knowing how to marshal values +// correctly for TraceLogging. +func (ed *EventData) AddSimple(data interface{}) { + binary.Write(&ed.buffer, binary.LittleEndian, data) +} diff --git a/internal/etw/eventmetadata.go b/internal/etw/eventmetadata.go index cdcbfc8..4d74db9 100644 --- a/internal/etw/eventmetadata.go +++ b/internal/etw/eventmetadata.go @@ -37,6 +37,9 @@ const ( InTypeCountedANSIString InTypeStruct InTypeCountedBinary + + InTypeCountedArray InType = 32 + InTypeArray InType = 64 ) // OutType specifies a hint to the event decoder for how the value should be @@ -73,7 +76,7 @@ const ( OutTypeDateTimeUTC OutType = 38 ) -// EventMetadata maintains a buffer which builds up the metadatadata for an ETW +// EventMetadata maintains a buffer which builds up the metadata for an ETW // event. It needs to be paired with EventData which describes the event. type EventMetadata struct { buffer bytes.Buffer @@ -91,10 +94,11 @@ func NewEventMetadata(name string) *EventMetadata { } type field struct { - name string - inType InType - outType OutType - tags uint32 + name string + inType InType + outType OutType + tags uint32 + countedArraySize uint16 } func (em *EventMetadata) writeField(f field) { @@ -112,6 +116,10 @@ func (em *EventMetadata) writeField(f field) { em.writeTags(f.tags) } } + + if f.countedArraySize != 0 { + binary.Write(&em.buffer, binary.LittleEndian, f.countedArraySize) + } } // writeTags writes out the tags value to the event metadata. Tags is a 28-bit @@ -163,6 +171,24 @@ func WithTags(tags uint32) fieldOpt { } } +// WithCountedArray marks the field as being an array of a fixed number of +// elements. The number of elements is encoded directly into the field metadata. +func WithCountedArray(count uint16) fieldOpt { + return func(f *field) { + f.inType |= InTypeCountedArray + f.countedArraySize = count + } +} + +// WithArray marks the field as being an array of a dynamic number of elements. +// The number of elements must be written as a uint16 to the data block, +// immediately preceeding the array elements. +func WithArray() fieldOpt { + return func(f *field) { + f.inType |= InTypeArray + } +} + // AddField appends a single field to the end of the event metadata buffer. func (em *EventMetadata) AddField(name string, inType InType, opts ...fieldOpt) { f := field{ diff --git a/internal/etw/sample/sample.go b/internal/etw/sample/sample.go index 1b9d002..f041434 100644 --- a/internal/etw/sample/sample.go +++ b/internal/etw/sample/sample.go @@ -59,6 +59,13 @@ func main() { event.Data.AddString("Foo") event.Metadata.AddField("TestField2", etw.InTypeANSIString) event.Data.AddString("Bar") + event.Metadata.AddField("TestArray", etw.InTypeANSIString, etw.WithArray()) + event.Data.AddSimple(uint16(5)) + event.Data.AddString("Item1") + event.Data.AddString("Item2") + event.Data.AddString("Item3") + event.Data.AddString("Item4") + event.Data.AddString("Item5") if err := provider.WriteEvent(event); err != nil { fmt.Println(err) From fac5ca0c3ab944416c01eb598d4d5c6498a7d2c5 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Fri, 21 Dec 2018 15:29:25 -0800 Subject: [PATCH 13/17] Separate ETW into low-level and high-level API --- internal/etw/eventdata.go | 35 ++++-- internal/etw/{event.go => eventdescriptor.go} | 22 ---- internal/etw/eventmetadata.go | 100 +++++++++--------- internal/etw/eventopt.go | 29 +++++ internal/etw/fieldopt.go | 35 ++++++ internal/etw/provider.go | 67 ++++++++++-- internal/etw/sample/sample.go | 67 ++++++++---- pkg/etwlogrus/hook.go | 23 ++-- 8 files changed, 253 insertions(+), 125 deletions(-) rename internal/etw/{event.go => eventdescriptor.go} (75%) create mode 100644 internal/etw/eventopt.go create mode 100644 internal/etw/fieldopt.go diff --git a/internal/etw/eventdata.go b/internal/etw/eventdata.go index 6296099..fc270e1 100644 --- a/internal/etw/eventdata.go +++ b/internal/etw/eventdata.go @@ -11,20 +11,35 @@ type EventData struct { buffer bytes.Buffer } -// NewEventData returns a new EventData with an empty buffer. -func NewEventData() *EventData { - return &EventData{} +// Bytes returns the raw binary data containing the event data. The returned +// value is not copied from the internal buffer, so it can be mutated by the +// EventData object after it is returned. +func (ed *EventData) Bytes() []byte { + return ed.buffer.Bytes() } -// AddString appends the data for a string to the end of the buffer. -func (ed *EventData) AddString(data string) { +// WriteString appends a string, including the null terminator, to the buffer. +func (ed *EventData) WriteString(data string) { ed.buffer.WriteString(data) ed.buffer.WriteByte(0) } -// This is mostly added for testing purposes, and will be removed later, as we -// shouldn't take a dependency on binary.Write knowing how to marshal values -// correctly for TraceLogging. -func (ed *EventData) AddSimple(data interface{}) { - binary.Write(&ed.buffer, binary.LittleEndian, data) +// WriteUint8 appends a uint8 to the buffer. +func (ed *EventData) WriteUint8(value uint8) { + ed.buffer.WriteByte(value) +} + +// WriteUint16 appends a uint16 to the buffer. +func (ed *EventData) WriteUint16(value uint16) { + binary.Write(&ed.buffer, binary.LittleEndian, value) +} + +// WriteUint32 appends a uint32 to the buffer. +func (ed *EventData) WriteUint32(value uint32) { + binary.Write(&ed.buffer, binary.LittleEndian, value) +} + +// WriteUint64 appends a uint64 to the buffer. +func (ed *EventData) WriteUint64(value uint64) { + binary.Write(&ed.buffer, binary.LittleEndian, value) } diff --git a/internal/etw/event.go b/internal/etw/eventdescriptor.go similarity index 75% rename from internal/etw/event.go rename to internal/etw/eventdescriptor.go index a67e62c..3946765 100644 --- a/internal/etw/event.go +++ b/internal/etw/eventdescriptor.go @@ -27,23 +27,6 @@ const ( LevelVerbose ) -// Event represents a single ETW event. It can have field metadata and data -// added to it, and then be logged via a provider to actually send it to ETW. -type Event struct { - Descriptor *EventDescriptor - Metadata *EventMetadata - Data *EventData -} - -// NewEvent returns a new instance of an event object. -func NewEvent(name string, descriptor *EventDescriptor) *Event { - return &Event{ - Descriptor: descriptor, - Metadata: NewEventMetadata(name), - Data: &EventData{}, - } -} - // EventDescriptor represents various metadata for an ETW event. type EventDescriptor struct { id uint16 @@ -61,13 +44,8 @@ func NewEventDescriptor() *EventDescriptor { // Standard TraceLogging events default to the TraceLogging channel, and // verbose level. return &EventDescriptor{ - id: 0, - version: 0, Channel: ChannelTraceLogging, Level: LevelVerbose, - Opcode: 0, - Task: 0, - Keyword: 0, } } diff --git a/internal/etw/eventmetadata.go b/internal/etw/eventmetadata.go index 4d74db9..805b756 100644 --- a/internal/etw/eventmetadata.go +++ b/internal/etw/eventmetadata.go @@ -82,15 +82,24 @@ type EventMetadata struct { buffer bytes.Buffer } -// NewEventMetadata returns a new EventMetadata with event name and initial -// metadata written to the buffer. -func NewEventMetadata(name string) *EventMetadata { - em := EventMetadata{} +// Bytes returns the raw binary data containing the event metadata. Before being +// returned, the current size of the buffer is written to the start of the +// buffer. The returned value is not copied from the internal buffer, so it can +// be mutated by the EventMetadata object after it is returned. +func (em *EventMetadata) Bytes() []byte { + // Finalize the event metadata buffer by filling in the buffer length at the + // beginning. + binary.LittleEndian.PutUint16(em.buffer.Bytes(), uint16(em.buffer.Len())) + return em.buffer.Bytes() +} + +// WriteEventHeader writes the metadata for the start of an event to the buffer. +// This specifies the event name and tags. +func (em *EventMetadata) WriteEventHeader(name string, tags uint32) { binary.Write(&em.buffer, binary.LittleEndian, uint16(0)) // Length placeholder - em.writeTags(0) + em.writeTags(tags) em.buffer.WriteString(name) em.buffer.WriteByte(0) // Null terminator for name - return &em } type field struct { @@ -150,55 +159,44 @@ func (em *EventMetadata) writeTags(tags uint32) { } } -type fieldOpt func(f *field) - -// WithOutType specifies the out type for the field. This value is used as a -// hint by the event decoder for how the field value should be formatted. If no -// out type is specified, a default formatting based on the in type will be -// used. -func WithOutType(outType OutType) fieldOpt { - return func(f *field) { - f.outType = outType - } +// WriteField writes the metadata for a simple field to the buffer. +func (em *EventMetadata) WriteField(name string, inType InType, outType OutType, tags uint32) { + em.writeField(field{ + name: name, + inType: inType, + outType: outType, + tags: tags, + }) } -// WithTags adds a tag to the field. Tags are 28-bit values that have meaning -// only to the event consumer. The top 4 bits of the value will be ignored. -// Multiple uses of this option will cause the tags to be OR'd together. -func WithTags(tags uint32) fieldOpt { - return func(f *field) { - f.tags |= tags - } +// WriteArray writes the metadata for an array field to the buffer. The number +// of elements in the array must be written as a uint16 in the event data, +// immediately preceeding the event data. +func (em *EventMetadata) WriteArray(name string, inType InType, outType OutType, tags uint32) { + em.WriteField(name, inType|InTypeArray, outType, tags) } -// WithCountedArray marks the field as being an array of a fixed number of -// elements. The number of elements is encoded directly into the field metadata. -func WithCountedArray(count uint16) fieldOpt { - return func(f *field) { - f.inType |= InTypeCountedArray - f.countedArraySize = count - } +// WriteCountedArray writes the metadata for an array field to the buffer. The +// size of a counted array is fixed, and the size is written into the metadata +// directly. +func (em *EventMetadata) WriteCountedArray(name string, count uint16, inType InType, outType OutType, tags uint32) { + em.writeField(field{ + name: name, + inType: inType | InTypeCountedArray, + outType: outType, + tags: tags, + countedArraySize: count, + }) } -// WithArray marks the field as being an array of a dynamic number of elements. -// The number of elements must be written as a uint16 to the data block, -// immediately preceeding the array elements. -func WithArray() fieldOpt { - return func(f *field) { - f.inType |= InTypeArray - } -} - -// AddField appends a single field to the end of the event metadata buffer. -func (em *EventMetadata) AddField(name string, inType InType, opts ...fieldOpt) { - f := field{ - name: name, - inType: inType, - } - - for _, opt := range opts { - opt(&f) - } - - em.writeField(f) +// WriteStruct writes the metadata for a nested struct to the buffer. The struct +// contains the next N fields in the metadata, where N is specified by the +// fieldCount argument. +func (em *EventMetadata) WriteStruct(name string, fieldCount uint8, tags uint32) { + em.writeField(field{ + name: name, + inType: InTypeStruct, + outType: OutType(fieldCount), + tags: tags, + }) } diff --git a/internal/etw/eventopt.go b/internal/etw/eventopt.go new file mode 100644 index 0000000..78b7859 --- /dev/null +++ b/internal/etw/eventopt.go @@ -0,0 +1,29 @@ +package etw + +// EventOpt defines the option function type that can be passed to +// Provider.WriteEvent to specify general event options, such as level and +// keyword. +type EventOpt func(*EventDescriptor, *uint32) + +// WithLevel specifies the level of the event to be written. +func WithLevel(level Level) EventOpt { + return func(descriptor *EventDescriptor, tags *uint32) { + descriptor.Level = level + } +} + +// WithKeyword specifies the keywords of the event to be written. Multiple uses +// of this option are OR'd together. +func WithKeyword(keyword uint64) EventOpt { + return func(descriptor *EventDescriptor, tags *uint32) { + descriptor.Keyword |= keyword + } +} + +// WithTags specifies the tags of the event to be written. Tags is a 28-bit +// value (top 4 bits are ignored) which are interpreted by the event consumer. +func WithTags(newTags uint32) EventOpt { + return func(descriptor *EventDescriptor, tags *uint32) { + *tags |= newTags + } +} diff --git a/internal/etw/fieldopt.go b/internal/etw/fieldopt.go new file mode 100644 index 0000000..03854cc --- /dev/null +++ b/internal/etw/fieldopt.go @@ -0,0 +1,35 @@ +package etw + +// FieldOpt defines the option function type that can be passed to +// Provider.WriteEvent to add fields to the event. +type FieldOpt func(em *EventMetadata, ed *EventData) + +// StringField adds a single string field to the event. +func StringField(name string, value string) FieldOpt { + return func(em *EventMetadata, ed *EventData) { + em.WriteField(name, InTypeANSIString, OutTypeUTF8, 0) + ed.WriteString(value) + } +} + +// StringArray adds an array of strings to the event. +func StringArray(name string, values []string) FieldOpt { + return func(em *EventMetadata, ed *EventData) { + em.WriteArray(name, InTypeANSIString, OutTypeUTF8, 0) + ed.WriteUint16(uint16(len(values))) + for _, v := range values { + ed.WriteString(v) + } + } +} + +// Struct adds a nested struct to the event, the FieldOpts in the opts argument +// are used to specify the fields of the struct. +func Struct(name string, opts ...FieldOpt) FieldOpt { + return func(em *EventMetadata, ed *EventData) { + em.WriteStruct(name, uint8(len(opts)), 0) + for _, opt := range opts { + opt(em, ed) + } + } +} diff --git a/internal/etw/provider.go b/internal/etw/provider.go index 880f17e..501f707 100644 --- a/internal/etw/provider.go +++ b/internal/etw/provider.go @@ -172,6 +172,8 @@ func providerIDFromName(name string) (*windows.GUID, error) { }, nil } +// NewProvider creates and registers a new ETW provider. The provider ID is +// generated based on the provider name. func NewProvider(name string, callback EnableCallback) (provider *Provider, err error) { id, err := providerIDFromName(name) if err != nil { @@ -180,7 +182,10 @@ func NewProvider(name string, callback EnableCallback) (provider *Provider, err return NewProviderWithID(name, id, callback) } -// NewProvider creates and registers a new provider. +// NewProviderWithID creates and registers a new ETW provider, allowing the +// provider ID to be manually specified. This is most useful when there is an +// existing provider ID that must be used to conform to existing diagnostic +// infrastructure. func NewProviderWithID(name string, id *windows.GUID, callback EnableCallback) (provider *Provider, err error) { provider = providers.newProvider() defer func() { @@ -246,16 +251,56 @@ func (provider *Provider) IsEnabledForLevelAndKeywords(level Level, keywords uin return true } -// WriteEvent writes a single event to ETW, from this provider. -func (provider *Provider) WriteEvent(event *Event) error { - // Finalize the event metadata buffer by filling in the buffer length at the - // beginning. - binary.LittleEndian.PutUint16(event.Metadata.buffer.Bytes(), uint16(event.Metadata.buffer.Len())) +// WriteEvent writes a single ETW event from the provider. The event is +// constructed based on the EventOpt and FieldOpt values that are passed as +// opts. +func (provider *Provider) WriteEvent(name string, opts ...interface{}) error { + tags := uint32(0) + descriptor := NewEventDescriptor() + em := &EventMetadata{} + ed := &EventData{} - var dataDescriptors [3]eventDataDescriptor - dataDescriptors[0].set(eventDataDescriptorTypeProviderMetadata, provider.metadata) - dataDescriptors[1].set(eventDataDescriptorTypeEventMetadata, event.Metadata.buffer.Bytes()) - dataDescriptors[2].set(eventDataDescriptorTypeUserData, event.Data.buffer.Bytes()) + // We need to evaluate the EventOpts first since they might change tags, and + // we write out the tags before evaluating FieldOpts. + for _, opt := range opts { + if v, ok := opt.(EventOpt); ok { + v(descriptor, &tags) + } + } - return eventWriteTransfer(provider.handle, event.Descriptor, nil, nil, 3, &dataDescriptors[0]) + em.WriteEventHeader(name, tags) + + for _, opt := range opts { + if v, ok := opt.(FieldOpt); ok { + v(em, ed) + } + } + + return provider.WriteEventRaw(descriptor, [][]byte{em.Bytes()}, [][]byte{ed.Bytes()}) +} + +// WriteEventRaw writes a single ETW event from the provider. This function is +// less abstracted than WriteEvent, and presents a fairly direct interface to +// the event writing functionality. It expects a series of event metadata and +// event data blobs to be passed in, which must conform to the TraceLogging +// schema. The functions on EventMetadata and EventData can help with creating +// these blobs. The blobs of each type are effectively concatenated together by +// the ETW infrastructure. +func (provider *Provider) WriteEventRaw(descriptor *EventDescriptor, metadataBlobs [][]byte, dataBlobs [][]byte) error { + dataDescriptorCount := uint32(1 + len(metadataBlobs) + len(dataBlobs)) + dataDescriptors := make([]eventDataDescriptor, dataDescriptorCount) + + i := 0 + dataDescriptors[i].set(eventDataDescriptorTypeProviderMetadata, provider.metadata) + i++ + for _, blob := range metadataBlobs { + dataDescriptors[i].set(eventDataDescriptorTypeEventMetadata, blob) + i++ + } + for _, blob := range dataBlobs { + dataDescriptors[i].set(eventDataDescriptorTypeUserData, blob) + i++ + } + + return eventWriteTransfer(provider.handle, descriptor, nil, nil, dataDescriptorCount, &dataDescriptors[0]) } diff --git a/internal/etw/sample/sample.go b/internal/etw/sample/sample.go index f041434..1d8d363 100644 --- a/internal/etw/sample/sample.go +++ b/internal/etw/sample/sample.go @@ -51,29 +51,56 @@ func main() { reader := bufio.NewReader(os.Stdin) - fmt.Println("Press enter to log an event") + fmt.Println("Press enter to log events") reader.ReadString('\n') - event := etw.NewEvent("TestEvent", etw.NewEventDescriptor()) - event.Metadata.AddField("TestField", etw.InTypeANSIString) - event.Data.AddString("Foo") - event.Metadata.AddField("TestField2", etw.InTypeANSIString) - event.Data.AddString("Bar") - event.Metadata.AddField("TestArray", etw.InTypeANSIString, etw.WithArray()) - event.Data.AddSimple(uint16(5)) - event.Data.AddString("Item1") - event.Data.AddString("Item2") - event.Data.AddString("Item3") - event.Data.AddString("Item4") - event.Data.AddString("Item5") - - if err := provider.WriteEvent(event); err != nil { - fmt.Println(err) + // Write using high-level API. + if err := provider.WriteEvent( + "TestEvent", + etw.WithLevel(etw.LevelInfo), + etw.WithKeyword(0x140), + etw.StringField("TestField", "Foo"), + etw.StringField("TestField2", "Bar"), + etw.Struct("TestStruct", + etw.StringField("Field1", "Value1"), + etw.StringField("Field2", "Value2")), + etw.StringArray("TestArray", []string{ + "Item1", + "Item2", + "Item3", + "Item4", + "Item5", + }), + ); err != nil { + logrus.Error(err) return } - fmt.Println("Event written") - - fmt.Println("Press enter to exit") - reader.ReadString('\n') + // Write using low-level API. + descriptor := etw.NewEventDescriptor() + descriptor.Level = etw.LevelInfo + descriptor.Keyword = 0x140 + em := &etw.EventMetadata{} + ed := &etw.EventData{} + em.WriteEventHeader("TestEvent", 0) + em.WriteField("TestField", etw.InTypeANSIString, etw.OutTypeUTF8, 0) + ed.WriteString("Foo") + em.WriteField("TestField2", etw.InTypeANSIString, etw.OutTypeUTF8, 0) + ed.WriteString("Bar") + em.WriteStruct("TestStruct", 2, 0) + em.WriteField("Field1", etw.InTypeANSIString, etw.OutTypeUTF8, 0) + ed.WriteString("Value1") + em.WriteField("Field2", etw.InTypeANSIString, etw.OutTypeUTF8, 0) + ed.WriteString("Value2") + em.WriteArray("TestArray", etw.InTypeANSIString, etw.OutTypeDefault, 0) + ed.WriteUint16(5) + ed.WriteString("Item1") + ed.WriteString("Item2") + ed.WriteString("Item3") + ed.WriteString("Item4") + ed.WriteString("Item5") + if err := provider.WriteEventRaw(descriptor, [][]byte{em.Bytes()}, [][]byte{ed.Bytes()}); err != nil { + logrus.Error(err) + return + } } diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 294835a..7146765 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -46,30 +46,31 @@ func (h *Hook) Fire(e *logrus.Entry) error { return nil } - descriptor := etw.NewEventDescriptor() + opts := make([]interface{}, len(e.Data)) + i := 0 // We could try to map Logrus levels to ETW levels, but we would lose some // fidelity as there are fewer ETW levels. So instead we use the level // directly. - descriptor.Level = etw.Level(e.Level) + opts[i] = etw.WithLevel(etw.Level(e.Level)) + i++ - event := etw.NewEvent("LogrusEntry", descriptor) - - event.Metadata.AddField("Message", etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) - event.Data.AddString(e.Message) + opts[i] = etw.StringField("Message", e.Message) + i++ for k, v := range e.Data { switch v := v.(type) { case string: - event.Metadata.AddField(k, etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) - event.Data.AddString(v) + opts[i] = etw.StringField(k, v) default: - event.Metadata.AddField(k, etw.InTypeANSIString, etw.WithOutType(etw.OutTypeUTF8)) - event.Data.AddString(fmt.Sprintf(" %v", reflect.TypeOf(v), v)) + opts[i] = etw.StringField(k, fmt.Sprintf(" %v", reflect.TypeOf(v), v)) } + i++ } - h.provider.WriteEvent(event) + h.provider.WriteEvent( + "LogrusEntry", + opts...) return nil } From b87cea3696e200668257330aa5e7f697df05fc31 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 3 Jan 2019 13:08:23 -0800 Subject: [PATCH 14/17] Clean up and PR feedback --- internal/etw/eventdatadescriptor.go | 32 +++++++ internal/etw/eventmetadata.go | 57 ++++-------- internal/etw/eventopt.go | 5 + internal/etw/fieldopt.go | 5 + internal/etw/provider.go | 136 ++++++---------------------- internal/etw/providerglobal.go | 52 +++++++++++ internal/etw/sample/sample.go | 31 ++++--- pkg/etwlogrus/hook.go | 27 +++--- 8 files changed, 168 insertions(+), 177 deletions(-) create mode 100644 internal/etw/eventdatadescriptor.go create mode 100644 internal/etw/providerglobal.go diff --git a/internal/etw/eventdatadescriptor.go b/internal/etw/eventdatadescriptor.go new file mode 100644 index 0000000..efa5f78 --- /dev/null +++ b/internal/etw/eventdatadescriptor.go @@ -0,0 +1,32 @@ +package etw + +import ( + "unsafe" +) + +type eventDataDescriptorType uint8 + +const ( + eventDataDescriptorTypeUserData eventDataDescriptorType = iota + eventDataDescriptorTypeEventMetadata + eventDataDescriptorTypeProviderMetadata +) + +type eventDataDescriptor struct { + ptr uint64 + size uint32 + dataType eventDataDescriptorType + reserved1 uint8 + reserved2 uint16 +} + +func newEventDataDescriptor(dataType eventDataDescriptorType, buffer []byte) eventDataDescriptor { + // Passing a pointer to Go-managed memory as part of a block of memory is + // risky since the GC doesn't know about it. If we find a better way to do + // this we should use it instead. + return eventDataDescriptor{ + ptr: uint64(uintptr(unsafe.Pointer(&buffer[0]))), + size: uint32(len(buffer)), + dataType: dataType, + } +} diff --git a/internal/etw/eventmetadata.go b/internal/etw/eventmetadata.go index 805b756..d294027 100644 --- a/internal/etw/eventmetadata.go +++ b/internal/etw/eventmetadata.go @@ -37,7 +37,6 @@ const ( InTypeCountedANSIString InTypeStruct InTypeCountedBinary - InTypeCountedArray InType = 32 InTypeArray InType = 64 ) @@ -49,7 +48,7 @@ type OutType byte // Various OutType definitions for TraceLogging. These must match the // definitions found in TraceLoggingProvider.h in the Windows SDK. const ( - // OutTypeDefault indicates that the default formatting for the in type will + // OutTypeDefault indicates that the default formatting for the InType will // be used by the event decoder. OutTypeDefault OutType = iota OutTypeNoPrint @@ -102,32 +101,24 @@ func (em *EventMetadata) WriteEventHeader(name string, tags uint32) { em.buffer.WriteByte(0) // Null terminator for name } -type field struct { - name string - inType InType - outType OutType - tags uint32 - countedArraySize uint16 -} - -func (em *EventMetadata) writeField(f field) { - em.buffer.WriteString(f.name) +func (em *EventMetadata) writeField(name string, inType InType, outType OutType, tags uint32, arrSize uint16) { + em.buffer.WriteString(name) em.buffer.WriteByte(0) // Null terminator for name - if f.outType == OutTypeDefault && f.tags == 0 { - em.buffer.WriteByte(byte(f.inType)) + if outType == OutTypeDefault && tags == 0 { + em.buffer.WriteByte(byte(inType)) } else { - em.buffer.WriteByte(byte(f.inType | 128)) - if f.tags == 0 { - em.buffer.WriteByte(byte(f.outType)) + em.buffer.WriteByte(byte(inType | 128)) + if tags == 0 { + em.buffer.WriteByte(byte(outType)) } else { - em.buffer.WriteByte(byte(f.outType | 128)) - em.writeTags(f.tags) + em.buffer.WriteByte(byte(outType | 128)) + em.writeTags(tags) } } - if f.countedArraySize != 0 { - binary.Write(&em.buffer, binary.LittleEndian, f.countedArraySize) + if arrSize != 0 { + binary.Write(&em.buffer, binary.LittleEndian, arrSize) } } @@ -161,42 +152,26 @@ func (em *EventMetadata) writeTags(tags uint32) { // WriteField writes the metadata for a simple field to the buffer. func (em *EventMetadata) WriteField(name string, inType InType, outType OutType, tags uint32) { - em.writeField(field{ - name: name, - inType: inType, - outType: outType, - tags: tags, - }) + em.writeField(name, inType, outType, tags, 0) } // WriteArray writes the metadata for an array field to the buffer. The number // of elements in the array must be written as a uint16 in the event data, // immediately preceeding the event data. func (em *EventMetadata) WriteArray(name string, inType InType, outType OutType, tags uint32) { - em.WriteField(name, inType|InTypeArray, outType, tags) + em.writeField(name, inType|InTypeArray, outType, tags, 0) } // WriteCountedArray writes the metadata for an array field to the buffer. The // size of a counted array is fixed, and the size is written into the metadata // directly. func (em *EventMetadata) WriteCountedArray(name string, count uint16, inType InType, outType OutType, tags uint32) { - em.writeField(field{ - name: name, - inType: inType | InTypeCountedArray, - outType: outType, - tags: tags, - countedArraySize: count, - }) + em.writeField(name, inType|InTypeCountedArray, outType, tags, count) } // WriteStruct writes the metadata for a nested struct to the buffer. The struct // contains the next N fields in the metadata, where N is specified by the // fieldCount argument. func (em *EventMetadata) WriteStruct(name string, fieldCount uint8, tags uint32) { - em.writeField(field{ - name: name, - inType: InTypeStruct, - outType: OutType(fieldCount), - tags: tags, - }) + em.writeField(name, InTypeStruct, OutType(fieldCount), tags, 0) } diff --git a/internal/etw/eventopt.go b/internal/etw/eventopt.go index 78b7859..3fe0cda 100644 --- a/internal/etw/eventopt.go +++ b/internal/etw/eventopt.go @@ -5,6 +5,11 @@ package etw // keyword. type EventOpt func(*EventDescriptor, *uint32) +// WithEventOpts returns the variadic arguments as a single slice. +func WithEventOpts(opts ...EventOpt) []EventOpt { + return opts +} + // WithLevel specifies the level of the event to be written. func WithLevel(level Level) EventOpt { return func(descriptor *EventDescriptor, tags *uint32) { diff --git a/internal/etw/fieldopt.go b/internal/etw/fieldopt.go index 03854cc..0e6a20f 100644 --- a/internal/etw/fieldopt.go +++ b/internal/etw/fieldopt.go @@ -4,6 +4,11 @@ package etw // Provider.WriteEvent to add fields to the event. type FieldOpt func(em *EventMetadata, ed *EventData) +// WithFields returns the variadic arguments as a single slice. +func WithFields(opts ...FieldOpt) []FieldOpt { + return opts +} + // StringField adds a single string field to the event. func StringField(name string, value string) FieldOpt { return func(em *EventMetadata, ed *EventData) { diff --git a/internal/etw/provider.go b/internal/etw/provider.go index 501f707..6171f6a 100644 --- a/internal/etw/provider.go +++ b/internal/etw/provider.go @@ -5,20 +5,11 @@ import ( "crypto/sha1" "encoding/binary" "strings" - "sync" - "unsafe" + "unicode/utf16" "golang.org/x/sys/windows" ) -type eventDataDescriptorType uint8 - -const ( - eventDataDescriptorTypeUserData eventDataDescriptorType = iota - eventDataDescriptorTypeEventMetadata - eventDataDescriptorTypeProviderMetadata -) - // Provider represents an ETW event provider. It is identified by a provider // name and ID (GUID), which should always have a 1:1 mapping to each other // (e.g. don't use multiple provider names with the same ID, or vice versa). @@ -54,66 +45,6 @@ const ( // enable/disable notifications from ETW. type EnableCallback func(*windows.GUID, ProviderState, Level, uint64, uint64, uintptr) -type eventDataDescriptor struct { - ptr uint64 - size uint32 - dataType eventDataDescriptorType - reserved1 uint8 - reserved2 uint16 -} - -func (descriptor *eventDataDescriptor) set(dataType eventDataDescriptorType, buffer []byte) { - // Passing a pointer to Go-managed memory as part of a block of memory is - // risky since the GC doesn't know about it. If we find a better way to do - // this we should use it instead. - descriptor.ptr = uint64(uintptr(unsafe.Pointer(&buffer[0]))) - descriptor.size = uint32(len(buffer)) - descriptor.dataType = dataType -} - -// Because the provider callback function needs to be able to access the -// provider data when it is invoked by ETW, we need to keep provider data stored -// in a global map based on an index. The index is passed as the callback -// context to ETW. -type providerMap struct { - m map[uint]*Provider - i uint - lock sync.Mutex -} - -var providers = providerMap{ - m: make(map[uint]*Provider), -} - -func (p *providerMap) newProvider() *Provider { - p.lock.Lock() - defer p.lock.Unlock() - - i := p.i - p.i++ - - provider := &Provider{ - index: i, - } - - p.m[i] = provider - return provider -} - -func (p *providerMap) removeProvider(provider *Provider) { - p.lock.Lock() - defer p.lock.Unlock() - - delete(p.m, provider.index) -} - -func (p *providerMap) getProvider(index uint) *Provider { - p.lock.Lock() - defer p.lock.Unlock() - - return p.m[index] -} - func providerCallback(sourceID *windows.GUID, state ProviderState, level Level, matchAnyKeyword uint64, matchAllKeyword uint64, filterData uintptr, i uintptr) { provider := providers.getProvider(uint(i)) @@ -148,38 +79,29 @@ func providerCallbackAdapter(sourceID *windows.GUID, state uintptr, level uintpt // The algorithm is roughly: // Hash = Sha1(namespace + arg.ToUpper().ToUtf16be()) // Guid = Hash[0..15], with Hash[7] tweaked according to RFC 4122 -func providerIDFromName(name string) (*windows.GUID, error) { +func providerIDFromName(name string) *windows.GUID { + buffer := sha1.New() + namespace := []byte{0x48, 0x2C, 0x2D, 0xB2, 0xC3, 0x90, 0x47, 0xC8, 0x87, 0xF8, 0x1A, 0x15, 0xBF, 0xC1, 0x30, 0xFB} - buffer := &bytes.Buffer{} buffer.Write(namespace) - nameUTF16, err := windows.UTF16FromString(strings.ToUpper(name)) - if err != nil { - return nil, err - } - // nameUTF16 includes a null terminator, which we don't want included in the - // hash. - binary.Write(buffer, binary.BigEndian, nameUTF16[:len(nameUTF16)-1]) + binary.Write(buffer, binary.BigEndian, utf16.Encode([]rune(strings.ToUpper(name)))) - sum := sha1.Sum(buffer.Bytes()) + sum := buffer.Sum(nil) sum[7] = (sum[7] & 0xf) | 0x50 return &windows.GUID{ - Data1: (uint32(sum[3]) << 24) | (uint32(sum[2]) << 16) | (uint32(sum[1]) << 8) | uint32(sum[0]), - Data2: (uint16(sum[5]) << 8) | uint16(sum[4]), - Data3: (uint16(sum[7]) << 8) | uint16(sum[6]), + Data1: binary.LittleEndian.Uint32(sum[0:3]), + Data2: binary.LittleEndian.Uint16(sum[4:5]), + Data3: binary.LittleEndian.Uint16(sum[6:7]), Data4: [8]byte{sum[8], sum[9], sum[10], sum[11], sum[12], sum[13], sum[14], sum[15]}, - }, nil + } } // NewProvider creates and registers a new ETW provider. The provider ID is // generated based on the provider name. func NewProvider(name string, callback EnableCallback) (provider *Provider, err error) { - id, err := providerIDFromName(name) - if err != nil { - return nil, err - } - return NewProviderWithID(name, id, callback) + return NewProviderWithID(name, providerIDFromName(name), callback) } // NewProviderWithID creates and registers a new ETW provider, allowing the @@ -187,6 +109,10 @@ func NewProvider(name string, callback EnableCallback) (provider *Provider, err // existing provider ID that must be used to conform to existing diagnostic // infrastructure. func NewProviderWithID(name string, id *windows.GUID, callback EnableCallback) (provider *Provider, err error) { + providerCallbackOnce.Do(func() { + globalProviderCallback = windows.NewCallback(providerCallbackAdapter) + }) + provider = providers.newProvider() defer func() { if err != nil { @@ -196,7 +122,7 @@ func NewProviderWithID(name string, id *windows.GUID, callback EnableCallback) ( provider.ID = id provider.callback = callback - if err := eventRegister(provider.ID, windows.NewCallback(providerCallbackAdapter), uintptr(provider.index), &provider.handle); err != nil { + if err := eventRegister(provider.ID, globalProviderCallback, uintptr(provider.index), &provider.handle); err != nil { return nil, err } @@ -254,7 +180,7 @@ func (provider *Provider) IsEnabledForLevelAndKeywords(level Level, keywords uin // WriteEvent writes a single ETW event from the provider. The event is // constructed based on the EventOpt and FieldOpt values that are passed as // opts. -func (provider *Provider) WriteEvent(name string, opts ...interface{}) error { +func (provider *Provider) WriteEvent(name string, eventOpts []EventOpt, fieldOpts []FieldOpt) error { tags := uint32(0) descriptor := NewEventDescriptor() em := &EventMetadata{} @@ -262,18 +188,18 @@ func (provider *Provider) WriteEvent(name string, opts ...interface{}) error { // We need to evaluate the EventOpts first since they might change tags, and // we write out the tags before evaluating FieldOpts. - for _, opt := range opts { - if v, ok := opt.(EventOpt); ok { - v(descriptor, &tags) - } + for _, opt := range eventOpts { + opt(descriptor, &tags) + } + + if !provider.IsEnabledForLevelAndKeywords(descriptor.Level, descriptor.Keyword) { + return nil } em.WriteEventHeader(name, tags) - for _, opt := range opts { - if v, ok := opt.(FieldOpt); ok { - v(em, ed) - } + for _, opt := range fieldOpts { + opt(em, ed) } return provider.WriteEventRaw(descriptor, [][]byte{em.Bytes()}, [][]byte{ed.Bytes()}) @@ -288,18 +214,14 @@ func (provider *Provider) WriteEvent(name string, opts ...interface{}) error { // the ETW infrastructure. func (provider *Provider) WriteEventRaw(descriptor *EventDescriptor, metadataBlobs [][]byte, dataBlobs [][]byte) error { dataDescriptorCount := uint32(1 + len(metadataBlobs) + len(dataBlobs)) - dataDescriptors := make([]eventDataDescriptor, dataDescriptorCount) + dataDescriptors := make([]eventDataDescriptor, 0, dataDescriptorCount) - i := 0 - dataDescriptors[i].set(eventDataDescriptorTypeProviderMetadata, provider.metadata) - i++ + dataDescriptors = append(dataDescriptors, newEventDataDescriptor(eventDataDescriptorTypeProviderMetadata, provider.metadata)) for _, blob := range metadataBlobs { - dataDescriptors[i].set(eventDataDescriptorTypeEventMetadata, blob) - i++ + dataDescriptors = append(dataDescriptors, newEventDataDescriptor(eventDataDescriptorTypeEventMetadata, blob)) } for _, blob := range dataBlobs { - dataDescriptors[i].set(eventDataDescriptorTypeUserData, blob) - i++ + dataDescriptors = append(dataDescriptors, newEventDataDescriptor(eventDataDescriptorTypeUserData, blob)) } return eventWriteTransfer(provider.handle, descriptor, nil, nil, dataDescriptorCount, &dataDescriptors[0]) diff --git a/internal/etw/providerglobal.go b/internal/etw/providerglobal.go new file mode 100644 index 0000000..28177a1 --- /dev/null +++ b/internal/etw/providerglobal.go @@ -0,0 +1,52 @@ +package etw + +import ( + "sync" +) + +// Because the provider callback function needs to be able to access the +// provider data when it is invoked by ETW, we need to keep provider data stored +// in a global map based on an index. The index is passed as the callback +// context to ETW. +type providerMap struct { + m map[uint]*Provider + i uint + lock sync.Mutex + once sync.Once +} + +var providers = providerMap{ + m: make(map[uint]*Provider), +} + +func (p *providerMap) newProvider() *Provider { + p.lock.Lock() + defer p.lock.Unlock() + + i := p.i + p.i++ + + provider := &Provider{ + index: i, + } + + p.m[i] = provider + return provider +} + +func (p *providerMap) removeProvider(provider *Provider) { + p.lock.Lock() + defer p.lock.Unlock() + + delete(p.m, provider.index) +} + +func (p *providerMap) getProvider(index uint) *Provider { + p.lock.Lock() + defer p.lock.Unlock() + + return p.m[index] +} + +var providerCallbackOnce sync.Once +var globalProviderCallback uintptr diff --git a/internal/etw/sample/sample.go b/internal/etw/sample/sample.go index 1d8d363..20cef4a 100644 --- a/internal/etw/sample/sample.go +++ b/internal/etw/sample/sample.go @@ -57,20 +57,23 @@ func main() { // Write using high-level API. if err := provider.WriteEvent( "TestEvent", - etw.WithLevel(etw.LevelInfo), - etw.WithKeyword(0x140), - etw.StringField("TestField", "Foo"), - etw.StringField("TestField2", "Bar"), - etw.Struct("TestStruct", - etw.StringField("Field1", "Value1"), - etw.StringField("Field2", "Value2")), - etw.StringArray("TestArray", []string{ - "Item1", - "Item2", - "Item3", - "Item4", - "Item5", - }), + etw.WithEventOpts( + etw.WithLevel(etw.LevelInfo), + etw.WithKeyword(0x140), + ), + etw.WithFields( + etw.StringField("TestField", "Foo"), + etw.StringField("TestField2", "Bar"), + etw.Struct("TestStruct", + etw.StringField("Field1", "Value1"), + etw.StringField("Field2", "Value2")), + etw.StringArray("TestArray", []string{ + "Item1", + "Item2", + "Item3", + "Item4", + "Item5", + })), ); err != nil { logrus.Error(err) return diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 7146765..3a24282 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -42,35 +42,32 @@ func (h *Hook) Levels() []logrus.Level { // Fire receives each Logrus entry as it is logged, and logs it to ETW. func (h *Hook) Fire(e *logrus.Entry) error { - if !h.provider.IsEnabledForLevel(etw.Level(e.Level)) { + level := etw.Level(e.Level) + if !h.provider.IsEnabledForLevel(level) { return nil } - opts := make([]interface{}, len(e.Data)) - i := 0 + // Reserve extra space for the message field. + fields := make([]etw.FieldOpt, 0, len(e.Data)+1) - // We could try to map Logrus levels to ETW levels, but we would lose some - // fidelity as there are fewer ETW levels. So instead we use the level - // directly. - opts[i] = etw.WithLevel(etw.Level(e.Level)) - i++ - - opts[i] = etw.StringField("Message", e.Message) - i++ + fields = append(fields, etw.StringField("Message", e.Message)) for k, v := range e.Data { switch v := v.(type) { case string: - opts[i] = etw.StringField(k, v) + fields = append(fields, etw.StringField(k, v)) default: - opts[i] = etw.StringField(k, fmt.Sprintf(" %v", reflect.TypeOf(v), v)) + fields = append(fields, etw.StringField(k, fmt.Sprintf(" %v", reflect.TypeOf(v), v))) } - i++ } + // We could try to map Logrus levels to ETW levels, but we would lose some + // fidelity as there are fewer ETW levels. So instead we use the level + // directly. h.provider.WriteEvent( "LogrusEntry", - opts...) + etw.WithEventOpts(etw.WithLevel(level)), + fields) return nil } From 37af28e005ed15388e8140463bf95c7a9532808a Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 3 Jan 2019 13:57:57 -0800 Subject: [PATCH 15/17] Pass blob pointers safely to ETW --- internal/etw/eventdatadescriptor.go | 7 ++----- internal/etw/ptr64_32.go | 16 ++++++++++++++++ internal/etw/ptr64_64.go | 15 +++++++++++++++ 3 files changed, 33 insertions(+), 5 deletions(-) create mode 100644 internal/etw/ptr64_32.go create mode 100644 internal/etw/ptr64_64.go diff --git a/internal/etw/eventdatadescriptor.go b/internal/etw/eventdatadescriptor.go index efa5f78..e7c53cf 100644 --- a/internal/etw/eventdatadescriptor.go +++ b/internal/etw/eventdatadescriptor.go @@ -13,7 +13,7 @@ const ( ) type eventDataDescriptor struct { - ptr uint64 + ptr ptr64 size uint32 dataType eventDataDescriptorType reserved1 uint8 @@ -21,11 +21,8 @@ type eventDataDescriptor struct { } func newEventDataDescriptor(dataType eventDataDescriptorType, buffer []byte) eventDataDescriptor { - // Passing a pointer to Go-managed memory as part of a block of memory is - // risky since the GC doesn't know about it. If we find a better way to do - // this we should use it instead. return eventDataDescriptor{ - ptr: uint64(uintptr(unsafe.Pointer(&buffer[0]))), + ptr: ptr64{ptr: unsafe.Pointer(&buffer[0])}, size: uint32(len(buffer)), dataType: dataType, } diff --git a/internal/etw/ptr64_32.go b/internal/etw/ptr64_32.go new file mode 100644 index 0000000..435ec3c --- /dev/null +++ b/internal/etw/ptr64_32.go @@ -0,0 +1,16 @@ +// +build 386 arm + +package etw + +import ( + "unsafe" +) + +// byteptr64 defines a struct containing a pointer. The struct is guaranteed to +// be 64 bits, regardless of the actual size of a pointer on the platform. This +// is intended for use with certain Windows APIs that expect a pointer as a +// ULONGLONG. +type ptr64 struct { + ptr unsafe.Pointer + _ uint32 +} diff --git a/internal/etw/ptr64_64.go b/internal/etw/ptr64_64.go new file mode 100644 index 0000000..903d3c0 --- /dev/null +++ b/internal/etw/ptr64_64.go @@ -0,0 +1,15 @@ +// +build amd64 arm64 + +package etw + +import ( + "unsafe" +) + +// byteptr64 defines a struct containing a pointer. The struct is guaranteed to +// be 64 bits, regardless of the actual size of a pointer on the platform. This +// is intended for use with certain Windows APIs that expect a pointer as a +// ULONGLONG. +type ptr64 struct { + ptr unsafe.Pointer +} From d23783336b4d3522b997e635c61bfef51d0ed919 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 3 Jan 2019 14:57:37 -0800 Subject: [PATCH 16/17] Fix indices in provider name to ID --- internal/etw/provider.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/etw/provider.go b/internal/etw/provider.go index 6171f6a..c413351 100644 --- a/internal/etw/provider.go +++ b/internal/etw/provider.go @@ -91,9 +91,9 @@ func providerIDFromName(name string) *windows.GUID { sum[7] = (sum[7] & 0xf) | 0x50 return &windows.GUID{ - Data1: binary.LittleEndian.Uint32(sum[0:3]), - Data2: binary.LittleEndian.Uint16(sum[4:5]), - Data3: binary.LittleEndian.Uint16(sum[6:7]), + Data1: binary.LittleEndian.Uint32(sum[0:4]), + Data2: binary.LittleEndian.Uint16(sum[4:6]), + Data3: binary.LittleEndian.Uint16(sum[6:8]), Data4: [8]byte{sum[8], sum[9], sum[10], sum[11], sum[12], sum[13], sum[14], sum[15]}, } } From 82fc62aed230ab9441ecb4a2f44be64a155ac9a6 Mon Sep 17 00:00:00 2001 From: Kevin Parsons Date: Thu, 3 Jan 2019 16:08:24 -0800 Subject: [PATCH 17/17] Return error from WriteEvent in Logrus hook --- pkg/etwlogrus/hook.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/pkg/etwlogrus/hook.go b/pkg/etwlogrus/hook.go index 3a24282..28d079f 100644 --- a/pkg/etwlogrus/hook.go +++ b/pkg/etwlogrus/hook.go @@ -64,12 +64,10 @@ func (h *Hook) Fire(e *logrus.Entry) error { // We could try to map Logrus levels to ETW levels, but we would lose some // fidelity as there are fewer ETW levels. So instead we use the level // directly. - h.provider.WriteEvent( + return h.provider.WriteEvent( "LogrusEntry", etw.WithEventOpts(etw.WithLevel(level)), fields) - - return nil } // Close cleans up the hook and closes the ETW provider.