[8.1](backport #30942) winlogbeat/sys/wineventlog: extend testing and…

… fix bugs (#31075) * winlogbeat: fix event handling for Windows 2022 (#30942) This fixes failures in event handling on Windows 2022[1] where parts of events available from the Windows API are not reflected in the events recovered by winlogbeat[2]. There is unfortunately quite a lot of movement in this change due to the need to satisfy linter requirements. Beyond those changes, the substantive changes here are: 1. Addition of new testing infrastructure to allow addition of evtx files and comparison with there expected XML renderings, and adding some test cases (shown below). 2. Fixing a buffer length parameter in the call to _EvtFormatMessage in evtFormatMessage that was the result of a lack of clarity in the API documentation for that syscall. 3. Fixing a var shadowing decl of the publisher handle EvtHandle in FormatEventString. 4. Providing a call back for the legacy (non-experimental) API through wineventlog.Message to allow it to obtain the event message in the case that the RenderingInfo element is not available via the Windows API. 5. Ensure that keyword, opcode and level are obtained by the non-experimental API by calling winevent.EnrichRawValuesWithNames in buildRecordFromXML. This change also required making winevent.Event.OpcodeRaw a pointer to allow an absent System>Opcode element to be distinquished from the zero, but present element. The change also enables testing on Windows 2022. [1]#30621 [2]#30622 (comment) New events in testing as rendered by the Event Viewer: ec1: eventcreate /id 1000 /t error /l application /d "My custom error event for the application log" - <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event"> - <System> <Provider Name="EventCreate" /> <EventID Qualifiers="0">1000</EventID> <Version>0</Version> <Level>2</Level> <Task>0</Task> <Opcode>0</Opcode> <Keywords>0x80000000000000</Keywords> <TimeCreated SystemTime="2022-03-22T02:03:11.3106672Z" /> <EventRecordID>316</EventRecordID> <Correlation /> <Execution ProcessID="0" ThreadID="0" /> <Channel>Application</Channel> <Computer>vagrant</Computer> <Security UserID="S-1-5-21-2297499104-2362337018-4092230427-1000" /> </System> - <EventData> <Data>My custom error event for the application log</Data> </EventData> </Event> ec2: eventcreate /id 999 /t error /l application /so WinWord /d "Winword event 999 happened due to low diskspace" - <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event"> - <System> <Provider Name="WinWord" /> <EventID Qualifiers="0">999</EventID> <Version>0</Version> <Level>2</Level> <Task>0</Task> <Opcode>0</Opcode> <Keywords>0x80000000000000</Keywords> <TimeCreated SystemTime="2022-03-22T02:03:11.5132246Z" /> <EventRecordID>317</EventRecordID> <Correlation /> <Execution ProcessID="0" ThreadID="0" /> <Channel>Application</Channel> <Computer>vagrant</Computer> <Security UserID="S-1-5-21-2297499104-2362337018-4092230427-1000" /> </System> - <EventData> <Data>Winword event 999 happened due to low diskspace</Data> </EventData> </Event> ec3: eventcreate /id 5 /t error /l system /d "Catastrophe!" - <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event"> - <System> <Provider Name="system" /> <EventID Qualifiers="0">5</EventID> <Version>0</Version> <Level>2</Level> <Task>0</Task> <Opcode>0</Opcode> <Keywords>0x80000000000000</Keywords> <TimeCreated SystemTime="2022-03-22T02:03:11.5455572Z" /> <EventRecordID>1413</EventRecordID> <Correlation /> <Execution ProcessID="0" ThreadID="0" /> <Channel>System</Channel> <Computer>vagrant</Computer> <Security UserID="S-1-5-21-2297499104-2362337018-4092230427-1000" /> </System> - <EventData> <Data>Catastrophe!</Data> </EventData> </Event> ec4: eventcreate /id 5 /t error /l system /so Backup /d "Backup failure" - <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event"> - <System> <Provider Name="Backup" /> <EventID Qualifiers="0">5</EventID> <Version>0</Version> <Level>2</Level> <Task>0</Task> <Opcode>0</Opcode> <Keywords>0x80000000000000</Keywords> <TimeCreated SystemTime="2022-03-22T02:03:11.8616638Z" /> <EventRecordID>1414</EventRecordID> <Correlation /> <Execution ProcessID="0" ThreadID="0" /> <Channel>System</Channel> <Computer>vagrant</Computer> <Security UserID="S-1-5-21-2297499104-2362337018-4092230427-1000" /> </System> - <EventData> <Data>Backup failure</Data> </EventData> </Event> Co-authored-by: Andrew Kroh <[email protected]> (cherry picked from commit 34bdc3d) # Conflicts: # winlogbeat/beater/winlogbeat.go # winlogbeat/eventlog/wineventlog.go # winlogbeat/eventlog/wineventlog_experimental.go # winlogbeat/sys/wineventlog/wineventlog_windows.go # x-pack/winlogbeat/Jenkinsfile.yml * fix conflict Co-authored-by: Dan Kortschak <[email protected]> Co-authored-by: Dan Kortschak <[email protected]>
elastic · Mar 31, 2022 · 73f93c4 · 73f93c4
1 parent 40e2669
commit 73f93c4
Show file tree

Hide file tree

Showing 31 changed files with 387 additions and 178 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -62,6 +62,8 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...main[Check the HEAD dif
 
 *Winlogbeat*
 
+- Fix evtx parsing failures. {issue}30621[30621] {pull}30942[30942]
+
 
 *Functionbeat*
 

diff --git a/winlogbeat/Jenkinsfile.yml b/winlogbeat/Jenkinsfile.yml
@@ -24,6 +24,11 @@ stages:
     crosscompile:
         make: "make -C winlogbeat crosscompile"
         stage: mandatory
+    windows-2022:
+      mage: "mage build unitTest"
+      platforms: ## override default labels in this specific stage.
+        - "windows-2022"
+      stage: mandatory
     windows-2019:
         mage: "mage build unitTest"
         platforms:             ## override default labels in this specific stage.

diff --git a/winlogbeat/beater/winlogbeat.go b/winlogbeat/beater/winlogbeat.go
@@ -98,7 +98,7 @@ func (eb *Winlogbeat) init(b *beat.Beat) error {
 		if err != nil {
 			return fmt.Errorf("failed to create new event log: %w", err)
 		}
-		eb.log.Debugw("Initialized EventLog", "id", eventLog.Name())
+		eb.log.Debugf("initialized WinEventLog[%s]", eventLog.Name())
 
 		logger, err := newEventLogger(b.Info, eventLog, config, eb.log)
 		if err != nil {

diff --git a/winlogbeat/eventlog/wineventlog.go b/winlogbeat/eventlog/wineventlog.go
@@ -55,6 +55,15 @@ const (
 	eventLoggingAPIName = "eventlogging"
 )
 
+func init() {
+	// Register wineventlog API if it is available.
+	available, _ := win.IsAvailable()
+	if available {
+		Register(winEventLogAPIName, 0, newWinEventLog, win.Channels)
+		Register(eventLoggingAPIName, 1, newEventLogging, win.Channels)
+	}
+}
+
 type winEventLogConfig struct {
 	ConfigCommon  `config:",inline"`
 	BatchReadSize int                `config:"batch_read_size"` // Maximum number of events that Read will return.
@@ -160,6 +169,7 @@ type winEventLog struct {
 	lastRead     checkpoint.EventLogState // Record number of the last read event.
 
 	render    func(event win.EvtHandle, out io.Writer) error // Function for rendering the event to XML.
+	message   func(event win.EvtHandle) (string, error)      // Message fallback function.
 	renderBuf []byte                                         // Buffer used for rendering event.
 	outputBuf *sys.ByteBuffer                                // Buffer for receiving XML
 	cache     *messageFilesCache                             // Cached mapping of source name to event message file handles.
@@ -198,7 +208,7 @@ func (l *winEventLog) openChannel(bookmark win.EvtHandle) error {
 	if err != nil {
 		return err
 	}
-	defer func() { _ = windows.CloseHandle(signalEvent) }()
+	defer windows.CloseHandle(signalEvent) //nolint:errcheck // This is just a resource release.
 
 	var flags win.EvtSubscribeFlag
 	if bookmark > 0 {
@@ -286,13 +296,12 @@ func (l *winEventLog) Read() ([]Record, error) {
 	}()
 	detailf("%s EventHandles returned %d handles", l.logPrefix, len(handles))
 
-	//nolint: prealloc // some handles can be skipped, the final size is unknown
-	var records []Record
+	var records []Record //nolint:prealloc // This linter gives bad advice and does not take into account conditionals in loops.
 	for _, h := range handles {
 		l.outputBuf.Reset()
 		err := l.render(h, l.outputBuf)
 		var bufErr sys.InsufficientBufferError
-		if ok := errors.As(err, &bufErr); ok {
+		if errors.As(err, &bufErr) {
 			detailf("%s Increasing render buffer size to %d", l.logPrefix,
 				bufErr.RequiredSize)
 			l.renderBuf = make([]byte, bufErr.RequiredSize)
@@ -314,6 +323,12 @@ func (l *winEventLog) Read() ([]Record, error) {
 		if r.Offset.Bookmark, err = l.createBookmarkFromEvent(h); err != nil {
 			logp.Warn("%s failed creating bookmark: %v", l.logPrefix, err)
 		}
+		if r.Message == "" {
+			r.Message, err = l.message(h)
+			if err != nil {
+				logp.Err("%s error salvaging message: %v", l.logPrefix, err)
+			}
+		}
 		records = append(records, r)
 		l.lastRead = r.Offset
 	}
@@ -329,20 +344,20 @@ func (l *winEventLog) Close() error {
 
 func (l *winEventLog) eventHandles(maxRead int) ([]win.EvtHandle, int, error) {
 	handles, err := win.EventHandles(l.subscription, maxRead)
-	switch {
-	case err == nil:
+	switch err { //nolint:errorlint // This is an errno or nil.
+	case nil:
 		if l.maxRead > maxRead {
 			debugf("%s Recovered from RPC_S_INVALID_BOUND error (errno 1734) "+
 				"by decreasing batch_read_size to %v", l.logPrefix, maxRead)
 		}
 		return handles, maxRead, nil
-	case errors.Is(err, win.ERROR_NO_MORE_ITEMS):
+	case win.ERROR_NO_MORE_ITEMS:
 		detailf("%s No more events", l.logPrefix)
 		if l.config.NoMoreEvents == Stop {
 			return nil, maxRead, io.EOF
 		}
 		return nil, maxRead, nil
-	case errors.Is(err, win.RPC_S_INVALID_BOUND):
+	case win.RPC_S_INVALID_BOUND:
 		incrementMetric(readErrors, err)
 		if err := l.Close(); err != nil {
 			return nil, 0, fmt.Errorf("failed to recover from RPC_S_INVALID_BOUND: %w", err)
@@ -381,13 +396,15 @@ func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) Record {
 		e.RenderErr = append(e.RenderErr, recoveredErr.Error())
 	}
 
+	// Get basic string values for raw fields.
+	winevent.EnrichRawValuesWithNames(nil, &e)
 	if e.Level == "" {
 		// Fallback on LevelRaw if the Level is not set in the RenderingInfo.
 		e.Level = win.EventLevel(e.LevelRaw).String()
 	}
 
 	if logp.IsDebug(detailSelector) {
-		detailf("%s XML=%s Event=%+v", l.logPrefix, string(x), e)
+		detailf("%s XML=%s Event=%+v", l.logPrefix, x, e)
 	}
 
 	r := Record{
@@ -489,6 +506,9 @@ func newWinEventLog(options *common.Config) (EventLog, error) {
 			return win.RenderEvent(event, c.EventLanguage, l.renderBuf, l.cache.get, out)
 		}
 	}
+	l.message = func(event win.EvtHandle) (string, error) {
+		return win.Message(event, l.renderBuf, l.cache.get)
+	}
 
 	return l, nil
 }
@@ -503,12 +523,3 @@ func (l *winEventLog) createBookmarkFromEvent(evtHandle win.EvtHandle) (string,
 	win.Close(bmHandle)
 	return string(l.outputBuf.Bytes()), err
 }
-
-func init() {
-	// Register wineventlog API if it is available.
-	available, _ := win.IsAvailable()
-	if available {
-		Register(winEventLogAPIName, 0, newWinEventLog, win.Channels)
-		Register(eventLoggingAPIName, 1, newEventLogging, win.Channels)
-	}
-}
diff --git a/winlogbeat/eventlog/wineventlog_experimental.go b/winlogbeat/eventlog/wineventlog_experimental.go
@@ -21,7 +21,6 @@
 package eventlog
 
 import (
-	"errors"
 	"fmt"
 	"io"
 	"os"
@@ -43,6 +42,14 @@ const (
 	winEventLogExpAPIName = "wineventlog-experimental"
 )
 
+func init() {
+	// Register wineventlog API if it is available.
+	available, _ := win.IsAvailable()
+	if available {
+		Register(winEventLogExpAPIName, 10, newWinEventLogExp, win.Channels)
+	}
+}
+
 // winEventLogExp implements the EventLog interface for reading from the Windows
 // Event Log API.
 type winEventLogExp struct {
@@ -100,7 +107,7 @@ func (l *winEventLogExp) openChannel(bookmark win.Bookmark) (win.EvtHandle, erro
 	if err != nil {
 		return win.NilHandle, err
 	}
-	defer func() { _ = windows.CloseHandle(signalEvent) }()
+	defer windows.CloseHandle(signalEvent) //nolint:errcheck // This is just a resource release.
 
 	var flags win.EvtSubscribeFlag
 	if bookmark > 0 {
@@ -120,11 +127,10 @@ func (l *winEventLogExp) openChannel(bookmark win.Bookmark) (win.EvtHandle, erro
 		win.EvtHandle(bookmark), // Bookmark - for resuming from a specific event
 		flags)
 
-	switch {
-	case err == nil:
+	switch err { //nolint:errorlint // This is an errno or nil.
+	case nil:
 		return h, nil
-	case errors.Is(err, win.ERROR_NOT_FOUND), errors.Is(err, win.ERROR_EVT_QUERY_RESULT_STALE),
-		errors.Is(err, win.ERROR_EVT_QUERY_RESULT_INVALID_POSITION):
+	case win.ERROR_NOT_FOUND, win.ERROR_EVT_QUERY_RESULT_STALE, win.ERROR_EVT_QUERY_RESULT_INVALID_POSITION:
 		// The bookmarked event was not found, we retry the subscription from the start.
 		incrementMetric(readErrors, err)
 		return win.Subscribe(0, signalEvent, "", l.query, 0, win.EvtSubscribeStartAtOldestRecord)
@@ -213,7 +219,7 @@ func (l *winEventLogExp) processHandle(h win.EvtHandle) (*Record, error) {
 		evt.RenderErr = append(evt.RenderErr, err.Error())
 	}
 
-	//nolint: godox // keep to have a record of feature disparity between non-experimental vs experimental
+	//nolint:godox // Bad linter! Keep to have a record of feature disparity between non-experimental vs experimental.
 	// TODO: Need to add XML when configured.
 
 	r := &Record{
@@ -321,11 +327,3 @@ func newWinEventLogExp(options *common.Config) (EventLog, error) {
 
 	return l, nil
 }
-
-func init() {
-	// Register wineventlog API if it is available.
-	available, _ := win.IsAvailable()
-	if available {
-		Register(winEventLogExpAPIName, 10, newWinEventLogExp, win.Channels)
-	}
-}
diff --git a/winlogbeat/eventlog/wineventlog_test.go b/winlogbeat/eventlog/wineventlog_test.go
@@ -31,6 +31,7 @@ import (
 
 	"github.com/andrewkroh/sys/windows/svc/eventlog"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 
 	"github.com/elastic/beats/v7/libbeat/common"
 	"github.com/elastic/beats/v7/winlogbeat/checkpoint"
@@ -187,13 +188,27 @@ func testWindowsEventLog(t *testing.T, api string) {
 	const messageSize = 256 // Originally 31800, such a large value resulted in an empty eventlog under Win10.
 	const totalEvents = 1000
 	for i := 0; i < totalEvents; i++ {
-		safeWriteEvent(t, writer, eventlog.Info, uint32(i%1000), []string{strconv.Itoa(i) + " " + randomSentence(messageSize)})
+		safeWriteEvent(t, writer, eventlog.Info, uint32(i%1000)+1, []string{strconv.Itoa(i) + " " + randomSentence(messageSize)})
 	}
 
 	openLog := func(t testing.TB, config map[string]interface{}) EventLog {
 		return openLog(t, api, nil, config)
 	}
 
+	t.Run("has_message", func(t *testing.T) {
+		log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": 1})
+		defer log.Close()
+
+		for i := 0; i < 10; i++ {
+			records, err := log.Read()
+			require.NotEmpty(t, records)
+			require.NoError(t, err)
+
+			r := records[0]
+			require.NotEmpty(t, r.Message, "message field is empty: errors:%v\nrecord:%#v", r.Event.RenderErr, r)
+		}
+	})
+
 	// Test reading from an event log using a custom XML query.
 	t.Run("custom_xml_query", func(t *testing.T) {
 		cfg := map[string]interface{}{
@@ -307,16 +322,18 @@ func createLog(t testing.TB, messageFiles ...string) (log *eventlog.Log, tearDow
 	}
 
 	if existed {
-		wineventlog.EvtClearLog(wineventlog.NilHandle, name, "")
+		wineventlog.EvtClearLog(wineventlog.NilHandle, name, "") //nolint:errcheck // This is just a resource release.
 	}
 
 	log, err = eventlog.Open(source)
+	//nolint:errcheck // This is just a resource release.
 	if err != nil {
 		eventlog.RemoveSource(name, source)
 		eventlog.RemoveProvider(name)
 		t.Fatal(err)
 	}
 
+	//nolint:errcheck // This is just a resource release.
 	tearDown = func() {
 		log.Close()
 		wineventlog.EvtClearLog(wineventlog.NilHandle, name, "")
@@ -343,7 +360,7 @@ func safeWriteEvent(t testing.TB, log *eventlog.Log, etype uint16, eid uint32, m
 
 // setLogSize set the maximum number of bytes that an event log can hold.
 func setLogSize(t testing.TB, provider string, sizeBytes int) {
-	output, err := exec.Command("wevtutil.exe", "sl", "/ms:"+strconv.Itoa(sizeBytes), provider).CombinedOutput()
+	output, err := exec.Command("wevtutil.exe", "sl", "/ms:"+strconv.Itoa(sizeBytes), provider).CombinedOutput() //nolint:gosec // No possibility of command injection.
 	if err != nil {
 		t.Fatal("Failed to set log size", err, string(output))
 	}

diff --git a/winlogbeat/sys/winevent/event.go b/winlogbeat/sys/winevent/event.go
@@ -44,11 +44,6 @@ var (
 const (
 	keywordAuditFailure = 0x10000000000000
 	keywordAuditSuccess = 0x20000000000000
-
-	// keywordClassic indicates the log was published with the "classic" event
-	// logging API.
-	// https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.eventing.reader.standardeventkeywords?view=netframework-4.8
-	keywordClassic = 0x80000000000000
 )
 
 // UnmarshalXML unmarshals the given XML into a new Event.
@@ -67,7 +62,7 @@ type Event struct {
 	Version         Version         `xml:"System>Version"`
 	LevelRaw        uint8           `xml:"System>Level"`
 	TaskRaw         uint16          `xml:"System>Task"`
-	OpcodeRaw       uint8           `xml:"System>Opcode"`
+	OpcodeRaw       *uint8          `xml:"System>Opcode,omitempty"`
 	KeywordsRaw     HexInt64        `xml:"System>Keywords"`
 	TimeCreated     TimeCreated     `xml:"System>TimeCreated"`
 	RecordID        uint64          `xml:"System>EventRecordID"`
@@ -258,7 +253,10 @@ func (u *UserData) UnmarshalXML(d *xml.Decoder, start xml.StartElement) error {
 
 			u.Name = se.Name
 			u.Pairs = in.Pairs
-			d.Skip()
+			err = d.Skip()
+			if err != nil {
+				return err
+			}
 			break
 		}
 	}
@@ -309,8 +307,7 @@ func (v *Version) UnmarshalXML(d *xml.Decoder, start xml.StartElement) error {
 
 	version, err := strconv.ParseUint(s, 10, 8)
 	if err != nil {
-		// Ignore invalid version values.
-		return nil
+		return nil //nolint:nilerr // Ignore invalid version values.
 	}
 
 	*v = Version(version)
@@ -341,20 +338,19 @@ func (v *HexInt64) UnmarshalXML(d *xml.Decoder, start xml.StartElement) error {
 func EnrichRawValuesWithNames(publisherMeta *WinMeta, event *Event) {
 	// Keywords. Each bit in the value can represent a keyword.
 	rawKeyword := int64(event.KeywordsRaw)
-	isClassic := keywordClassic&rawKeyword > 0
 
 	if len(event.Keywords) == 0 {
 		for mask, keyword := range defaultWinMeta.Keywords {
-			if rawKeyword&mask > 0 {
+			if rawKeyword&mask != 0 {
 				event.Keywords = append(event.Keywords, keyword)
-				rawKeyword -= mask
+				rawKeyword &^= mask
 			}
 		}
 		if publisherMeta != nil {
 			for mask, keyword := range publisherMeta.Keywords {
-				if rawKeyword&mask > 0 {
+				if rawKeyword&mask != 0 {
 					event.Keywords = append(event.Keywords, keyword)
-					rawKeyword -= mask
+					rawKeyword &^= mask
 				}
 			}
 		}
@@ -363,10 +359,10 @@ func EnrichRawValuesWithNames(publisherMeta *WinMeta, event *Event) {
 	var found bool
 	if event.Opcode == "" {
 		// Opcode (search in defaultWinMeta first).
-		if !isClassic {
-			event.Opcode, found = defaultWinMeta.Opcodes[event.OpcodeRaw]
+		if event.OpcodeRaw != nil {
+			event.Opcode, found = defaultWinMeta.Opcodes[*event.OpcodeRaw]
 			if !found && publisherMeta != nil {
-				event.Opcode = publisherMeta.Opcodes[event.OpcodeRaw]
+				event.Opcode = publisherMeta.Opcodes[*event.OpcodeRaw]
 			}
 		}
 	}

diff --git a/winlogbeat/sys/winevent/event_test.go b/winlogbeat/sys/winevent/event_test.go
@@ -20,7 +20,6 @@ package winevent
 import (
 	"encoding/json"
 	"encoding/xml"
-	"fmt"
 	"strings"
 	"testing"
 	"time"
@@ -97,6 +96,7 @@ func TestXML(t *testing.T) {
 				EventIdentifier: EventIdentifier{ID: 91},
 				LevelRaw:        4,
 				TaskRaw:         9,
+				OpcodeRaw:       new(uint8), // The value in the XML is 0.
 				KeywordsRaw:     0x8020000000000000,
 				TimeCreated:     TimeCreated{allXMLTimeCreated},
 				RecordID:        100,
@@ -180,7 +180,7 @@ func TestXML(t *testing.T) {
 			if err != nil {
 				t.Error(err)
 			}
-			fmt.Println(string(json))
+			t.Logf("%s", json)
 		}
 	}
 }
Original file line number	Diff line number	Diff line change
Expand Up		@@ -62,6 +62,8 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...main[Check the HEAD dif

		Winlogbeat

		- Fix evtx parsing failures. {issue}30621[30621] {pull}30942[30942]


		Functionbeat

Expand Down