[Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11006

adriansr · 2019-03-01T03:10:40Z

Golang's xml parser is refusing to process XML documents that contain an ASCII control character, resulting in those events being dropped. This patch pre-processes the XML document in order to replace invalid characters with the unicode escape sequence \uNNNN.

Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN".

This updates the wineventlog logic to ingest windows event logs whose rendering fails.

winlogbeat/sys/xmlreader.go

+	return output(n)
+}
+
+func newXmlSafeReader(rawXML []byte) io.Reader {


andrewkroh · 2019-03-01T04:25:31Z

As a side-effect, at batch_size=100 it's 47.2% faster! 🥇

(update: Something else must have been using CPU during the first run b/c I couldn't replicate the results from the first run. Both master and this branch performed about the same.)

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -v -benchtime 10s -benchtest -benchmem -run TestB
enchmarkBatchReadSize  .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (96.50s)
    bench_test.go:98: batch_size=10, total_events=30000, batch_time=4.452175ms, events_per_sec=2246.0932016374018, bytes_alloced_per_event=21 kB, total_allocs=7344626
    bench_test.go:98: batch_size=100, total_events=30000, batch_time=43.886812ms, events_per_sec=2278.5888389432344, bytes_alloced_per_event=19 kB, total_allocs=6592877
    bench_test.go:98: batch_size=500, total_events=25000, batch_time=230.723254ms, events_per_sec=2167.098423464503, bytes_alloced_per_event=14 kB, total_allocs=2437639
    bench_test.go:98: batch_size=1000, total_events=30000, batch_time=444.63076ms, events_per_sec=2249.0571727426145, bytes_alloced_per_event=6.9 kB, total_allocs=235204
PASS
ok      github.com/elastic/beats/winlogbeat/eventlog    96.544s
PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -v -benchtime 10s -benchtest -benchmem -run TestB
enchmarkBatchReadSize  .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (65.73s)
    bench_test.go:98: batch_size=10, total_events=50000, batch_time=3.090045ms, events_per_sec=3236.1988255834463, bytes_alloced_per_event=18 kB, total_allocs=12380608
    bench_test.go:98: batch_size=100, total_events=50000, batch_time=29.812684ms, events_per_sec=3354.276991632152, bytes_alloced_per_event=18 kB, total_allocs=12310026
    bench_test.go:98: batch_size=500, total_events=50000, batch_time=148.310654ms, events_per_sec=3371.301969985245, bytes_alloced_per_event=18 kB, total_allocs=12301886
    bench_test.go:98: batch_size=1000, total_events=50000, batch_time=297.246802ms, events_per_sec=3364.2077669854966, bytes_alloced_per_event=18 kB, total_allocs=12300631
PASS
ok      github.com/elastic/beats/winlogbeat/eventlog    65.767s

adriansr · 2019-03-01T15:02:28Z

@andrewkroh please have another look to see if you like the changes I did to RenderErr. Now error.message can be a list of strings.

Kill me if I know where that speedup comes from. Buffering? In my tests, decoding the XML was marginally slower than before (from 105 to 125 us per op)

adriansr · 2019-03-01T15:16:22Z

jenkins, test this

andrewkroh

Can you add a test case passes that causes some invalid XML.

Otherwise it LGTM.

…elastic#11006) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…#11006) (#11039) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…#11006) (#11040) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…#11006) (#11041) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…#11006) (#11038) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…elastic#11006) * [Winlogbeat] Escape control characters in XML Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…#11006) (#11066) * [Winlogbeat] Escape control characters in XML Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328

Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328

Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328 (cherry picked from commit 6865403)

Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328 (cherry picked from commit 6865403)

Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328 (cherry picked from commit 6865403)

Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328 (cherry picked from commit 6865403)

…1372) Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328 (cherry picked from commit 6865403)

…1370) Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328 (cherry picked from commit 6865403)

…elastic#11006) (elastic#11039) Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit 6a078f5)

