Search code examples
postgresqlkubernetespgbouncer

"tlsv1 alert unknown ca" error in pgbouncer logs when pgbouncer is trying to connect with postgres using SSL/TLS

We have a k8s cluster and postgres pods are running in it. Our backend services connect to postgres K8s service. I am trying to introduce PgBouncer as proxy when connecting to postgres pods. Postgres has ssl mode enabled and we have our own ROOT_CA, and an intermediate CA that is signed by the ROOT_CA. We create certificates for postgres signed by this intermediate CA. I am using the same intermediate CA to sign certificates for pgbouncer and creating a Self signed certificate for pgbouncer. I am mounting these certificates on pgbouncer pod. When I configure the backend service to redirect traffic to pgbouncer service and through pgbouncer to postgres,I am seeing below error:

2022-10-06 11:43:13.030 1 DEBUG parse_ini_file: 'verbose' = '2' ok:1
2022-10-06 11:43:13.033 1 NOISE event: 128, SBuf: 192, PgSocket: 400, IOBuf: 4108
2022-10-06 11:43:13.033 1 LOG file descriptor limit: 1048576 (H:1048576), max_client_conn: 100, max fds possible: 110
2022-10-06 11:43:13.033 1 DEBUG pktbuf_dynamic(128): 0x55a4515583c0
2022-10-06 11:43:13.033 1 DEBUG make_room(0x55a4515583c0, 4): realloc newlen=256
2022-10-06 11:43:13.033 1 DEBUG pktbuf_dynamic(128): 0x55a4515585c0
2022-10-06 11:43:13.034 1 NOISE connect(3, unix:/tmp/.s.PGSQL.5432) = No such file or directory
2022-10-06 11:43:13.034 1 DEBUG adns_create_context: udns 0.4
2022-10-06 11:43:13.034 1 DEBUG add_listen: 0.0.0.0:5432
2022-10-06 11:43:13.035 1 NOISE old TCP_DEFER_ACCEPT on 7 = 0
2022-10-06 11:43:13.035 1 NOISE install TCP_DEFER_ACCEPT on 7
2022-10-06 11:43:13.035 1 LOG listening on 0.0.0.0:5432
2022-10-06 11:43:13.035 1 DEBUG add_listen: ::/5432
2022-10-06 11:43:13.035 1 NOISE old TCP_DEFER_ACCEPT on 8 = 0
2022-10-06 11:43:13.035 1 NOISE install TCP_DEFER_ACCEPT on 8
2022-10-06 11:43:13.035 1 LOG listening on ::/5432
2022-10-06 11:43:13.035 1 DEBUG add_listen: unix:/tmp/.s.PGSQL.5432
2022-10-06 11:43:13.036 1 LOG listening on unix:/tmp/.s.PGSQL.5432
2022-10-06 11:43:13.036 1 LOG process up: pgbouncer 1.9.0, libevent 2.1.8-stable (epoll), adns: udns 0.4, tls: LibreSSL 2.6.5
2022-10-06 11:43:16.166 1 NOISE new fd from accept=10
2022-10-06 11:43:16.167 1 NOISE resync: done=0, parse=0, recv=0
2022-10-06 11:43:16.167 1 NOISE C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 pkt='!' len=8
2022-10-06 11:43:16.167 1 NOISE C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 C: req SSL
2022-10-06 11:43:16.167 1 NOISE C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 P: nak
2022-10-06 11:43:16.167 1 NOISE resync: done=8, parse=8, recv=8
2022-10-06 11:43:16.167 1 DEBUG C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 P: got connection: 127.0.0.6:38446 -> 127.0.0.6:5432
2022-10-06 11:43:16.167 1 NOISE safe_accept(7) = Resource temporarily unavailable
2022-10-06 11:43:16.167 1 NOISE resync: done=0, parse=0, recv=0
2022-10-06 11:43:16.167 1 NOISE C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 pkt='!' len=69
2022-10-06 11:43:16.168 1 DEBUG C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 got var: user=<user_name>
2022-10-06 11:43:16.168 1 DEBUG C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 got var: database=<database_name>
2022-10-06 11:43:16.168 1 DEBUG C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 using application_name: pg_isready
2022-10-06 11:43:16.168 1 NOISE cstr_get_pair: "host"="postgres-cluster"
2022-10-06 11:43:16.168 1 NOISE cstr_get_pair: "port"="5432"
2022-10-06 11:43:16.168 1 NOISE cstr_get_pair: "auth_user"="<user_name>"
2022-10-06 11:43:16.168 1 DEBUG pktbuf_dynamic(128): 0x55a4515686c0
2022-10-06 11:43:16.168 1 LOG C-0x55a451568fb0: (nodb)/(nouser)@127.0.0.6:38446 registered new auto-database: db=<database_name>
2022-10-06 11:43:16.168 1 DEBUG C-0x55a451568fb0: <user_name>/(nouser)@127.0.0.6:38446 pause_client
2022-10-06 11:43:16.168 1 NOISE S-0x55a45156ddf0: <database_name>/<user_name>@(bad-af):0 inet socket: postgres-db-pg-cluster
2022-10-06 11:43:16.168 1 NOISE S-0x55a45156ddf0: <database_name>/<user_name>@(bad-af):0 dns socket: postgres-db-pg-cluster
2022-10-06 11:43:16.168 1 NOISE dns: new req: postgres-cluster
2022-10-06 11:43:16.168 1 DEBUG zone_register(postgres-cluster)
2022-10-06 11:43:16.168 1 NOISE udns_timer_setter: ctx=0x55a4515665e0 timeout=0
2022-10-06 11:43:16.168 1 NOISE dns: udns_launch_query(postgres-cluster)=0x55a4515688e0
2022-10-06 11:43:16.168 1 NOISE udns_timer_cb
2022-10-06 11:43:16.168 1 NOISE udns_timer_setter: ctx=0x55a4515665e0 timeout=4
2022-10-06 11:43:16.168 1 DEBUG launch_new_connection: already progress
2022-10-06 11:43:16.168 1 NOISE udns_io_cb
2022-10-06 11:43:16.168 1 NOISE udns_result_a4: postgres-cluster: 1 ips
2022-10-06 11:43:16.168 1 NOISE DNS: postgres-cluster[0] = 10.43.169.137:0 [STREAM]
2022-10-06 11:43:16.168 1 NOISE dns: deliver_info(postgres-cluster) addr=10.43.169.137:0
2022-10-06 11:43:16.168 1 DEBUG S-0x55a45156ddf0: <database_name>/<user_name>@(bad-af):0 dns_callback: inet4: 10.43.169.137:5432
2022-10-06 11:43:16.168 1 DEBUG S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 launching new connection to server
2022-10-06 11:43:16.169 1 NOISE udns_timer_setter: ctx=0x55a4515665e0 timeout=-1
2022-10-06 11:43:16.169 1 DEBUG launch_new_connection: already progress
2022-10-06 11:43:16.169 1 DEBUG S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 S: connect ok
2022-10-06 11:43:16.169 1 LOG S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 new connection to server (from 10.42.2.120:54000)
2022-10-06 11:43:16.169 1 NOISE S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 P: SSL request
2022-10-06 11:43:16.169 1 DEBUG launch_new_connection: already progress
2022-10-06 11:43:16.175 1 NOISE resync: done=0, parse=0, recv=0
2022-10-06 11:43:16.175 1 NOISE S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 launching tls
2022-10-06 11:43:16.175 1 NOISE resync: done=1, parse=1, recv=1
2022-10-06 11:43:16.175 1 NOISE tls_handshake: err=-2
2022-10-06 11:43:16.175 1 DEBUG launch_new_connection: already progress
2022-10-06 11:43:16.183 1 NOISE tls_handshake: err=-2
2022-10-06 11:43:16.183 1 DEBUG launch_new_connection: already progress
2022-10-06 11:43:16.184 1 NOISE tls_handshake: err=-1
**2022-10-06 11:43:16.184 1 WARNING TLS handshake error: handshake failed: error:1401E418:SSL routines:CONNECT_CR_FINISHED:tlsv1 alert unknown ca**
2022-10-06 11:43:16.184 1 LOG S-0x55a45156ddf0: <database_name>/<user_name>@10.43.169.137:5432 closing because: server conn crashed? (age=0)
2022-10-06 11:43:16.184 1 NOISE tls_close

