tmessi
commented
1 year ago Thanks for the detailed report. Looking at the logs I see a couple things. In the data-workers.txt there are a lot of errors due to rpc error: code = DeadlineExceeded desc = context deadline exceeded when the worker is trying to report status to the controllers, ie:
{
"id": "Tmf5FUXdWQ",
"source": "https://hashicorp.com/boundary/boundary-worker-1/worker",
"specversion": "1.0",
"type": "error",
"data": {
"error": "rpc error: code = DeadlineExceeded desc = context deadline exceeded",
"error_fields": {},
"id": "e_H1ZibNYS6F",
"version": "v0.1",
"op": "worker.(Worker).sendWorkerStatus",
"info": {
"msg": "error making status request to controller"
}
},
"datacontentype": "application/cloudevents",
"time": "2023-06-08T14:57:20.529216848Z"
}If the worker is unable to report to the controller for too long, it will terminate all sessions and connections on the worker, this can also be seen in the logs:
{
"id": "MUxazwTLgj",
"source": "https://hashicorp.com/boundary/boundary-worker-1/worker",
"specversion": "1.0",
"type": "error",
"data": {
"error": "status error grace period has expired, canceling all sessions on worker",
"error_fields": {},
"id": "e_9aQdikjlBe",
"version": "v0.1",
"op": "worker.(Worker).sendWorkerStatus",
"info": {
"grace_period": 15000000000,
"last_status_time": "2023-06-08 14:57:56.406564739 +0000 UTC m=+367.954064626"
}
},
"datacontentype": "application/cloudevents",
"time": "2023-06-08T14:58:17.791085825Z"
}The rpc error: code = DeadlineExceeded desc = context deadline exceeded error indicates that the status request took too long to respond. So looking at the controller logs to see why it is taking so long, I can see errors on the controller when it is processing these status requests. There are two in particular:
{
"id": "IrUdOUgOb1",
"source": "https://hashicorp.com/boundary/boundary-controller-0/controller",
"specversion": "1.0",
"type": "error",
"data": {
"error": "session.(Repository).checkIfNotActive: db.Query: unknown, unknown: error #0: context deadline exceeded",
"error_fields": {
"Code": 0,
"Msg": "",
"Op": "session.(Repository).checkIfNotActive",
"Wrapped": {
"Code": 0,
"Msg": "",
"Op": "db.Query",
"Wrapped": {}
}
},
"id": "e_6Ri6sVmgzz",
"version": "v0.1",
"op": "session.(Repository).checkIfNotActive",
"request_info": {
"id": "gtraceid_aiMosV9g4KUbC54jCNjr",
"method": "/controller.servers.services.v1.ServerCoordinationService/Status"
}
},
"datacontentype": "application/cloudevents",
"time": "2023-06-08T14:58:45.112276325Z"
}and
{
"id": "jdboc37S8o",
"source": "https://hashicorp.com/boundary/boundary-controller-0/controller",
"specversion": "1.0",
"type": "error",
"data": {
"error": "session.(Repository).checkIfNotActive: error checking if sessions are no longer active: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back",
"error_fields": {
"Code": 0,
"Msg": "error checking if sessions are no longer active",
"Op": "session.(Repository).checkIfNotActive",
"Wrapped": {
"Code": 0,
"Msg": "",
"Op": "db.DoTx",
"Wrapped": {}
}
},
"id": "e_6Ri6sVmgzz",
"version": "v0.1",
"op": "session.(Repository).checkIfNotActive",
"request_info": {
"id": "gtraceid_aiMosV9g4KUbC54jCNjr",
"method": "/controller.servers.services.v1.ServerCoordinationService/Status"
}
},
"datacontentype": "application/cloudevents",
"time": "2023-06-08T14:58:45.112614501Z"
}In both cases it looks like the request timed out in the middle of running these queries. It is also worth noting that the closedOrphanedConnections query happens after the checkIfNoLongerActive query as part of processing a worker status request. And it will run the second query even if the first failed, so if the checkIfNoLongerActive query fails due to a timeout, I would expect to also see a timeout error for the closeOrphanedConnections query.
So this points to load issues on the database and/or the controllers. Would you be able to collect some resource utilization metrics for both the database and controllers? Specifically, for the controllers:
- CPU utilization
- Memory utilization
And for the database:
- CPU utilization
- Memory utilization
- Wait Events
- Slow queries
It looks like there are three queries that normally run as part of the processing the status report, so ones of particular interest would be queries like:
UPDATE "session_connection" SET "bytes_down"=$1,"bytes_up"=$2,"closed_reason"=$3 WHERE "public_id" = $4select session_id, state
from session_state ss
where
(ss.state = 'canceling' or ss.state = 'terminated')
and ss.end_time is null-- Find connections that are not closed so we can reference those IDs
with
unclosed_connections as (
select connection_id
from session_connection_state
where
-- It's the current state
end_time is null
-- Current state isn't closed state
and state in ('authorized', 'connected')
-- It's not in limbo between when it moved into this state and when
-- it started being reported by the worker, which is roughly every
-- 2-3 seconds
and start_time < wt_sub_seconds_from_now(@worker_state_delay_seconds)
),
connections_to_close as (
select public_id
from session_connection
where
-- Related to the worker that just reported to us
worker_id = @worker_id
-- Only unclosed ones
and public_id in (select connection_id from unclosed_connections)
-- These are connection IDs that just got reported to us by the given
-- worker, so they should not be considered closed.
)
update session_connection
set
closed_reason = 'system error'
where
public_id in (select public_id from connections_to_close)
returning public_id;(This last one looks like one that we looked at as part of #3283)
But it is also possible that some other query might be contributing to the load issue, so if there are any other slow queries that would also be helpful.
macmiranda
AdamBouhmad
Describe the bug
For now very little is known about the problem.
psqlsessions break withThe symptom only arises when a certain data pipeline runs 1000s of tests using
dbtagainst a Postgres instance proxied via Boundary. It uses high concurrency (8 parallel jobs) and each job can create multiple session connections because of the way the underlyinglibpqparallelizes the queries, so connection churn may be a factor.Another thing we noticed, when that happens, it affects the other sessions on the same worker too, and as far as I can tell, it may affect sessions of users connected to other workers (i.e. in different clusters) - it's hard to say for sure, but it seems that the dropped connections are all related (which makes me think that something is affecting the controllers).
Other than that, sessions and connections work just fine.
We're running Boundary version
0.12.2on both controllers and workers, as Kubernetes StatefulSets.To Reproduce
At a high level:
dbtwith 1000s of tests, with high concurrency, against a single targetExpected behavior
Stable connection even under heavy load and concurrency.
Additional context
We've have manually applied the fixes https://github.com/hashicorp/boundary/pull/3283 and https://github.com/hashicorp/boundary/pull/3280
I'm attaching logs from the workers where the machine that runs the data pipeline connects (data-workers.txt) and from the controllers and workers running on a different cluster (controllers+workers.txt). We noticed connection breakage on the workers of this cluster as well. The logs are JSON formatted (but extension was changed because Github didn't like
.json) and span a 2-min interval in which we observed the issue. They are ordered from the most recent to the oldest.I'd be happy to investigate the issue further and run any debugging commands or gather extra logs.
Thanks.