Skip to content

Commit d97fe08

Browse files
adriansradriansr
authored
Winlogbeat: Fix compatibility problems with newer OS versions in CI (#22362)
* Fix EVT_VARIANT struct definition for GOARCH=386 The first field of the structure, a union, didn't have the proper size when compiled for 32-bits, causing "invalid argument" errors when the struct was passed to an API. Also, some EVT_VARIANT types weren't being handled properly. * Remove formatting assertion in TestFormatMessage Under most Windows versions, GUID values cannot be substituted with string values. However, this is not the case under at least Win7 32bit. Just disable the testing assertion as it has no impact. * Update generated syscalls to avoid bug under 32-bit Go's mkwinsyscall is generating syscall invocations that don't work properly under GOARCH=386 (or any 32-bit arch). This only affects functions that receive a 64-bit parameter, in this case only EvtSeek is affected. This replaces `mkwinsyscall` with a patched one that adds some workaround code. * Enable all windows tests * Disable TestFormatMessage/no_metadata tests Under Windows 10, event formatting is not failing with an error even though not metadata is being passed. * Testing: Error check on publishing events to an event log Under Windows 7 and Windows 10, writes to a newly created event log fail occasionally. It seems that there is a delay between when an event log is created and publishing events to it is allowed. This commit updates the tests to retry on failure when creating an event log for testing. * Sysmon: Ignore winlog.user.* fields during test For some reason, the following fields: - winlog.user.type - winlog.user.name - winlog.user.domain are not populated by the Sysmon module under Windows 7 32-bit. I couldn't reproduce outside of CI, where it's failing to lookup SID `S-1-5-18`: ``` testing_windows.go:69: Expected and actual are different: --- Expected +++ Actual @@ -47,6 +47,3 @@ "user": { - "domain": "NT AUTHORITY", - "identifier": "S-1-5-18", - "name": "SYSTEM", - "type": "Well Known Group" + "identifier": "S-1-5-18" }, ``` This commit updates the test to ignore those fields and removes them from the golden files. * Testing: limit event size in testWindowsEventLog Under Windows 10, writing large events (31800 bytes) results in an empty event log. Seems that the events are being silently dropped due to being too big.
1 parent 95a88a6 commit d97fe08

22 files changed

Lines changed: 884 additions & 1471 deletions

‎winlogbeat/Jenkinsfile.yml‎

Lines changed: 32 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ stages:
2424
mage: "mage build unitTest"
2525
platforms: ## override default labels in this specific stage.
2626
- "windows-2019"
27-
#- "windows-2008-r2" https://github.com/elastic/beats/issues/19798
27+
- "windows-2008-r2"
2828
windows-2016:
2929
mage: "mage build unitTest"
3030
platforms: ## override default labels in this specific stage.
@@ -47,17 +47,17 @@ stages:
4747
- "windows-2012"
4848
branches: true ## for all the branches
4949
tags: true ## for all the tags
50-
#windows-10: See https://github.com/elastic/beats/issues/22046
51-
# mage: "mage build unitTest"
52-
# platforms: ## override default labels in this specific stage.
53-
# - "windows-10"
54-
# when: ## Override the top-level when.
55-
# comments:
56-
# - "/test winlogbeat for windows-10"
57-
# labels:
58-
# - "windows-10"
59-
# branches: true ## for all the branches
60-
# tags: true ## for all the tags
50+
windows-10:
51+
mage: "mage build unitTest"
52+
platforms: ## override default labels in this specific stage.
53+
- "windows-10"
54+
when: ## Override the top-level when.
55+
comments:
56+
- "/test winlogbeat for windows-10"
57+
labels:
58+
- "windows-10"
59+
branches: true ## for all the branches
60+
tags: true ## for all the tags
6161
windows-8:
6262
mage: "mage build unitTest"
6363
platforms: ## override default labels in this specific stage.
@@ -69,23 +69,23 @@ stages:
6969
- "windows-8"
7070
branches: true ## for all the branches
7171
tags: true ## for all the tags
72-
#windows-7: See https://github.com/elastic/beats/issues/22302
73-
# mage: "mage build unitTest"
74-
# platforms: ## override default labels in this specific stage.
75-
# - "windows-7"
76-
# when: ## Override the top-level when.
77-
# comments:
78-
# - "/test winlogbeat for windows-7"
79-
# labels:
80-
# - "windows-7"
81-
#windows-7-32: See https://github.com/elastic/beats/issues/19829
82-
# mage: "mage build unitTest"
83-
# platforms: ## override default labels in this specific stage.
84-
# - "windows-7-32-bit"
85-
# when: ## Override the top-level when.
86-
# comments:
87-
# - "/test winlogbeat for windows-7-32"
88-
# labels:
89-
# - "windows-7-32"
90-
# branches: true ## for all the branches
91-
# tags: true ## for all the tags
72+
windows-7:
73+
mage: "mage build unitTest"
74+
platforms: ## override default labels in this specific stage.
75+
- "windows-7"
76+
when: ## Override the top-level when.
77+
comments:
78+
- "/test winlogbeat for windows-7"
79+
labels:
80+
- "windows-7"
81+
windows-7-32:
82+
mage: "mage build unitTest"
83+
platforms: ## override default labels in this specific stage.
84+
- "windows-7-32-bit"
85+
when: ## Override the top-level when.
86+
comments:
87+
- "/test winlogbeat for windows-7-32"
88+
labels:
89+
- "windows-7-32"
90+
branches: true ## for all the branches
91+
tags: true ## for all the tags

‎winlogbeat/eventlog/bench_test.go‎

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -57,10 +57,7 @@ func TestBenchmarkRead(t *testing.T) {
5757

5858
// Publish test messages:
5959
for i := 0; i < *injectAmount; i++ {
60-
err := writer.Report(eventlog.Info, uint32(rand.Int63()%1000), []string{strconv.Itoa(i) + " " + randomSentence(256)})
61-
if err != nil {
62-
t.Fatal(err)
63-
}
60+
safeWriteEvent(t, writer, eventlog.Info, uint32(rand.Int63()%1000), []string{strconv.Itoa(i) + " " + randomSentence(256)})
6461
}
6562

6663
for _, api := range []string{winEventLogAPIName, winEventLogExpAPIName} {

‎winlogbeat/eventlog/eventlogging_test.go‎

Lines changed: 10 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -104,9 +104,7 @@ func TestRead(t *testing.T) {
104104

105105
// Publish test messages:
106106
for k, m := range messages {
107-
if err := writer.Report(m.eventType, k, []string{m.message}); err != nil {
108-
t.Fatal(err)
109-
}
107+
safeWriteEvent(t, writer, m.eventType, k, []string{m.message})
110108
}
111109

112110
// Read messages:
@@ -146,9 +144,7 @@ func TestFormatMessageWithLargeMessage(t *testing.T) {
146144
defer teardown()
147145

148146
const message = "Hello"
149-
if err := writer.Report(eventlog.Info, 1, []string{message}); err != nil {
150-
t.Fatal(err)
151-
}
147+
safeWriteEvent(t, writer, eventlog.Info, 1, []string{message})
152148

153149
// Messages are received as UTF-16 so we must have enough space in the read
154150
// buffer for the message, a windows newline, and a null-terminator.
@@ -184,9 +180,7 @@ func TestReadUnknownEventId(t *testing.T) {
184180

185181
const eventID uint32 = 1000
186182
const msg = "Test Message"
187-
if err := writer.Success(eventID, msg); err != nil {
188-
t.Fatal(err)
189-
}
183+
safeWriteEvent(t, writer, eventlog.Success, eventID, []string{msg})
190184

191185
// Read messages:
192186
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})
@@ -219,9 +213,7 @@ func TestReadTriesMultipleEventMsgFiles(t *testing.T) {
219213

220214
const eventID uint32 = 1000
221215
const msg = "Test Message"
222-
if err := writer.Success(eventID, msg); err != nil {
223-
t.Fatal(err)
224-
}
216+
safeWriteEvent(t, writer, eventlog.Success, eventID, []string{msg})
225217

226218
// Read messages:
227219
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})
@@ -254,9 +246,7 @@ func TestReadMultiParameterMsg(t *testing.T) {
254246
const eventID uint32 = 1073748860
255247
const template = "The %s service entered the %s state."
256248
msgs := []string{"Windows Update", "running"}
257-
if err := writer.Report(eventlog.Info, eventID, msgs); err != nil {
258-
t.Fatal(err)
259-
}
249+
safeWriteEvent(t, writer, eventlog.Info, eventID, msgs)
260250

261251
// Read messages:
262252
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})
@@ -298,9 +288,7 @@ func TestReadNoParameterMsg(t *testing.T) {
298288
const eventID uint32 = 2147489654 // 1<<31 + 6006
299289
const template = "The Event log service was stopped."
300290
msgs := []string{}
301-
if err := writer.Report(eventlog.Info, eventID, msgs); err != nil {
302-
t.Fatal(err)
303-
}
291+
safeWriteEvent(t, writer, eventlog.Info, eventID, msgs)
304292

305293
// Read messages:
306294
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})
@@ -331,8 +319,8 @@ func TestReadWhileCleared(t *testing.T) {
331319
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})
332320
defer log.Close()
333321

