Beats (metricbeat and filebeat) does't start as windows service

Harpello · April 20, 2020, 1:59pm

Behavior:
Behaviors for filebeat and metricbeat are exactly the same.
Windows services filebeat and metricbeat does not start automatic after reboot.
Manual start of service failes with error '1053: The service did not respond to the start or control request in a timely fashion' after 30 seconds

Environment:
Using metricbeat and filebeat to monitor IIS loggings
Windows Server 2019 (build 1809) (german version, i don't think this matters)
Filebeat and Metricbeat 7.6.2 installed with provided msi installer
Activated modules filebeat: IIS
Activated modules metricbeat: windows, system

Diagnostics:
Starting filebeat manual on powershell window console works fine
Increase starttimeout for windows services to 60 seconds does not help
Configure service with delayed autostart doesn't help
Manually install service with provides powershell scripts doesn't help
Try another windows server doesn't help
I noticed service starting errors with my first tries on fileversion 7.4.1

Workarround:
Start service again after it fails with error 1053
--> service starts service successful in less than 3 seconds
During the next minute filebeatservice can be started and stopped without problems
After some time starting of filebeat service failed again with error 1053
This is a strange behavior and does not solve the problem of starting service after windows reboot

Deeper Diagnostics:
Monitoring the starting process with procmon (https://docs.microsoft.com/de-de/sysinternals/downloads/procmon)
shows that service stucks after 2 seconds, and does nothing till,
starttimeout after 30 seconds ends the process
C:\ProgramData\Elastic\Beats\filebeat\data is not created or accessed
C:\ProgramData\Elastic\Beats\filebeat\logs\ is not created or accessed
So there is no logging for failed start. Loggins is written, if service starts successful.

Any idea to get rid of the starting problem of beat windows services?
Thanks for your support

MarianaD · April 21, 2020, 12:02pm

hi @Harpello, a few questions here:

when starting the filebeat service manually and succeeds, do you see any data and logs created after? Does it stop randomly or this is only after the reboot?
how do the config files look like?
for the metricbeat service can you just enable the windows module and let us know if that worked? Just checking to see if the system module could be an issue

Harpello · April 22, 2020, 9:25am

Hi @MarianaD,
thank you for your answer.

When I start filebeat service and it succeeds, it runs perfect over days and is only stopped in case of rebooting computer or manually stopping service. Logging can only accessed after
stopping service, because logfile is still opened from filebeat.exe and has filezize 0.

Configfile is mostly unchanged default shipped, only fields for setup.kibana.host and
output.elasticsearch.host are changed.

As you told me, I tried start of metricbeat with disabled system module. This has no effects of starting behavior.

Please have a look on attached logfiles from procmon.
In case of successful servicestart filebeat.yml is accessed on 11:33:33.1136235 This is less than 1 second after service start.

In case of failed servicestart filebeat.yml is never accessed. The process hangs from 11:08:41 to 11:09:01 and does nothing. Afterwards is process shutwown because of timeout.

It seems to be an issue of starting or running main service thread before configfiles are read.

If you are interested, i can provide full logfiles. For now I don'r know how to upload logfiles to ticket.

I hope my analysis can help.

warkolm · April 22, 2020, 10:33am

Please don't post pictures of text/logs/config, they are difficult to read, impossible to search and some people may not be even able to see them

Harpello · April 22, 2020, 7:20pm

sorry for posting pictures, i didn't understand how to format them.
Here is the Logging from filebeat after successful start:

2020-04-19T10:59:57.939+0200	INFO	instance/beat.go:622	Home path: [C:\Program Files\Elastic\Beats\7.6.2\filebeat] Config path: [C:\ProgramData\Elastic\Beats\filebeat] Data path: [C:\ProgramData\Elastic\Beats\filebeat\data] Logs path: [C:\ProgramData\Elastic\Beats\filebeat\logs]
2020-04-19T10:59:57.974+0200	INFO	instance/beat.go:630	Beat ID: 5ee2d815-5322-4100-b302-591a17c86a48
2020-04-19T10:59:57.984+0200	INFO	[beat]	instance/beat.go:958	Beat info	{"system_info": {"beat": {"path": {"config": "C:\\ProgramData\\Elastic\\Beats\\filebeat", "data": "C:\\ProgramData\\Elastic\\Beats\\filebeat\\data", "home": "C:\\Program Files\\Elastic\\Beats\\7.6.2\\filebeat", "logs": "C:\\ProgramData\\Elastic\\Beats\\filebeat\\logs"}, "type": "filebeat", "uuid": "5ee2d815-5322-4100-b302-591a17c86a48"}}}
2020-04-19T10:59:57.985+0200	INFO	[beat]	instance/beat.go:967	Build info	{"system_info": {"build": {"commit": "d57bcf8684602e15000d65b75afcd110e2b12b59", "libbeat": "7.6.2", "time": "2020-03-26T05:23:36.000Z", "version": "7.6.2"}}}
2020-04-19T10:59:57.985+0200	INFO	[beat]	instance/beat.go:970	Go runtime info	{"system_info": {"go": {"os":"windows","arch":"amd64","max_procs":8,"version":"go1.13.8"}}}
2020-04-19T10:59:57.985+0200	INFO	add_cloud_metadata/add_cloud_metadata.go:89	add_cloud_metadata: hosting provider type not detected.
2020-04-19T10:59:57.991+0200	INFO	[beat]	instance/beat.go:974	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2020-04-16T00:48:33.51+02:00","name":"IW-LIVE-01","ip":["192.168.40.205/21","172.16.17.201/16","::1/128","127.0.0.1/8"],"kernel_version":"10.0.17763.1158 (WinBuild.160101.0800)","mac":["00:15:5d:28:65:07","00:15:5d:28:65:08"],"os":{"family":"windows","platform":"windows","name":"Windows Server 2019 Standard","version":"10.0","major":10,"minor":0,"patch":0,"build":"17763.1158"},"timezone":"CEST","timezone_offset_sec":7200,"id":"a2f16018-ab2d-4ad5-b3ac-9e5fa6f11dd9"}}}
2020-04-19T10:59:57.993+0200	INFO	[beat]	instance/beat.go:1003	Process info	{"system_info": {"process": {"cwd": "C:\\Windows\\system32", "exe": "C:\\Program Files\\Elastic\\Beats\\7.6.2\\filebeat\\filebeat.exe", "name": "filebeat.exe", "pid": 4516, "ppid": 800, "start_time": "2020-04-19T10:59:52.894+0200"}}}
2020-04-19T10:59:57.993+0200	INFO	instance/beat.go:298	Setup Beat: filebeat; Version: 7.6.2
2020-04-19T10:59:57.994+0200	INFO	[index-management]	idxmgmt/std.go:182	Set output.elasticsearch.index to 'filebeat-7.6.2' as ILM is enabled.
2020-04-19T10:59:57.994+0200	INFO	elasticsearch/client.go:174	Elasticsearch url: http://iw-elastic-01:9290
2020-04-19T10:59:57.994+0200	INFO	[publisher]	pipeline/module.go:110	Beat name: IW-LIVE-01
2020-04-19T10:59:57.998+0200	INFO	instance/beat.go:439	filebeat start running.
2020-04-19T10:59:57.998+0200	INFO	[monitoring]	log/log.go:118	Starting metrics logging every 30s
2020-04-19T10:59:57.999+0200	INFO	registrar/registrar.go:145	Loading registrar data from C:\ProgramData\Elastic\Beats\filebeat\data\registry\filebeat\data.json
2020-04-19T10:59:58.001+0200	INFO	registrar/registrar.go:152	States Loaded from registrar: 407
2020-04-19T10:59:58.001+0200	INFO	crawler/crawler.go:72	Loading Inputs: 1
2020-04-19T11:00:01.250+0200	INFO	log/input.go:152	Configured paths: [C:\inetpub\logs\LogFiles\*\*.log]
2020-04-19T11:00:01.251+0200	INFO	log/input.go:152	Configured paths: [c:\Windows\System32\LogFiles\HTTPERR\*.log]
2020-04-19T11:00:01.251+0200	INFO	crawler/crawler.go:106	Loading and starting Inputs completed. Enabled inputs: 0
2020-04-19T11:00:01.251+0200	INFO	cfgfile/reload.go:175	Config reloader started
2020-04-19T11:00:04.499+0200	INFO	log/input.go:152	Configured paths: [C:\inetpub\logs\LogFiles\*\*.log]
2020-04-19T11:00:04.500+0200	INFO	log/input.go:152	Configured paths: [c:\Windows\System32\LogFiles\HTTPERR\*.log]
2020-04-19T11:00:04.500+0200	INFO	elasticsearch/client.go:174	Elasticsearch url: http://iw-elastic-01:9290
2020-04-19T11:00:04.509+0200	INFO	elasticsearch/client.go:757	Attempting to connect to Elasticsearch version 7.6.2
2020-04-19T11:00:04.531+0200	INFO	[license]	licenser/es_callback.go:50	Elasticsearch license: Basic
2020-04-19T11:00:04.537+0200	INFO	input/input.go:114	Starting input of type: log; ID: 14001612453279639696 
2020-04-19T11:00:04.537+0200	INFO	input/input.go:114	Starting input of type: log; ID: 14018380790357231115 
2020-04-19T11:00:04.537+0200	INFO	cfgfile/reload.go:235	Loading of config files completed.
2020-04-19T11:00:04.597+0200	INFO	log/harvester.go:297	Harvester started for file: C:\inetpub\logs\LogFiles\W3SVC3\u_ex200419.log
2020-04-19T11:00:05.612+0200	INFO	pipeline/output.go:95	Connecting to backoff(elasticsearch(http://iw-elastic-01:9290))
2020-04-19T11:00:05.615+0200	INFO	elasticsearch/client.go:757	Attempting to connect to Elasticsearch version 7.6.2
2020-04-19T11:00:05.633+0200	INFO	[license]	licenser/es_callback.go:50	Elasticsearch license: Basic
2020-04-19T11:00:05.652+0200	INFO	[index-management]	idxmgmt/std.go:258	Auto ILM enable success.
2020-04-19T11:00:05.653+0200	INFO	[index-management.ilm]	ilm/std.go:139	do not generate ilm policy: exists=true, overwrite=false
2020-04-19T11:00:05.653+0200	INFO	[index-management]	idxmgmt/std.go:271	ILM policy successfully loaded.
2020-04-19T11:00:05.653+0200	INFO	[index-management]	idxmgmt/std.go:410	Set setup.template.name to '{filebeat-7.6.2 {now/d}-000001}' as ILM is enabled.
2020-04-19T11:00:05.653+0200	INFO	[index-management]	idxmgmt/std.go:415	Set setup.template.pattern to 'filebeat-7.6.2-*' as ILM is enabled.
2020-04-19T11:00:05.653+0200	INFO	[index-management]	idxmgmt/std.go:449	Set settings.index.lifecycle.rollover_alias in template to {filebeat-7.6.2 {now/d}-000001} as ILM is enabled.
2020-04-19T11:00:05.653+0200	INFO	[index-management]	idxmgmt/std.go:453	Set settings.index.lifecycle.name in template to {filebeat {"policy":{"phases":{"hot":{"actions":{"rollover":{"max_age":"30d","max_size":"50gb"}}}}}}} as ILM is enabled.
2020-04-19T11:00:05.656+0200	INFO	template/load.go:89	Template filebeat-7.6.2 already exists and will not be overwritten.
2020-04-19T11:00:05.656+0200	INFO	[index-management]	idxmgmt/std.go:295	Loaded index template.
2020-04-19T11:00:05.657+0200	INFO	[index-management]	idxmgmt/std.go:306	Write alias successfully generated.
2020-04-19T11:00:05.660+0200	INFO	pipeline/output.go:105	Connection to backoff(elasticsearch(http://iw-elastic-01:9290)) established
2020-04-19T11:00:27.999+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2828,"time":{"ms":2828}},"total":{"ticks":3687,"time":{"ms":3687},"value":3687},"user":{"ticks":859,"time":{"ms":859}}},"handles":{"open":310},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":35089}},"memstats":{"gc_next":11953072,"memory_alloc":9243680,"memory_total":133469296,"rss":42442752},"runtime":{"goroutines":50}},"filebeat":{"events":{"added":821,"done":821},"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":{"last_event_published_time":"2020-04-19T11:00:04.598Z","last_event_timestamp":"2020-04-19T11:00:04.598Z","name":"C:\\inetpub\\logs\\LogFiles\\W3SVC3\\u_ex200419.log","read_offset":396087,"size":396087,"start_time":"2020-04-19T11:00:04.597Z"}},"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0},"reloads":1,"scans":1},"output":{"events":{"acked":6,"batches":1,"total":6},"read":{"bytes":6075},"type":"elasticsearch","write":{"bytes":7598}},"pipeline":{"clients":4,"events":{"active":0,"filtered":815,"published":6,"retry":6,"total":821},"queue":{"acked":6}}},"registrar":{"states":{"current":407,"update":821},"writes":{"success":816,"total":816}},"system":{"cpu":{"cores":8}}}}}
2020-04-19T11:00:58.000+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":3187,"time":{"ms":359}},"total":{"ticks":4124,"time":{"ms":437},"value":4124},"user":{"ticks":937,"time":{"ms":78}}},"handles":{"open":310},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":65090}},"memstats":{"gc_next":11965568,"memory_alloc":9143304,"memory_total":138474672,"rss":397312},"runtime":{"goroutines":50}},"filebeat":{"events":{"added":6,"done":6},"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":{"last_event_published_time":"2020-04-19T11:00:39.649Z","last_event_timestamp":"2020-04-19T11:00:39.649Z","read_offset":732}},"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":6,"batches":1,"total":6},"read":{"bytes":390},"write":{"bytes":6002}},"pipeline":{"clients":4,"events":{"active":0,"published":6,"total":6},"queue":{"acked":6}}},"registrar":{"states":{"current":407,"update":6},"writes":{"success":1,"total":1}}}}}
2020-04-19T11:01:28.001+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":3562,"time":{"ms":375}},"total":{"ticks":4530,"time":{"ms":406},"value":4530},"user":{"ticks":968,"time":{"ms":31}}},"handles":{"open":310},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":95090}},"memstats":{"gc_next":11760992,"memory_alloc":8582752,"memory_total":143113736,"rss":73728},"runtime":{"goroutines":50}},"filebeat":{"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":{"size":732}},"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":4,"events":{"active":0}}},"registrar":{"states":{"current":407}}}}}
2020-04-19T11:01:58.000+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":3968,"time":{"ms":406}},"total":{"ticks":4936,"time":{"ms":406},"value":4936},"user":{"ticks":968}},"handles":{"open":312},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":125089}},"memstats":{"gc_next":12142880,"memory_alloc":9044272,"memory_total":148455176,"rss":196608},"runtime":{"goroutines":50}},"filebeat":{"events":{"added":6,"done":6},"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":{"last_event_published_time":"2020-04-19T11:01:44.741Z","last_event_timestamp":"2020-04-19T11:01:44.741Z","read_offset":732}},"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":6,"batches":1,"total":6},"read":{"bytes":392},"write":{"bytes":6002}},"pipeline":{"clients":4,"events":{"active":0,"published":6,"total":6},"queue":{"acked":6}}},"registrar":{"states":{"current":407,"update":6},"writes":{"success":1,"total":1}}}}}
2020-04-19T11:02:28.002+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4281,"time":{"ms":313}},"total":{"ticks":5312,"time":{"ms":376},"value":5312},"user":{"ticks":1031,"time":{"ms":63}}},"handles":{"open":312},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":155090}},"memstats":{"gc_next":11677504,"memory_alloc":8286880,"memory_total":153022960,"rss":-253952},"runtime":{"goroutines":50}},"filebeat":{"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":{"size":732}},"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":4,"events":{"active":0}}},"registrar":{"states":{"current":407}}}}}
2020-04-19T11:02:58.002+0200	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4656,"time":{"ms":375}},"total":{"ticks":5734,"time":{"ms":422},"value":5734},"user":{"ticks":1078,"time":{"ms":47}}},"handles":{"open":313},"info":{"ephemeral_id":"5a9eaf8b-707d-49bd-95bf-15a3039654a5","uptime":{"ms":185089}},"memstats":{"gc_next":11640656,"memory_alloc":8812696,"memory_total":158401328,"rss":-163840},"runtime":{"goroutines":50}},"filebeat":{"events":{"added":6,"done":6},"harvester":{"files":{"e3497f40-44ac-4ff1-9fa3-25b333c50189":

system · May 20, 2020, 9:31pm

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