winlogbeat: system.test_wineventlog failures for Windows-2022

[v1v]

Please post all questions and issues on https://discuss.elastic.co/c/beats
before opening a Github Issue. Your questions will reach a wider audience there,
and if we confirm that there is a bug, then you can open a new issue.

For security vulnerabilities please only send reports to [email protected].
See https://www.elastic.co/community/security for more information.

Please include configurations and logs if available.

For confirmed bugs, please report:

• Version: main
• Operating System: windows-2022
• Steps to Reproduce: mage build unitTest

Test failures

• winlogbeat.tests.system.test_wineventlog.Test.test_fields_not_under_root
• winlogbeat.tests.system.test_wineventlog.Test.test_fields_under_root
• winlogbeat.tests.system.test_wineventlog.Test.test_include_xml
• winlogbeat.tests.system.test_wineventlog.Test.test_multiline_events
• winlogbeat.tests.system.test_wineventlog.Test.test_query_multi_param
• winlogbeat.tests.system.test_wineventlog.Test.test_read_one_event
• winlogbeat.tests.system.test_wineventlog.Test.test_read_unknown_event_id
• winlogbeat.tests.system.test_wineventlog.Test.test_read_unknown_sid
• winlogbeat.tests.system.test_wineventlog.Test.test_resume_reading_events
• winlogbeat.tests.system.test_wineventlog.Test.test_utf16_characters

[elasticmachine]

Pinging @elastic/security-external-integrations (Team:Security-External Integrations)

[botelastic]

This issue doesn't have a Team:<team> label.

[andrewkroh]

Test failure details can be found from #30622.

[andrewkroh]

I have encountered a few issues:

1. When calling EvtFormatMessage in we pass the number of WCHARs. That was resulting in ERROR_INVALID_DATA ("The data is invalid." / errno 13). After changing this to pass the number of bytes it works. This only affects the wineventlog-experimental API.

