diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index 3570ba5e5ad..c5d55aa0a8f 100644 --- a/CHANGELOG.next.asciidoc +++ b/CHANGELOG.next.asciidoc @@ -406,6 +406,12 @@ https://github.com/elastic/beats/compare/v8.8.1\...main[Check the HEAD diff] *Winlogbeat* - Add handling for missing `EvtVarType`s in experimental api. {issue}19337[19337] {pull}41418[41418] +- Properly set events `UserData` when experimental api is used. {pull}41525[41525] +- Include XML is respected for experimental api {pull}41525[41525] +- Forwarded events use renderedtext info for experimental api {pull}41525[41525] +- Language setting is respected for experimental api {pull}41525[41525] +- Language setting also added to decode xml wineventlog processor {pull}41525[41525] +- Format embedded messages in the experimental api {pull}41525[41525] - Implement exclusion range support for event_id. {issue}38623[38623] {pull}41639[41639] diff --git a/libbeat/processors/decode_xml_wineventlog/config.go b/libbeat/processors/decode_xml_wineventlog/config.go index 061a4d0a52f..28373651c21 100644 --- a/libbeat/processors/decode_xml_wineventlog/config.go +++ b/libbeat/processors/decode_xml_wineventlog/config.go @@ -24,6 +24,7 @@ type config struct { MapECSFields bool `config:"map_ecs_fields"` IgnoreMissing bool `config:"ignore_missing"` IgnoreFailure bool `config:"ignore_failure"` + Language uint32 `config:"language"` } func defaultConfig() config { diff --git a/libbeat/processors/decode_xml_wineventlog/decoder.go b/libbeat/processors/decode_xml_wineventlog/decoder.go index 7f0d298c815..3849a06af45 100644 --- a/libbeat/processors/decode_xml_wineventlog/decoder.go +++ b/libbeat/processors/decode_xml_wineventlog/decoder.go @@ -26,7 +26,7 @@ import ( type nonWinDecoder struct{} -func newDecoder() decoder { +func newDecoder(uint32) decoder { return nonWinDecoder{} } diff --git a/libbeat/processors/decode_xml_wineventlog/decoder_windows.go b/libbeat/processors/decode_xml_wineventlog/decoder_windows.go index ba27cf51ddc..7989b36459b 100644 --- a/libbeat/processors/decode_xml_wineventlog/decoder_windows.go +++ b/libbeat/processors/decode_xml_wineventlog/decoder_windows.go @@ -29,11 +29,13 @@ import ( ) type winDecoder struct { - cache *metadataCache + locale uint32 + cache *metadataCache } -func newDecoder() decoder { +func newDecoder(locale uint32) decoder { return &winDecoder{ + locale: locale, cache: &metadataCache{ store: map[string]*winevent.WinMeta{}, log: logp.NewLogger(logName), @@ -46,7 +48,7 @@ func (dec *winDecoder) decode(data []byte) (mapstr.M, mapstr.M, error) { if err != nil { return nil, nil, err } - md := dec.cache.getPublisherMetadata(evt.Provider.Name) + md := dec.cache.getPublisherMetadata(evt.Provider.Name, dec.locale) winevent.EnrichRawValuesWithNames(md, &evt) win, ecs := fields(evt) return win, ecs, nil @@ -59,7 +61,7 @@ type metadataCache struct { log *logp.Logger } -func (c *metadataCache) getPublisherMetadata(publisher string) *winevent.WinMeta { +func (c *metadataCache) getPublisherMetadata(publisher string, locale uint32) *winevent.WinMeta { // NOTE: This code uses double-check locking to elevate to a write-lock // when a cache value needs initialized. c.mutex.RLock() @@ -79,7 +81,7 @@ func (c *metadataCache) getPublisherMetadata(publisher string) *winevent.WinMeta } // Load metadata from the publisher. - md, err := wineventlog.NewPublisherMetadataStore(wineventlog.NilHandle, publisher, c.log) + md, err := wineventlog.NewPublisherMetadataStore(wineventlog.NilHandle, publisher, locale, c.log) if err != nil { // Return an empty store on error (can happen in cases where the // log was forwarded and the provider doesn't exist on collector). diff --git a/libbeat/processors/decode_xml_wineventlog/docs/decode_xml_wineventlog.asciidoc b/libbeat/processors/decode_xml_wineventlog/docs/decode_xml_wineventlog.asciidoc index 1e30d57f698..c86bb06e440 100644 --- a/libbeat/processors/decode_xml_wineventlog/docs/decode_xml_wineventlog.asciidoc +++ b/libbeat/processors/decode_xml_wineventlog/docs/decode_xml_wineventlog.asciidoc @@ -35,6 +35,11 @@ when a specified field does not exist. Defaults to `false`. `ignore_failure`:: (Optional) Ignore all errors produced by the processor. Defaults to `false`. +`language`:: (Optional) The language ID the events will be rendered in. The language will be forced regardless +of the system language. Forwarded events will ignore this setting. A complete list of language IDs can be found +https://docs.microsoft.com/en-us/openspecs/windows_protocols/ms-lcid/a9eac961-e77d-41a6-90a5-ce1a8b0cdb9c[here]. +It defaults to `0`, which indicates to use the system language. + Example: [source,yaml] diff --git a/libbeat/processors/decode_xml_wineventlog/processor.go b/libbeat/processors/decode_xml_wineventlog/processor.go index c6eacdf9467..85a514d6d44 100644 --- a/libbeat/processors/decode_xml_wineventlog/processor.go +++ b/libbeat/processors/decode_xml_wineventlog/processor.go @@ -83,7 +83,7 @@ func newProcessor(config config) (beat.Processor, error) { return &processor{ config: config, - decoder: newDecoder(), + decoder: newDecoder(config.Language), log: logp.NewLogger(logName), }, nil } diff --git a/winlogbeat/docs/winlogbeat-options.asciidoc b/winlogbeat/docs/winlogbeat-options.asciidoc index 27a86bc04fb..1a68787dade 100644 --- a/winlogbeat/docs/winlogbeat-options.asciidoc +++ b/winlogbeat/docs/winlogbeat-options.asciidoc @@ -515,9 +515,8 @@ winlogbeat.event_logs: 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. +* If `include_xml` is `true` the performance will be the same as the default API, +as performance improvements are lost when parsing the XML. [float] diff --git a/winlogbeat/eventlog/bench_test.go b/winlogbeat/eventlog/bench_test.go index 44b25fb81f2..97946a509b3 100644 --- a/winlogbeat/eventlog/bench_test.go +++ b/winlogbeat/eventlog/bench_test.go @@ -60,22 +60,25 @@ func TestBenchmarkRead(t *testing.T) { for _, api := range []string{winEventLogAPIName, winEventLogExpAPIName} { t.Run("api="+api, func(t *testing.T) { - for _, batchSize := range []int{10, 100, 500, 1000} { - t.Run(fmt.Sprintf("batch_size=%d", batchSize), func(t *testing.T) { - result := testing.Benchmark(benchmarkEventLog(api, batchSize)) - outputBenchmarkResults(t, result) - }) + for _, includexml := range []bool{true, false} { + for _, batchSize := range []int{10, 100, 500, 1000} { + t.Run(fmt.Sprintf("include_xml=%v/batch_size=%d", includexml, batchSize), func(t *testing.T) { + result := testing.Benchmark(benchmarkEventLog(api, includexml, batchSize)) + outputBenchmarkResults(t, result) + }) + } } }) } } -func benchmarkEventLog(api string, batchSize int) func(b *testing.B) { +func benchmarkEventLog(api string, includexml bool, batchSize int) func(b *testing.B) { return func(b *testing.B) { conf := mapstr.M{ "name": providerName, "batch_read_size": batchSize, "no_more_events": "stop", + "include_xml": includexml, } log := openLog(b, api, nil, conf) diff --git a/winlogbeat/eventlog/cache.go b/winlogbeat/eventlog/cache.go index 3280267d0c7..985c28f433c 100644 --- a/winlogbeat/eventlog/cache.go +++ b/winlogbeat/eventlog/cache.go @@ -15,6 +15,8 @@ // specific language governing permissions and limitations // under the License. +//go:build windows + package eventlog // This component of the eventlog package provides a cache for storing Handles @@ -26,6 +28,7 @@ import ( "github.com/elastic/beats/v7/libbeat/common" "github.com/elastic/beats/v7/winlogbeat/sys" + win "github.com/elastic/beats/v7/winlogbeat/sys/wineventlog" "github.com/elastic/elastic-agent-libs/logp" ) @@ -92,7 +95,7 @@ func newMessageFilesCache(eventLogName string, loader messageFileLoaderFunc, // If no item is cached, then one is loaded, stored, and returned. // Callers should check the MessageFiles.Err value to see if an error occurred // while loading the message files. -func (hc *messageFilesCache) get(sourceName string) sys.MessageFiles { +func (hc *messageFilesCache) get(sourceName string) win.EvtHandle { v := hc.cache.Get(sourceName) if v == nil { hc.miss() @@ -111,7 +114,12 @@ func (hc *messageFilesCache) get(sourceName string) sys.MessageFiles { // Return the existing cached value. messageFiles, _ = existing.(sys.MessageFiles) - return messageFiles + + if messageFiles.Err == nil { + // There is only ever a single handle when using the Windows Event + // Log API. + return win.EvtHandle(messageFiles.Handles[0].Handle) + } } hc.size() } else { @@ -119,7 +127,12 @@ func (hc *messageFilesCache) get(sourceName string) sys.MessageFiles { } messageFiles, _ := v.(sys.MessageFiles) - return messageFiles + if messageFiles.Err == nil { + // There is only ever a single handle when using the Windows Event + // Log API. + return win.EvtHandle(messageFiles.Handles[0].Handle) + } + return win.NilHandle } // evictionHandler is the callback handler that receives notifications when diff --git a/winlogbeat/eventlog/wineventlog.go b/winlogbeat/eventlog/wineventlog.go index 43654284218..4fee3824122 100644 --- a/winlogbeat/eventlog/wineventlog.go +++ b/winlogbeat/eventlog/wineventlog.go @@ -538,7 +538,7 @@ func (l *winEventLog) buildRecordFromXML(x []byte, recoveredErr error) Record { } // Get basic string values for raw fields. - winevent.EnrichRawValuesWithNames(l.winMeta(e.Provider.Name), &e) + winevent.EnrichRawValuesWithNames(l.winMeta(e.Provider.Name, l.config.EventLanguage), &e) if e.Level == "" { // Fallback on LevelRaw if the Level is not set in the RenderingInfo. e.Level = win.EventLevel(e.LevelRaw).String() @@ -605,7 +605,7 @@ func newWinMetaCache(ttl time.Duration) winMetaCache { return winMetaCache{cache: make(map[string]winMetaCacheEntry), ttl: ttl, logger: logp.L()} } -func (c *winMetaCache) winMeta(provider string) *winevent.WinMeta { +func (c *winMetaCache) winMeta(provider string, locale uint32) *winevent.WinMeta { c.mu.RLock() e, ok := c.cache[provider] c.mu.RUnlock() @@ -624,7 +624,7 @@ func (c *winMetaCache) winMeta(provider string) *winevent.WinMeta { return e.WinMeta } - s, err := win.NewPublisherMetadataStore(win.NilHandle, provider, c.logger) + s, err := win.NewPublisherMetadataStore(win.NilHandle, provider, locale, c.logger) if err != nil { // Return an empty store on error (can happen in cases where the // log was forwarded and the provider doesn't exist on collector). diff --git a/winlogbeat/eventlog/wineventlog_experimental.go b/winlogbeat/eventlog/wineventlog_experimental.go index 126e92fdace..580adb1cfe2 100644 --- a/winlogbeat/eventlog/wineventlog_experimental.go +++ b/winlogbeat/eventlog/wineventlog_experimental.go @@ -62,7 +62,7 @@ type winEventLogExp struct { log *logp.Logger iterator *win.EventIterator - renderer *win.Renderer + renderer win.EventRenderer metrics *inputMetrics } @@ -115,11 +115,6 @@ func newWinEventLogExp(options *conf.C) (EventLog, error) { log = logp.NewLogger("wineventlog").With("id", id).With("channel", c.Name) } - renderer, err := win.NewRenderer(win.NilHandle, log) - if err != nil { - return nil, err - } - l := &winEventLogExp{ config: c, query: xmlQuery, @@ -127,10 +122,29 @@ func newWinEventLogExp(options *conf.C) (EventLog, error) { channelName: c.Name, file: isFile, maxRead: c.BatchReadSize, - renderer: renderer, log: log, } + switch c.IncludeXML { + case true: + l.renderer = win.NewXMLRenderer( + win.RenderConfig{ + IsForwarded: l.isForwarded(), + Locale: c.EventLanguage, + }, + win.NilHandle, log) + case false: + l.renderer, err = win.NewRenderer( + win.RenderConfig{ + IsForwarded: l.isForwarded(), + Locale: c.EventLanguage, + }, + win.NilHandle, log) + if err != nil { + return nil, err + } + } + return l, nil } @@ -309,7 +323,7 @@ func (l *winEventLogExp) processHandle(h win.EvtHandle) (*Record, error) { defer h.Close() // NOTE: Render can return an error and a partial event. - evt, err := l.renderer.Render(h) + evt, xml, err := l.renderer.Render(h) if evt == nil { return nil, err } @@ -317,14 +331,15 @@ func (l *winEventLogExp) processHandle(h win.EvtHandle) (*Record, error) { evt.RenderErr = append(evt.RenderErr, err.Error()) } - //nolint:godox // Bad linter! Keep to have a record of feature disparity between non-experimental vs experimental. - // TODO: Need to add XML when configured. - r := &Record{ API: winEventLogExpAPIName, Event: *evt, } + if l.config.IncludeXML { + r.XML = xml + } + if l.file { r.File = l.id } diff --git a/winlogbeat/eventlog/wineventlog_test.go b/winlogbeat/eventlog/wineventlog_test.go index 81e32afa373..3277bb5d7f1 100644 --- a/winlogbeat/eventlog/wineventlog_test.go +++ b/winlogbeat/eventlog/wineventlog_test.go @@ -167,14 +167,17 @@ func TestWinEventLogConfig_Validate(t *testing.T) { } func TestWindowsEventLogAPI(t *testing.T) { - testWindowsEventLog(t, winEventLogAPIName) + testWindowsEventLog(t, winEventLogAPIName, false) } func TestWindowsEventLogAPIExperimental(t *testing.T) { - testWindowsEventLog(t, winEventLogExpAPIName) + // for the experimental api using include xml behave differently than not + // so we must test both settings + testWindowsEventLog(t, winEventLogExpAPIName, true) + testWindowsEventLog(t, winEventLogExpAPIName, false) } -func testWindowsEventLog(t *testing.T, api string) { +func testWindowsEventLog(t *testing.T, api string, includeXML bool) { writer, teardown := createLog(t) defer teardown() @@ -192,7 +195,7 @@ func testWindowsEventLog(t *testing.T, api string) { } t.Run("has_message", func(t *testing.T) { - log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": 1}) + log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": 1, "include_xml": includeXML}) defer log.Close() for i := 0; i < 10; i++ { @@ -208,8 +211,9 @@ func testWindowsEventLog(t *testing.T, api string) { // Test reading from an event log using a custom XML query. t.Run("custom_xml_query", func(t *testing.T) { cfg := map[string]interface{}{ - "id": "custom-xml-query", - "xml_query": customXMLQuery, + "id": "custom-xml-query", + "xml_query": customXMLQuery, + "include_xml": includeXML, } log := openLog(t, cfg) @@ -236,7 +240,7 @@ func testWindowsEventLog(t *testing.T, api string) { t.Run("batch_read_size_config", func(t *testing.T) { const batchReadSize = 2 - log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": batchReadSize}) + log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": batchReadSize, "include_xml": includeXML}) defer log.Close() records, err := log.Read() @@ -251,7 +255,7 @@ func testWindowsEventLog(t *testing.T, api string) { // When combined with large messages this causes EvtNext to fail with // RPC_S_INVALID_BOUND error. The reader should recover from the error. t.Run("large_batch_read", func(t *testing.T) { - log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": 1024}) + log := openLog(t, map[string]interface{}{"name": providerName, "batch_read_size": 1024, "include_xml": includeXML}) defer log.Close() var eventCount int @@ -282,6 +286,7 @@ func testWindowsEventLog(t *testing.T, api string) { log := openLog(t, map[string]interface{}{ "name": path, "no_more_events": "stop", + "include_xml": includeXML, }) defer log.Close() @@ -310,6 +315,7 @@ func testWindowsEventLog(t *testing.T, api string) { "name": path, "no_more_events": "stop", "event_id": "3, 5", + "include_xml": includeXML, }) defer log.Close() diff --git a/winlogbeat/sys/wineventlog/format_message_test.go b/winlogbeat/sys/wineventlog/format_message_test.go index b2090528104..c677bc148ac 100644 --- a/winlogbeat/sys/wineventlog/format_message_test.go +++ b/winlogbeat/sys/wineventlog/format_message_test.go @@ -33,7 +33,7 @@ func TestFormatMessage(t *testing.T) { evtHandle := mustNextHandle(t, log) defer evtHandle.Close() - publisherMetadata, err := NewPublisherMetadata(NilHandle, "Microsoft-Windows-Security-Auditing") + publisherMetadata, err := NewPublisherMetadata(NilHandle, "Microsoft-Windows-Security-Auditing", 0) if err != nil { t.Fatal(err) } diff --git a/winlogbeat/sys/wineventlog/metadata_store.go b/winlogbeat/sys/wineventlog/metadata_store.go index 6b45237b0bf..4373451717a 100644 --- a/winlogbeat/sys/wineventlog/metadata_store.go +++ b/winlogbeat/sys/wineventlog/metadata_store.go @@ -55,19 +55,24 @@ type PublisherMetadataStore struct { // Event ID to map of fingerprints to event metadata. The fingerprint value // is hash of the event data parameters count and types. EventFingerprints map[uint16]map[uint64]*EventMetadata + // Stores used messages by their ID. Message can be found in events as references + // such as %%1111. This need to be formatted the first time, and they are stored + // from that point after. + MessagesByID map[uint32]string mutex sync.RWMutex log *logp.Logger } -func NewPublisherMetadataStore(session EvtHandle, provider string, log *logp.Logger) (*PublisherMetadataStore, error) { - md, err := NewPublisherMetadata(session, provider) +func NewPublisherMetadataStore(session EvtHandle, provider string, locale uint32, log *logp.Logger) (*PublisherMetadataStore, error) { + md, err := NewPublisherMetadata(session, provider, locale) if err != nil { return nil, err } store := &PublisherMetadataStore{ Metadata: md, EventFingerprints: map[uint16]map[uint64]*EventMetadata{}, + MessagesByID: map[uint32]string{}, log: log.With("publisher", provider), } @@ -99,6 +104,7 @@ func NewEmptyPublisherMetadataStore(provider string, log *logp.Logger) *Publishe }, Events: map[uint16]*EventMetadata{}, EventFingerprints: map[uint16]map[uint64]*EventMetadata{}, + MessagesByID: map[uint32]string{}, log: log.With("publisher", provider, "empty", true), } } @@ -269,6 +275,45 @@ func (s *PublisherMetadataStore) getEventMetadata(eventID uint16, eventDataFinge return em } +// getMessageByID returns the rendered message from its ID. If it is not cached it will format it. +// In case of any error this never fails, and will return the original reference instead. +func (s *PublisherMetadataStore) getMessageByID(messageID uint32) string { + // Use a read lock to get a cached value. + s.mutex.RLock() + message, found := s.MessagesByID[messageID] + if found { + s.mutex.RUnlock() + return message + } + + // Elevate to write lock. + s.mutex.RUnlock() + s.mutex.Lock() + defer s.mutex.Unlock() + + message, found = s.MessagesByID[messageID] + if found { + return message + } + + handle := NilHandle + if s.Metadata != nil { + handle = s.Metadata.Handle + } + + message, err := evtFormatMessage(handle, NilHandle, messageID, nil, EvtFormatMessageId) + if err != nil { + s.log.Debugw("Failed to format message. "+ + "Will not try to format it anymore", + "message_id", messageID, + "error", err) + message = fmt.Sprintf("%%%%%d", messageID) + } + + s.MessagesByID[messageID] = message + return message +} + func (s *PublisherMetadataStore) Close() error { if s.Metadata != nil { s.mutex.Lock() @@ -285,6 +330,7 @@ type EventMetadata struct { MsgStatic string // Used when the message has no parameters. MsgTemplate *template.Template `json:"-"` // Template that expects an array of values as its data. EventData []EventData // Names of parameters from XML template. + HasUserData bool // Event has a UserData section or not. } // newEventMetadataFromEventHandle collects metadata about an event type using @@ -311,6 +357,7 @@ func newEventMetadataFromEventHandle(publisher *PublisherMetadata, eventHandle E em.EventData = append(em.EventData, EventData{Name: pair.Key}) } } else { + em.HasUserData = true for _, pair := range event.UserData.Pairs { em.EventData = append(em.EventData, EventData{Name: pair.Key}) } @@ -469,6 +516,82 @@ func (em *EventMetadata) equal(other *EventMetadata) bool { eventDataNamesEqual(em.EventData, other.EventData) } +type publisherMetadataCache struct { + // Mutex to guard the metadataCache. The other members are immutable. + mutex sync.RWMutex + // Cache of publisher metadata. Maps publisher names to stored metadata. + metadataCache map[string]*PublisherMetadataStore + locale uint32 + session EvtHandle + log *logp.Logger +} + +func newPublisherMetadataCache(session EvtHandle, locale uint32, log *logp.Logger) *publisherMetadataCache { + return &publisherMetadataCache{ + metadataCache: map[string]*PublisherMetadataStore{}, + locale: locale, + session: session, + log: log.Named("publisher_metadata_cache"), + } +} + +// getPublisherStore returns a PublisherMetadataStore for the provider. It +// never returns nil, as if it does not exists it tries to initialise it, +// but may return an error if it couldn't open a publisher. +func (c *publisherMetadataCache) getPublisherStore(publisher string) (*PublisherMetadataStore, error) { + var err error + + // NOTE: This code uses double-check locking to elevate to a write-lock + // when a cache value needs initialized. + c.mutex.RLock() + + // Lookup cached value. + md, found := c.metadataCache[publisher] + if !found { + // Elevate to write lock. + c.mutex.RUnlock() + c.mutex.Lock() + defer c.mutex.Unlock() + + // Double-check if the condition changed while upgrading the lock. + md, found = c.metadataCache[publisher] + if found { + return md, nil + } + + // Load metadata from the publisher. + md, err = NewPublisherMetadataStore(c.session, publisher, c.locale, c.log) + if err != nil { + // 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, c.log) + err = fmt.Errorf("failed to load publisher metadata for %v "+ + "(returning an empty metadata store): %w", publisher, err) + } + c.metadataCache[publisher] = md + } else { + c.mutex.RUnlock() + } + + return md, err +} + +func (c *publisherMetadataCache) close() error { + if c == nil { + return nil + } + c.mutex.Lock() + defer c.mutex.Unlock() + + errs := []error{} + for _, md := range c.metadataCache { + if err := md.Close(); err != nil { + errs = append(errs, err) + } + } + return multierr.Combine(errs...) +} + // --- Template Funcs // eventParam return an event data value inside a text/template. diff --git a/winlogbeat/sys/wineventlog/metadata_store_test.go b/winlogbeat/sys/wineventlog/metadata_store_test.go index 2ee7ef9dceb..86b02edd681 100644 --- a/winlogbeat/sys/wineventlog/metadata_store_test.go +++ b/winlogbeat/sys/wineventlog/metadata_store_test.go @@ -33,6 +33,7 @@ func TestPublisherMetadataStore(t *testing.T) { s, err := NewPublisherMetadataStore( NilHandle, "Microsoft-Windows-Security-Auditing", + 0, logp.NewLogger("metadata")) if err != nil { t.Fatal(err) diff --git a/winlogbeat/sys/wineventlog/publisher_metadata.go b/winlogbeat/sys/wineventlog/publisher_metadata.go index eb99bfb43ce..2e5ed2411c5 100644 --- a/winlogbeat/sys/wineventlog/publisher_metadata.go +++ b/winlogbeat/sys/wineventlog/publisher_metadata.go @@ -42,7 +42,7 @@ func (m *PublisherMetadata) Close() error { // NewPublisherMetadata opens the publisher's metadata. Close must be called on // the returned PublisherMetadata to release its handle. -func NewPublisherMetadata(session EvtHandle, name string) (*PublisherMetadata, error) { +func NewPublisherMetadata(session EvtHandle, name string, locale uint32) (*PublisherMetadata, error) { var publisherName, logFile *uint16 if info, err := os.Stat(name); err == nil && info.Mode().IsRegular() { logFile, err = syscall.UTF16PtrFromString(name) diff --git a/winlogbeat/sys/wineventlog/publisher_metadata_test.go b/winlogbeat/sys/wineventlog/publisher_metadata_test.go index f2daa0b69cf..8851407f9f9 100644 --- a/winlogbeat/sys/wineventlog/publisher_metadata_test.go +++ b/winlogbeat/sys/wineventlog/publisher_metadata_test.go @@ -39,7 +39,7 @@ func TestPublisherMetadata(t *testing.T) { func testPublisherMetadata(t *testing.T, provider string) { t.Run(provider, func(t *testing.T) { - md, err := NewPublisherMetadata(NilHandle, provider) + md, err := NewPublisherMetadata(NilHandle, provider, 0) if err != nil { t.Fatalf("%+v", err) } @@ -224,6 +224,6 @@ func testPublisherMetadata(t *testing.T, provider string) { } func TestNewPublisherMetadataUnknown(t *testing.T) { - _, err := NewPublisherMetadata(NilHandle, "Fake-Publisher") + _, err := NewPublisherMetadata(NilHandle, "Fake-Publisher", 0) assert.ErrorIs(t, err, fs.ErrNotExist) } diff --git a/winlogbeat/sys/wineventlog/renderer.go b/winlogbeat/sys/wineventlog/renderer.go index 4471b7b6aff..6b7042d25dd 100644 --- a/winlogbeat/sys/wineventlog/renderer.go +++ b/winlogbeat/sys/wineventlog/renderer.go @@ -23,8 +23,11 @@ import ( "encoding/binary" "errors" "fmt" + "io" + "regexp" "strconv" - "sync" + "strings" + "syscall" "text/template" "time" "unsafe" @@ -38,21 +41,27 @@ import ( "github.com/elastic/elastic-agent-libs/logp" ) +type RenderConfig struct { + IsForwarded bool + Locale uint32 +} + +type EventRenderer interface { + Render(handle EvtHandle) (event *winevent.Event, xml string, err error) + Close() error +} + // Renderer is used for converting event log handles into complete events. type Renderer struct { - // Mutex to guard the metadataCache. The other members are immutable. - mutex sync.RWMutex - // Cache of publisher metadata. Maps publisher names to stored metadata. - metadataCache map[string]*PublisherMetadataStore - - session EvtHandle // Session handle if working with remote log. + conf RenderConfig + metadataCache *publisherMetadataCache systemContext EvtHandle // Render context for system values. userContext EvtHandle // Render context for user values (event data). log *logp.Logger } // NewRenderer returns a new Renderer. -func NewRenderer(session EvtHandle, log *logp.Logger) (*Renderer, error) { +func NewRenderer(conf RenderConfig, session EvtHandle, log *logp.Logger) (*Renderer, error) { systemContext, err := _EvtCreateRenderContext(0, nil, EvtRenderContextSystem) if err != nil { return nil, fmt.Errorf("failed in EvtCreateRenderContext for system context: %w", err) @@ -63,12 +72,14 @@ func NewRenderer(session EvtHandle, log *logp.Logger) (*Renderer, error) { return nil, fmt.Errorf("failed in EvtCreateRenderContext for user context: %w", err) } + rlog := log.Named("renderer") + return &Renderer{ - metadataCache: map[string]*PublisherMetadataStore{}, - session: session, + conf: conf, + metadataCache: newPublisherMetadataCache(session, conf.Locale, rlog), systemContext: systemContext, userContext: userContext, - log: log.Named("renderer"), + log: rlog, }, nil } @@ -77,24 +88,19 @@ func (r *Renderer) Close() error { if r == nil { return errors.New("closing nil renderer") } - r.mutex.Lock() - defer r.mutex.Unlock() - - errs := []error{r.systemContext.Close(), r.userContext.Close()} - for _, md := range r.metadataCache { - if err := md.Close(); err != nil { - errs = append(errs, err) - } - } - return multierr.Combine(errs...) + return multierr.Combine( + r.metadataCache.close(), + r.systemContext.Close(), + r.userContext.Close(), + ) } // Render renders the event handle into an Event. -func (r *Renderer) Render(handle EvtHandle) (*winevent.Event, error) { +func (r *Renderer) Render(handle EvtHandle) (*winevent.Event, string, error) { event := &winevent.Event{} if err := r.renderSystem(handle, event); err != nil { - return nil, fmt.Errorf("failed to render system properties: %w", err) + return nil, "", fmt.Errorf("failed to render system properties: %w", err) } // From this point on it will return both the event and any errors. It's @@ -102,15 +108,19 @@ func (r *Renderer) Render(handle EvtHandle) (*winevent.Event, error) { var errs []error // This always returns a non-nil value (even on error). - md, err := r.getPublisherMetadata(event.Provider.Name) + md, err := r.metadataCache.getPublisherStore(event.Provider.Name) if err != nil { errs = append(errs, err) } // Associate raw system properties to names (e.g. level=2 to Error). winevent.EnrichRawValuesWithNames(&md.WinMeta, event) + if event.Level == "" { + // Fallback on LevelRaw if the Level is not set in the RenderingInfo. + event.Level = EventLevel(event.LevelRaw).String() + } - eventData, fingerprint, err := r.renderUser(handle, event) + eventData, fingerprint, err := r.renderUser(md, handle, event) if err != nil { errs = append(errs, fmt.Errorf("failed to render event data: %w", err)) } @@ -121,54 +131,14 @@ func (r *Renderer) Render(handle EvtHandle) (*winevent.Event, error) { // 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 { + if event.Message, err = r.formatMessage(md.Metadata, eventMeta, handle, eventData, uint16(event.EventIdentifier.ID)); err != nil { errs = append(errs, fmt.Errorf("failed to get the event message string: %w", err)) } if len(errs) > 0 { - return event, multierr.Combine(errs...) + return event, "", multierr.Combine(errs...) } - return event, nil -} - -// getPublisherMetadata return a PublisherMetadataStore for the provider. It -// never returns nil, but may return an error if it couldn't open a publisher. -func (r *Renderer) getPublisherMetadata(publisher string) (*PublisherMetadataStore, error) { - var err error - - // NOTE: This code uses double-check locking to elevate to a write-lock - // when a cache value needs initialized. - r.mutex.RLock() - - // Lookup cached value. - md, found := r.metadataCache[publisher] - if !found { - // Elevate to write lock. - r.mutex.RUnlock() - r.mutex.Lock() - defer r.mutex.Unlock() - - // Double-check if the condition changed while upgrading the lock. - md, found = r.metadataCache[publisher] - if found { - return md, nil - } - - // Load metadata from the publisher. - md, err = NewPublisherMetadataStore(r.session, publisher, r.log) - if err != nil { - // 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 = fmt.Errorf("failed to load publisher metadata for %v "+ - "(returning an empty metadata store): %w", publisher, err) - } - r.metadataCache[publisher] = md - } else { - r.mutex.RUnlock() - } - - return md, err + return event, "", nil } // renderSystem writes all the system context properties into the event. @@ -242,7 +212,7 @@ func (r *Renderer) renderSystem(handle EvtHandle, event *winevent.Event) error { // renderUser returns the event/user data values. This does not provide the // parameter names. It computes a fingerprint of the values types to help the // caller match the correct names to the returned values. -func (r *Renderer) renderUser(handle EvtHandle, event *winevent.Event) (values []interface{}, fingerprint uint64, err error) { +func (r *Renderer) renderUser(mds *PublisherMetadataStore, handle EvtHandle, event *winevent.Event) (values []interface{}, fingerprint uint64, err error) { bb, propertyCount, err := r.render(r.userContext, handle) if err != nil { return nil, 0, fmt.Errorf("failed to get user values: %w", err) @@ -277,11 +247,27 @@ func (r *Renderer) renderUser(handle EvtHandle, event *winevent.Event) (values [ "error", err, ) } + if str, ok := values[i].(string); ok { + values[i] = expandMessageIDs(mds, str) + } } return values, argumentHash.Sum64(), nil } +var messageIDsRegexp = regexp.MustCompile(`%%\d+`) + +func expandMessageIDs(mds *PublisherMetadataStore, v string) string { + // Replace each occurrence by finding a message based on its value + return messageIDsRegexp.ReplaceAllStringFunc(v, func(match string) string { + messageID, err := strconv.Atoi(strings.Trim(match, `%`)) + if err != nil { + return match + } + return mds.getMessageByID(uint32(messageID)) + }) +} + // render uses EvtRender to event data. The caller must free() the returned when // done accessing the bytes. func (r *Renderer) render(context EvtHandle, eventHandle EvtHandle) (*sys.PooledByteBuffer, int, error) { @@ -342,6 +328,7 @@ func (r *Renderer) addEventData(evtMeta *EventMetadata, values []interface{}, ev return "param" + strconv.Itoa(idx) } + pairs := make([]winevent.KeyValue, len(values)) for i, v := range values { var strVal string switch t := v.(type) { @@ -353,15 +340,21 @@ func (r *Renderer) addEventData(evtMeta *EventMetadata, values []interface{}, ev strVal = fmt.Sprintf("%v", v) } - event.EventData.Pairs = append(event.EventData.Pairs, winevent.KeyValue{ + pairs[i] = winevent.KeyValue{ Key: paramName(i), Value: strVal, - }) + } + } + + if evtMeta != nil && evtMeta.HasUserData { + event.UserData.Pairs = pairs + } else { + event.EventData.Pairs = pairs } } // formatMessage adds the message to the event. -func (r *Renderer) formatMessage(publisherMeta *PublisherMetadataStore, +func (r *Renderer) formatMessage(publisherMeta *PublisherMetadata, eventMeta *EventMetadata, eventHandle EvtHandle, values []interface{}, eventID uint16) (string, error, ) { @@ -375,11 +368,13 @@ func (r *Renderer) formatMessage(publisherMeta *PublisherMetadataStore, // Fallback to the trying EvtFormatMessage mechanism. // This is the path for forwarded events in RenderedText mode where the - // local publisher metadata is not present. NOTE that if the local publisher - // metadata exists it will be preferred over the RenderedText. A config - // option might be desirable to control this behavior. + // local publisher metadata is not present. r.log.Debugf("Falling back to EvtFormatMessage for event ID %d.", eventID) - return getMessageString(publisherMeta.Metadata, eventHandle, 0, nil) + metadata := publisherMeta + if r.conf.IsForwarded { + metadata = nil + } + return getMessageString(metadata, eventHandle, 0, nil) } // formatMessageFromTemplate creates the message by executing the stored Go @@ -394,3 +389,119 @@ func (r *Renderer) formatMessageFromTemplate(msgTmpl *template.Template, values return string(bb.Bytes()), nil } + +// XMLRenderer is used for converting event log handles into complete events. +type XMLRenderer struct { + conf RenderConfig + metadataCache *publisherMetadataCache + renderBuf []byte + outBuf *sys.ByteBuffer + + render func(event EvtHandle, out io.Writer) error // Function for rendering the event to XML. + + log *logp.Logger +} + +// NewXMLRenderer returns a new Renderer. +func NewXMLRenderer(conf RenderConfig, session EvtHandle, log *logp.Logger) *XMLRenderer { + const renderBufferSize = 1 << 19 // 512KB, 256K wide characters + rlog := log.Named("xml_renderer") + r := &XMLRenderer{ + conf: conf, + renderBuf: make([]byte, renderBufferSize), + outBuf: sys.NewByteBuffer(renderBufferSize), + metadataCache: newPublisherMetadataCache(session, conf.Locale, rlog), + log: rlog, + } + // Forwarded events should be rendered using RenderEventXML. It is more + // efficient and does not attempt to use local message files for rendering + // the event's message. + switch conf.IsForwarded { + case true: + r.render = func(event EvtHandle, out io.Writer) error { + return RenderEventXML(event, r.renderBuf, out) + } + case false: + r.render = func(event EvtHandle, out io.Writer) error { + get := func(providerName string) EvtHandle { + md, _ := r.metadataCache.getPublisherStore(providerName) + if md.Metadata != nil { + return md.Metadata.Handle + } + return NilHandle + } + return RenderEvent(event, conf.Locale, r.renderBuf, get, out) + } + } + return r +} + +// Close closes all handles held by the Renderer. +func (r *XMLRenderer) Close() error { + if r == nil { + return errors.New("closing nil renderer") + } + return r.metadataCache.close() +} + +// Render renders the event handle into an Event. +func (r *XMLRenderer) Render(handle EvtHandle) (*winevent.Event, string, error) { + // From this point on it will return both the event and any errors. It's + // critical to not drop data. + var errs []error + + r.outBuf.Reset() + err := r.render(handle, r.outBuf) + if err != nil { + errs = append(errs, err) + } + outBytes := r.outBuf.Bytes() + event := r.buildEventFromXML(outBytes, err) + + // This always returns a non-nil value (even on error). + md, err := r.metadataCache.getPublisherStore(event.Provider.Name) + if err != nil { + errs = append(errs, err) + } + + // Associate raw system properties to names (e.g. level=2 to Error). + winevent.EnrichRawValuesWithNames(&md.WinMeta, event) + if event.Level == "" { + // Fallback on LevelRaw if the Level is not set in the RenderingInfo. + event.Level = EventLevel(event.LevelRaw).String() + } + + if event.Message == "" && !r.conf.IsForwarded { + if event.Message, err = getMessageString(md.Metadata, handle, 0, nil); err != nil { + errs = append(errs, fmt.Errorf("failed to get the event message string: %w", err)) + } + } + + if len(errs) > 0 { + return event, string(outBytes), multierr.Combine(errs...) + } + return event, string(outBytes), nil +} + +func (r *XMLRenderer) buildEventFromXML(x []byte, recoveredErr error) *winevent.Event { + e, err := winevent.UnmarshalXML(x) + if err != nil { + e.RenderErr = append(e.RenderErr, err.Error()) + } + + err = winevent.PopulateAccount(&e.User) + if err != nil { + r.log.Debugf("SID %s account lookup failed. %v", + e.User.Identifier, err) + } + + if e.RenderErrorCode != 0 { + // Convert the render error code to an error message that can be + // included in the "error.message" field. + e.RenderErr = append(e.RenderErr, syscall.Errno(e.RenderErrorCode).Error()) + } else if recoveredErr != nil { + e.RenderErr = append(e.RenderErr, recoveredErr.Error()) + } + + return &e +} diff --git a/winlogbeat/sys/wineventlog/renderer_test.go b/winlogbeat/sys/wineventlog/renderer_test.go index 026082df5a5..339122d8a29 100644 --- a/winlogbeat/sys/wineventlog/renderer_test.go +++ b/winlogbeat/sys/wineventlog/renderer_test.go @@ -44,7 +44,7 @@ func TestRenderer(t *testing.T) { log := openLog(t, sysmon9File) defer log.Close() - r, err := NewRenderer(NilHandle, logp.L()) + r, err := NewRenderer(RenderConfig{}, NilHandle, logp.L()) if err != nil { t.Fatal(err) } @@ -62,7 +62,7 @@ func TestRenderer(t *testing.T) { log := openLog(t, security4752File) defer log.Close() - r, err := NewRenderer(NilHandle, logp.L()) + r, err := NewRenderer(RenderConfig{}, NilHandle, logp.L()) if err != nil { t.Fatal(err) } @@ -108,7 +108,7 @@ func TestRenderer(t *testing.T) { log := openLog(t, winErrorReportingFile) defer log.Close() - r, err := NewRenderer(NilHandle, logp.L()) + r, err := NewRenderer(RenderConfig{}, NilHandle, logp.L()) if err != nil { t.Fatal(err) } @@ -148,6 +148,68 @@ func TestRenderer(t *testing.T) { logAsJSON(t, events) } }) + + t.Run(filepath.Base(security4738File), func(t *testing.T) { + log := openLog(t, security4738File) + defer log.Close() + + r, err := NewRenderer(RenderConfig{}, NilHandle, logp.L()) + if err != nil { + t.Fatal(err) + } + defer r.Close() + + events := renderAllEvents(t, log, r, false) + if !assert.Len(t, events, 2) { + return + } + e := events[0] + + assert.EqualValues(t, 4738, e.EventIdentifier.ID) + assert.Equal(t, "Microsoft-Windows-Security-Auditing", e.Provider.Name) + assertEqualIgnoreCase(t, "{54849625-5478-4994-a5ba-3e3b0328c30d}", e.Provider.GUID) + assert.Equal(t, "WIN-41OB2LO92CR", e.Computer) + assert.Equal(t, "Security", e.Channel) + assert.EqualValues(t, 2866, e.RecordID) + + assert.Equal(t, e.Keywords, []string{"Audit Success"}) + + assert.NotNil(t, 0, e.OpcodeRaw) + assert.EqualValues(t, 0, *e.OpcodeRaw) + assert.Equal(t, "Info", e.Opcode) + + assert.EqualValues(t, 0, e.LevelRaw) + assert.Equal(t, "Information", e.Level) + + assert.EqualValues(t, 13824, e.TaskRaw) + assert.Equal(t, "User Account Management", e.Task) + + assert.EqualValues(t, 780, e.Execution.ProcessID) + assert.EqualValues(t, 808, e.Execution.ThreadID) + assert.Len(t, e.EventData.Pairs, 27) + + assert.NotEmpty(t, e.Message) + + // Check for message replacements in form of %%xxxx + for _, p := range e.EventData.Pairs { + switch p.Key { + case "HomeDirectory", "HomePath", + "ScriptPath", "ProfilePath", "UserWorkstations", + "UserParameters": + assert.EqualValues(t, "", p.Value) + case "AccountExpires": + assert.EqualValues(t, "", p.Value) + case "Logon Hours": + assert.EqualValues(t, "All", p.Value) + case "UserAccountControl": + assert.EqualValues(t, "\r\n\t\t'Don't Expire Password' - Enabled", p.Value) + } + } + + if t.Failed() { + logAsJSON(t, events) + } + }) } func TestTemplateFunc(t *testing.T) { @@ -178,9 +240,9 @@ func renderAllEvents(t *testing.T, log EvtHandle, renderer *Renderer, ignoreMiss func() { defer h.Close() - evt, err := renderer.Render(h) + evt, _, err := renderer.Render(h) if err != nil { - md := renderer.metadataCache[evt.Provider.Name] + md, _ := renderer.metadataCache.getPublisherStore(evt.Provider.Name) if !ignoreMissingMetadataError || md.Metadata != nil { t.Fatalf("Render failed: %+v", err) } @@ -220,7 +282,7 @@ func BenchmarkRenderer(b *testing.B) { b.Fatal(err) } - r, err := NewRenderer(NilHandle, logp.NewLogger("bench")) + r, err := NewRenderer(RenderConfig{}, NilHandle, logp.NewLogger("bench")) if err != nil { log.Close() itr.Close() @@ -247,7 +309,7 @@ func BenchmarkRenderer(b *testing.B) { } // Render it. - _, err := r.Render(h) + _, _, err := r.Render(h) if err != nil { b.Fatal(err) } @@ -277,7 +339,7 @@ func BenchmarkRenderer(b *testing.B) { } // Render it. - _, err := r.Render(h) + _, _, err := r.Render(h) if err != nil { b.Fatal(err) } diff --git a/winlogbeat/sys/wineventlog/testdata/4738.evtx b/winlogbeat/sys/wineventlog/testdata/4738.evtx new file mode 100644 index 00000000000..9f521b36a0c Binary files /dev/null and b/winlogbeat/sys/wineventlog/testdata/4738.evtx differ diff --git a/winlogbeat/sys/wineventlog/util_test.go b/winlogbeat/sys/wineventlog/util_test.go index 7927f91ce8b..c29e5ed8d1f 100644 --- a/winlogbeat/sys/wineventlog/util_test.go +++ b/winlogbeat/sys/wineventlog/util_test.go @@ -38,6 +38,7 @@ const ( winlogbeatTestLogName = "WinEventLogTestGo" security4752File = "testdata/4752.evtx" + security4738File = "testdata/4738.evtx" sysmon9File = "testdata/sysmon-9.01.evtx" winErrorReportingFile = "testdata/application-windows-error-reporting.evtx" ) diff --git a/winlogbeat/sys/wineventlog/wineventlog_windows.go b/winlogbeat/sys/wineventlog/wineventlog_windows.go index 66ab869fb24..3c70799535e 100644 --- a/winlogbeat/sys/wineventlog/wineventlog_windows.go +++ b/winlogbeat/sys/wineventlog/wineventlog_windows.go @@ -219,7 +219,7 @@ func RenderEvent( eventHandle EvtHandle, lang uint32, renderBuf []byte, - pubHandleProvider func(string) sys.MessageFiles, + pubHandleProvider func(string) EvtHandle, out io.Writer, ) error { providerName, err := evtRenderProviderName(renderBuf, eventHandle) @@ -227,19 +227,9 @@ func RenderEvent( return err } - var publisherHandle uintptr - if pubHandleProvider != nil { - messageFiles := pubHandleProvider(providerName) - if messageFiles.Err == nil { - // There is only ever a single handle when using the Windows Event - // Log API. - publisherHandle = messageFiles.Handles[0].Handle - } - } - // Only a single string is returned when rendering XML. err = FormatEventString(EvtFormatMessageXml, - eventHandle, providerName, EvtHandle(publisherHandle), lang, renderBuf, out) + eventHandle, providerName, pubHandleProvider(providerName), lang, renderBuf, out) // Recover by rendering the XML without the RenderingInfo (message string). if err != nil { err = RenderEventXML(eventHandle, renderBuf, out) @@ -250,22 +240,13 @@ func RenderEvent( // Message reads the event data associated with the EvtHandle and renders // and returns the message only. -func Message(h EvtHandle, renderBuf []byte, pubHandleProvider func(string) sys.MessageFiles) (message string, err error) { +func Message(h EvtHandle, renderBuf []byte, pubHandleProvider func(string) EvtHandle) (message string, err error) { providerName, err := evtRenderProviderName(renderBuf, h) if err != nil { return "", err } - var pub EvtHandle - if pubHandleProvider != nil { - messageFiles := pubHandleProvider(providerName) - if messageFiles.Err == nil { - // There is only ever a single handle when using the Windows Event - // Log API. - pub = EvtHandle(messageFiles.Handles[0].Handle) - } - } - return getMessageStringFromHandle(&PublisherMetadata{Handle: pub}, h, nil) + return getMessageStringFromHandle(&PublisherMetadata{Handle: pubHandleProvider(providerName)}, h, nil) } // RenderEventXML renders the event as XML. If the event is already rendered, as