Postgres filter does not close the connection when the client is terminated non-gracefully
- Dominant language
- C++
- Stars
- 28.9k
- Forks
- 5.6k
- Avg merge
- 1d 22h
- Merged PRs (30d)
- 430
Description
**Title**: Postgres filter does not close the connection when the client is terminated non-gracefully
**Description:**
> When postgres client (psql in this case) is running a long running operations - select a really big table or doing a really long index build.
Or in the repro, just doing a sleep.
When the client is killed, while doing the long operation, envoy does not terminate upstream connection.
**Repro steps**
In the setup, I ran envoy locally with this command: `envoy -c pg-config.yaml -l trace --use-dynamic-base-id`
I also have postgres docker container running locally with this command:
```
docker run --rm -it \
-v $(pwd)/envoy-pg-config.yaml:/envoy-pg-config.yaml \
-v $(pwd)/server.key:/server.key \
-v $(pwd)/server.pem:/server.pem \
-p 5432:5432 \
envoyproxy/envoy-contrib:v1.31-latest \
-c /envoy-pg-config.yaml -l debug
````
Envoy is configured to listen on port 5555 and forward traffic to a Postgres server running on port 5432. The Postgres filter is set up to handle SSL termination and uses a StartTLS configuration.
*envoy config*
```
admin:
address:
socket_address:
protocol: TCP
address: 0.0.0.0
port_value: 9901
static_resources:
listeners:
name: listener_0
address:
socket_address:
address: 0.0.0.0
port_value: 5555
socket_options:
- description: "Enable TCP keepalives"
int_value: 1
level: 1
name: 9
- description: "Set TCP keepidle time to 25 seconds"
int_value: 25
level: 6
name: 4
- description: "Set TCP keepcnt to 12"
int_value: 12
level: 6
name: 6
- description: "Set TCP keepintvl to 25 seconds"
int_value: 25
level: 6
name: 5
filter_chains:
- transport_socket:
name: "starttls"
typed_config:
"@type": type.googleapis.com/envoy.extensions.transport_sockets.starttls.v3.StartTlsConfig
cleartext_socket_config:
tls_socket_config:
common_tls_context:
tls_certificates:
certificate_chain:
filename: "~/envoy-fork/server.pem"
private_key:
filename: "~envoy-fork/server.key"
filters:
- name: postgres
typed_config:
"@type": type.googleapis.com/envoy.extensions.filters.network.postgres_proxy.v3alpha.PostgresProxy
stat_prefix: postgres_stats
enable_sql_parsing: false
terminate_ssl: true
upstream_ssl: REQUIRE
- name: tcp
typed_config:
"@type": type.googleapis.com/envoy.extensions.filters.network.tcp_proxy.v3.TcpProxy
stat_prefix: tcp_stats
cluster: postgres_cluster_westus
clusters:
- name: postgres_cluster_westus
type: STATIC
load_assignment:
cluster_name: cluster_0
endpoints:
- lb_endpoints:
- endpoint:
address:
socket_address:
address: 127.0.0.1
port_value: 5432
transport_socket:
name: "starttls"
typed_config:
"@type": type.googleapis.com/envoy.extensions.transport_sockets.starttls.v3.UpstreamStartTlsConfig
tls_socket_config:
common_tls_context: {}
```
Once everything is set up, I connect to postgres using psql and run `select pg_sleep(90*60);` to simulate a long-running operation.
After that, I kill the psql client using `kill -9 `.
**Expected behavior:**
When the psql client is killed, the Postgres filter in Envoy should close the upstream connection to the Postgres server.
**Actual behavior:**
When the psql client is killed, the Postgres filter does not close the upstream connection to the Postgres server.
When I connect to the Postgres server using `psql` again, I can still see the previous connection is still alive and running the `pg_sleep` command.
```
postgres=# select
datid, datname, pid, usename, query, application_name, client_addr, client_port, backend_start, xact_start, query_start, state, wait_event
from pg_stat_activity
where usename <> 'databricks_monitor';
datid | datname | pid | usename | query | application_name | client_addr | client_port | backend_start | xact_start | query_start | state | wait_event
-------+----------+-----+----------+--------------------------------------------------------------------------------------------------------------------------------------------+------------------+-------------+-------------+-------------------------------+-------------------------------+-------------------------------+--------+---------------------
| | 31 | postgres | | | | | 2025-06-26 03:12:37.190338+00 | | | | LogicalLauncherMain
5 | postgres | 33 | postgres | select +| psql | 172.17.0.1 | 51086 | 2025-06-26 03:13:33.116473+00 | 2025-06-26 03:39:08.569535+00 | 2025-06-26 03:39:08.569535+00 | active |
| | | | datid, datname, pid, usename, query, application_name, client_addr, client_port, backend_start, xact_start, query_start, state, wait_event+| | | | | | | |
| | | | from pg_stat_activity +| | | | | | | |
| | | | where usename <> 'databricks_monitor'; | | | | | | | |
5 | postgres | 61 | postgres | select pg_sleep(90*60); | psql | 172.17.0.1 | 33422 | 2025-06-26 03:37:43.310983+00 | 2025-06-26 03:37:51.251618+00 | 2025-06-26 03:37:51.251618+00 | active | PgSleep
(3 rows)
```
**Envoy logs:**
```
[2025-06-26 03:37:46.467][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:655] [Tags: "ConnectionId":"0"] socket event: 3
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:801] [Tags: "ConnectionId":"0"] write ready
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:701] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"0"] ssl read returns: 29
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"0"] ssl read returns: -1
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"0"] ssl error occurred while read: WANT_READ
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"0"] ssl read 29 bytes
[2025-06-26 03:37:51.251][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_filter.cc:31] [Tags: "ConnectionId":"0"] postgres_proxy: got 29 bytes
[2025-06-26 03:37:51.251][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:333] postgres_proxy: decoding 29 bytes
[2025-06-26 03:37:51.251][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:335] postgres_proxy: parsing message, len 29
[2025-06-26 03:37:51.251][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:344] postgres_proxy: command is Q
[2025-06-26 03:37:51.251][20654][debug][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:318] (Frontend) command = Q (Query)
[2025-06-26 03:37:51.251][20654][debug][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:319] (Frontend) length = 28
[2025-06-26 03:37:51.251][20654][debug][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:320] (Frontend) message = [select pg_sleep(90*60);]
[2025-06-26 03:37:51.251][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_decoder.cc:322] postgres_proxy: 24 bytes remaining in buffer
[2025-06-26 03:37:51.251][20654][trace][filter] [source/common/tcp_proxy/tcp_proxy.cc:827] [Tags: "ConnectionId":"0"] downstream connection received 29 bytes, end_stream=false, has upstream true
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:570] [Tags: "ConnectionId":"1"] writing 29 bytes, end_stream false
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:655] [Tags: "ConnectionId":"1"] socket event: 2
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/network/connection_impl.cc:801] [Tags: "ConnectionId":"1"] write ready
[2025-06-26 03:37:51.251][20654][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"1"] ssl write returns: 29
< bunch of flushing stats log>
# After issue a kill command
< Client sent FIN ACK >
[2025-06-26 03:39:01.524][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:39:06.528][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:39:11.532][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:39:16.535][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:655] [Tags: "ConnectionId":"0"] socket event: 3
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:801] [Tags: "ConnectionId":"0"] write ready
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:701] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"0"] ssl read returns: 0
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"0"] ssl error occurred while read: SYSCALL
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"0"] ssl read 0 bytes
[2025-06-26 03:39:18.970][20654][trace][filter] [contrib/postgres_proxy/filters/network/source/postgres_filter.cc:31] [Tags: "ConnectionId":"0"] postgres_proxy: got 0 bytes
[2025-06-26 03:39:18.970][20654][trace][filter] [source/common/tcp_proxy/tcp_proxy.cc:827] [Tags: "ConnectionId":"0"] downstream connection received 0 bytes, end_stream=true, has upstream true
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:570] [Tags: "ConnectionId":"1"] writing 0 bytes, end_stream true
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:655] [Tags: "ConnectionId":"1"] socket event: 2
[2025-06-26 03:39:18.970][20654][trace][connection] [source/common/network/connection_impl.cc:801] [Tags: "ConnectionId":"1"] write ready
[2025-06-26 03:39:18.970][20654][debug][connection] [source/common/tls/ssl_socket.cc:336] [Tags: "ConnectionId":"1"] SSL shutdown: rc=0
[2025-06-26 03:39:21.539][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:39:26.543][20587][debug][main] [source/server/server.cc:245] flushing stats
< after RST packet >
[2025-06-26 03:40:26.592][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:40:31.596][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:40:36.599][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/network/connection_impl.cc:655] [Tags: "ConnectionId":"0"] socket event: 3
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/network/connection_impl.cc:801] [Tags: "ConnectionId":"0"] write ready
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/network/connection_impl.cc:701] [Tags: "ConnectionId":"0"] read ready. dispatch_buffered_data=0
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"0"] ssl read returns: 0
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"0"] ssl error occurred while read: SYSCALL
[2025-06-26 03:40:37.151][20654][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"0"] ssl read 0 bytes
[2025-06-26 03:40:41.604][20587][debug][main] [source/server/server.cc:245] flushing stats
[2025-06-26 03:40:46.607][20587][debug][main] [source/server/server.cc:245] flushing stats
```
TCP Dump screen shot
56362 is the psql client port.

From the screenshot,
33422 is the port reported by postgres but this the port used by docker
56362 is the client port that used by envoy to connect to postgres.
Contributor guide
Assessment
This issue has not been assessed yet.