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/Jenkinsfile.yml # winlogbeat/beater/winlogbeat.go # winlogbeat/eventlog/wineventlog.go # winlogbeat/eventlog/wineventlog_experimental.go # winlogbeat/sys/wineventlog/wineventlog_windows.go # x-pack/winlogbeat/Jenkinsfile.yml
elastic · Mar 31, 2022 · f0be195 · f0be195
1 parent d91bb8a
commit f0be195
Show file tree

Hide file tree

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

diff --git a/winlogbeat/Jenkinsfile.yml b/winlogbeat/Jenkinsfile.yml
@@ -24,7 +24,16 @@ stages:
     crosscompile:
         make: "make -C winlogbeat crosscompile"
         stage: mandatory
+<<<<<<< HEAD
     windows:
+=======
+    windows-2022:
+      mage: "mage build unitTest"
+      platforms: ## override default labels in this specific stage.
+        - "windows-2022"
+      stage: mandatory
+    windows-2019:
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
         mage: "mage build unitTest"
         platforms:             ## override default labels in this specific stage.
             - "windows-2019"

diff --git a/winlogbeat/beater/winlogbeat.go b/winlogbeat/beater/winlogbeat.go
@@ -91,7 +91,11 @@ func (eb *Winlogbeat) init(b *beat.Beat) error {
 		if err != nil {
 			return fmt.Errorf("failed to create new event log: %w", err)
 		}
+<<<<<<< HEAD
 		eb.log.Debugf("Initialized EventLog]", eventLog.Name())
+=======
+		eb.log.Debugf("initialized WinEventLog[%s]", eventLog.Name())
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 
 		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,11 @@ func (l *winEventLog) openChannel(bookmark win.EvtHandle) error {
 	if err != nil {
 		return nil
 	}
+<<<<<<< HEAD
 	defer windows.CloseHandle(signalEvent)
+=======
+	defer windows.CloseHandle(signalEvent) //nolint:errcheck // This is just a resource release.
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 
 	var flags win.EvtSubscribeFlag
 	if bookmark > 0 {
@@ -273,11 +287,20 @@ func (l *winEventLog) Read() ([]Record, error) {
 	}()
 	detailf("%s EventHandles returned %d handles", l.logPrefix, len(handles))
 
+<<<<<<< HEAD
 	var records []Record
 	for _, h := range handles {
 		l.outputBuf.Reset()
 		err := l.render(h, l.outputBuf)
 		if bufErr, ok := err.(sys.InsufficientBufferError); ok {
+=======
+	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 errors.As(err, &bufErr) {
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 			detailf("%s Increasing render buffer size to %d", l.logPrefix,
 				bufErr.RequiredSize)
 			l.renderBuf = make([]byte, bufErr.RequiredSize)
@@ -299,6 +322,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
 	}
@@ -314,7 +343,11 @@ func (l *winEventLog) Close() error {
 
 func (l *winEventLog) eventHandles(maxRead int) ([]win.EvtHandle, int, error) {
 	handles, err := win.EventHandles(l.subscription, maxRead)
+<<<<<<< HEAD
 	switch err {
+=======
+	switch err { //nolint:errorlint // This is an errno or nil.
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 	case nil:
 		if l.maxRead > maxRead {
 			debugf("%s Recovered from RPC_S_INVALID_BOUND error (errno 1734) "+
@@ -366,13 +399,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{
@@ -474,6 +509,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
 }
@@ -488,12 +526,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,6 +21,10 @@
 package eventlog
 
 import (
+<<<<<<< HEAD
+=======
+	"fmt"
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 	"io"
 	"os"
 	"path/filepath"
@@ -42,6 +46,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 {
@@ -99,7 +111,11 @@ func (l *winEventLogExp) openChannel(bookmark win.Bookmark) (win.EvtHandle, erro
 	if err != nil {
 		return win.NilHandle, err
 	}
+<<<<<<< HEAD
 	defer windows.CloseHandle(signalEvent)
+=======
+	defer windows.CloseHandle(signalEvent) //nolint:errcheck // This is just a resource release.
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 
 	var flags win.EvtSubscribeFlag
 	if bookmark > 0 {
@@ -116,6 +132,20 @@ func (l *winEventLogExp) openChannel(bookmark win.Bookmark) (win.EvtHandle, erro
 		l.query,                 // Query - nil means all events
 		win.EvtHandle(bookmark), // Bookmark - for resuming from a specific event
 		flags)
+<<<<<<< HEAD
+=======
+
+	switch err { //nolint:errorlint // This is an errno or nil.
+	case nil:
+		return h, nil
+	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)
+	default:
+		return 0, err
+	}
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 }
 
 func (l *winEventLogExp) openFile(state checkpoint.EventLogState, bookmark win.Bookmark) (win.EvtHandle, error) {
@@ -198,6 +228,10 @@ func (l *winEventLogExp) processHandle(h win.EvtHandle) (*Record, error) {
 		evt.RenderErr = append(evt.RenderErr, err.Error())
 	}
 
+<<<<<<< HEAD
+=======
+	//nolint:godox // Bad linter! Keep to have a record of feature disparity between non-experimental vs experimental.
+>>>>>>> 34bdc3d468 (winlogbeat: fix event handling for Windows 2022 (#30942))
 	// TODO: Need to add XML when configured.
 
 	r := &Record{
@@ -305,11 +339,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]
 			}
 		}
 	}
Original file line number	Diff line number	Diff line change
Expand Up		@@ -64,6 +64,8 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d

		Winlogbeat

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


		Functionbeat

Expand Down