Thread: psql trying twice to connect to local DB

psql trying twice to connect to local DB

From
Steve Baldwin
Date:
I have a local DB (15.2) running in a docker container.

If I make a connection to that DB from most clients I see log entries like this:

2023-10-07 22:32:26.518 UTC,,,16278,"172.21.0.1:33192",6521dc7a.3f96,1,"",2023-10-07 22:32:26 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=33192",,,,,,,,,"","not initialized",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,2,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,3,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=crystal",,,,,,,,,"","client backend",,0

If however I use psql I see two connection log entries - sometimes almost a second apart. For example:

2023-10-07 22:33:16.214 UTC,,,16431,"172.21.0.1:48550",6521dcac.402f,1,"",2023-10-07 22:33:16 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48550",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.130 UTC,,,16432,"172.21.0.1:48558",6521dcad.4030,1,"",2023-10-07 22:33:17 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48558",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.151 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,2,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:33:17.152 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,3,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=psql",,,,,,,,,"","client backend",,0

The version of psql is 15.4.

Obviously this isn't a major problem, but I'm curious if I've got something configured incorrectly, or just something I missed from the docs.

Thanks,

Steve

Re: psql trying twice to connect to local DB

From
Steve Baldwin
Date:
It seems this is not restricted to local connections. Here's the log entries from making a connection with the same psql client to a remote (RDS) instance:

2023-10-07 22:47:06.506 UTC,,,23005,"10.117.100.26:55302",6521dfea.59dd,1,"",2023-10-07 22:47:06 UTC,,0,LOG,00000,"connection received: host=10.117.100.26 port=55302",,,,,,,,,"","not initialized",,0
2023-10-07 22:47:08.479 UTC,,,23010,"10.117.100.26:55306",6521dfec.59e2,1,"",2023-10-07 22:47:08 UTC,,0,LOG,00000,"connection received: host=10.117.100.26 port=55306",,,,,,,,,"","not initialized",,0
2023-10-07 22:47:09.992 UTC,"b2bc_owner","b2bcreditonline",23010,"10.117.100.26:55306",6521dfec.59e2,2,"authentication",2023-10-07 22:47:08 UTC,29/840773,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=md5 (/rdsdbdata/config/pg_hba.conf:14)",,,,,,,,,"","client backend",,0
2023-10-07 22:47:09.993 UTC,"b2bc_owner","b2bcreditonline",23010,"10.117.100.26:55306",6521dfec.59e2,3,"authentication",2023-10-07 22:47:08 UTC,29/840773,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=psql SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256)",,,,,,,,,"","client backend",,0

Compared to a connection made from our application:

2023-10-07 22:28:26.565 UTC,,,22121,"10.120.166.33:47748",6521db8a.5669,1,"",2023-10-07 22:28:26 UTC,,0,LOG,00000,"connection received: host=10.120.166.33 port=47748",,,,,,,,,"","not initialized",,0
2023-10-07 22:28:26.583 UTC,"b2bc_api","b2bcreditonline",22121,"10.120.166.33:47748",6521db8a.5669,2,"authentication",2023-10-07 22:28:26 UTC,18/1263698,0,LOG,00000,"connection authenticated: identity=""b2bc_api"" method=md5 (/rdsdbdata/config/pg_hba.conf:14)",,,,,,,,,"","client backend",,0
2023-10-07 22:28:26.583 UTC,"b2bc_api","b2bcreditonline",22121,"10.120.166.33:47748",6521db8a.5669,3,"authentication",2023-10-07 22:28:26 UTC,18/1263698,0,LOG,00000,"connection authorized: user=b2bc_api database=b2bcreditonline SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256)",,,,,,,,,"","client backend",,0

It seems psql 16.0 (homebrew) behaves the same.

Steve

On Sun, Oct 8, 2023 at 9:44 AM Steve Baldwin <steve.baldwin@gmail.com> wrote:
I have a local DB (15.2) running in a docker container.