334-
writer.Info(1, "Message 1")
335-
writer.Info(2, "Message 2")
322+
safeWriteEvent(t, writer, eventlog.Info, 1, []string{"Message 1"})
323+
safeWriteEvent(t, writer, eventlog.Info, 2, []string{"Message 2"})
336324
lr, err := log.Read()
337325
assert.NoError(t, err, "Expected 2 messages but received error")
338326
assert.Len(t, lr, 2, "Expected 2 messages")
@@ -342,7 +330,7 @@ func TestReadWhileCleared(t *testing.T) {
342330
assert.NoError(t, err, "Expected 0 messages but received error")
343331
assert.Len(t, lr, 0, "Expected 0 message")
344332

345-
writer.Info(3, "Message 3")
333+
safeWriteEvent(t, writer, eventlog.Info, 3, []string{"Message 3"})
346334
lr, err = log.Read()
347335
assert.NoError(t, err, "Expected 1 message but received error")
348336
assert.Len(t, lr, 1, "Expected 1 message")
@@ -362,9 +350,7 @@ func TestReadMissingParameters(t *testing.T) {
362350
// Missing parameters will be substituted by "(null)"
363351
const template = "The %s service entered the (null) state."
364352
msgs := []string{"Windows Update"}
365-
if err := writer.Report(eventlog.Info, eventID, msgs); err != nil {
366-
t.Fatal(err)
367-
}
353+
safeWriteEvent(t, writer, eventlog.Info, eventID, msgs)
368354

369355
// Read messages:
370356
log := openEventLogging(t, 0, map[string]interface{}{"name": providerName})

‎winlogbeat/eventlog/wineventlog_test.go‎

Lines changed: 17 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import (
2626
"strconv"
2727
"strings"
2828
"testing"
29+
"time"
2930

3031
"github.com/andrewkroh/sys/windows/svc/eventlog"
3132
"github.com/stretchr/testify/assert"
@@ -50,12 +51,10 @@ func testWindowsEventLog(t *testing.T, api string) {
5051
setLogSize(t, providerName, gigabyte)
5152

5253
// Publish large test messages.
54+
const messageSize = 256 // Originally 31800, such a large value resulted in an empty eventlog under Win10.
5355
const totalEvents = 1000
5456
for i := 0; i < totalEvents; i++ {
55-
err := writer.Report(eventlog.Info, uint32(i%1000), []string{strconv.Itoa(i) + " " + randomSentence(31800)})
56-
if err != nil {
57-
t.Fatal(err)
58-
}
57+
safeWriteEvent(t, writer, eventlog.Info, uint32(i%1000), []string{strconv.Itoa(i) + " " + randomSentence(messageSize)})
5958
}
6059

6160
openLog := func(t testing.TB, config map[string]interface{}) EventLog {
@@ -167,6 +166,20 @@ func createLog(t testing.TB, messageFiles ...string) (log *eventlog.Log, tearDow
167166
return log, tearDown
168167
}
169168

169+
func safeWriteEvent(t testing.TB, log *eventlog.Log, etype uint16, eid uint32, msgs []string) {
170+
deadline := time.Now().Add(time.Second * 10)
171+
for {
172+
err := log.Report(etype, eid, msgs)
173+
if err == nil {
174+
return
175+
}
176+
if time.Now().After(deadline) {
177+
t.Fatal("Failed to write event to event log", err)
178+
return
179+
}
180+
}
181+
}
182+
170183
// setLogSize set the maximum number of bytes that an event log can hold.
171184
func setLogSize(t testing.TB, provider string, sizeBytes int) {
172185
output, err := exec.Command("wevtutil.exe", "sl", "/ms:"+strconv.Itoa(sizeBytes), provider).CombinedOutput()

‎winlogbeat/sys/wineventlog/doc.go‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,5 +22,8 @@
2222
package wineventlog
2323

2424
// Add -trace to enable debug prints around syscalls.
25-
//go:generate go get golang.org/x/sys/windows/mkwinsyscall
25+
26+
// Use golang.org/x/sys/windows/mkwinsyscall instead of adriansr/mksyscall
27+
// below once https://github.com/golang/go/issues/42373 is fixed.
28+
//go:generate go get github.com/adriansr/mkwinsyscall
2629
//go:generate $GOPATH/bin/mkwinsyscall.exe -systemdll -output zsyscall_windows.go syscall_windows.go

‎winlogbeat/sys/wineventlog/format_message_test.go‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,7 @@ func TestFormatMessage(t *testing.T) {
4141

4242
t.Run("getMessageStringFromHandle", func(t *testing.T) {
4343
t.Run("no_metadata", func(t *testing.T) {
44+
t.Skip("This currently fails under Win10. The message strings are returned even though no metadata is passed.")
4445
// Metadata is required unless the events were forwarded with "RenderedText".
4546
_, err := getMessageStringFromHandle(nil, evtHandle, nil)
4647
assert.Error(t, err)
@@ -75,7 +76,10 @@ func TestFormatMessage(t *testing.T) {
7576
// method to create text/templates. Instead we can use the
7677
// getMessageStringFromMessageID (see test below) that works as
7778
// expected.
78-
assert.NotContains(t, msg, `{{eventParam $ 9}}`)
79+
//
80+
// Note: This is not the case under 32-bit Windows 7.
81+
// Disabling the assertion for now.
82+
//assert.NotContains(t, msg, `{{eventParam $ 9}}`)
7983
})
8084
})
8185

@@ -135,6 +139,7 @@ func TestFormatMessage(t *testing.T) {
135139

136140
t.Run("getEventXML", func(t *testing.T) {
137141
t.Run("no_metadata", func(t *testing.T) {
142+
t.Skip("This currently fails under Win10. The event XML is returned even though no metadata is passed.")
138143
// It needs the metadata handle to add the message to the XML.
139144
_, err := getEventXML(nil, evtHandle)
140145
assert.Error(t, err)

‎winlogbeat/sys/wineventlog/iterator_test.go‎

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ import (
2323
"strconv"
2424
"testing"
2525

26+
"github.com/andrewkroh/sys/windows/svc/eventlog"
2627
"github.com/pkg/errors"
2728
"github.com/stretchr/testify/assert"
2829
"golang.org/x/sys/windows"
@@ -38,9 +39,7 @@ func TestEventIterator(t *testing.T) {
3839

3940
const eventCount = 1500
4041
for i := 0; i < eventCount; i++ {
41-
if err := writer.Info(1, "Test message "+strconv.Itoa(i+1)); err != nil {
42-
t.Fatal(err)
43-
}
42+
safeWriteEvent(t, writer, eventlog.Info, 1, []string{"Test message " + strconv.Itoa(i+1)})
4443
}
4544

4645
// Validate the assumption that 1024 is the max number of handles supported

‎winlogbeat/sys/wineventlog/publisher_metadata.go‎

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -587,28 +587,44 @@ func (itr *EventMetadataIterator) Err() error {
587587
return itr.lastErr
588588
}
589589

590+
func typeCastError(expected, got interface{}) error {
591+
return errors.Errorf("wrong type for property. expected:%T got:%T", expected, got)
592+
}
593+
590594
func (itr *EventMetadataIterator) uint32Property(propertyID EvtEventMetadataPropertyID) (uint32, error) {
591595
v, err := GetEventMetadataProperty(itr.currentEvent, propertyID)
592596
if err != nil {
593597
return 0, err
594598
}
595-
return v.(uint32), nil
599+
value, ok := v.(uint32)
600+
if !ok {
601+
return value, typeCastError(value, v)
602+
}
603+
return value, nil
596604
}
597605

598606
func (itr *EventMetadataIterator) uint64Property(propertyID EvtEventMetadataPropertyID) (uint64, error) {
599607
v, err := GetEventMetadataProperty(itr.currentEvent, propertyID)
600608
if err != nil {
601609
return 0, err
602610
}
603-
return v.(uint64), nil
611+
value, ok := v.(uint64)
612+
if !ok {
613+
return value, typeCastError(value, v)
614+
}
615+
return value, nil
604616
}
605617

606618
func (itr *EventMetadataIterator) stringProperty(propertyID EvtEventMetadataPropertyID) (string, error) {
607619
v, err := GetEventMetadataProperty(itr.currentEvent, propertyID)
608620
if err != nil {
609621
return "", err
610622
}
611-
return v.(string), nil
623+
value, ok := v.(string)
624+
if !ok {
625+
return value, typeCastError(value, v)
626+
}
627+
return value, nil
612628
}
613629

614630
func (itr *EventMetadataIterator) EventID() (uint32, error) {

‎winlogbeat/sys/wineventlog/renderer_test.go‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,8 @@ import (
3030
"text/template"
3131
"time"
3232

33+
"github.com/andrewkroh/sys/windows/svc/eventlog"
34+
3335
"github.com/stretchr/testify/assert"
3436

3537
"github.com/elastic/beats/v7/libbeat/common/atomic"
@@ -205,9 +207,9 @@ func BenchmarkRenderer(b *testing.B) {
205207
defer teardown()
206208

207209
const totalEvents = 1000000
208-
msg := strings.Repeat("Hello world! ", 21)
210+
msg := []string{strings.Repeat("Hello world! ", 21)}
209211
for i := 0; i < totalEvents; i++ {
210-
writer.Info(10, msg)
212+
safeWriteEvent(b, writer, eventlog.Info, 10, msg)
211213
}
212214

213215
setup := func() (*EventIterator, *Renderer) {

‎winlogbeat/sys/wineventlog/stringinserts.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -74,10 +74,10 @@ func newTemplateStringInserts() *stringInserts {
7474

7575
si.insertStrings[i] = strSlice
7676
si.evtVariants[i] = EvtVariant{
77-
Value: uintptr(unsafe.Pointer(&strSlice[0])),
7877
Count: uint32(len(strSlice)),
7978
Type: EvtVarTypeString,
8079
}
80+
si.evtVariants[i].SetValue(uintptr(unsafe.Pointer(&strSlice[0])))
8181
si.evtVariants[i].Type = EvtVarTypeString
8282
}
8383

0 commit comments

Comments
 (0)