Hi,
Just noticed this behavior today that’s kinda boggling me. Clients connecting via Boundary to a Postgres database either by using
-
boundary connect(and inputting creds) or -
boundary connect postgres(automatically authenticates) or - Boundary Desktop + external program (e.g. pgAdmin4)
all get the same error at exactly 10m00s of running a query.
As an illustration of that, see the following output:
❯ boundary connect postgres -target-id ttcp_naGseB1PAs -dbname data_warehouse
psql (15.2, server 14.6)
SSL connection (protocol: TLSv1.2, cipher: ECDHE-RSA-AES128-GCM-SHA256, compression: off)
You are now connected to database "data_warehouse" as user "v-token-to-data_war-PFXW7wY0o4V4emQh9KCn-1680173682".
data_warehouse=> select pg_sleep(601);
SSL SYSCALL error: EOF detected
The connection to the server was lost. Attempting reset: Succeeded.
psql (15.2, server 14.6)
SSL connection (protocol: TLSv1.2, cipher: ECDHE-RSA-AES128-GCM-SHA256, compression: off)
Postgres itself logs to postgresql.log:
2023-03-30 09:43:18 UTC:10.14.37.204(51926):*****@*****:[3435]:LOG: could not send data to client: Connection timed out
2023-03-30 09:43:18 UTC:10.14.37.204(51926):*****@*****:[3435]:FATAL: connection to client lost
It happens with at least Boundary versions 0.10.5 and 0.12.0.
Below are the relevant logs:
{"id":"vkhYtQVHQO","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_CTEMrPiFJN","version":"v0.1","op":"worker.(Worker).sendWorkerStatus","info":{"msg":"error making status request to controller"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.520607375Z"}
2023-03-30T08:23:28.520Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: unable to write error: session.(ConnectionRepository).closeOrphanedConnections: db.Query: unknown, unknown: error #0: context deadline exceeded
2023-03-30T08:23:28.521Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: unable to write error: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back
2023-03-30T08:23:28.521Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.521Z [ERROR] event.WriteError: unable to write error: session.WorkerStatusReport: Error closing orphaned connections for worker w_1qqKtUnH5H: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back: unknown: error #500
{"id":"ndOl83VsdJ","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.(ConnectionRepository).closeOrphanedConnections: db.Query: unknown, unknown: error #0: context deadline exceeded","error_fields":{"Code":0,"Msg":"","Op":"session.(ConnectionRepository).closeOrphanedConnections","Wrapped":{"Code":0,"Msg":"","Op":"db.Query","Wrapped":{}}},"id":"e_iLgC1isb68","version":"v0.1","op":"session.(ConnectionRepository).closeOrphanedConnections","request_info":{"id":"gtraceid_oRh3Tvp3SzY2Uqyt0vof","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.520890808Z"}
{"id":"QHV7YGVDyX","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back","error_fields":{"Code":0,"Msg":"error comparing state","Op":"session.(ConnectionRepository).closeOrphanedConnections","Wrapped":{"Code":0,"Msg":"","Op":"db.DoTx","Wrapped":{}}},"id":"e_iLgC1isb68","version":"v0.1","op":"session.(ConnectionRepository).closeOrphanedConnections","request_info":{"id":"gtraceid_oRh3Tvp3SzY2Uqyt0vof","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.521249236Z"}
{"id":"zpmF4fuP1Q","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.WorkerStatusReport: Error closing orphaned connections for worker w_1qqKtUnH5H: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back: unknown: error #500","error_fields":{"Code":500,"Msg":"Error closing orphaned connections for worker w_1qqKtUnH5H: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back","Op":"session.WorkerStatusReport","Wrapped":null},"id":"e_iLgC1isb68","version":"v0.1","op":"session.WorkerStatusReport","request_info":{"id":"gtraceid_oRh3Tvp3SzY2Uqyt0vof","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.521356357Z"}
{"id":"ZBjEoaUwLD","source":"https://hashicorp.com/boundary/boundary-worker-0/worker","specversion":"1.0","type":"error","data":{"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded","error_fields":{},"id":"e_18tR27tOYI","version":"v0.1","op":"worker.(Worker).sendWorkerStatus","info":{"msg":"error making status request to controller"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.523464217Z"}
2023-03-30T08:23:28.523Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.523Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.523Z [ERROR] event.WriteError: unable to write error: session.(ConnectionRepository).closeOrphanedConnections: db.Query: unknown, unknown: error #0: context deadline exceeded
2023-03-30T08:23:28.523Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.523Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.523Z [ERROR] event.WriteError: unable to write error: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back
{"id":"0jisII16lE","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.(ConnectionRepository).closeOrphanedConnections: db.Query: unknown, unknown: error #0: context deadline exceeded","error_fields":{"Code":0,"Msg":"","Op":"session.(ConnectionRepository).closeOrphanedConnections","Wrapped":{"Code":0,"Msg":"","Op":"db.Query","Wrapped":{}}},"id":"e_TCbtGabie1","version":"v0.1","op":"session.(ConnectionRepository).closeOrphanedConnections","request_info":{"id":"gtraceid_nzMgg1hruTbaIjxbniic","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.523659533Z"}
{"id":"42hw5WFTzC","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back","error_fields":{"Code":0,"Msg":"error comparing state","Op":"session.(ConnectionRepository).closeOrphanedConnections","Wrapped":{"Code":0,"Msg":"","Op":"db.DoTx","Wrapped":{}}},"id":"e_TCbtGabie1","version":"v0.1","op":"session.(ConnectionRepository).closeOrphanedConnections","request_info":{"id":"gtraceid_nzMgg1hruTbaIjxbniic","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.523770068Z"}
2023-03-30T08:23:28.524Z [ERROR] encountered an error sending an error event:
error:=
| event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.524Z [ERROR] event.WriteError: event.(Eventer).writeError: event.(Eventer).retrySend: failed to send event: 2 errors occurred:
2023-03-30T08:23:28.524Z [ERROR] event.WriteError: unable to write error: session.WorkerStatusReport: Error closing orphaned connections for worker w_nkXuxs6JmW: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back: unknown: error #500
{"id":"HFQBHddmmB","source":"https://hashicorp.com/boundary/boundary-controller-0/controller","specversion":"1.0","type":"error","data":{"error":"session.WorkerStatusReport: Error closing orphaned connections for worker w_nkXuxs6JmW: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back: unknown: error #500","error_fields":{"Code":500,"Msg":"Error closing orphaned connections for worker w_nkXuxs6JmW: session.(ConnectionRepository).closeOrphanedConnections: error comparing state: db.DoTx: unknown, unknown: error #0: dbw.Rollback: sql: transaction has already been committed or rolled back","Op":"session.WorkerStatusReport","Wrapped":null},"id":"e_TCbtGabie1","version":"v0.1","op":"session.WorkerStatusReport","request_info":{"id":"gtraceid_nzMgg1hruTbaIjxbniic","method":"/controller.servers.services.v1.ServerCoordinationService/Status"}},"datacontentype":"application/cloudevents","time":"2023-03-30T08:23:28.523988484Z"}
Executing the same query without Boundary works as expected.