Metricbeat Windows fails to start on reboot - timeout

Elastic Stack Beats
1

We are running Windows Server 2012 R2 running Metricbeat 5.3.1 and have even tried 5.4.0. I am able to start up the service manually via services manager (services.msc). I have the service set to automatic start but for some reason it is not starting automatically. I read some other articles about by using -process metricset it might cause issues so I tried to comment it out. No change. I turned on debug in the config but since the service doesn't start up there is no info that I can see related to the failed start.
I found the following error in eventview logs -

A timeout was reached (30000 milliseconds) while waiting for the metricbeat service to connect.
The metricbeat service failed to start due to the following error:
The service did not respond to the start or control request in a timely fashion.

here is our config. And we are outputting to Redis

metricbeat.modules:

#------------------------------- System Module -------------------------------

  • module: system
    metricsets:

    CPU stats

    • cpu

    System Load stats

    #- load

    Per CPU core stats

    #- core

    IO stats

    #- diskio

    Per filesystem stats

    #- filesystem

    File system summary stats

    #- fsstat

    Memory stats

    • memory

    Network stats

    #- network

    Per process stats

    • process

    Sockets (linux only)

    #- socket
    enabled: true
    period: 5m
    processes: ['w3wp']

2

Could you share the log output of filebeat?

3

Here are two logs that were generated after turning on debug. I turned on debugging and restarted service for it to take effect. Then I rebooted the box and then since the service was not started (and therefore no logging) I started the service to get the second section. Below is the log from prior to reboot I will post another with after reboot with manual service starting