Postgres logs show below error:


    "postgres","aorsdb","authentication","connection authenticated: 
    identity=""postgres"" method=md5 
    (/home/postgres/pgdata/pgroot/data/pg_hba.conf:12) 
    "postgres","aorsdb","authentication","connection authorized: 
    user=postgres database=aorsdb application_name=pgwatch2 SSL enabled 
    (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256) "could 
    not accept SSL connection: certificate verify failed

Can anyone suggest what might be wrong and what I can look at? pgbouncer.ini file:

[databases]
* = host=postgres-cluster port=5432 auth_user=postgres

[pgbouncer]
listen_addr = *
listen_port = 5432
pool_mode = session
max_client_conn = 100
ignore_startup_parameters = extra_float_digits
server_tls_sslmode = require
server_tls_key_file = /etc/pgbouncer/certs/server.key
server_tls_cert_file = /etc/pgbouncer/certs/server.crt
server_tls_ca_file = /etc/pgbouncer/certs/ca.crt
verbose = 2

Few questions:

  • Since both postgres and pgbouncer's certificates are signed by the same CA what can be the issue?
  • Also I want to understand the flow, so based on the ip addresses in the logs, it is pgbouncer trying to communicate to postgres(as expected), so I thought process is that postgres is unable to recognise the CA and throws this error, is it correct or is it the other way around(pgbouncer is rejecting and throwing this error). Ideally I am hoping this should not happen as both are signed by the same CA.

I have done multiple things like mounting certificates in pgbouncer pod signed by the ROOT_CA itself, mounting certificate chain for pgbouncer(Generated certificate, Intermediate CA, ROOT CA) but no luck so far.

Solution

  • For me when I just use Intermediate_CA for pgbouncer, I can see it working properly and SSL connection getting established. Problem seems to be that postgres was not able to validate the SSL certificate that I was mounting in pgbouncer pod.