…ces (elastic#11370) Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328 (cherry picked from commit 5db0f15)

…elastic#11006) (elastic#11066) * [Winlogbeat] Escape control characters in XML Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN". (cherry picked from commit a6102a8)

…ces (elastic#11372) Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328 (cherry picked from commit 6865403)

adriansr added 2 commits March 1, 2019 03:40

[Winlogbeat] Escape control characters in XML

13f1b2e

Golang's xml parser is pretty strict about the presence of control characters in the XML it is fed. This patch replaces those characters with an unicode escape sequence: "\uNNNN".

[Winlogbeat] Do not drop events after XML rendering error

84ad874

This updates the wineventlog logic to ingest windows event logs whose rendering fails.

adriansr requested a review from a team as a code owner March 1, 2019 03:10

houndci-bot reviewed Mar 1, 2019

View reviewed changes

winlogbeat/sys/xmlreader.go Outdated

return output(n)

}

func newXmlSafeReader(rawXML []byte) io.Reader {

This comment was marked as resolved.

Sign in to view

Update CHANGELOG

0d72734

adriansr changed the title ~~[WIP]~~ [Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML Mar 1, 2019

adriansr added bug Winlogbeat needs_backport PR is waiting to be backported to other branches. review labels Mar 1, 2019

adriansr added 2 commits March 1, 2019 13:03

Save error message when XML decoding fails

bdc4431

Fix unit test

0c067ff

andrewkroh reviewed Mar 1, 2019

View reviewed changes

Test for invalid characters in XML

4c2db85

adriansr merged commit a6102a8 into elastic:master Mar 1, 2019

adriansr mentioned this pull request Mar 1, 2019

Cherry-pick #11006 to 6.7: [Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11038

Merged

adriansr added v6.7.0 and removed needs_backport PR is waiting to be backported to other branches. labels Mar 1, 2019

adriansr mentioned this pull request Mar 1, 2019

Cherry-pick #11006 to 6.6: [Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11039

Merged

adriansr added the v6.6.2 label Mar 1, 2019

adriansr mentioned this pull request Mar 1, 2019

Cherry-pick #11006 to 7.x: [Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11041

Merged

adriansr added the v7.2.0 label Mar 1, 2019

andrewkroh mentioned this pull request Mar 4, 2019

Cherry-pick #11006 to 5.6: [Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11066

Merged

adriansr added a commit to adriansr/beats that referenced this pull request Mar 21, 2019

Fix Winlogbeat escaping CRLF sequences

aeea9c4

Previous fix (elastic#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes elastic#11328

adriansr mentioned this pull request Mar 21, 2019

Fix Winlogbeat escaping CRLF sequences #11357

Merged

adriansr added a commit that referenced this pull request Mar 21, 2019

Fix Winlogbeat escaping CRLF and TAB characters (#11357)

6865403

Previous fix (#11006) made Winlogbeat escape CRLF control characters which are expected in Windows event logs. Fixes #11328

adriansr mentioned this pull request Mar 21, 2019

Cherry-pick #11357 to 6.7: Fix Winlogbeat escaping CRLF sequences #11369

Merged

adriansr mentioned this pull request Mar 21, 2019

Cherry-pick #11357 to 6.6: Fix Winlogbeat escaping CRLF sequences #11370

Merged

adriansr mentioned this pull request Mar 21, 2019

Cherry-pick #11357 to 5.6: Fix Winlogbeat escaping CRLF sequences #11371

Closed

adriansr mentioned this pull request Mar 21, 2019

Cherry-pick #11357 to 5.6: Fix Winlogbeat escaping CRLF sequences #11372

Merged

adriansr mentioned this pull request Mar 21, 2019

Cherry-pick #11357 to 7.0: Fix Winlogbeat escaping CRLF sequences #11373

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11006

[Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11006

adriansr commented Mar 1, 2019 •

edited

Loading

This comment was marked as resolved.

andrewkroh commented Mar 1, 2019 •

edited

Loading

adriansr commented Mar 1, 2019 •

edited

Loading

adriansr commented Mar 1, 2019

andrewkroh left a comment

[Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11006

[Winlogbeat] Prevent Winlogbeat from dropping events with invalid XML #11006

Conversation

adriansr commented Mar 1, 2019 • edited Loading

This comment was marked as resolved.

andrewkroh commented Mar 1, 2019 • edited Loading

adriansr commented Mar 1, 2019 • edited Loading

adriansr commented Mar 1, 2019

andrewkroh left a comment

Choose a reason for hiding this comment

adriansr commented Mar 1, 2019 •

edited

Loading

andrewkroh commented Mar 1, 2019 •

edited

Loading

adriansr commented Mar 1, 2019 •

edited

Loading