2017-05-09T09:33:30-04:00 DBG Disable stderr logging
2017-05-09T09:33:30-04:00 INFO Home path: [C:\Program Files\metricbeat] Config path: [C:\Program Files\metricbeat] Data path: [C:\ProgramData\metricbeat] Logs path: [C:\Program Files\metricbeat\logs]
2017-05-09T09:33:30-04:00 INFO Setup Beat: metricbeat; Version: 5.3.1
2017-05-09T09:33:30-04:00 DBG Processors:
2017-05-09T09:33:30-04:00 DBG Initializing output plugins
2017-05-09T09:33:30-04:00 INFO Max Retries set to: 3
2017-05-09T09:33:30-04:00 INFO Activated redis as output plugin.
2017-05-09T09:33:30-04:00 DBG Create output worker
2017-05-09T09:33:30-04:00 DBG No output is defined to store the topology. The server fields might not be filled.
2017-05-09T09:33:30-04:00 INFO Publisher name: dcmipavqtb008
2017-05-09T09:33:30-04:00 INFO Flush Interval set to: 1s
2017-05-09T09:33:30-04:00 INFO Max Bulk Size set to: 2048
2017-05-09T09:33:30-04:00 DBG create bulk processing worker (interval=1s, bulk size=2048)
2017-05-09T09:33:30-04:00 INFO Register [ModuleFactory:[docker, mongodb, mysql, postgresql, system], MetricSetFactory:[apache/status, ceph/cluster_disk, ceph/cluster_health, ceph/monitor_health, ceph/pool_disk, couchbase/bucket, couchbase/cluster, couchbase/node, docker/container, docker/cpu, docker/diskio, docker/healthcheck, docker/image, docker/info, docker/memory, docker/network, haproxy/info, haproxy/stat, kafka/consumergroup, kafka/partition, mongodb/dbstats, mongodb/status, mysql/status, nginx/stubstatus, php_fpm/pool, postgresql/activity, postgresql/bgwriter, postgresql/database, prometheus/collector, prometheus/stats, redis/info, redis/keyspace, system/core, system/cpu, system/diskio, system/filesystem, system/fsstat, system/memory, system/network, system/process, zookeeper/mntr]]
2017-05-09T09:33:30-04:00 INFO Metricbeat process and system info: {"OSVersion":{"Major":6,"Minor":2,"Build":9200},"Arch":"amd64","NumCPU":4,"User":{"SID":"S-1-5-18","Account":"SYSTEM","Domain":"NT AUTHORITY","Type":1},"ProcessPrivs":{"SeAssignPrimaryTokenPrivilege":{"enabled":false},"SeAuditPrivilege":{"enabled_by_default":true,"enabled":true},"SeBackupPrivilege":{"enabled":false},"SeChangeNotifyPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreateGlobalPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreatePagefilePrivilege":{"enabled_by_default":true,"enabled":true},"SeCreatePermanentPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreateSymbolicLinkPrivilege":{"enabled_by_default":true,"enabled":true},"SeDebugPrivilege":{"enabled_by_default":true,"enabled":true},"SeImpersonatePrivilege":{"enabled_by_default":true,"enabled":true},"SeIncreaseBasePriorityPrivilege":{"enabled_by_default":true,"enabled":true},"SeIncreaseQuotaPrivilege":{"enabled":false},"SeIncreaseWorkingSetPrivilege":{"enabled_by_default":true,"enabled":true},"SeLoadDriverPrivilege":{"enabled":false},"SeLockMemoryPrivilege":{"enabled_by_default":true,"enabled":true},"SeManageVolumePrivilege":{"enabled":false},"SeProfileSingleProcessPrivilege":{"enabled_by_default":true,"enabled":true},"SeRestorePrivilege":{"enabled":false},"SeSecurityPrivilege":{"enabled":false},"SeShutdownPrivilege":{"enabled":false},"SeSystemEnvironmentPrivilege":{"enabled":false},"SeSystemProfilePrivilege":{"enabled_by_default":true,"enabled":true},"SeSystemtimePrivilege":{"enabled":false},"SeTakeOwnershipPrivilege":{"enabled":false},"SeTcbPrivilege":{"enabled_by_default":true,"enabled":true},"SeTimeZonePrivilege":{"enabled_by_default":true,"enabled":true},"SeUndockPrivilege":{"enabled":false}}}
2017-05-09T09:33:30-04:00 INFO SeDebugPrivilege is enabled. SeDebugPrivilege=(Default, Enabled)
2017-05-09T09:33:30-04:00 DBG mb.NewModules() is returning map[{name:"system", config:{Module:"system", MetricSets:[cpu memory process], Enabled:true, Hosts:[0 hosts], Period:"5m0s", Timeout:"5m0s", Raw:false, Fields:null, FieldsUnderRoot:false, Tags:[]}}:[{name:"cpu", module:"system", hostData:{SanitizedURI:"", Host:""}} {name:"memory", module:"system", hostData:{SanitizedURI:"", Host:""}} {name:"process", module:"system", hostData:{SanitizedURI:"", Host:""}}]]
2017-05-09T09:33:30-04:00 DBG Initializing Module type 'system': *system.Module={name:"system", config:{Module:"system", MetricSets:[cpu memory process], Enabled:true, Hosts:[0 hosts], Period:"5m0s", Timeout:"5m0s", Raw:false, Fields:null, FieldsUnderRoot:false, Tags:[]}}
2017-05-09T09:33:30-04:00 DBG Processors:
2017-05-09T09:33:30-04:00 DBG Initializing MetricSet type 'system/cpu' for host '': *cpu.MetricSet={name:"cpu", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:33:30-04:00 DBG Initializing MetricSet type 'system/memory' for host '': *memory.MetricSet={name:"memory", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:33:30-04:00 DBG Initializing MetricSet type 'system/process' for host '': *process.MetricSet={name:"process", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:33:30-04:00 INFO metricbeat start running.
2017-05-09T09:33:30-04:00 DBG Starting Wrapper[name=system, len(metricSetWrappers)=3]
2017-05-09T09:33:30-04:00 DBG Stopped Wrapper[name=system, len(metricSetWrappers)=3]
2017-05-09T09:33:30-04:00 DBG Starting metricSetWrapper[module=system, name=cpu, host=]
2017-05-09T09:33:30-04:00 DBG Starting metricSetWrapper[module=system, name=memory, host=]
2017-05-09T09:33:30-04:00 DBG Starting metricSetWrapper[module=system, name=process, host=]
2017-05-09T09:33:30-04:00 DBG Windows is interactive: false

4

2017-05-09T09:35:52-04:00 DBG Disable stderr logging
2017-05-09T09:35:52-04:00 INFO Home path: [C:\Program Files\metricbeat] Config path: [C:\Program Files\metricbeat] Data path: [C:\ProgramData\metricbeat] Logs path: [C:\Program Files\metricbeat\logs]
2017-05-09T09:35:52-04:00 INFO Setup Beat: metricbeat; Version: 5.3.1
2017-05-09T09:35:52-04:00 DBG Processors:
2017-05-09T09:35:52-04:00 DBG Initializing output plugins
2017-05-09T09:35:52-04:00 INFO Max Retries set to: 3
2017-05-09T09:35:52-04:00 INFO Activated redis as output plugin.
2017-05-09T09:35:52-04:00 DBG Create output worker
2017-05-09T09:35:52-04:00 DBG No output is defined to store the topology. The server fields might not be filled.
2017-05-09T09:35:52-04:00 INFO Publisher name: dcmipavqtb008
2017-05-09T09:35:52-04:00 INFO Flush Interval set to: 1s
2017-05-09T09:35:52-04:00 INFO Max Bulk Size set to: 2048
2017-05-09T09:35:52-04:00 DBG create bulk processing worker (interval=1s, bulk size=2048)
2017-05-09T09:35:52-04:00 INFO Register [ModuleFactory:[docker, mongodb, mysql, postgresql, system], MetricSetFactory:[apache/status, ceph/cluster_disk, ceph/cluster_health, ceph/monitor_health, ceph/pool_disk, couchbase/bucket, couchbase/cluster, couchbase/node, docker/container, docker/cpu, docker/diskio, docker/healthcheck, docker/image, docker/info, docker/memory, docker/network, haproxy/info, haproxy/stat, kafka/consumergroup, kafka/partition, mongodb/dbstats, mongodb/status, mysql/status, nginx/stubstatus, php_fpm/pool, postgresql/activity, postgresql/bgwriter, postgresql/database, prometheus/collector, prometheus/stats, redis/info, redis/keyspace, system/core, system/cpu, system/diskio, system/filesystem, system/fsstat, system/memory, system/network, system/process, zookeeper/mntr]]
2017-05-09T09:35:52-04:00 INFO Metricbeat process and system info: {"OSVersion":{"Major":6,"Minor":2,"Build":9200},"Arch":"amd64","NumCPU":4,"User":{"SID":"S-1-5-18","Account":"SYSTEM","Domain":"NT AUTHORITY","Type":1},"ProcessPrivs":{"SeAssignPrimaryTokenPrivilege":{"enabled":false},"SeAuditPrivilege":{"enabled_by_default":true,"enabled":true},"SeBackupPrivilege":{"enabled":false},"SeChangeNotifyPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreateGlobalPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreatePagefilePrivilege":{"enabled_by_default":true,"enabled":true},"SeCreatePermanentPrivilege":{"enabled_by_default":true,"enabled":true},"SeCreateSymbolicLinkPrivilege":{"enabled_by_default":true,"enabled":true},"SeDebugPrivilege":{"enabled_by_default":true,"enabled":true},"SeImpersonatePrivilege":{"enabled_by_default":true,"enabled":true},"SeIncreaseBasePriorityPrivilege":{"enabled_by_default":true,"enabled":true},"SeIncreaseQuotaPrivilege":{"enabled":false},"SeIncreaseWorkingSetPrivilege":{"enabled_by_default":true,"enabled":true},"SeLoadDriverPrivilege":{"enabled":false},"SeLockMemoryPrivilege":{"enabled_by_default":true,"enabled":true},"SeManageVolumePrivilege":{"enabled":false},"SeProfileSingleProcessPrivilege":{"enabled_by_default":true,"enabled":true},"SeRestorePrivilege":{"enabled":false},"SeSecurityPrivilege":{"enabled":false},"SeShutdownPrivilege":{"enabled":false},"SeSystemEnvironmentPrivilege":{"enabled":false},"SeSystemProfilePrivilege":{"enabled_by_default":true,"enabled":true},"SeSystemtimePrivilege":{"enabled":false},"SeTakeOwnershipPrivilege":{"enabled":false},"SeTcbPrivilege":{"enabled_by_default":true,"enabled":true},"SeTimeZonePrivilege":{"enabled_by_default":true,"enabled":true},"SeUndockPrivilege":{"enabled":false}}}
2017-05-09T09:35:52-04:00 INFO SeDebugPrivilege is enabled. SeDebugPrivilege=(Default, Enabled)
2017-05-09T09:35:52-04:00 DBG mb.NewModules() is returning map[{name:"system", config:{Module:"system", MetricSets:[cpu memory process], Enabled:true, Hosts:[0 hosts], Period:"5m0s", Timeout:"5m0s", Raw:false, Fields:null, FieldsUnderRoot:false, Tags:[]}}:[{name:"cpu", module:"system", hostData:{SanitizedURI:"", Host:""}} {name:"memory", module:"system", hostData:{SanitizedURI:"", Host:""}} {name:"process", module:"system", hostData:{SanitizedURI:"", Host:""}}]]
2017-05-09T09:35:52-04:00 DBG Initializing Module type 'system': *system.Module={name:"system", config:{Module:"system", MetricSets:[cpu memory process], Enabled:true, Hosts:[0 hosts], Period:"5m0s", Timeout:"5m0s", Raw:false, Fields:null, FieldsUnderRoot:false, Tags:[]}}
2017-05-09T09:35:52-04:00 DBG Processors:
2017-05-09T09:35:52-04:00 DBG Initializing MetricSet type 'system/cpu' for host '': *cpu.MetricSet={name:"cpu", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:35:52-04:00 DBG Initializing MetricSet type 'system/memory' for host '': *memory.MetricSet={name:"memory", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:35:52-04:00 DBG Initializing MetricSet type 'system/process' for host '': *process.MetricSet={name:"process", module:"system", hostData:{SanitizedURI:"", Host:""}}
2017-05-09T09:35:52-04:00 INFO metricbeat start running.
2017-05-09T09:35:52-04:00 DBG Starting Wrapper[name=system, len(metricSetWrappers)=3]
2017-05-09T09:35:52-04:00 DBG Stopped Wrapper[name=system, len(metricSetWrappers)=3]
2017-05-09T09:35:52-04:00 DBG Starting metricSetWrapper[module=system, name=cpu, host=]
2017-05-09T09:35:52-04:00 DBG Windows is interactive: false
2017-05-09T09:35:52-04:00 DBG Starting metricSetWrapper[module=system, name=process, host=]
2017-05-09T09:35:52-04:00 DBG Starting metricSetWrapper[module=system, name=memory, host=]
.................
2017-05-09T09:35:52-04:00 DBG Skip process pid=0: error getting process state for pid=0: getProcName failed: OpenProcess failed for pid=0: The parameter is incorrect.; getProcStatus failed: OpenProcess failed for pid=0: The parameter is incorrect.; getParentPid failed: OpenProcess failed for pid=0: The parameter is incorrect.; getProcCredName failed: OpenProcess failed for pid=0: The parameter is incorrect.
2017-05-09T09:35:52-04:00 DBG Skip process pid=4: error getting process state for pid=4: getProcName failed: GetProcessImageFileName failed for pid=4: GetProcessImageFileName failed: invalid argument; getProcCredName failed: OpenProcess failed for pid=4: Access is denied.
2017-05-09T09:35:52-04:00 DBG Skip process pid=240: error getting process state for pid=240: getProcCredName failed: OpenProcess failed for pid=240: Access is denied.
2017-05-09T09:35:52-04:00 DBG Skip process pid=392: error getting process state for pid=392: getProcCredName failed: OpenProcess failed for pid=392: Access is denied...............
2017-05-09T09:35:52-04:00 DBG Skip process pid=4648: error getting process state for pid=4648: getProcCredName failed: OpenProcess failed for pid=4648: Access is denied.

5

Also I wanted to mention that filebeat works fine on these same boxes. And it is affecting all servers the same. We are running as 'Local System'. We installed using metricbeats PS installation scripts.

6

I tried reproducing this on my machine which is Windows 2012 R2 with Metricbeat 5.4.0. I used the same system module config as you. I did several rounds of this

PS > Start-Service metricbeat
PS > Stop-Service metricbeat

and didn't get any timeout errors. Is this consistently reproducible on your end?

7

Hello,

Yes this occurs on all 30 boxes that we have metricbeat installed on.
Again it is just when windows starts up that it occurs. If I start the
service manually it works. Also as a work around I created a task
scheduler job with 'on startup' as criteria that calls a batch script with
just 'net start metricbeat'. I added a 1 minute delay on when to run.
This will start up the metricbeat service successfully on reboot.

8

I'm seeing this issue too, I upgraded from 5.1.0 to 5.4.0 and now on reboot metricbeat fails to start. I enabled debug logging however nothing is logged at all. It seems it's probably starting too soon and requires some dependency service to be started first.

As a workaround I've changed metricbeat to be Automatic Delayed Start.

9

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