Filebeat service randomly stopping

I’m having an issue running filebeat on some Windows VM’s where the filebeat collector/sidecar randomly stops, sometimes after a couple hours, sometimes after a couple days. I can’t seem to figure out why it’s stopping so I increased log level to debug so I can gather some more details about the stoppage but I can’t decipher what is happening.

2022-07-12T16:09:27.149-0700	DEBUG	[harvester]	log/log.go:107	End of file reached: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log; Backoff now.
2022-07-12T16:09:27.903-0700	DEBUG	[service]	service/service.go:65	Received svc stop/shutdown request
2022-07-12T16:09:27.903-0700	INFO	beater/filebeat.go:515	Stopping filebeat
2022-07-12T16:09:27.903-0700	DEBUG	[publisher]	pipeline/client.go:158	client: closing acker
2022-07-12T16:09:27.903-0700	DEBUG	[publisher]	pipeline/client.go:163	client: done closing acker
2022-07-12T16:09:27.903-0700	INFO	beater/crawler.go:148	Stopping Crawler
2022-07-12T16:09:27.904-0700	INFO	beater/crawler.go:158	Stopping 2 inputs
2022-07-12T16:09:27.904-0700	DEBUG	[publisher]	pipeline/client.go:165	client: unlink from queue
2022-07-12T16:09:27.904-0700	INFO	[crawler]	beater/crawler.go:163	Stopping input: 12961389870753776509
2022-07-12T16:09:27.904-0700	INFO	[crawler]	beater/crawler.go:163	Stopping input: 10275958006650416499
2022-07-12T16:09:27.904-0700	INFO	input/input.go:136	input ticker stopped
2022-07-12T16:09:27.904-0700	INFO	input/input.go:136	input ticker stopped
2022-07-12T16:09:27.904-0700	DEBUG	[publisher]	pipeline/client.go:187	client: cancelled 0 events
2022-07-12T16:09:27.904-0700	INFO	log/harvester.go:329	Reader was closed: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log. Closing.
2022-07-12T16:09:27.904-0700	DEBUG	[publisher]	pipeline/client.go:167	client: done unlink
2022-07-12T16:09:27.905-0700	DEBUG	[publisher]	pipeline/client.go:170	client: closing processors
2022-07-12T16:09:27.905-0700	DEBUG	[harvester]	log/harvester.go:612	Stopping harvester for file: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log
2022-07-12T16:09:27.905-0700	DEBUG	[publisher]	pipeline/client.go:175	client: done closing processors
2022-07-12T16:09:27.905-0700	DEBUG	[harvester]	log/harvester.go:622	Closing file: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log
2022-07-12T16:09:27.905-0700	DEBUG	[harvester]	log/harvester.go:488	Update state: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log, offset: 4408143
2022-07-12T16:09:27.906-0700	DEBUG	[harvester]	log/harvester.go:633	harvester cleanup finished for file: C:\inetpub\logs\LogFiles\W3SVC1\u_ex22071223_x.log
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:158	client: closing acker
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:163	client: done closing acker
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:165	client: unlink from queue
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:187	client: cancelled 0 events
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:167	client: done unlink
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:170	client: closing processors
2022-07-12T16:09:27.906-0700	DEBUG	[publisher]	pipeline/client.go:175	client: done closing processors
2022-07-12T16:09:27.906-0700	INFO	beater/crawler.go:178	Crawler stopped
2022-07-12T16:09:27.906-0700	INFO	[registrar]	registrar/registrar.go:132	Stopping Registrar
2022-07-12T16:09:27.906-0700	INFO	[registrar]	registrar/registrar.go:166	Ending Registrar
2022-07-12T16:09:27.916-0700	DEBUG	[registrar]	registrar/registrar.go:167	Stopping Registrar
2022-07-12T16:09:27.916-0700	INFO	[registrar]	registrar/registrar.go:137	Registrar stopped
2022-07-12T16:09:27.921-0700	INFO	[monitoring]	log/log.go:152	Total non-zero metrics	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1966781,"time":{"ms":1966781}},"total":{"ticks":2764812,"time":{"ms":2764812},"value":2764812},"user":{"ticks":798031,"time":{"ms":798031}}},"handles":{"open":190},"info":{"ephemeral_id":"ff97be90-9c50-42a7-b4f4-68a4862d390b","uptime":{"ms":119969889}},"memstats":{"gc_next":9458608,"memory_alloc":6029200,"memory_sys":25856928,"memory_total":77213790384,"rss":42139648},"runtime":{"goroutines":15}},"filebeat":{"events":{"active":49,"added":1982148,"done":1982099},"harvester":{"closed":35,"open_files":0,"running":0,"started":35}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1981870,"active":0,"batches":13590,"total":1981870},"read":{"bytes":81540},"type":"logstash","write":{"bytes":254162631}},"pipeline":{"clients":0,"events":{"active":49,"filtered":229,"published":1981919,"retry":341,"total":1982148},"queue":{"acked":1981870}}},"registrar":{"states":{"cleanup":48,"current":98,"update":1982099},"writes":{"success":13817,"total":13817}},"system":{"cpu":{"cores":4}}}}}
2022-07-12T16:09:27.921-0700	INFO	[monitoring]	log/log.go:153	Uptime: 33h19m29.8912989s
2022-07-12T16:09:27.921-0700	INFO	[monitoring]	log/log.go:130	Stopping metrics logging.
2022-07-12T16:09:27.922-0700	INFO	instance/beat.go:474	filebeat stopped.

