Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Increase short 10 second timeout in TestFakeComponent #4101

Merged
merged 3 commits into from
Jan 18, 2024

Conversation

cmacknz
Copy link
Member

@cmacknz cmacknz commented Jan 18, 2024

The TestFakeComponent test had a short 10 second context timeout, which is shorter than the retry interval of when waiting for the control socket. This is causing the test to continue to be flaky because it isn't allowing the control socket and agent enough time to start on Windows.

Fixes the failure below, where we start polling for the control socket at 2024-01-18T16:30:05.0297061 but the first agent logs have timestamp 2024-01-18T16:30:13.362Z 8 seconds later.

=== RUN   TestFakeComponent
    fixture.go:262: Extracting artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent2648583623\001
    fixture.go:275: Completed extraction of artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent2648583623\001
    fixture.go:884: All component specifications where removed
    fixture.go:925: Placed component specifications: fake, fake-shipper
    fixture.go:1058: 2024-01-18T16:30:05.0297061Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 532.40549ms
    fixture.go:1058: 2024-01-18T16:30:05.565829Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 1.094082138s
    fixture.go:1058: 2024-01-18T16:30:06.6621144Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 1.633534321s
    fixture.go:1058: 2024-01-18T16:30:08.3044546Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 2.035781094s
    fixture.go:1058: 2024-01-18T16:30:10.3555798Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 1.512547881s
    fixture.go:1058: 2024-01-18T16:30:11.8729448Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 2.240724656s
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.362Z","log.origin":{"file.name":"cmd/run.go","file.line":170},"message":"Elastic Agent started","log":{"source":"elastic-agent"},"process.pid":1720,"agent.version":"8.13.0","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.654Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":126},"message":"Starting upgrade watcher","log":{"source":"elastic-agent"},"path":"C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent2648583623\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","args":["C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent2648583623\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","watch","--path.config","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent2648583623\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64","--path.home","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent2648583623\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64"],"env":[],"dir":"","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.666Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":133},"message":"Upgrade Watcher invoked","log":{"source":"elastic-agent"},"agent.upgrade.watcher.process.pid":3436,"agent.process.pid":1720,"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.666Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":121},"message":"releasing watcher 3436","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.666Z","log.origin":{"file.name":"cmd/run.go","file.line":259},"message":"APM instrumentation disabled","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.692Z","log.origin":{"file.name":"application/application.go","file.line":62},"message":"Gathered system information","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.726Z","log.origin":{"file.name":"application/application.go","file.line":68},"message":"Detected available inputs and outputs","log":{"source":"elastic-agent"},"inputs":["fake-apm","fake"],"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.726Z","log.origin":{"file.name":"capabilities/capabilities.go","file.line":48},"message":"Capabilities file not found in C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent2648583623\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\capabilities.yml","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:13.726Z","log.origin":{"file.name":"application/application.go","file.line":74},"message":"Determined allowed capabilities","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:14.072Z","log.origin":{"file.name":"application/application.go","file.line":131},"message":"Elastic Agent has been started in testing mode and is managed through the control protocol","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:14.095Z","log.logger":"control","log.origin":{"file.name":"server/server.go","file.line":88},"message":"GRPC control socket listening at npipe:///N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock","log":{"source":"elastic-agent"},"address":"npipe:///N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:14.097Z","log.logger":"composable.providers.docker","log.origin":{"file.name":"docker/docker.go","file.line":44},"message":"Docker provider skipped, unable to connect: protocol not available","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    fixture.go:1058: 2024-01-18T16:30:14.1148712Z: StateWatch failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\N9Y9ahnCHPpDNZod7ZjMEtiWhV1Jg_v7.sock: The system cannot find the file specified." retrying: 2.490751082s
    log.go:96: {"log.level":"info","@timestamp":"2024-01-18T16:30:14.118Z","log.origin":{"file.name":"runtime/manager.go","file.line":209},"message":"Starting grpc control protocol listener on port 6789 with max_message_size 104857600","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    fake_test.go:107: 
        	Error Trace:	C:/Users/windows/agent/testing/integration/fake_test.go:107
        	Error:      	Received unexpected error:
        	            	context deadline exceeded
        	Test:       	TestFakeComponent
--- FAIL: TestFakeComponent (28.63s)

@cmacknz cmacknz added the Team:Elastic-Agent Label for the Agent team label Jan 18, 2024
@cmacknz cmacknz self-assigned this Jan 18, 2024
@cmacknz cmacknz requested a review from a team as a code owner January 18, 2024 17:20
@cmacknz cmacknz requested review from AndersonQ and pchila January 18, 2024 17:20
@elasticmachine
Copy link
Contributor

Pinging @elastic/elastic-agent (Team:Elastic-Agent)

@cmacknz cmacknz added skip-changelog backport-v8.12.0 Automated backport with mergify labels Jan 18, 2024
@@ -57,9 +57,6 @@ func TestFakeComponent(t *testing.T) {
err = f.Prepare(ctx, fakeComponent, fakeShipper)
require.NoError(t, err)

ctx, cancel = context.WithTimeout(context.Background(), 10*time.Second)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is another context with timeout just above this one:

ctx, cancel := testcontext.WithDeadline(t, context.Background(), time.Now().Add(10*time.Minute))
	defer cancel()

@cmacknz cmacknz requested a review from blakerouse January 18, 2024 17:21
Copy link
Contributor

@blakerouse blakerouse left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good.

@cmacknz
Copy link
Member Author

cmacknz commented Jan 18, 2024

buildkite test it

Copy link

Quality Gate passed Quality Gate passed

Kudos, no new issues were introduced!

0 New issues
0 Security Hotspots
No Coverage information No data about Coverage
No Duplication information No data about Duplication

See analysis details on SonarQube

@cmacknz cmacknz merged commit a79407e into elastic:main Jan 18, 2024
9 of 12 checks passed
@cmacknz cmacknz deleted the adjust-test-timeouts-for-retries branch January 18, 2024 19:44
mergify bot pushed a commit that referenced this pull request Jan 18, 2024
* Remove duplicated short timeout.

* Log when statewatch starts.

* Lower initial retry interval.

(cherry picked from commit a79407e)
cmacknz added a commit that referenced this pull request Jan 18, 2024
* Remove duplicated short timeout.

* Log when statewatch starts.

* Lower initial retry interval.

(cherry picked from commit a79407e)

Co-authored-by: Craig MacKenzie <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport-v8.12.0 Automated backport with mergify skip-changelog Team:Elastic-Agent Label for the Agent team
Projects
None yet
3 participants