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 }