Add winlog.api to the documentation + fixes

This explain how and why to enable the experimental implementation.

Bug fixes

Wrap errors to add more details to the cause

Account for sysmon not being installed in tests

Increase event log size everywhere

Use a unique test event log per package

TIL Go will run tests for different packages in parallel.

winlogbeat/docs/winlogbeat-options.asciidoc

@@ -410,3 +410,29 @@ stopped. *{vista_and_newer}*
 Setting `no_more_events` to `stop` is useful when reading from archived event
 log files where you want to read the whole file then exit. There's a complete
 example of how to read from an `.evtx` file in the <<reading-from-evtx,FAQ>>.
+
+[float]
+==== `event_logs.api`
+
+experimental[]
+
+This selects the event log reader implementation that is used to read events
+from the Windows APIs. You should only set this option when testing experimental
+features. When the value is set to `wineventlog-experimental` Winlogbeat will
+replace the default event log reader with the experimental implementation.
+We are evaluating this implementation to see if it can provide increased
+performance and reduce CPU usage. *{vista_and_newer}*
+
+[source,yaml]
+--------------------------------------------------------------------------------
+winlogbeat.event_logs:
+  - name: ForwardedEvents
+    api: wineventlog-experimental
+--------------------------------------------------------------------------------
+
+There are a few notable differences in the events:
+
+* Events that contained data under `winlog.user_data` will now have it under
+  `winlog.event_data`.
+* Setting `include_xml: true` has no effect.
+

winlogbeat/eventlog/wineventlog_expirimental.go

@@ -69,7 +69,8 @@ func (l *winEventLogExp) Open(state checkpoint.EventLogState) error {
 		win.WithSubscriptionFactory(func() (handle win.EvtHandle, err error) {
 			return l.open(l.lastRead)
 		}),
-		win.WithBatchSize(l.maxRead))
+		win.WithBatchSize(l.maxRead),
+		win.WithLogger(l.log))
 
 	return err
 }

winlogbeat/sys/wineventlog/iterator_test.go

