Winlogbeat 5.0.0 stops sending data to Logstash (EOF)

Elastic Stack Beats
1

Winlogbeat stops sending data to logstash 5 or 2.4, I have been been able to reproduce this consistently and haven't ruled out user error.

What I have done is the following:
write an event log every 2 minutes using powershell:
while($true){sleep 120; eventcreate /ID 1 /L APPLICATION /T INFORMATION /SO MYEVENTSOURCE /D "Dude"}

Then start up winlogbeat in debug mode here is my yaml file:

winlogbeat.event_logs:

  • name: Application
    ignore_older: 24h
  • name: Security
    ignore_older: 24h
  • name: System
    ignore_older: 24h
    output.logstash:
    enabled: true
    hosts: ["logstash.local:50001"]
    worker: 3
    pipelining: 4
    index: 'logstash'
    logging.level: debug
    logging.metrics.enabled: true
    logging.metrics.period: 30s
    logging.to_files: true
    logging.files:
    name: winlogbeat
    rotateeverybytes: 10485760 # = 10MB
    keepfiles: 7

Here is debug logs but when it works, when it fails it fails silently, when winlogbeat is working this is what the generate a log message and the debug would output

2016-11-03T09:25:17-06:00 DBG EventLog[System] Read() returned 0 records
2016-11-03T09:25:17-06:00 DBG WinEventLog[Application] EventHandles returned 1 handles
2016-11-03T09:25:17-06:00 DBG messageFilesCache[Application] size=1
2016-11-03T09:25:17-06:00 DBG WinEventLog[Application] XML=1400x8000000000000078309Applicationwin7-testDudeDudeInformationInfoClassic Event={Provider:{Name:MYEVENTSOURCE GUID: EventSourceName:} EventIdentifier:{Qualifiers:0 ID:1} Version:0 LevelRaw:4 TaskRaw:0 OpcodeRaw:0 TimeCreated:{SystemTime:2016-11-03 15:25:17 +0000 UTC} RecordID:78309 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel:Application Computer:win7-test User:SID Identifier[S-1-5-21-2615742154-2476360751-2198875621-1000] Name[admin] Domain[WIN7-TEST] Type[User] EventData:{Pairs:[{Key:Data Value:Dude}]} UserData:{Name:{Space: Local:} Pairs:} Message:Dude Level:Information Task: Opcode:Info Keywords:[Classic] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}
2016-11-03T09:25:17-06:00 DBG WinEventLog[Application] Read() is returning 1 records
2016-11-03T09:25:17-06:00 DBG EventLog[Application] Read() returned 1 records
2016-11-03T09:25:17-06:00 DBG Publish: {
"@timestamp": "2016-11-03T15:25:17.000Z",
"beat": {
"hostname": "win7-test",
"name": "win7-test",
"version": "5.0.0"
},
"computer_name": "win7-test",
"event_data": {
"param1": "Dude"
},
"event_id": 1,
"keywords": [
"Classic"
],
"level": "Information",
"log_name": "Application",
"message": "Dude",
"opcode": "Info",
"record_number": "78309",
"source_name": "MYEVENTSOURCE",
"type": "wineventlog",
"user": {
"domain": "WIN7-TEST",
"identifier": "S-1-5-21-2615742154-2476360751-2198875621-1000",
"name": "admin",
"type": "User"
}
}
2016-11-03T09:25:17-06:00 DBG output worker: publish 1 events
2016-11-03T09:25:17-06:00 DBG forwards msg with attempts=-1
2016-11-03T09:25:17-06:00 DBG message forwarded
2016-11-03T09:25:17-06:00 DBG events from worker worker queue
2016-11-03T09:25:17-06:00 DBG Try to publish 1 events to logstash with window size 10
2016-11-03T09:25:17-06:00 DBG 1 events out of 1 events sent to logstash. Continue sending
2016-11-03T09:25:17-06:00 DBG handleResults
2016-11-03T09:25:17-06:00 DBG async bulk publish success
2016-11-03T09:25:17-06:00 INFO EventLog[Application] Successfully published 1 events
2016-11-03T09:25:17-06:00 DBG WinEventLog[Application] No more events
2016-11-03T09:25:17-06:00 DBG EventLog[Application] Read() returned 0 records
2016-11-03T09:25:18-06:00 DBG WinEventLog[Security] No more events
2016-11-03T09:25:18-06:00 DBG EventLog[Security] Read() returned 0 records

I would include the logstash stuff but it doesn't get there. I can restart winlogbeat and everything flows and then after a bit of time it stop.
Does anyone else experience this. Is it my user error. Is there a way for winlogbeat to restart itself if things start to fail?
Bueller .... bueller

2

It's good that you are running with debug enabled. Another useful insight would be to add -httpprof localhost:6060. Then capture the metrics from http://localhost:6060/debug/vars and share that data. How long does it take for this problem to occur? Can you provide the complete log?

Can you attempt to reproduce this problem using the file output and not the Logstash output.

What OS version is this?

Tip: if you surround your config posting with three backticks they will be formatted correctly.

3

I have uploaded the debug log and the debug vars from the last fail. It took 25 minutes before winlogbeat stopped sending data. I am running this on windows7 however we have in our enviroment windows server 2008 and 2012

debug_vars.txt

complete log
winlogbeat.log

4

I removed these 2 items and things are working, Were going to put in on one of our DC's and see what happens.

5

There seems to be some issues with Logstash, but no events should be lost but some could be duplicated (at-least-once guarantees). From looking at the log, a few times while it was sending to LS it encountered an EOF and had to resend the event(s).

6

Moved logstash to 5.0 for just the winlogbeat piece going into our ES cluster. Upgraded cluster from 2.4.0 -> 2.4.1 we'll be moving it to 5.0 next week.

Looks like in the end for some reason pipelining was the issue. Remove that and no timeouts, go figure.

7

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.