Skip to content

test flake: TestAgentStats #9105

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.

Sign up for GitHub

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

Jump to bottom
Closed
johnstcn opened this issue Aug 15, 2023 · 2 comments · Fixed by #9465
Closed

test flake: TestAgentStats #9105

johnstcn opened this issue Aug 15, 2023 · 2 comments · Fixed by #9465
Assignees
@johnstcn
Labels
s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks

Comments

@johnstcn
Copy link
Member

Seen here: https://github.com/coder/coder/actions/runs/5865237892/job/15901814232

Relevant excerpt:

2023-08-15T08:41:07.9174591Z     t.go:85: 2023-08-15 08:40:14.373 [debu]  read stats report  request_id=df4a2f52-2d3e-42e2-bee6-e368293de12f  interval=5m0s  workspace_agent_id=7804b8b1-e4a4-4ac5-9606-4f22e5730769  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc  payload={"connections_by_proto":{"TCP":1},"connection_count":7,"connection_median_latency_ms":8000,"rx_packets":0,"rx_bytes":2,"tx_packets":0,"tx_bytes":1,"session_count_vscode":3,"session_count_jetbrains":4,"session_count_reconnecting_pty":5,"session_count_ssh":6,"metrics":null}
2023-08-15T08:41:07.9175423Z     t.go:85: 2023-08-15 08:40:14.446 [debu]  activity_bump: bumped deadline from activity  request_id=df4a2f52-2d3e-42e2-bee6-e368293de12f  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc
2023-08-15T08:41:07.9176214Z     t.go:85: 2023-08-15 08:40:14.471 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=112.639486ms  status_code=200  latency_ms=112  request_id=df4a2f52-2d3e-42e2-bee6-e368293de12f
2023-08-15T08:41:07.9177515Z     t.go:85: 2023-08-15 08:40:14.509 [debu]  read stats report  request_id=90ffedc8-354e-41ce-9a1e-b987f6af2b1b  interval=5m0s  workspace_agent_id=6fcc9420-153d-4465-ba76-8eec460d15f1  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac  payload={"connections_by_proto":{"TCP":1},"connection_count":8,"connection_median_latency_ms":10000,"rx_packets":0,"rx_bytes":4,"tx_packets":0,"tx_bytes":2,"session_count_vscode":6,"session_count_jetbrains":8,"session_count_reconnecting_pty":10,"session_count_ssh":12,"metrics":null}
2023-08-15T08:41:07.9178389Z     t.go:85: 2023-08-15 08:40:14.536 [debu]  activity_bump: bumped deadline from activity  request_id=90ffedc8-354e-41ce-9a1e-b987f6af2b1b  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac
2023-08-15T08:41:07.9179151Z     t.go:85: 2023-08-15 08:40:14.541 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=69.593232ms  status_code=200  latency_ms=69  request_id=90ffedc8-354e-41ce-9a1e-b987f6af2b1b
2023-08-15T08:41:07.9180409Z     t.go:85: 2023-08-15 08:40:14.553 [debu]  read stats report  request_id=cd30a872-65d7-4eaf-8a3f-0aef75f8832f  interval=5m0s  workspace_agent_id=1de64d4f-2a05-449b-b9ee-67e7d09967ad  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf  payload={"connections_by_proto":{"TCP":1},"connection_count":9,"connection_median_latency_ms":12000,"rx_packets":0,"rx_bytes":6,"tx_packets":0,"tx_bytes":3,"session_count_vscode":12,"session_count_jetbrains":14,"session_count_reconnecting_pty":16,"session_count_ssh":18,"metrics":null}
2023-08-15T08:41:07.9181317Z     t.go:85: 2023-08-15 08:40:14.564 [debu]  activity_bump: bumped deadline from activity  request_id=cd30a872-65d7-4eaf-8a3f-0aef75f8832f  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf
2023-08-15T08:41:07.9182059Z     t.go:85: 2023-08-15 08:40:14.573 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=32.244629ms  status_code=200  latency_ms=32  request_id=cd30a872-65d7-4eaf-8a3f-0aef75f8832f
2023-08-15T08:41:07.9183333Z     t.go:85: 2023-08-15 08:40:14.583 [debu]  read stats report  request_id=3c61c16a-93db-4aa0-ac1d-6a0f6e31c8a1  interval=5m0s  workspace_agent_id=7804b8b1-e4a4-4ac5-9606-4f22e5730769  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc  payload={"connections_by_proto":{"TCP":1},"connection_count":8,"connection_median_latency_ms":8000,"rx_packets":0,"rx_bytes":3,"tx_packets":0,"tx_bytes":2,"session_count_vscode":4,"session_count_jetbrains":5,"session_count_reconnecting_pty":6,"session_count_ssh":7,"metrics":null}
2023-08-15T08:41:07.9184169Z     t.go:85: 2023-08-15 08:40:14.600 [debu]  activity_bump: bumped deadline from activity  request_id=3c61c16a-93db-4aa0-ac1d-6a0f6e31c8a1  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc
2023-08-15T08:41:07.9184905Z     t.go:85: 2023-08-15 08:40:14.605 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=31.20304ms  status_code=200  latency_ms=31  request_id=3c61c16a-93db-4aa0-ac1d-6a0f6e31c8a1
2023-08-15T08:41:07.9186175Z     t.go:85: 2023-08-15 08:40:14.619 [debu]  read stats report  request_id=c8d6d363-c53a-421b-9240-97dc7fa75943  interval=5m0s  workspace_agent_id=6fcc9420-153d-4465-ba76-8eec460d15f1  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac  payload={"connections_by_proto":{"TCP":1},"connection_count":9,"connection_median_latency_ms":10000,"rx_packets":0,"rx_bytes":5,"tx_packets":0,"tx_bytes":3,"session_count_vscode":7,"session_count_jetbrains":9,"session_count_reconnecting_pty":11,"session_count_ssh":13,"metrics":null}
2023-08-15T08:41:07.9186999Z     t.go:85: 2023-08-15 08:40:14.625 [debu]  activity_bump: bumped deadline from activity  request_id=c8d6d363-c53a-421b-9240-97dc7fa75943  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac
2023-08-15T08:41:07.9187848Z     t.go:85: 2023-08-15 08:40:14.627 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=22.36924ms  status_code=200  latency_ms=22  request_id=c8d6d363-c53a-421b-9240-97dc7fa75943
2023-08-15T08:41:07.9189193Z     t.go:85: 2023-08-15 08:40:14.634 [debu]  read stats report  request_id=8252bc6a-6e30-4a2c-acfc-3e21a7148fdf  interval=5m0s  workspace_agent_id=1de64d4f-2a05-449b-b9ee-67e7d09967ad  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf  payload={"connections_by_proto":{"TCP":1},"connection_count":10,"connection_median_latency_ms":12000,"rx_packets":0,"rx_bytes":7,"tx_packets":0,"tx_bytes":4,"session_count_vscode":13,"session_count_jetbrains":15,"session_count_reconnecting_pty":17,"session_count_ssh":19,"metrics":null}
2023-08-15T08:41:07.9190056Z     t.go:85: 2023-08-15 08:40:14.646 [debu]  activity_bump: bumped deadline from activity  request_id=8252bc6a-6e30-4a2c-acfc-3e21a7148fdf  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf
2023-08-15T08:41:07.9190814Z     t.go:85: 2023-08-15 08:40:14.647 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=19.327856ms  status_code=200  latency_ms=19  request_id=8252bc6a-6e30-4a2c-acfc-3e21a7148fdf
2023-08-15T08:41:07.9192045Z     t.go:85: 2023-08-15 08:40:14.661 [debu]  read stats report  request_id=51920ba1-2876-46a1-a659-732c21b962f3  interval=5m0s  workspace_agent_id=7804b8b1-e4a4-4ac5-9606-4f22e5730769  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc  payload={"connections_by_proto":{"TCP":1},"connection_count":9,"connection_median_latency_ms":8000,"rx_packets":0,"rx_bytes":4,"tx_packets":0,"tx_bytes":3,"session_count_vscode":5,"session_count_jetbrains":6,"session_count_reconnecting_pty":7,"session_count_ssh":8,"metrics":null}
2023-08-15T08:41:07.9192951Z     t.go:85: 2023-08-15 08:40:14.663 [debu]  activity_bump: bumped deadline from activity  request_id=51920ba1-2876-46a1-a659-732c21b962f3  workspace_id=d3093ff2-06b0-4de1-a5cf-b0daf6c45bcc
2023-08-15T08:41:07.9193671Z     t.go:85: 2023-08-15 08:40:14.664 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=16.628788ms  status_code=200  latency_ms=16  request_id=51920ba1-2876-46a1-a659-732c21b962f3
2023-08-15T08:41:07.9194902Z     t.go:85: 2023-08-15 08:40:14.669 [debu]  read stats report  request_id=43927a78-72a5-474d-bee6-9457847f0d7e  interval=5m0s  workspace_agent_id=6fcc9420-153d-4465-ba76-8eec460d15f1  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac  payload={"connections_by_proto":{"TCP":1},"connection_count":10,"connection_median_latency_ms":10000,"rx_packets":0,"rx_bytes":6,"tx_packets":0,"tx_bytes":4,"session_count_vscode":8,"session_count_jetbrains":10,"session_count_reconnecting_pty":12,"session_count_ssh":14,"metrics":null}
2023-08-15T08:41:07.9195749Z     t.go:85: 2023-08-15 08:40:14.689 [debu]  activity_bump: bumped deadline from activity  request_id=43927a78-72a5-474d-bee6-9457847f0d7e  workspace_id=3231f8fa-6c99-48aa-8ad8-e8a93d577eac
2023-08-15T08:41:07.9196714Z     t.go:85: 2023-08-15 08:40:14.690 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=26.307904ms  status_code=200  latency_ms=26  request_id=43927a78-72a5-474d-bee6-9457847f0d7e
2023-08-15T08:41:07.9197988Z     t.go:85: 2023-08-15 08:40:14.708 [debu]  read stats report  request_id=3b9c2da7-b0ba-40cb-922f-4395ed11141b  interval=5m0s  workspace_agent_id=1de64d4f-2a05-449b-b9ee-67e7d09967ad  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf  payload={"connections_by_proto":{"TCP":1},"connection_count":11,"connection_median_latency_ms":12000,"rx_packets":0,"rx_bytes":8,"tx_packets":0,"tx_bytes":5,"session_count_vscode":14,"session_count_jetbrains":16,"session_count_reconnecting_pty":18,"session_count_ssh":20,"metrics":null}
2023-08-15T08:41:07.9198847Z     t.go:85: 2023-08-15 08:40:14.748 [debu]  activity_bump: bumped deadline from activity  request_id=3b9c2da7-b0ba-40cb-922f-4395ed11141b  workspace_id=0a3e4daf-3e6d-4785-8ec1-e4dd9ceffedf
2023-08-15T08:41:07.9199586Z     t.go:85: 2023-08-15 08:40:14.754 [debu]  POST  host=localhost:38147  path=/api/v2/workspaceagents/me/report-stats  proto=HTTP/1.1  remote_addr=127.0.0.1  took=63.120834ms  status_code=200  latency_ms=63  request_id=3b9c2da7-b0ba-40cb-922f-4395ed11141b
2023-08-15T08:41:07.9199962Z     prometheusmetrics_test.go:457:
2023-08-15T08:41:07.9200571Z         	Error Trace:	/home/runner/actions-runner/_work/coder/coder/coderd/prometheusmetrics/prometheusmetrics_test.go:457
2023-08-15T08:41:07.9200932Z         	Error:      	Condition never satisfied
2023-08-15T08:41:07.9201174Z         	Test:       	TestAgentStats
2023-08-15T08:41:07.9201457Z     prometheusmetrics_test.go:489:
2023-08-15T08:41:07.9202022Z         	Error Trace:	/home/runner/actions-runner/_work/coder/coder/coderd/prometheusmetrics/prometheusmetrics_test.go:489
2023-08-15T08:41:07.9202325Z         	Error:      	Not equal:
2023-08-15T08:41:07.9210285Z         	            	expected: map[string]int{"testuser:workspace-1:example:coderd_agentstats_connection_count":9, "testuser:workspace-1:example:coderd_agentstats_connection_median_latency_seconds":8, "testuser:workspace-1:example:coderd_agentstats_rx_bytes":9, "testuser:workspace-1:example:coderd_agentstats_session_count_jetbrains":6, "testuser:workspace-1:example:coderd_agentstats_session_count_reconnecting_pty":7, "testuser:workspace-1:example:coderd_agentstats_session_count_ssh":8, "testuser:workspace-1:example:coderd_agentstats_session_count_vscode":5, "testuser:workspace-1:example:coderd_agentstats_tx_bytes":6, "testuser:workspace-2:example:coderd_agentstats_connection_count":10, "testuser:workspace-2:example:coderd_agentstats_connection_median_latency_seconds":10, "testuser:workspace-2:example:coderd_agentstats_rx_bytes":15, "testuser:workspace-2:example:coderd_agentstats_session_count_jetbrains":10, "testuser:workspace-2:example:coderd_agentstats_session_count_reconnecting_pty":12, "testuser:workspace-2:example:coderd_agentstats_session_count_ssh":14, "testuser:workspace-2:example:coderd_agentstats_session_count_vscode":8, "testuser:workspace-2:example:coderd_agentstats_tx_bytes":9, "testuser:workspace-3:example:coderd_agentstats_connection_count":11, "testuser:workspace-3:example:coderd_agentstats_connection_median_latency_seconds":12, "testuser:workspace-3:example:coderd_agentstats_rx_bytes":21, "testuser:workspace-3:example:coderd_agentstats_session_count_jetbrains":16, "testuser:workspace-3:example:coderd_agentstats_session_count_reconnecting_pty":18, "testuser:workspace-3:example:coderd_agentstats_session_count_ssh":20, "testuser:workspace-3:example:coderd_agentstats_session_count_vscode":14, "testuser:workspace-3:example:coderd_agentstats_tx_bytes":12}
2023-08-15T08:41:07.9219755Z         	            	actual  : map[string]int{"testuser:workspace-1:example:coderd_agentstats_connection_count":9, "testuser:workspace-1:example:coderd_agentstats_connection_median_latency_seconds":8, "testuser:workspace-1:example:coderd_agentstats_rx_bytes":9, "testuser:workspace-1:example:coderd_agentstats_session_count_jetbrains":6, "testuser:workspace-1:example:coderd_agentstats_session_count_reconnecting_pty":7, "testuser:workspace-1:example:coderd_agentstats_session_count_ssh":8, "testuser:workspace-1:example:coderd_agentstats_session_count_vscode":5, "testuser:workspace-1:example:coderd_agentstats_tx_bytes":6, "testuser:workspace-2:example:coderd_agentstats_connection_count":10, "testuser:workspace-2:example:coderd_agentstats_connection_median_latency_seconds":10, "testuser:workspace-2:example:coderd_agentstats_rx_bytes":15, "testuser:workspace-2:example:coderd_agentstats_session_count_jetbrains":10, "testuser:workspace-2:example:coderd_agentstats_session_count_reconnecting_pty":12, "testuser:workspace-2:example:coderd_agentstats_session_count_ssh":14, "testuser:workspace-2:example:coderd_agentstats_session_count_vscode":8, "testuser:workspace-2:example:coderd_agentstats_tx_bytes":9, "testuser:workspace-3:example:coderd_agentstats_connection_count":10, "testuser:workspace-3:example:coderd_agentstats_connection_median_latency_seconds":12, "testuser:workspace-3:example:coderd_agentstats_rx_bytes":13, "testuser:workspace-3:example:coderd_agentstats_session_count_jetbrains":15, "testuser:workspace-3:example:coderd_agentstats_session_count_reconnecting_pty":17, "testuser:workspace-3:example:coderd_agentstats_session_count_ssh":19, "testuser:workspace-3:example:coderd_agentstats_session_count_vscode":13, "testuser:workspace-3:example:coderd_agentstats_tx_bytes":7}
2023-08-15T08:41:07.9221296Z
2023-08-15T08:41:07.9221543Z         	            	Diff:
2023-08-15T08:41:07.9221831Z         	            	--- Expected
2023-08-15T08:41:07.9222080Z         	            	+++ Actual
2023-08-15T08:41:07.9222393Z         	            	@@ -17,10 +17,10 @@
2023-08-15T08:41:07.9223097Z         	            	  (string) (len=55) "testuser:workspace-2:example:coderd_agentstats_tx_bytes": (int) 9,
2023-08-15T08:41:07.9223809Z         	            	- (string) (len=63) "testuser:workspace-3:example:coderd_agentstats_connection_count": (int) 11,
2023-08-15T08:41:07.9224529Z         	            	+ (string) (len=63) "testuser:workspace-3:example:coderd_agentstats_connection_count": (int) 10,
2023-08-15T08:41:07.9225371Z         	            	  (string) (len=80) "testuser:workspace-3:example:coderd_agentstats_connection_median_latency_seconds": (int) 12,
2023-08-15T08:41:07.9226149Z         	            	- (string) (len=55) "testuser:workspace-3:example:coderd_agentstats_rx_bytes": (int) 21,
2023-08-15T08:41:07.9226888Z         	            	- (string) (len=70) "testuser:workspace-3:example:coderd_agentstats_session_count_jetbrains": (int) 16,
2023-08-15T08:41:07.9227751Z         	            	- (string) (len=77) "testuser:workspace-3:example:coderd_agentstats_session_count_reconnecting_pty": (int) 18,
2023-08-15T08:41:07.9228502Z         	            	- (string) (len=64) "testuser:workspace-3:example:coderd_agentstats_session_count_ssh": (int) 20,
2023-08-15T08:41:07.9229252Z         	            	- (string) (len=67) "testuser:workspace-3:example:coderd_agentstats_session_count_vscode": (int) 14,
2023-08-15T08:41:07.9229934Z         	            	- (string) (len=55) "testuser:workspace-3:example:coderd_agentstats_tx_bytes": (int) 12
2023-08-15T08:41:07.9230605Z         	            	+ (string) (len=55) "testuser:workspace-3:example:coderd_agentstats_rx_bytes": (int) 13,
2023-08-15T08:41:07.9231346Z         	            	+ (string) (len=70) "testuser:workspace-3:example:coderd_agentstats_session_count_jetbrains": (int) 15,
2023-08-15T08:41:07.9232144Z         	            	+ (string) (len=77) "testuser:workspace-3:example:coderd_agentstats_session_count_reconnecting_pty": (int) 17,
2023-08-15T08:41:07.9232876Z         	            	+ (string) (len=64) "testuser:workspace-3:example:coderd_agentstats_session_count_ssh": (int) 19,
2023-08-15T08:41:07.9233636Z         	            	+ (string) (len=67) "testuser:workspace-3:example:coderd_agentstats_session_count_vscode": (int) 13,
2023-08-15T08:41:07.9234303Z         	            	+ (string) (len=55) "testuser:workspace-3:example:coderd_agentstats_tx_bytes": (int) 7
2023-08-15T08:41:07.9234601Z         	            	 }
2023-08-15T08:41:07.9234840Z         	Test:       	TestAgentStats
2023-08-15T08:41:07.9235207Z     t.go:88: 2023-08-15 08:40:24.759 [erro]  can't get agent stats  error="context canceled"
2023-08-15T08:41:07.9235619Z     t.go:85: 2023-08-15 08:40:24.759 [debu]  provisionerd: closing server with error  error=<nil>
2023-08-15T08:41:07.9236047Z     t.go:85: 2023-08-15 08:40:24.759 [warn]  context done, flushing before exit
2023-08-15T08:41:07.9236333Z
@johnstcn johnstcn added the flake label Aug 15, 2023
@johnstcn johnstcn self-assigned this Aug 15, 2023
@cdr-bot cdr-bot bot added the chore label Aug 15, 2023
@johnstcn johnstcn mentioned this issue Aug 15, 2023
Closed
@spikecurtis
Copy link
Contributor

Still seeing this bad boi https://github.com/coder/coder/actions/runs/6023835356/job/16341363670

@johnstcn johnstcn mentioned this issue Aug 31, 2023
Merged
@johnstcn johnstcn added bug s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks and removed chore labels Aug 31, 2023
@johnstcn
Copy link
Member Author

@spikecurtis this should be fixed now 🤞

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@johnstcn johnstcn

Labels
s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix(coderd/prometheusmetrics): close batcher to force flush before asserting agent stats coder/coder
2 participants
@johnstcn @spikecurtis