Winlogbeat: Use bookmarks to persist last published event #6150

adriansr · 2018-01-23T16:20:24Z

When using the Windows Event Log API, a bookmark is used to persist the
last position read in the stream. This is a first step to support XML
queries potentially involving multiple channels (#1054). Also fixes a problem
when using Forwarded Events (#3731).

houndci-bot · 2018-01-23T16:20:34Z

winlogbeat/sys/wineventlog/wineventlog_windows.go

+
+// CreateBookmarkFromEvent creates a new handle to a bookmark. Close must be called on
+// returned EvtHandle when finished with the handle.
+func CreateBookmarkFromXml(bookmarkXml string) (EvtHandle, error) {


func CreateBookmarkFromXml should be CreateBookmarkFromXML
func parameter bookmarkXml should be bookmarkXML

houndci-bot · 2018-01-23T16:20:34Z

winlogbeat/sys/wineventlog/wineventlog_windows.go

+	return h, nil
+}
+
+// CreateBookmarkFromEvent creates a new handle to a bookmark. Close must be called on


comment on exported function CreateBookmarkFromXml should be of the form "CreateBookmarkFromXml ..."

houndci-bot · 2018-01-23T16:28:07Z

winlogbeat/sys/wineventlog/wineventlog_windows.go

+// CreateBookmarkFromXml creates a new bookmark from the serialised representation
+// of an existing bookmark. Close must be called on returned EvtHandle when
+// finished with the handle.
+func CreateBookmarkFromXml(bookmarkXml string) (EvtHandle, error) {


func CreateBookmarkFromXml should be CreateBookmarkFromXML
func parameter bookmarkXml should be bookmarkXML

houndci-bot · 2018-01-23T16:28:07Z

winlogbeat/sys/wineventlog/wineventlog_windows.go

+// CreateBookmarkFromXml creates a new bookmark from the serialised representation
+// of an existing bookmark. Close must be called on returned EvtHandle when
+// finished with the handle.
+func CreateBookmarkFromXml(bookmarkXml string) (EvtHandle, error) {


func CreateBookmarkFromXml should be CreateBookmarkFromXML
func parameter bookmarkXml should be bookmarkXML

adriansr · 2018-01-24T15:39:10Z

Jenkins, test it and not fail this time please

andrewkroh

This looks good. There are some registry tests that should be updated too.

beats/winlogbeat/tests/system/test_wineventlog.py

Line 311 in e53f42d

def test_registry_data(self):
beats/winlogbeat/tests/system/test_eventlogging.py

Line 173 in e53f42d

def test_registry_data(self):

andrewkroh · 2018-01-24T18:51:03Z

winlogbeat/eventlog/eventlog.go

@@ -41,7 +41,7 @@ type EventLog interface {
 	// Open the event log. recordNumber is the last successfully read event log


The godocs should be updated.

andrewkroh · 2018-01-24T18:53:25Z

winlogbeat/eventlog/eventlogging.go

@@ -9,6 +9,8 @@ import (

 	"github.com/joeshaw/multierror"

+	"github.com/elastic/beats/winlogbeat/checkpoint"


This could be added to the group below.

andrewkroh · 2018-01-24T19:04:45Z

winlogbeat/eventlog/wineventlog.go

+	var bookmark win.EvtHandle
+	var err error
+	if len(state.Bookmark) > 0 {
+		bookmark, err = win.CreateBookmarkFromXML(state.Bookmark)


This is missing an error check. Looks like you intended to move the error check below outside the if/else.

andrewkroh · 2018-01-24T19:13:51Z

winlogbeat/eventlog/wineventlog.go

+			RecordNumber: r.RecordID,
+			Timestamp:    r.TimeCreated.SystemTime,
+		}
+		if r.Offset.Bookmark, err = l.createBookmarkFromEvent(h); err != nil {


Any idea as to the impact of calling this for every event? Could you run these benchmarks and share the before and after results.

I did run some tests at first and method was taking less than 1ms to complete. However, I also found out that every event was persisted so it was necessary to always create a bookmark anyway. Maybe there was something wrong in my configuration, a side-effect of running with -N.

The benchmark results:

Before:

=== RUN TestBenchmarkBatchReadSize --- PASS: TestBenchmarkBatchReadSize (74.86s) bench_test.go:80: batch_size=10, total_events=50000, batch_time=3.543758ms, events_per_sec=2821.863118192608, bytes_alloced_per_event=14 kB, total_allocs=12330717 bench_test.go:80: batch_size=100, total_events=50000, batch_time=33.800801ms, events_per_sec=2958.509770227043, bytes_alloced_per_event=14 kB, total_allocs=12260220 bench_test.go:80: batch_size=500, total_events=50000, batch_time=169.47269ms, events_per_sec=2950.32786698553, bytes_alloced_per_event=14 kB, total_allocs=12252311 bench_test.go:80: batch_size=1000, total_events=50000, batch_time=333.476478ms, events_per_sec=2998.7122510032027, bytes_alloced_per_event=14 kB, total_allocs=12251057 PASS ok github.com/elastic/beats/winlogbeat/eventlog 74.900s

After:

=== RUN TestBenchmarkBatchReadSize --- PASS: TestBenchmarkBatchReadSize (77.18s) bench_test.go:80: batch_size=10, total_events=50000, batch_time=3.655664ms, events_per_sec=2735.4811601941537, bytes_alloced_per_event=14 kB, total_allocs=12430766 bench_test.go:80: batch_size=100, total_events=50000, batch_time=34.74005ms, events_per_sec=2878.522051637807, bytes_alloced_per_event=14 kB, total_allocs=12360267 bench_test.go:80: batch_size=500, total_events=50000, batch_time=173.232487ms, events_per_sec=2886.294647492996, bytes_alloced_per_event=14 kB, total_allocs=12352376 bench_test.go:80: batch_size=1000, total_events=50000, batch_time=343.0666ms, events_per_sec=2914.885914280201, bytes_alloced_per_event=14 kB, total_allocs=12351096 PASS ok github.com/elastic/beats/winlogbeat/eventlog 77.221s

andrewkroh · 2018-01-24T19:28:16Z

winlogbeat/sys/wineventlog/wineventlog_windows.go

@@ -197,9 +197,9 @@ func RenderEvent(
 // include the RenderingInfo (message). If the event is not rendered then the
 // XML will not include the message, and in this case RenderEvent should be
 // used.
-func RenderEventXML(eventHandle EvtHandle, renderBuf []byte, out io.Writer) error {
+func RenderEventXML(eventHandle EvtHandle, flag EvtRenderFlag, renderBuf []byte, out io.Writer) error {


This function name is no longer fully reflective of the usage because it can render both events and bookmarks based on the flag. I suggest renaming it to be more general such as RenderXML or create RenderEventXML and RenderBookmarkXML and have them call this function (with it being renamed to something like renderXML).

andrewkroh · 2018-01-24T19:29:01Z

winlogbeat/eventlog/wineventlog.go

@@ -12,6 +12,8 @@ import (
 	"github.com/pkg/errors"
 	"golang.org/x/sys/windows"

+	"github.com/elastic/beats/winlogbeat/checkpoint"


Group this import with the other elastic imports.

andrewkroh · 2018-01-24T19:36:52Z

winlogbeat/checkpoint/checkpoint.go

@@ -45,6 +45,7 @@ type EventLogState struct {
 	Name         string    `yaml:"name"`
 	RecordNumber uint64    `yaml:"record_number"`
 	Timestamp    time.Time `yaml:"timestamp"`
+	Bookmark     string    `yaml:"bookmark"`


Since this is optional for the eventlog API add ,omitempty to the yaml tag.

update_time: 2018-01-24T16:05:31.2972263Z event_logs: - name: WinlogbeatTestPython record_number: 37134 timestamp: 2018-01-24T16:05:30Z bookmark: ""

source

andrewkroh · 2018-01-24T19:47:59Z

There doesn't appear to be any existing test that verifies Winlogbeat resumes from the position specified in the registry. I think this would be a good test to add. Something like

write an event to the log
run WLB
stop WLB after the event is read
write more events to the log
run WLB
assert that the first event has the correct record number

When using the Windows Event Log API, a bookmark is used to persist the last position read in the stream. This is a first step to support XML queries (potentially involving multiple channels). Also fixes a problem when using Forwarded Events.

The hostname reported by beats is fully-qualified wheter platform.node() might only include the host name.

andrewkroh

LGTM. Can you please add a CHANGLOG entry.

adriansr requested a review from andrewkroh January 23, 2018 16:20

houndci-bot reviewed Jan 23, 2018

View reviewed changes

adriansr added the Winlogbeat label Jan 23, 2018

adriansr force-pushed the wb/feature/bookmarks branch from 61c2408 to 14f23fe Compare January 23, 2018 16:28

houndci-bot reviewed Jan 23, 2018

View reviewed changes

adriansr force-pushed the wb/feature/bookmarks branch from 14f23fe to 0f3eed9 Compare January 23, 2018 16:29

adriansr added enhancement in progress Pull request is currently in progress. review labels Jan 23, 2018

adriansr force-pushed the wb/feature/bookmarks branch from 0f3eed9 to 54a63d4 Compare January 23, 2018 16:39

adriansr removed the in progress Pull request is currently in progress. label Jan 24, 2018

andrewkroh reviewed Jan 24, 2018

View reviewed changes

adriansr added 6 commits January 25, 2018 08:21

Omit the bookmark field when empty

205d2ed

Update godoc for EventLog interface

5d2c5ad

Reorder imports

ae98c9b

Fix error check

779930b

Refactor RenderEventXML

3658953

adriansr force-pushed the wb/feature/bookmarks branch from 54a63d4 to 3658953 Compare January 25, 2018 14:45

adriansr added 2 commits January 27, 2018 10:38

Winlogbeat: Fix tests on computers belonging to a domain

d1ca13c

The hostname reported by beats is fully-qualified wheter platform.node() might only include the host name.

System test to validate resuming from registry

80b86af

adriansr force-pushed the wb/feature/bookmarks branch from 0880765 to 80b86af Compare January 27, 2018 13:04

andrewkroh approved these changes Jan 30, 2018

View reviewed changes

Update CHANGELOG

ca6d69c

andrewkroh merged commit e3f055f into elastic:master Jan 30, 2018

andrewkroh mentioned this pull request Jan 30, 2018

Winlogbeat misses some events with Forwarded Events #3731

Closed

andrewkroh mentioned this pull request Mar 16, 2018

[Winlogbeat] Compare performance of event rendering without using XML #6585

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Winlogbeat: Use bookmarks to persist last published event #6150

Winlogbeat: Use bookmarks to persist last published event #6150

adriansr commented Jan 23, 2018

houndci-bot Jan 23, 2018

houndci-bot Jan 23, 2018

houndci-bot Jan 23, 2018

houndci-bot Jan 23, 2018

adriansr commented Jan 24, 2018

andrewkroh left a comment

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018 •

edited

Loading

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh Jan 24, 2018

adriansr Jan 25, 2018

andrewkroh commented Jan 24, 2018

andrewkroh left a comment

		@@ -41,7 +41,7 @@ type EventLog interface {
		// Open the event log. recordNumber is the last successfully read event log

		@@ -9,6 +9,8 @@ import (

		"github.com/joeshaw/multierror"

		"github.com/elastic/beats/winlogbeat/checkpoint"

Winlogbeat: Use bookmarks to persist last published event #6150

Winlogbeat: Use bookmarks to persist last published event #6150

Conversation

adriansr commented Jan 23, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

adriansr commented Jan 24, 2018

andrewkroh left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

adriansr Jan 25, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andrewkroh commented Jan 24, 2018

andrewkroh left a comment

Choose a reason for hiding this comment

adriansr Jan 25, 2018 •

edited

Loading