Thread: psql sslmode behavior and trace_connection_negotiation in PG17

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=vzQgUsuqiTFjFDZaebdg@mail.gmail.com
Hao Zhang <kennthhz@gmail.com> writes:
> 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.

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?

> 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)

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