From 13f1b2e11fdb1d23fa5f992976d45e54ac096d41 Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 03:33:51 +0100 Subject: [PATCH 1/6] [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". --- winlogbeat/sys/event.go | 3 +- winlogbeat/sys/xmlreader.go | 78 +++++++++++++++++++++++++++++++++++++ 2 files changed, 80 insertions(+), 1 deletion(-) create mode 100644 winlogbeat/sys/xmlreader.go diff --git a/winlogbeat/sys/event.go b/winlogbeat/sys/event.go index f113ba87f582..50843fd09332 100644 --- a/winlogbeat/sys/event.go +++ b/winlogbeat/sys/event.go @@ -26,7 +26,8 @@ import ( // UnmarshalEventXML unmarshals the given XML into a new Event. func UnmarshalEventXML(rawXML []byte) (Event, error) { var event Event - err := xml.Unmarshal(rawXML, &event) + decoder := xml.NewDecoder(newXmlSafeReader(rawXML)) + err := decoder.Decode(&event) return event, err } diff --git a/winlogbeat/sys/xmlreader.go b/winlogbeat/sys/xmlreader.go new file mode 100644 index 000000000000..d7a3bd73bda0 --- /dev/null +++ b/winlogbeat/sys/xmlreader.go @@ -0,0 +1,78 @@ +// Licensed to Elasticsearch B.V. under one or more contributor +// license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright +// ownership. Elasticsearch B.V. licenses this file to you under +// the Apache License, Version 2.0 (the "License"); you may +// not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +package sys + +import ( + "bytes" + "fmt" + "io" + "unicode" + "unicode/utf8" +) + +// The type xmlSafeReader escapes UTF control characters in the io.Reader +// it wraps, so that it can be fed to Go's xml parser. +// Characters for which `unicode.IsControl` returns true will be output as +// an hexadecimal unicode escape sequence "\\uNNNN". +type xmlSafeReader struct { + inner io.Reader + backing [256]byte + buf []byte + code []byte +} + +var _ io.Reader = (*xmlSafeReader)(nil) + +func output(n int) (int, error) { + if n == 0 { + return 0, io.EOF + } + return n, nil +} + +// Read implements the io.Reader interface. +func (r *xmlSafeReader) Read(d []byte) (n int, err error) { + if len(r.code) > 0 { + n = copy(d, r.code) + r.code = r.code[n:] + return output(n) + } + if len(r.buf) == 0 { + n, _ = r.inner.Read(r.backing[:]) + r.buf = r.backing[:n] + } + for i := 0; i < len(r.buf); { + code, size := utf8.DecodeRune(r.buf[i:]) + if unicode.IsControl(code) { + n = copy(d, r.buf[:i]) + r.buf = r.buf[n+1:] + r.code = []byte(fmt.Sprintf("\\u%04x", code)) + m := copy(d[n:], r.code) + r.code = r.code[m:] + return output(n + m) + } + i += size + } + n = copy(d, r.buf) + r.buf = r.buf[n:] + return output(n) +} + +func newXmlSafeReader(rawXML []byte) io.Reader { + return &xmlSafeReader{inner: bytes.NewReader(rawXML)} +} From 84ad8748ef5544eca8d83fb90b402c6296cd6711 Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 04:08:26 +0100 Subject: [PATCH 2/6] [Winlogbeat] Do not drop events after XML rendering error This updates the wineventlog logic to ingest windows event logs whose rendering fails. --- winlogbeat/eventlog/wineventlog.go | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/winlogbeat/eventlog/wineventlog.go b/winlogbeat/eventlog/wineventlog.go index b43981924cdd..fbcc6672126e 100644 --- a/winlogbeat/eventlog/wineventlog.go +++ b/winlogbeat/eventlog/wineventlog.go @@ -174,12 +174,6 @@ func (l *winEventLog) Read() ([]Record, error) { } r, err := l.buildRecordFromXML(l.outputBuf.Bytes(), err) - if err != nil { - logp.Err("%s Dropping event. %v", l.logPrefix, err) - incrementMetric(dropReasons, err) - continue - } - r.Offset = checkpoint.EventLogState{ Name: l.channelName, RecordNumber: r.RecordID, @@ -231,8 +225,8 @@ func (l *winEventLog) eventHandles(maxRead int) ([]win.EvtHandle, int, error) { func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) (Record, error) { e, err := sys.UnmarshalEventXML(x) - if err != nil { - return Record{}, fmt.Errorf("Failed to unmarshal XML='%s'. %v", x, err) + if err != nil && recoveredErr == nil { + recoveredErr = err } err = sys.PopulateAccount(&e.User) From 0d72734e1a306ed1d197cae54ff8e5d4fe339dcd Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 10:50:08 +0100 Subject: [PATCH 3/6] Update CHANGELOG --- CHANGELOG.next.asciidoc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index adbe33d0e6f0..d8b0eee1d493 100644 --- a/CHANGELOG.next.asciidoc +++ b/CHANGELOG.next.asciidoc @@ -186,6 +186,8 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d *Winlogbeat* +- Prevent Winlogbeat from dropping events with invalid XML. {pull}11006{11006} + *Functionbeat* - Ensure that functionbeat is logging at info level not debug. {issue}10262[10262] From bdc4431f221dd2b7f5d260a598beb7df0f6ada1f Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 13:03:40 +0100 Subject: [PATCH 4/6] Save error message when XML decoding fails --- winlogbeat/eventlog/eventlog.go | 6 +++++- winlogbeat/eventlog/wineventlog.go | 15 +++++++++------ winlogbeat/sys/event.go | 4 ++-- .../sys/eventlogging/eventlogging_windows.go | 4 ++-- winlogbeat/sys/xmlreader.go | 2 +- 5 files changed, 19 insertions(+), 12 deletions(-) diff --git a/winlogbeat/eventlog/eventlog.go b/winlogbeat/eventlog/eventlog.go index 8d3ed476afcf..c9f7662750d1 100644 --- a/winlogbeat/eventlog/eventlog.go +++ b/winlogbeat/eventlog/eventlog.go @@ -138,7 +138,11 @@ func (e Record) ToEvent() beat.Event { addOptional(m, "message", sys.RemoveWindowsLineEndings(e.Message)) // Errors addOptional(m, "error.code", e.RenderErrorCode) - addOptional(m, "error.message", e.RenderErr) + if len(e.RenderErr) == 1 { + addOptional(m, "error.message", e.RenderErr[0]) + } else { + addOptional(m, "error.message", e.RenderErr) + } addOptional(m, "event.original", e.XML) diff --git a/winlogbeat/eventlog/wineventlog.go b/winlogbeat/eventlog/wineventlog.go index fbcc6672126e..c20833d4f67b 100644 --- a/winlogbeat/eventlog/wineventlog.go +++ b/winlogbeat/eventlog/wineventlog.go @@ -173,7 +173,7 @@ func (l *winEventLog) Read() ([]Record, error) { continue } - r, err := l.buildRecordFromXML(l.outputBuf.Bytes(), err) + r, _ := l.buildRecordFromXML(l.outputBuf.Bytes(), err) r.Offset = checkpoint.EventLogState{ Name: l.channelName, RecordNumber: r.RecordID, @@ -224,9 +224,12 @@ func (l *winEventLog) eventHandles(maxRead int) ([]win.EvtHandle, int, error) { } func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) (Record, error) { + includeXML := l.config.IncludeXML e, err := sys.UnmarshalEventXML(x) - if err != nil && recoveredErr == nil { - recoveredErr = err + if err != nil { + e.RenderErr = append(e.RenderErr, err.Error()) + // Add raw XML to event.original when decoding fails + includeXML = true } err = sys.PopulateAccount(&e.User) @@ -238,9 +241,9 @@ func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) (Record, if e.RenderErrorCode != 0 { // Convert the render error code to an error message that can be // included in the "error.message" field. - e.RenderErr = syscall.Errno(e.RenderErrorCode).Error() + e.RenderErr = append(e.RenderErr, syscall.Errno(e.RenderErrorCode).Error()) } else if recoveredErr != nil { - e.RenderErr = recoveredErr.Error() + e.RenderErr = append(e.RenderErr, recoveredErr.Error()) } if e.Level == "" { @@ -257,7 +260,7 @@ func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) (Record, Event: e, } - if l.config.IncludeXML { + if includeXML { r.XML = string(x) } diff --git a/winlogbeat/sys/event.go b/winlogbeat/sys/event.go index 50843fd09332..e9a9f473aac2 100644 --- a/winlogbeat/sys/event.go +++ b/winlogbeat/sys/event.go @@ -26,7 +26,7 @@ import ( // UnmarshalEventXML unmarshals the given XML into a new Event. func UnmarshalEventXML(rawXML []byte) (Event, error) { var event Event - decoder := xml.NewDecoder(newXmlSafeReader(rawXML)) + decoder := xml.NewDecoder(newXMLSafeReader(rawXML)) err := decoder.Decode(&event) return event, err } @@ -61,7 +61,7 @@ type Event struct { // ProcessingErrorData RenderErrorCode uint32 `xml:"ProcessingErrorData>ErrorCode"` RenderErrorDataItemName string `xml:"ProcessingErrorData>DataItemName"` - RenderErr string + RenderErr []string } // Provider identifies the provider that logged the event. The Name and GUID diff --git a/winlogbeat/sys/eventlogging/eventlogging_windows.go b/winlogbeat/sys/eventlogging/eventlogging_windows.go index 6c5b45c0d3e1..29d2c47fdefd 100644 --- a/winlogbeat/sys/eventlogging/eventlogging_windows.go +++ b/winlogbeat/sys/eventlogging/eventlogging_windows.go @@ -163,7 +163,7 @@ func RenderEvents( } // Parse the UTF-16 message insert strings. if err = insertStrings.Parse(record, recordBuf); err != nil { - event.RenderErr = err.Error() + event.RenderErr = append(event.RenderErr, err.Error()) events = append(events, event) continue } @@ -176,7 +176,7 @@ func RenderEvents( event.Message, err = formatMessage(record.sourceName, record.eventID, lang, insertStrings.Pointer(), buffer, pubHandleProvider) if err != nil { - event.RenderErr = err.Error() + event.RenderErr = append(event.RenderErr, err.Error()) if errno, ok := err.(syscall.Errno); ok { event.RenderErrorCode = uint32(errno) } diff --git a/winlogbeat/sys/xmlreader.go b/winlogbeat/sys/xmlreader.go index d7a3bd73bda0..8eb23e1ce144 100644 --- a/winlogbeat/sys/xmlreader.go +++ b/winlogbeat/sys/xmlreader.go @@ -73,6 +73,6 @@ func (r *xmlSafeReader) Read(d []byte) (n int, err error) { return output(n) } -func newXmlSafeReader(rawXML []byte) io.Reader { +func newXMLSafeReader(rawXML []byte) io.Reader { return &xmlSafeReader{inner: bytes.NewReader(rawXML)} } From 0c067ffc3817af3dd345bb166301fa7b54daf46f Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 14:58:44 +0100 Subject: [PATCH 5/6] Fix unit test --- winlogbeat/eventlog/eventlogging_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/winlogbeat/eventlog/eventlogging_test.go b/winlogbeat/eventlog/eventlogging_test.go index b102a80fd2ad..3f5acd679552 100644 --- a/winlogbeat/eventlog/eventlogging_test.go +++ b/winlogbeat/eventlog/eventlogging_test.go @@ -267,7 +267,7 @@ func TestFormatMessageWithLargeMessage(t *testing.T) { assert.Len(t, records, 1) for _, record := range records { t.Log(record) - assert.Equal(t, "The data area passed to a system call is too small.", record.RenderErr) + assert.Equal(t, []string{"The data area passed to a system call is too small."}, record.RenderErr) } } From 4c2db854dc615e6f4a0eeba8abc55a87839d58d3 Mon Sep 17 00:00:00 2001 From: Adrian Serrano Date: Fri, 1 Mar 2019 19:32:29 +0100 Subject: [PATCH 6/6] Test for invalid characters in XML --- winlogbeat/sys/event_test.go | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/winlogbeat/sys/event_test.go b/winlogbeat/sys/event_test.go index 91797dcc59c6..c77c05c2ea37 100644 --- a/winlogbeat/sys/event_test.go +++ b/winlogbeat/sys/event_test.go @@ -168,6 +168,23 @@ func TestXML(t *testing.T) { } } +func TestInvalidXML(t *testing.T) { + eventXML := fmt.Sprintf(` + + + + {00000000-0000-0000-0000-000000000000} + じゃあ宇宙カウボーイ。。。%s + + + +`, "\x1b") + _, err := UnmarshalEventXML([]byte(eventXML)) + if !assert.NoError(t, err) { + assert.Equal(t, err.Error(), "XML syntax error on line 6: illegal character code U+001B") + } +} + func BenchmarkXMLUnmarshal(b *testing.B) { for i := 0; i < b.N; i++ { _, err := UnmarshalEventXML([]byte(allXML))