aws.ec2_metrics system test fails

[adriansr]

The system test fails with:

could not find hits in metrics-aws.ec2_metrics-ep data stream

[elasticmachine]

Pinging @elastic/integrations (Team:Integrations)

[mtojek]

Ok, so the issue occurred once again and it seems that we aren't able collect host metrics in time limit (10 minutes).

Terraform worked correctly:

�[36mterraform_1  |�[0m �[0m�[1mPlan:�[0m 1 to add, 0 to change, 0 to destroy.
�[36mterraform_1  |�[0m �[0m�[0m�[1maws_instance.i: Creating...�[0m�[0m
�[36mterraform_1  |�[0m �[0m�[1maws_instance.i: Still creating... [10s elapsed]�[0m�[0m
�[36mterraform_1  |�[0m �[0m�[1maws_instance.i: Still creating... [20s elapsed]�[0m�[0m
�[36mterraform_1  |�[0m �[0m�[1maws_instance.i: Creation complete after 24s [id=i-03d33127f3b7324e1]�[0m
�[36mterraform_1  |�[0m �[0m�[1m�[32m
�[36mterraform_1  |�[0m Apply complete! Resources: 1 added, 0 changed, 0 destroyed.
�[36mterraform_1  |�[0m �[0m+ touch /tmp/tf-applied
�[36mterraform_1  |�[0m + echo 'Terraform definitions applied.'
�[36mterraform_1  |�[0m Terraform definitions applied.
�[36mterraform_1  |�[0m + set +x

[mtojek]

It looks like the machine i-03d33127f3b7324e1 booted successfully at 03:25am and elastic-package started watching for metrics at 03:28am until 03:38am. According to CloudWatch we should see following datapoints:

Let me check what's in metricbeat logs.

[mtojek]

Metricbeat logs:

<redacted, security reasons>
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.024Z","log.logger":"esclientleg","log.origin":{"file.name":"eslegclient/connection.go","file.line":102},"message":"elasticsearch url: http://localhost:9200","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.024Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/module.go","file.line":113},"message":"Beat name: docker-fleet-agent","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.053Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":142},"message":"Starting metrics logging every 30s","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.053Z","log.origin":{"file.name":"instance/beat.go","file.line":473},"message":"metricbeat start running.","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2021-10-13T03:28:36.053Z","log.logger":"cfgwarn","log.origin":{"file.name":"management/manager.go","file.line":108},"message":"BETA: Fleet management is enabled","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.053Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":109},"message":"Starting fleet management service","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.568Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":150},"message":"Status change to Configuring: Updating configuration","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:36.569Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for metricbeat.modules","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2021-10-13T03:28:36.581Z","log.logger":"aws.ec2","log.origin":{"file.name":"aws/aws.go","file.line":101},"message":"extra charges on AWS API requests will be generated by this metricset","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.119Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for output","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.120Z","log.logger":"esclientleg","log.origin":{"file.name":"eslegclient/connection.go","file.line":102},"message":"elasticsearch url: http://elasticsearch:9200","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.120Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":213},"message":"retryer: send wait signal to consumer","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.120Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":217},"message":"  done","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.120Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":219},"message":"retryer: send unwait signal to consumer","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:28:37.120Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":223},"message":"  done","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:29:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpu":{"cfs":{"period":{"us":100000}},"id":"/"},"cpuacct":{"id":"/","total":{"ns":43913549800}},"memory":{"id":"/","mem":{"limit":{"bytes":9223372036854771712},"usage":{"bytes":614903808}}}},"cpu":{"system":{"ticks":210,"time":{"ms":214}},"total":{"ticks":610,"time":{"ms":614},"value":610},"user":{"ticks":400,"time":{"ms":400}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":17},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":30117},"version":"7.16.0"},"memstats":{"gc_next":21228288,"memory_alloc":17116264,"memory_sys":76629000,"memory_total":59106384,"rss":160022528},"runtime":{"goroutines":55}},"libbeat":{"config":{"module":{"running":1,"starts":1}},"output":{"events":{"active":0},"type":"elasticsearch"},"pipeline":{"clients":1,"events":{"active":0},"queue":{"max_events":4096}}},"system":{"cpu":{"cores":8},"load":{"1":1.64,"15":1.62,"5":2.56,"norm":{"1":0.205,"15":0.2025,"5":0.32}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:29:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4346575653}},"memory":{"mem":{"usage":{"bytes":-135168}}}},"cpu":{"system":{"ticks":220,"time":{"ms":14}},"total":{"ticks":620,"time":{"ms":22},"value":620},"user":{"ticks":400,"time":{"ms":8}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":17},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":60122},"version":"7.16.0"},"memstats":{"gc_next":21228288,"memory_alloc":17655312,"memory_total":59645432,"rss":160022528},"runtime":{"goroutines":55}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.37,"15":1.59,"5":2.39,"norm":{"1":0.1713,"15":0.1988,"5":0.2988}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:30:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4885056651}},"memory":{"mem":{"usage":{"bytes":1114112}}}},"cpu":{"system":{"ticks":320,"time":{"ms":99}},"total":{"ticks":890,"time":{"ms":265},"value":890},"user":{"ticks":570,"time":{"ms":166}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":90118},"version":"7.16.0"},"memstats":{"gc_next":21438704,"memory_alloc":17896944,"memory_total":77211648,"rss":162136064},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":2.07,"15":1.65,"5":2.48,"norm":{"1":0.2588,"15":0.2063,"5":0.31}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:30:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4249317287}},"memory":{"mem":{"usage":{"bytes":61440}}}},"cpu":{"system":{"ticks":330,"time":{"ms":7}},"total":{"ticks":910,"time":{"ms":22},"value":910},"user":{"ticks":580,"time":{"ms":15}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":120122},"version":"7.16.0"},"memstats":{"gc_next":21438704,"memory_alloc":18423680,"memory_total":77738384,"rss":162136064},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.49,"15":1.61,"5":2.29,"norm":{"1":0.1863,"15":0.2013,"5":0.2863}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:31:06.068Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4764219166}},"memory":{"mem":{"usage":{"bytes":126976}}}},"cpu":{"system":{"ticks":380,"time":{"ms":54}},"total":{"ticks":1170,"time":{"ms":265},"value":1170},"user":{"ticks":790,"time":{"ms":211}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":150116},"version":"7.16.0"},"memstats":{"gc_next":21371664,"memory_alloc":17766920,"memory_total":94997168,"rss":162009088},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.93,"15":1.64,"5":2.33,"norm":{"1":0.2413,"15":0.205,"5":0.2913}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:31:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4310204388}},"memory":{"mem":{"usage":{"bytes":-86016}}}},"cpu":{"system":{"ticks":390,"time":{"ms":11}},"total":{"ticks":1200,"time":{"ms":23},"value":1200},"user":{"ticks":810,"time":{"ms":12}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":180120},"version":"7.16.0"},"memstats":{"gc_next":21371664,"memory_alloc":18995680,"memory_total":96225928,"rss":162009088},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.39,"15":1.61,"5":2.15,"norm":{"1":0.1737,"15":0.2013,"5":0.2688}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:32:06.061Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4743773194}},"memory":{"mem":{"usage":{"bytes":-466944}}}},"cpu":{"system":{"ticks":480,"time":{"ms":90}},"total":{"ticks":1460,"time":{"ms":262},"value":1460},"user":{"ticks":980,"time":{"ms":172}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":210116},"version":"7.16.0"},"memstats":{"gc_next":21349920,"memory_alloc":18122448,"memory_total":112522504,"rss":161611776},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.11,"15":1.58,"5":2.02,"norm":{"1":0.1388,"15":0.1975,"5":0.2525}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:32:36.061Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4396666483}},"memory":{"mem":{"usage":{"bytes":19308544}}}},"cpu":{"system":{"ticks":490,"time":{"ms":5}},"total":{"ticks":1490,"time":{"ms":22},"value":1490},"user":{"ticks":1000,"time":{"ms":17}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":240121},"version":"7.16.0"},"memstats":{"gc_next":21349920,"memory_alloc":19302144,"memory_total":113702200,"rss":161611776},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.12,"15":1.56,"5":1.92,"norm":{"1":0.14,"15":0.195,"5":0.24}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:33:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4438326256}},"memory":{"mem":{"usage":{"bytes":-18710528}}}},"cpu":{"system":{"ticks":580,"time":{"ms":95}},"total":{"ticks":1720,"time":{"ms":236},"value":1720},"user":{"ticks":1140,"time":{"ms":141}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":270115},"version":"7.16.0"},"memstats":{"gc_next":20893136,"memory_alloc":18256664,"memory_total":130137672,"rss":162299904},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.04,"15":1.54,"5":1.83,"norm":{"1":0.13,"15":0.1925,"5":0.2288}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:33:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4478813976}},"memory":{"mem":{"usage":{"bytes":77824}}}},"cpu":{"system":{"ticks":590,"time":{"ms":11}},"total":{"ticks":1740,"time":{"ms":27},"value":1740},"user":{"ticks":1150,"time":{"ms":16}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":300119},"version":"7.16.0"},"memstats":{"gc_next":20893136,"memory_alloc":19295128,"memory_total":131176136,"rss":162299904},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.87,"15":1.52,"5":1.72,"norm":{"1":0.1088,"15":0.19,"5":0.215}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:34:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4455601236}},"memory":{"mem":{"usage":{"bytes":438272}}}},"cpu":{"system":{"ticks":660,"time":{"ms":64}},"total":{"ticks":1970,"time":{"ms":225},"value":1970},"user":{"ticks":1310,"time":{"ms":161}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":11},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":330120},"version":"7.16.0"},"memstats":{"gc_next":21685168,"memory_alloc":18700224,"memory_total":148226552,"rss":163037184},"runtime":{"goroutines":43}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.02,"15":1.52,"5":1.69,"norm":{"1":0.1275,"15":0.19,"5":0.2113}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:34:36.061Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4336866457}},"memory":{"mem":{"usage":{"bytes":36864}}}},"cpu":{"system":{"ticks":670,"time":{"ms":9}},"total":{"ticks":2000,"time":{"ms":23},"value":2000},"user":{"ticks":1330,"time":{"ms":14}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":11},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":360116},"version":"7.16.0"},"memstats":{"gc_next":21685168,"memory_alloc":18947808,"memory_total":148474136,"rss":163037184},"runtime":{"goroutines":43}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.85,"15":1.49,"5":1.59,"norm":{"1":0.1063,"15":0.1863,"5":0.1988}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:35:06.059Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4474583653}},"memory":{"mem":{"usage":{"bytes":-299008}}}},"cpu":{"system":{"ticks":720,"time":{"ms":54}},"total":{"ticks":2250,"time":{"ms":258},"value":2250},"user":{"ticks":1530,"time":{"ms":204}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":390117},"version":"7.16.0"},"memstats":{"gc_next":21160576,"memory_alloc":17922392,"memory_total":166101440,"rss":162746368},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.18,"15":1.49,"5":1.6,"norm":{"1":0.1475,"15":0.1863,"5":0.2}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:35:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4391309092}}},"cpu":{"system":{"ticks":730,"time":{"ms":8}},"total":{"ticks":2280,"time":{"ms":24},"value":2280},"user":{"ticks":1550,"time":{"ms":16}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":420119},"version":"7.16.0"},"memstats":{"gc_next":21160576,"memory_alloc":18766208,"memory_total":166945256,"rss":162746368},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.77,"15":1.45,"5":1.46,"norm":{"1":0.0963,"15":0.1813,"5":0.1825}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:36:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4600047537}},"memory":{"mem":{"usage":{"bytes":-20480}}}},"cpu":{"system":{"ticks":800,"time":{"ms":70}},"total":{"ticks":2540,"time":{"ms":267},"value":2540},"user":{"ticks":1740,"time":{"ms":197}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":450119},"version":"7.16.0"},"memstats":{"gc_next":21040576,"memory_alloc":18437664,"memory_total":184378664,"rss":162369536},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.77,"15":1.43,"5":1.4,"norm":{"1":0.0963,"15":0.1788,"5":0.175}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:36:36.068Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4188888861}},"memory":{"mem":{"usage":{"bytes":118784}}}},"cpu":{"system":{"ticks":810,"time":{"ms":8}},"total":{"ticks":2560,"time":{"ms":18},"value":2560},"user":{"ticks":1750,"time":{"ms":10}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":480128},"version":"7.16.0"},"memstats":{"gc_next":21040576,"memory_alloc":19312232,"memory_total":185253232,"rss":162615296},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.53,"15":1.39,"5":1.28,"norm":{"1":0.0663,"15":0.1737,"5":0.16}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:37:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4547512686}},"memory":{"mem":{"usage":{"bytes":-20480}}}},"cpu":{"system":{"ticks":880,"time":{"ms":71}},"total":{"ticks":2810,"time":{"ms":244},"value":2810},"user":{"ticks":1930,"time":{"ms":173}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":510119},"version":"7.16.0"},"memstats":{"gc_next":21203488,"memory_alloc":18596320,"memory_total":202038720,"rss":162713600},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.28,"15":1.43,"5":1.41,"norm":{"1":0.16,"15":0.1788,"5":0.1763}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:37:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4221098997}},"memory":{"mem":{"usage":{"bytes":376832}}}},"cpu":{"system":{"ticks":890,"time":{"ms":11}},"total":{"ticks":2830,"time":{"ms":20},"value":2830},"user":{"ticks":1940,"time":{"ms":9}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":540115},"version":"7.16.0"},"memstats":{"gc_next":21203488,"memory_alloc":19017808,"memory_total":202460208,"rss":162713600},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.05,"15":1.4,"5":1.34,"norm":{"1":0.1313,"15":0.175,"5":0.1675}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:38:06.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4636806633}},"memory":{"mem":{"usage":{"bytes":-487424}}}},"cpu":{"system":{"ticks":950,"time":{"ms":57}},"total":{"ticks":3080,"time":{"ms":250},"value":3080},"user":{"ticks":2130,"time":{"ms":193}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":570116},"version":"7.16.0"},"memstats":{"gc_next":21368608,"memory_alloc":18267984,"memory_total":219321040,"rss":162496512},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":1.1,"15":1.4,"5":1.33,"norm":{"1":0.1375,"15":0.175,"5":0.1663}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:38:36.060Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"metricbeat","monitoring":{"metrics":{"beat":{"cgroup":{"cpuacct":{"total":{"ns":4381163787}},"memory":{"mem":{"usage":{"bytes":831488}}}},"cpu":{"system":{"ticks":960,"time":{"ms":12}},"total":{"ticks":3100,"time":{"ms":25},"value":3100},"user":{"ticks":2140,"time":{"ms":13}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":15},"info":{"ephemeral_id":"43c8ed7d-add7-4fe0-9472-386e9fc33c67","uptime":{"ms":600118},"version":"7.16.0"},"memstats":{"gc_next":21368608,"memory_alloc":19219784,"memory_total":220272840,"rss":162762752},"runtime":{"goroutines":51}},"libbeat":{"config":{"module":{"running":1}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":0.84,"15":1.37,"5":1.25,"norm":{"1":0.105,"15":0.1713,"5":0.1563}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.346Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for metricbeat.modules","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.350Z","log.logger":"system.fsstat","log.origin":{"file.name":"fsstat/fsstat.go","file.line":57},"message":"Ignoring filesystem types: %ssysfs, tmpfs, bdev, proc, cgroup, cgroup2, cpuset, devtmpfs, configfs, debugfs, tracefs, securityfs, sockfs, bpf, pipefs, ramfs, hugetlbfs, devpts, ecryptfs, fuse, fusectl, efivarfs, mqueue, pstore, autofs, binfmt_misc, overlay","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.351Z","log.origin":{"file.name":"filesystem/filesystem.go","file.line":57},"message":"Ignoring filesystem types: sysfs, tmpfs, bdev, proc, cgroup, cgroup2, cpuset, devtmpfs, configfs, debugfs, tracefs, securityfs, sockfs, bpf, pipefs, ramfs, hugetlbfs, devpts, ecryptfs, fuse, fusectl, efivarfs, mqueue, pstore, autofs, binfmt_misc, overlay","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.352Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":271},"message":"Applying settings for output","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.353Z","log.logger":"esclientleg","log.origin":{"file.name":"eslegclient/connection.go","file.line":102},"message":"elasticsearch url: http://elasticsearch:9200","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.353Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":213},"message":"retryer: send wait signal to consumer","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.354Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":217},"message":"  done","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.354Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":219},"message":"retryer: send unwait signal to consumer","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.354Z","log.logger":"publisher","log.origin":{"file.name":"pipeline/retry.go","file.line":223},"message":"  done","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.811Z","log.logger":"centralmgmt","log.origin":{"file.name":"cfgfile/list.go","file.line":129},"message":"Stopping 11 runners ...","service.name":"metricbeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2021-10-13T03:38:44.811Z","log.logger":"centralmgmt.fleet","log.origin":{"file.name":"management/manager.go","file.line":128},"message":"Stopping fleet management service","service.name":"metricbeat","ecs.version":"1.6.0"}

I'm afraid there is nothing in them.

Hey @kaiyan-sheng , do you know if there is any trick to check if Metricbeat has called AWS API except for enabling debug mode (probably it's something we have to do)?

I can assume that this is happening, because metrics delivery is delayed by at least 10 minutes. Does it look to you as possible root cause?

[kaiyan-sheng]

I agree with your assumption and actually this happens quite often. We added a latency config option to deal with that in Beats and this is also migrated into aws package. Can we set this parameter in the system test?

[mtojek]

This is one part of the story. We need to introduce also a customizable timeout in the elastic-package. Right now, this is constant value = 10 minutes (will open an issue for this).

EDIT:

created: elastic/elastic-package#540

[mtojek]

I deployed the fix (custom timeout for wait-for-data), but it's still failing for some cases:

Even with increased timeout to 20min, metricbeat didn't receive any metrics here: https://beats-ci.elastic.co/blue/organizations/jenkins/Ingest-manager%2Felastic-package/detail/master/240/pipeline

@kaiyan-sheng could you please elaborate on how the "latency" option may help here? Is it designed to overcome exactly such issues? I can see metrics on the CloudWatch graph. What is the recommended value in this case?

I can also see that the "period" var is set to 60s.