[7.17](backport #30942) winlogbeat/sys/wineventlog: extend testing an…

…d fix bugs (#31096)

* 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 <andrew.kroh@elastic.co>
(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

* clean up conflict scars

* cherrypick winlogbeat test fixes relevant to 7.17 from #31464

Co-authored-by: Dan Kortschak <90160302+efd6@users.noreply.github.com>
Co-authored-by: Dan Kortschak <dan.kortschak@elastic.co>

CHANGELOG.next.asciidoc

@@ -55,6 +55,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*
 

winlogbeat/Jenkinsfile.yml

@@ -24,7 +24,12 @@ stages:
     crosscompile:
         make: "make -C winlogbeat crosscompile"
         stage: mandatory
-    windows:
+    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.
             - "windows-2019"

winlogbeat/beater/winlogbeat.go

@@ -91,7 +91,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 {

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,24 @@ func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) Record {
 		e.RenderErr = append(e.RenderErr, recoveredErr.Error())
 	}
 
+	md, err := win.NewPublisherMetadataStore(win.NilHandle, e.Provider.Name, logp.L())
+	if err != nil {
+		// Return an empty store on error (can happen in cases where the
+		// log was forwarded and the provider doesn't exist on collector).
+		md = win.NewEmptyPublisherMetadataStore(e.Provider.Name, logp.L())
+		logp.Warn("failed to load publisher metadata for %v "+
+			"(returning an empty metadata store): %v", e.Provider.Name, err)
+	}
+
+	// Get basic string values for raw fields.
+	winevent.EnrichRawValuesWithNames(&md.WinMeta, &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 +515,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 +532,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)
-	}
-}

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)
-	}
-}

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))
 	}

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]
 			}
 		}
 	}