Subject: psql sslmode behavior and trace_connection_negotiation in PG17

From: Hao Zhang <[email-masked]>
Date: Wed, 17 Jul 2024 21:12:52 -0700

Hi

I tried to connect with psql + client sslmode = require + server requiring
ssl with PG17 and trace_connection_negotiation = "on". So "SSLRequest
accepted" is logged twice with two different PID. I believe the PID 15553
is psql and 15554 is the PG backend. How do you explain the two connections
with SSLRequest? From the log, it seems psql made a connection to itself
with SSLRequest and proxied that to Postgres server with a full SSL
negotiation. I never saw a log on 15553's connection being closed when I
closed the psql process. Does this behavior match what was talked about in
the below hacker thread on additional connection?

2024-07-17 03:06:54.492 PDT [15553] LOG:  connection received:
host=127.0.0.1 port=54002
2024-07-17 03:06:54.492 PDT [15553] LOG:  SSLRequest accepted
2024-07-17 03:06:59.982 PDT [15554] LOG:  connection received:
host=127.0.0.1 port=54004
2024-07-17 03:06:59.982 PDT [15554] LOG:  SSLRequest accepted
2024-07-17 03:06:59.994 PDT [15554] LOG:  connection authenticated:
identity="postgres" method=md5 (/usr/local/pgsql/data/pg_hba.conf:18)
2024-07-17 03:06:59.994 PDT [15554] LOG:  connection authorized:
user=postgres database=postgres application_name=psql SSL enabled
(protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256)

https://www.postgresql.org/message-id/flat/CAM-w4HOEAzxyY01ZKOj-iq=M4-VDk=[email-masked]

---

From: Tom Lane <[email-masked]>
Date: Thu, 18 Jul 2024 00:48:30 -0400

Hao Zhang <[email-masked]> writes:
> is psql and 15554 is the PG backend.

Certainly not: psql has no ability to write to the postmaster log.
These PIDs are two different backend sessions.

> How do you explain the two connections
> with SSLRequest?

> (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256)

The first connection comes from psql trying to connect and discovering
that a password is required.  It gives up on that connection because
it hasn't got a password, and asks the user (you) for that.  We can
see from the log that it took about five-n-a-half seconds for you
to type your password, and then there was a second connection attempt
that was successful.

By default, the server doesn't log unceremonious client disconnections
after the password challenge, precisely because psql behaves this way.
So that's why we don't see any disconnection log entry from the
ill-fated 15553 session.  I kind of wonder if we could suppress these
other log entries too, but it's not very clear how.

If this behavior really annoys you, you can use psql's -W switch
to force it to prompt for a password in advance of knowing whether
the server will demand one.

			regards, tom lane