@@ -26,9 +26,13 @@ import (
 	"github.com/pkg/errors"
 	"github.com/stretchr/testify/assert"
 	"golang.org/x/sys/windows"
+
+	"github.com/elastic/beats/v7/libbeat/logp"
 )
 
 func TestEventIterator(t *testing.T) {
+	logp.TestingSetup()
+
 	writer, tearDown := createLog(t)
 	defer tearDown()
 
@@ -224,7 +228,7 @@ func TestEventIterator(t *testing.T) {
 				return log, err
 			}
 
-			itr, err := NewEventIterator(WithSubscriptionFactory(factory), WithBatchSize(7))
+			itr, err := NewEventIterator(WithSubscriptionFactory(factory), WithBatchSize(10))
 			if err != nil {
 				t.Fatal(err)
 			}

winlogbeat/sys/wineventlog/metadata_store.go

@@ -232,7 +232,6 @@ func (s *publisherMetadataStore) getEventMetadata(eventID uint16, eventDataFinge
 	if err != nil {
 		s.log.Debugw("Failed to make event metadata from event handle. Will "+
 			"use default event metadata from the publisher.",
-			"provider", s.Metadata.Name,
 			"event_id", eventID,
 			"fingerprint", eventDataFingerprint,
 			"error", err)
@@ -259,7 +258,6 @@ func (s *publisherMetadataStore) getEventMetadata(eventID uint16, eventDataFinge
 
 	s.log.Debugw("Obtained unique event metadata from event handle. "+
 		"It differed from what was listed in the publisher's metadata.",
-		"provider", s.Metadata.Name,
 		"event_id", eventID,
 		"fingerprint", eventDataFingerprint,
 		"default_event_metadata", defaultEM,

winlogbeat/sys/wineventlog/renderer.go

@@ -121,12 +121,11 @@ func (r *Renderer) Render(handle EvtHandle) (*sys.Event, error) {
 	// Load cached event metadata or try to bootstrap it from the event's XML.
 	eventMeta := md.getEventMetadata(uint16(event.EventIdentifier.ID), fingerprint, handle)
 
-	if err = r.addEventData(eventMeta, eventData, event); err != nil {
-		errs = append(errs, err)
-	}
+	// Associate key names with the event data values.
+	r.addEventData(eventMeta, eventData, event)
 
 	if event.Message, err = r.formatMessage(md, eventMeta, handle, eventData, uint16(event.EventIdentifier.ID)); err != nil {
-		errs = append(errs, err)
+		errs = append(errs, errors.Wrap(err, "failed to get the event message string"))
 	}
 
 	if len(errs) > 0 {
@@ -164,6 +163,8 @@ func (r *Renderer) getPublisherMetadata(publisher string) (*publisherMetadataSto
 			// Return an empty store on error (can happen in cases where the
 			// log was forwarded and the provider doesn't exist on collector).
 			md = newEmptyPublisherMetadataStore(publisher, r.log)
+			err = errors.Wrapf(err, "failed to load publisher metadata for %v "+
+				"(returning an empty metadata store)", publisher)
 		}
 		r.metadataCache[publisher] = md
 	} else {
@@ -305,9 +306,9 @@ func (r *Renderer) render(context EvtHandle, eventHandle EvtHandle) (*byteBuffer
 }
 
 // addEventData adds the event/user data values to the event.
-func (r *Renderer) addEventData(evtMeta *eventMetadata, values []interface{}, event *sys.Event) error {
+func (r *Renderer) addEventData(evtMeta *eventMetadata, values []interface{}, event *sys.Event) {
 	if len(values) == 0 {
-		return nil
+		return
 	}
 
 	if evtMeta == nil {
@@ -355,7 +356,7 @@ func (r *Renderer) addEventData(evtMeta *eventMetadata, values []interface{}, ev
 		})
 	}
 
-	return nil
+	return
 }
 
 // formatMessage adds the message to the event.

winlogbeat/sys/wineventlog/renderer_test.go

@@ -50,7 +50,7 @@ func TestRenderer(t *testing.T) {
 		}
 		defer r.Close()
 
-		events := renderAllEvents(t, log, r)
+		events := renderAllEvents(t, log, r, true)
 		assert.NotEmpty(t, events)
 
 		if t.Failed() {
@@ -68,7 +68,7 @@ func TestRenderer(t *testing.T) {
 		}
 		defer r.Close()
 
-		events := renderAllEvents(t, log, r)
+		events := renderAllEvents(t, log, r, false)
 		if !assert.Len(t, events, 1) {
 			return
 		}
@@ -113,7 +113,7 @@ func TestRenderer(t *testing.T) {
 		}
 		defer r.Close()
 
-		events := renderAllEvents(t, log, r)
+		events := renderAllEvents(t, log, r, false)
 		if !assert.Len(t, events, 1) {
 			return
 		}
@@ -164,7 +164,7 @@ func TestTemplateFunc(t *testing.T) {
 }
 
 // renderAllEvents reads all events and renders them.
-func renderAllEvents(t *testing.T, log EvtHandle, renderer *Renderer) []*sys.Event {
+func renderAllEvents(t *testing.T, log EvtHandle, renderer *Renderer, ignoreMissingMetadataError bool) []*sys.Event {
 	t.Helper()
 
 	var events []*sys.Event
@@ -179,7 +179,10 @@ func renderAllEvents(t *testing.T, log EvtHandle, renderer *Renderer) []*sys.Eve
 
 			evt, err := renderer.Render(h)
 			if err != nil {
-				t.Fatalf("Render failed: %+v", err)
+				md := renderer.metadataCache[evt.Provider.Name]
+				if !ignoreMissingMetadataError || md.Metadata != nil {
+					t.Fatalf("Render failed: %+v", err)
+				}
 			}
 
 			events = append(events, evt)
@@ -201,8 +204,6 @@ func BenchmarkRenderer(b *testing.B) {
 	writer, teardown := createLog(b)
 	defer teardown()
 
-	setLogSize(b, winlogbeatTestLogName, 1024*1024*1024) // 1 GiB
-
 	const totalEvents = 1000000
 	msg := strings.Repeat("Hello world! ", 21)
 	for i := 0; i < totalEvents; i++ {

winlogbeat/sys/wineventlog/util_test.go

@@ -32,7 +32,7 @@ import (
 )
 
 const (
-	winlogbeatTestLogName = "WinlogbeatTestGo"
+	winlogbeatTestLogName = "WinEventLogTestGo"
 
 	security4752File      = "../../../x-pack/winlogbeat/module/security/test/testdata/4752.evtx"
 	sysmon9File           = "../../../x-pack/winlogbeat/module/sysmon/test/testdata/sysmon-9.01.evtx"
@@ -43,7 +43,7 @@ const (
 // to the log.
 func createLog(t testing.TB) (log *eventlog.Log, tearDown func()) {
 	const name = winlogbeatTestLogName
-	const source = "wineventlog_pkg"
+	const source = "wineventlog_test"
 
 	existed, err := eventlog.InstallAsEventCreate(name, source, eventlog.Error|eventlog.Warning|eventlog.Info)
 	if err != nil {
@@ -61,6 +61,8 @@ func createLog(t testing.TB) (log *eventlog.Log, tearDown func()) {
 		t.Fatal(err)
 	}
 
+	setLogSize(t, winlogbeatTestLogName, 1024*1024*1024) // 1 GiB
+
 	tearDown = func() {
 		log.Close()
 		EvtClearLog(NilHandle, name, "")