aws / aws/amazon-cloudwatch-agent-test

Collectd tests fail due to a connection refused

Open
#211 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Go
Stars
22
Forks
45
Avg merge
2d 21h
Merged PRs (30d)
10

Description

# Description of the issue
* Collectd tests are currently failing with the following error:
```
2023/05/07 06:10:11 CollectD test group failed due to: %!w(*fmt.wrapError=&{Failed to complete setup after agent run due to: write udp 127.0.0.1:44705->127.0.0.1:25826: write: connection refused 0xc00026f400})
```
* Example: https://github.com/aws/amazon-cloudwatch-agent/actions/runs/4833290668/jobs/8613380241
* The issue seems to have started since https://github.com/aws/amazon-cloudwatch-agent-test/pull/165/files#diff-781bb3810ede78771b4deb63bb6bb797a2d06434f0d844429b5ad16a20304e0fR56-R88 was merged.

# Analysis
* Adding a small sleep after the first flush seemingly fixes the issue but root cause analysis to understand why the [first flush call](https://github.com/sky333999/amazon-cloudwatch-agent-test/blob/f36ca319f7683c8a41a2451a5c053d44d33ade3b/internal/common/metrics.go#L88) does not receive a connection refused but the [subsequent one](https://github.com/sky333999/amazon-cloudwatch-agent-test/blob/f36ca319f7683c8a41a2451a5c053d44d33ade3b/internal/common/metrics.go#L125) does is pending. See https://github.com/aws/amazon-cloudwatch-agent-test/pull/210 for the change.
* I also added additional logging to print the {status of the agent & the agent logs} once before the initial flush & again before the subsequent flush.
```
=== RUN TestMetricValueBenchmarkSuite
>>>> Starting MetricBenchmarkTestSuite
=== RUN TestMetricValueBenchmarkSuite/TestAllInSuite
2023/05/07 06:10:10 Executing subset of plugin tests: [collectd]
2023/05/07 06:10:10 Running CollectD
2023/05/07 06:10:10 Starting agent using agent config file agent_configs/collectd_config.json
2023/05/07 06:10:10 Copy File agent_configs/collectd_config.json to /opt/aws/amazon-cloudwatch-agent/bin/config.json
2023/05/07 06:10:10 File agent_configs/collectd_config.json abs path /home/ec2-user/amazon-cloudwatch-agent-test/test/metric_value_benchmark/agent_configs/collectd_config.json
2023/05/07 06:10:10 File : agent_configs/collectd_config.json copied to : /opt/aws/amazon-cloudwatch-agent/bin/config.json
2023/05/07 06:10:10 Agent has started
/////////////////////////////////////////////////////////////////////////
2023/05/07 06:10:10 First flush
2023/05/07 06:10:10 Agent status:{
"status": "running",
"starttime": "2023-05-07T06:10:09+0000",
"configstatus": "configured",
"cwoc_status": "stopped",
"cwoc_starttime": "",
"cwoc_configstatus": "not configured",
"version": "1.247354.0b251981"
}
May 07 06:10:10 ip-172-31-29-254.ec2.internal systemd[1]: Started Amazon CloudWatch Agent.
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: /opt/aws/amazon-cloudwatch-agent/etc/amazon-cloudwatch-agent.json does not exist or cannot read. Skipping it.
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: I! Detecting run_as_user...
/////////////////////////////////////////////////////////////////////////
2023/05/07 06:10:10 Next flush
2023/05/07 06:10:11 Collectd here8. write udp 127.0.0.1:44705->127.0.0.1:25826: write: connection refused
2023/05/07 06:10:11 Agent status:{
"status": "running",
"starttime": "2023-05-07T06:10:09+0000",
"configstatus": "configured",
"cwoc_status": "stopped",
"cwoc_starttime": "",
"cwoc_configstatus": "not configured",
"version": "1.247354.0b251981"
}
May 07 06:10:10 ip-172-31-29-254.ec2.internal systemd[1]: Started Amazon CloudWatch Agent.
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: /opt/aws/amazon-cloudwatch-agent/etc/amazon-cloudwatch-agent.json does not exist or cannot read. Skipping it.
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: I! Detecting run_as_user...
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! CWAGENT_LOG_LEVEL is set to "DEBUG"
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Starting AmazonCloudWatchAgent 1.247354.0b251981
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! AWS SDK log level not set
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Loaded inputs: socket_listener
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Loaded aggregators:
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Loaded processors: ec2tagger
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Loaded outputs: cloudwatch
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! Tags enabled: host=ip-172-31-29-254.ec2.internal
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [agent] Config: Interval:15s, Quiet:false, Hostname:"ip-172-31-29-254.ec2.internal", Flush Interval:1s
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! [agent] Initializing plugins
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [processors.ec2tagger] ec2tagger: Check ec2 metadata
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [logagent] starting
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [processors.ec2tagger] ec2tagger: EC2 tagger has started, finished initial retrieval of tags and Volumes
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [processors.ec2tagger] ec2tagger: Check ec2 metadata
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [processors.ec2tagger] ec2tagger: EC2 tagger has started, finished initial retrieval of tags and Volumes
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! [agent] Connecting outputs
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! [agent] Attempting connection to [outputs.cloudwatch]
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! Successfully created credential sessions
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! cloudwatch: get unique roll up list []
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! [agent] Successfully connected to outputs.cloudwatch
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z D! [agent] Starting service inputs
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! [inputs.socket_listener] Listening on udp://127.0.0.1:25826
May 07 06:10:10 ip-172-31-29-254.ec2.internal start-amazon-cloudwatch-agent[25301]: 2023-05-07T06:10:10Z I! cloudwatch: publish with ForceFlushInterval: 5s, Publish Jitter: 3s
2023/05/07 06:10:11 CollectD test group failed due to: %!w(*fmt.wrapError=&{Failed to complete setup after agent run due to: write udp 127.0.0.1:44705->127.0.0.1:25826: write: connection refused 0xc00026f400})
metrics_value_benchmark_test.go:103:
Error Trace: /home/ec2-user/amazon-cloudwatch-agent-test/test/metric_value_benchmark/metrics_value_benchmark_test.go:103
Error: Not equal:
expected: "Successful"
actual : "Failed"

Diff:
--- Expected
+++ Actual
@@ -1,2 +1,2 @@
-(status.TestStatus) (len=10) "Successful"
+(status.TestStatus) (len=6) "Failed"

Test: TestMetricValueBenchmarkSuite/TestAllInSuite
Messages: Metric Benchmark Test Suite Failed
2023/05/07 06:10:11 >>>>>>>>>>>>>><<<<<<<<<<<<<<
2023/05/07 06:10:11 >>>>>>>>>>>>>>Failed<<<<<<<<<<<<<<
2023/05/07 06:10:11 ==============CollectD==============
2023/05/07 06:10:11 ==============Failed==============
Starting Agent Failed
2023/05/07 06:10:11 ==============================
2023/05/07 06:10:11 >>>>>>>>>>>>>>><<<<<<<<<<<<<<<
>>>> Finished MetricBenchmarkTestSuite
--- FAIL: TestMetricValueBenchmarkSuite (1.32s)
--- FAIL: TestMetricValueBenchmarkSuite/TestAllInSuite (1.32s)
FAIL
FAIL github.com/aws/amazon-cloudwatch-agent-test/test/metric_value_benchmark 1.330s
FAIL
```
* As can be seen in the logs above, the agent says its in a running status in both cases but two things stand out:
1. For the initial flush, the agent logs indicate it was still at a very initial stage before any of the plugins were even initialized - so assuming the agent wasnt listening on the udp port yet, why did the flush not fail?
2. For the subsequent flush, the agent logs indicate it was listening on the udp port - so why did the flush fail this time with a connection refused?

Contributor guide

Open the contributing guide

Research direction

Start with internal/common/metrics.go and test/metric_value_benchmark/metrics_value_benchmark_test.go, then inspect agent_configs/collectd_config.json and the captured agent logs. Run TestMetricValueBenchmarkSuite/TestAllInSuite to compare the first and subsequent flushes; done means the connection-refused cause is identified and the CollectD test passes reliably.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.