If I make a connection to that DB from most clients I see log entries like this:

2023-10-07 22:32:26.518 UTC,,,16278,"172.21.0.1:33192",6521dc7a.3f96,1,"",2023-10-07 22:32:26 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=33192",,,,,,,,,"","not initialized",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,2,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,3,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=crystal",,,,,,,,,"","client backend",,0

If however I use psql I see two connection log entries - sometimes almost a second apart. For example:

2023-10-07 22:33:16.214 UTC,,,16431,"172.21.0.1:48550",6521dcac.402f,1,"",2023-10-07 22:33:16 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48550",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.130 UTC,,,16432,"172.21.0.1:48558",6521dcad.4030,1,"",2023-10-07 22:33:17 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48558",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.151 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,2,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:33:17.152 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,3,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=psql",,,,,,,,,"","client backend",,0

The version of psql is 15.4.

Obviously this isn't a major problem, but I'm curious if I've got something configured incorrectly, or just something I missed from the docs.

Thanks,

Steve

Re: psql trying twice to connect to local DB

From
Tom Lane
Date:
Steve Baldwin <steve.baldwin@gmail.com> writes:
> If I make a connection to that DB from most clients I see log entries like
> this:
> ...
> If however I use psql I see two connection log entries - sometimes almost a
> second apart. For example:

These log entries show that you're using password-based authentication.
I believe what is happening is that psql tries to connect, discovers
that it needs a password, and then tries again after it's got a
password.  The delay would correspond to the time for you to type
your password (I take it you're a fast typist).

If you don't like the extra log entries, there's a command-line
switch that forces psql to prompt for password before connecting
the first time.  Of course, that might result in prompting for
a password that's not really needed.

            regards, tom lane



Re: psql trying twice to connect to local DB

From
Ron
Date:
On 10/7/23 17:44, Steve Baldwin wrote:
I have a local DB (15.2) running in a docker container.

If I make a connection to that DB from most clients I see log entries like this:

2023-10-07 22:32:26.518 UTC,,,16278,"172.21.0.1:33192",6521dc7a.3f96,1,"",2023-10-07 22:32:26 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=33192",,,,,,,,,"","not initialized",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,2,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:32:26.529 UTC,"b2bc_owner","b2bcreditonline",16278,"172.21.0.1:33192",6521dc7a.3f96,3,"authentication",2023-10-07 22:32:26 UTC,4/340,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=crystal",,,,,,,,,"","client backend",,0

If however I use psql I see two connection log entries - sometimes almost a second apart. For example:

2023-10-07 22:33:16.214 UTC,,,16431,"172.21.0.1:48550",6521dcac.402f,1,"",2023-10-07 22:33:16 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48550",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.130 UTC,,,16432,"172.21.0.1:48558",6521dcad.4030,1,"",2023-10-07 22:33:17 UTC,,0,LOG,00000,"connection received: host=172.21.0.1 port=48558",,,,,,,,,"","not initialized",,0
2023-10-07 22:33:17.151 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,2,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authenticated: identity=""b2bc_owner"" method=scram-sha-256 (/var/lib/postgresql/data/pg_hba.conf:100)",,,,,,,,,"","client backend",,0
2023-10-07 22:33:17.152 UTC,"b2bc_owner","b2bcreditonline",16432,"172.21.0.1:48558",6521dcad.4030,3,"authentication",2023-10-07 22:33:17 UTC,4/354,0,LOG,00000,"connection authorized: user=b2bc_owner database=b2bcreditonline application_name=psql",,,,,,,,,"","client backend",,0

The version of psql is 15.4.

Obviously this isn't a major problem, but I'm curious if I've got something configured incorrectly, or just something I missed from the docs.

As follow-up to Tom's response: create a .pgpass file with an entry for b2bc_owner.  There might still be two entries, but the time between the two of them should be instantaneous.

--
Born in Arizona, moved to Babylonia.