Windows tests failing with: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified." #4076

cmacknz · 2024-01-11T20:56:49Z

Flaky Test

Test Name: TestFakeComponent, TestDiagnosticsCommand, etc.
Branch: main
Artifact Link:
- https://buildkite.com/elastic/elastic-agent/builds/6215
- https://buildkite.com/elastic/elastic-agent/builds/6233

Stack Trace

Stack trace with logs from #4088:

=== RUN   TestFakeComponent
    fixture.go:261: Extracting artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent363186115\001
    fixture.go:274: Completed extraction of artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent363186115\001
    fixture.go:880: All component specifications where removed
    fixture.go:921: Placed component specifications: fake, fake-shipper
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.207Z","log.origin":{"file.name":"cmd/run.go","file.line":170},"message":"Elastic Agent started","log":{"source":"elastic-agent"},"process.pid":6140,"agent.version":"8.13.0","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.477Z","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\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","args":["C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","watch","--path.config","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64","--path.home","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\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-16T20:53:03.484Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":133},"message":"Upgrade Watcher invoked","log":{"source":"elastic-agent"},"agent.upgrade.watcher.process.pid":5468,"agent.process.pid":6140,"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.484Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":121},"message":"releasing watcher 5468","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.484Z","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-16T20:53:03.506Z","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-16T20:53:03.535Z","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-16T20:53:03.535Z","log.origin":{"file.name":"capabilities/capabilities.go","file.line":48},"message":"Capabilities file not found in C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\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-16T20:53:03.535Z","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-16T20:53:03.845Z","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-16T20:53:03.862Z","log.logger":"control","log.origin":{"file.name":"server/server.go","file.line":88},"message":"GRPC control socket listening at npipe:///hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock","log":{"source":"elastic-agent"},"address":"npipe:///hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.868Z","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"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.879Z","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:
        	            	elastic-agent client received unexpected error: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock: The system cannot find the file specified."
        	Test:       	TestFakeComponent
--- FAIL: TestFakeComponent (27.57s)

=== RUN   TestFakeComponent
    fixture.go:261: Extracting artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent3288641072\001
    fixture.go:274: Completed extraction of artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent3288641072\001
    fixture.go:877: All component specifications where removed
    fixture.go:918: Placed component specifications: fake, fake-shipper
    fake_test.go:107: 
        	Error Trace:	C:/Users/windows/agent/testing/integration/fake_test.go:107
        	Error:      	Received unexpected error:
        	            	elastic-agent client received unexpected error: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified."
        	Test:       	TestFakeComponent
--- FAIL: TestFakeComponent (24.84s)

=== RUN   TestDiagnosticsCommand
    fixture.go:261: Extracting artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestDiagnosticsCommand1043038821\001
    fixture.go:274: Completed extraction of artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestDiagnosticsCommand1043038821\001
    fixture.go:877: All component specifications where removed
    fixture.go:918: Placed component specifications: fake, fake-shipper
    diagnostics_test.go:137: 
        	Error Trace:	C:/Users/windows/agent/testing/integration/diagnostics_test.go:137
        	Error:      	Received unexpected error:
        	            	elastic-agent client received unexpected error: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\IS0qswTSLNZkV-zZ-Z3lrqmBo8RFmedV.sock: The system cannot find the file specified."
        	Test:       	TestDiagnosticsCommand
--- FAIL: TestDiagnosticsCommand (33.80s)

The text was updated successfully, but these errors were encountered:

elasticmachine · 2024-01-11T20:56:51Z

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

cmacknz · 2024-01-16T20:12:29Z

I suspect this was introduced by #3909

cmacknz · 2024-01-16T21:40:20Z

Got some logs via #4088

=== RUN   TestFakeComponent
    fixture.go:261: Extracting artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent363186115\001
    fixture.go:274: Completed extraction of artifact elastic-agent-8.13.0-SNAPSHOT-windows-x86_64.zip to C:\Users\windows\AppData\Local\Temp\TestFakeComponent363186115\001
    fixture.go:880: All component specifications where removed
    fixture.go:921: Placed component specifications: fake, fake-shipper
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.207Z","log.origin":{"file.name":"cmd/run.go","file.line":170},"message":"Elastic Agent started","log":{"source":"elastic-agent"},"process.pid":6140,"agent.version":"8.13.0","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.477Z","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\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","args":["C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","watch","--path.config","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64","--path.home","C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\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-16T20:53:03.484Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":133},"message":"Upgrade Watcher invoked","log":{"source":"elastic-agent"},"agent.upgrade.watcher.process.pid":5468,"agent.process.pid":6140,"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.484Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":121},"message":"releasing watcher 5468","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.484Z","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-16T20:53:03.506Z","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-16T20:53:03.535Z","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-16T20:53:03.535Z","log.origin":{"file.name":"capabilities/capabilities.go","file.line":48},"message":"Capabilities file not found in C:\\Users\\windows\\AppData\\Local\\Temp\\TestFakeComponent363186115\\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-16T20:53:03.535Z","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-16T20:53:03.845Z","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-16T20:53:03.862Z","log.logger":"control","log.origin":{"file.name":"server/server.go","file.line":88},"message":"GRPC control socket listening at npipe:///hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock","log":{"source":"elastic-agent"},"address":"npipe:///hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.868Z","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"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T20:53:03.879Z","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:
        	            	elastic-agent client received unexpected error: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\hJ9D1yd8LDiUSmJucqaE1EFaSmA1yPv_.sock: The system cannot find the file specified."
        	Test:       	TestFakeComponent
--- FAIL: TestFakeComponent (27.57s)

cmacknz · 2024-01-17T02:46:06Z