Interesting part is the second line, I’m not sure why it receives service shutdown request?

Received svc stop/shutdown request

could you post your filebeat configuration for the affected machine? IT looks like you have a few things going on there including metricbeat? Obfuscate where needed of course! :slight_smile:

Sure - here is my configuration for the graylog sidecar:

# Needed for Graylog
fields_under_root: true
fields.collector_node_id: ${sidecar.nodeName}
fields.gl2_source_collector: ${sidecar.nodeId}
processors:
- rate_limit:
    limit: "10000/m"
output.logstash:
   hosts: ["logstash_host_here:12505"]
path:
  data: C:\Program Files\Graylog\sidecar\cache\filebeat\data
  logs: C:\Program Files\Graylog\sidecar\logs
tags:
 - windows
filebeat.inputs:
- type: log
  enabled: true
  paths:
    - C:\inetpub\logs\LogFiles\**\*.*
- type: log
  enabled: true
  paths:
    - C:\Folder\Logs\**\startup-exceptions.log
    - C:\Folder\Logs\**\stdout_*.log
  multiline.type: pattern
  multiline.pattern: '^\[[0-9]{4}-[0-9]{2}-[0-9]{2}'
  multiline.negate: true
  multiline.match: after
logging.level: debug
logging.to_files: true
logging.files:
  path: /var/log/filebeat
  name: filebeat
  keepfiles: 7
  permissions: 0640

Hello,

Just chiming in on this issue.
Found this post

Insure the YAML file is correct

PS > .\filebeat.exe test config -c .\filebeat.yml

config file looks to be okay

C:\Program Files\Graylog\sidecar>.\filebeat.exe test config -c generated/filebeat.conf
Config OK

Ok,
Since this is Windows OS , have you check Event Viewer to see why Windows is stopping FileBeat service? OR It may show why FileBeat did stop this may help troubleshoot this issue.

Yes - I’ve scoured event log (all logs) using powershell script to find any entries related to filebeat/graylog etc.

Only thing I’ve found is logs that simply indicate the service stopped or started:

233231 Jul 12 16:09 Information Service Control Manager 1073748860 The Graylog collector sidecar - filebeat backend service entered the stopped state.                                                                                                           
232871 Jul 11 06:49 Information Service Control Manager 1073748860 The Graylog collector sidecar - filebeat backend service entered the running state.                                                                                                           
232870 Jul 11 06:49 Information Service Control Manager 1073748860 The Graylog collector sidecar - filebeat backend service entered the stopped state.                                                                                                           
231672 Jul 06 13:30 Information Service Control Manager 1073748860 The Graylog collector sidecar - filebeat backend service entered the running state.                                                                                                           
231671 Jul 06 13:30 Information Service Control Manager 1073748860 The Graylog collector sidecar - filebeat backend service entered the stopped state. 

Hello,

Ok, this is odd. Anytime something happens like shutdown a service or start it up Windows should
have logged those events in detail showing what and why that happened.

Not sure if this will help, but you can enable Debug logs. Perhaps it may show more information on why this is happing.

Example this may very on version of Windows:

Event ID 7040 - covers Service start type change (eg disabled, manual, automatic)
Event ID 7036 - covers Service start/stop

Unsure but did you check Graylog-Sidecar logs? or are those the ones above?

Sidecar Logs

C:\Program Files\Graylog\sidecar\logs\sidecar.txt

FileBeat logs

C:\filebeat\logs

Couple suggestion for troubleshooting. Sometimes it can be the smallest thing, making a big issue.

If you have other beats running on this node, and for troubleshooting purposes make sure Filebeat/GL-Sidecar is the only one running.

Insure you don’t have a port confliction, this sometimes can cause problems. For troubleshooting try changing the port used for FileBeat. (i.e. 5066,etc…)

What I dont get is you stated

BUT you have this configuration… :thinking:

I have this commented out in my Sidecar configuration. Just another troubleshooting step.

C:\Program Files\Graylog\sidecar\sidecar.yml

collector_binaries_accesslist:
 - "C:\\Program Files\\Graylog\\sidecar\\filebeat.exe"
1 Like

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