diff --git a/winlogbeat/sys/wineventlog/format_message.go b/winlogbeat/sys/wineventlog/format_message.go
index d953c210b5..b72117cb6e 100644
--- a/winlogbeat/sys/wineventlog/format_message.go
+++ b/winlogbeat/sys/wineventlog/format_message.go
@@ -89,7 +89,7 @@ func evtFormatMessage(metadataHandle EvtHandle, eventHandle EvtHandle, messageID
        defer bb.Free()
        bb.Reserve(int(bufferUsed * 2))
 
-       err = _EvtFormatMessage(metadataHandle, eventHandle, messageID, valuesCount, valuesPtr, messageFlag, uint32(bb.Len()/2), bb.PtrAt(0), &bufferUsed)
+       err = _EvtFormatMessage(metadataHandle, eventHandle, messageID, valuesCount, valuesPtr, messageFlag, uint32(bb.Len()), bb.PtrAt(0), &bufferUsed)
        if err != nil {
                switch err {
                // Ignore some errors so it can tolerate missing or mismatched parameter values.

2. Calling EvtFormatMessage to get the the XML event with rendered text for an event log from eventcreate.exe results in ERROR_EVT_MESSAGE_ID_NOT_FOUND (errno 15028). Prior to installing Windows updates for 2022 I was getting ERROR_MR_MID_NOT_FOUND (errno 317) (I saw this mentioned as a bug in EventLog tests failing on Windows 11 and Windows Server 2022 dotnet/runtime#58829 (comment))).
   
   On the same event log calling both EvtRender to get the XML (without message) and EvtFormatMessage to get the message string works. So this may be a workaround.
   
   Reading other logs from Windows and reading data from stored .evtx files appears to be working normally. It's only the data from eventcreate which we use heavily in unit tests that I have observed problems.

3. This was only observed because I was adding unit tests. In the normal code path a handle is passed. But this code does not have the expected side-effect which is to set the outer scope's pub value.

diff --git a/winlogbeat/sys/wineventlog/wineventlog_windows.go b/winlogbeat/sys/wineventlog/wineventlog_windows.go
index 11cd5319e6..1d7d27e468 100644
--- a/winlogbeat/sys/wineventlog/wineventlog_windows.go
+++ b/winlogbeat/sys/wineventlog/wineventlog_windows.go
@@ -382,9 +382,10 @@ func FormatEventString(
        out io.Writer,
 ) error {
        // Open a publisher handle if one was not provided.
-       ph := publisherHandle
-       if ph == 0 {
-               ph, err := OpenPublisherMetadata(0, publisher, lang)
+       pub := publisherHandle
+       if pub == NilHandle {
+               var err error
+               pub, err = OpenPublisherMetadata(0, publisher, lang)
                if err != nil {
                        return err
                }

[efd6]

After making the changes above, the previous tests in sys/wineventlog all pass, including new tests that read a collection of evtx files. A test in winlogbeat/eventlog added by @andrewkroh in investigation (now in #30942) does fail, but in an odd way; the evtx created during the tests are fine to consume by the new tests in sys/wineventlog, but fail to be recognised as having a message.

    --- FAIL: TestWindowsEventLogAPI/has_message (0.02s)
        wineventlog_test.go:202:
                Error Trace:    wineventlog_test.go:202
                Error:          Should NOT be empty, but was
                Test:           TestWindowsEventLogAPI/has_message
                Messages:       message field is empty: errors:[]
                                record:eventlog.Record{Event:winevent.Event{Provider:winevent.Provider{Name:"Integration Test", GUID:"", EventSourceName:""}, EventIdentifier:winevent.EventIdentifier{Qualifiers:0x0, ID:0x0}, Version:0x0, LevelRaw:0x4, TaskRaw:0x0, OpcodeRaw:0x0, KeywordsRaw:0x80000000000000, TimeCreated:winevent.TimeCreated{SystemTime:time.Date(2022, time.March, 23, 1, 22, 13, 115512200, time.UTC)}, RecordID:0x4e76, Correlation:winevent.Correlation{ActivityID:"", RelatedActivityID:""}, Execution:winevent.Execution{ProcessID:0x0, ThreadID:0x0, ProcessorID:0x0, SessionID:0x0, KernelTime:0x0, UserTime:0x0, ProcessorTime:0x0}, Channel:"WinlogbeatTestGo", Computer:"vagrant", User:winevent.SID{Identifier:"", Name:"", Domain:"", Type:0x0}, EventData:winevent.EventData{Pairs:[]winevent.KeyValue{winevent.KeyValue{Key:"Data", Value:"0 wriggle neutral trolley hunting highway attract college percent highway recover arrange bargain percent arrange quality arrange manager quality trolley feather percent hunting highway quality neutral arrange recover quality recover article bargain wriggle "}}}, UserData:winevent.UserData{Name:xml.Name{Space:"", Local:""}, Pairs:[]winevent.KeyValue(nil)}, Message:"", Level:"Information", Task:"", Opcode:"", Keywords:[]string(nil), RenderErrorCode:0x0, RenderErrorDataItemName:"", RenderErr:[]string(nil)}, File:"", API:"wineventlog", XML:"", Offset:checkpoint.EventLogState{Name:"WinlogbeatTestGo", RecordNumber:0x4e76, Timestamp:time.Date(2022, time.March, 23, 1, 22, 13, 115512200, time.UTC), Bookmark:"<BookmarkList>\r\n  <Bookmark Channel='WinlogbeatTestGo' RecordId='20086' IsCurrent='true'/>\r\n</BookmarkList>"}}
--- FAIL: TestWindowsEventLogAPIExperimental (1.03s)
    --- FAIL: TestWindowsEventLogAPIExperimental/has_message (0.02s)
        wineventlog_test.go:202:
                Error Trace:    wineventlog_test.go:202
                Error:          Should NOT be empty, but was
                Test:           TestWindowsEventLogAPIExperimental/has_message
                Messages:       message field is empty: errors:[failed to get the event message string: failed in EvtFormatMessage: The message resource is present but the message was not found in the message table.]
                                record:eventlog.Record{Event:winevent.Event{Provider:winevent.Provider{Name:"Integration Test", GUID:"", EventSourceName:""}, EventIdentifier:winevent.EventIdentifier{Qualifiers:0x0, ID:0x0}, Version:0x0, LevelRaw:0x4, TaskRaw:0x0, OpcodeRaw:0x0, KeywordsRaw:0x80000000000000, TimeCreated:winevent.TimeCreated{SystemTime:time.Date(2022, time.March, 23, 1, 22, 13, 891772600, time.UTC)}, RecordID:0x525e, Correlation:winevent.Correlation{ActivityID:"", RelatedActivityID:""}, Execution:winevent.Execution{ProcessID:0x0, ThreadID:0x0, ProcessorID:0x0, SessionID:0x0, KernelTime:0x0, UserTime:0x0, ProcessorTime:0x0}, Channel:"WinlogbeatTestGo", Computer:"vagrant", User:winevent.SID{Identifier:"", Name:"", Domain:"", Type:0x0}, EventData:winevent.EventData{Pairs:[]winevent.KeyValue{winevent.KeyValue{Key:"param0", Value:"0 wriggle percent neutral arrange neutral college college hunting quality attract manager trolley wriggle trolley article bargain hunting quality hunting highway highway percent highway hunting percent highway arrange wriggle manager trolley highway college "}}}, UserData:winevent.UserData{Name:xml.Name{Space:"", Local:""}, Pairs:[]winevent.KeyValue(nil)}, Message:"", Level:"Information", Task:"None", Opcode:"", Keywords:[]string{"Classic"}, RenderErrorCode:0x0, RenderErrorDataItemName:"", RenderErr:[]string{"failed to get the event message string: failed in EvtFormatMessage: The message resource is present but the message was not found in the message table."}}, File:"", API:"wineventlog-experimental", XML:"", Offset:checkpoint.EventLogState{Name:"WinlogbeatTestGo", RecordNumber:0x525e, Timestamp:time.Date(2022, time.March, 23, 1, 22, 13, 891772600, time.UTC), Bookmark:"<BookmarkList>\r\n  <Bookmark Channel='WinlogbeatTestGo' RecordId='21086' IsCurrent='true'/>\r\n</BookmarkList>"}}
FAIL

What appears to be happening is that the data pair (param0 in the non-experimental API) of EventData holds the message. It looks like the Message field of Event is never actually populated from evtx files since there is no RenderingInfo element in the unpacked XML from the evtx. Looking at the events in the Event Viewer on a Windows VM (2022), this element is also absent there.

Something else worth noting is the difference in handling of rendering errors; the new API populates the RenderErr error field while the old API does not, since it does not call through to the Windows API.