From: Tom Lane <tgl@sss.pgh.pa.us>
To: Hao Zhang <kennthhz@gmail.com>
cc: pgsql-general <pgsql-general@lists.postgresql.org>
Subject: Re: psql sslmode behavior and trace_connection_negotiation in PG17
In-reply-to: <CAGXpB2mwQqJv0pJL8u1ZduiUERYuWxr8_xdGbhWRAfmYyq8J7g@mail.gmail.com>
References: <CAGXpB2mwQqJv0pJL8u1ZduiUERYuWxr8_xdGbhWRAfmYyq8J7g@mail.gmail.com>
Comments: In-reply-to Hao Zhang <kennthhz@gmail.com>
	message dated "Wed, 17 Jul 2024 21:12:52 -0700"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <3645732.1721278110.1@sss.pgh.pa.us>
Date: Thu, 18 Jul 2024 00:48:30 -0400
Message-ID: <3645733.1721278110@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/3645733.1721278110%40sss.pgh.pa.us>
Precedence: bulk

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