Adding some more timestamps it seems like we are trying to connect to the agent before the agent control server is initialized. See the Elastic agent client connecting... log line before we even get the GRPC control socket listening at npipe:///... log line that was seen above.

 fixture.go:1034: 2024-01-16T22:16:03Z: Elastic agent client connecting...
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T22:16:10.788Z","log.origin":{"file.name":"cmd/run.go","file.line":170},"message":"Elastic Agent started","log":{"source":"elastic-agent"},"process.pid":480,"agent.version":"8.13.0","ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T22:16:11.067Z","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\\TestDiagnosticsCommand3090460263\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","args":["C:\\Users\\windows\\AppData\\Local\\Temp\\TestDiagnosticsCommand3090460263\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64\\elastic-agent.exe","watch","--path.config","C:\\Users\\windows\\AppData\\Local\\Temp\\TestDiagnosticsCommand3090460263\\001\\elastic-agent-8.13.0-SNAPSHOT-windows-x86_64","--path.home","C:\\Users\\windows\\AppData\\Local\\Temp\\TestDiagnosticsCommand3090460263\\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-16T22:16:11.077Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":133},"message":"Upgrade Watcher invoked","log":{"source":"elastic-agent"},"agent.upgrade.watcher.process.pid":2512,"agent.process.pid":480,"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T22:16:11.077Z","log.origin":{"file.name":"upgrade/rollback.go","file.line":121},"message":"releasing watcher 2512","log":{"source":"elastic-agent"},"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T22:16:11.077Z","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-16T22:16:11.086Z","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-16T22:16:11.113Z","log.origin":{"file.name":"application/application.go","file.line":68},"message":"Detected available inputs and outputs","log":{"source":"elastic-agent"},"inputs":["fake","fake-apm"],"ecs.version":"1.6.0"}
    log.go:96: {"log.level":"info","@timestamp":"2024-01-16T22:16:11.114Z","log.origin":{"file.name":"capabilities/capabilities.go","file.line":48},"message":"Capabilities file not found in C:\\Users\\windows\\AppData\\Local\\Temp\\TestDiagnosticsCommand3090460263\\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-16T22:16:11.114Z","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-16T22:16:11.643Z","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"}
    diagnostics_test.go:137: 
        	Error Trace:	C:/Users/windows/agent/testing/integration/diagnostics_test.go:137
        	Error:      	Received unexpected error:
        	            	elastic-agent client received unexpected error: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\cP7kdP45qXiD-kwBBo3EEhyW9KA8L3UC.sock: The system cannot find the file specified."
        	Test:       	TestDiagnosticsCommand
--- FAIL: TestDiagnosticsCommand (25.56s)

cmacknz · 2024-01-17T15:51:47Z

I believe I've fixed this with #4088

cmacknz · 2024-01-18T17:08:38Z

Looks like we are still marginal with the timing here, from https://buildkite.com/elastic/elastic-agent/builds/6350#018d1d51-70cf-4f56-8b11-53239e990059

=== 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)

The gRPC endpoint starts at 2024-01-18T16:30:14.118Z but we fail the test at 2024-01-18T16:30:14.1148712Z. The test ran for 28.63s which is interesting.

Ah the failing test has a 10s timeout:

elastic-agent/testing/integration/fake_test.go

Lines 60 to 61 in 0beb0c1

    
           ctx, cancel = context.WithTimeout(context.Background(), 10*time.Second) 
        
           defer cancel()

cmacknz added the Team:Elastic-Agent Label for the Agent team label Jan 11, 2024

This was referenced Jan 11, 2024

[Automation] Bump Golang version to 1.21.6 #4073

Merged

The TestFakeComponent integration test is flaky on Windows #4002

Closed

Fix integration test timeouts on Windows #3949

Merged

pierrehilbert mentioned this issue Jan 16, 2024

Move FakeInput tests into their own test suite #4079

Merged

7 tasks

cmacknz mentioned this issue Jan 16, 2024

Add retries to control server connection and ensure logs are captured on failure #4088

Merged

pierrehilbert mentioned this issue Jan 17, 2024

Fix component control protocol to allow checkin to be chunked across multiple messages #3884

Merged

6 tasks

pierrehilbert assigned belimawr Jan 17, 2024

cmacknz assigned cmacknz and unassigned belimawr Jan 17, 2024

rdner added the flaky-test Unstable or unreliable test cases. label Jan 18, 2024

cmacknz closed this as completed in #4088 Jan 18, 2024

cmacknz reopened this Jan 18, 2024

cmacknz mentioned this issue Jan 18, 2024

Increase short 10 second timeout in TestFakeComponent #4101

Merged

cmacknz closed this as completed in #4101 Jan 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Windows tests failing with: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified." #4076

Windows tests failing with: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified." #4076

cmacknz commented Jan 11, 2024 •

edited

Loading

elasticmachine commented Jan 11, 2024

cmacknz commented Jan 16, 2024

cmacknz commented Jan 16, 2024

cmacknz commented Jan 17, 2024

cmacknz commented Jan 17, 2024

cmacknz commented Jan 18, 2024

Windows tests failing with: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified." #4076

Windows tests failing with: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: open \\\\.\\pipe\\08aEXWqjpu7u7318BQm1ZyV6ip9MmEzd.sock: The system cannot find the file specified." #4076

Comments

cmacknz commented Jan 11, 2024 • edited Loading

Flaky Test

Stack Trace

elasticmachine commented Jan 11, 2024

cmacknz commented Jan 16, 2024

cmacknz commented Jan 16, 2024

cmacknz commented Jan 17, 2024

cmacknz commented Jan 17, 2024

cmacknz commented Jan 18, 2024

cmacknz commented Jan 11, 2024 •

edited

Loading