Обсуждение: application_name backend (not) reporting back to the client : pgbouncer, PgSQL 16.1, pgbouncer 1.21.0

Hello

For the past few days now we were investigating a strange issue that 
affected our new test environment  : PostgreSQL 16.1 with pgbouncer 
1.21.0 . We tested with previous versions of pgbouncer against PgSQL 
16.1 and 10.23 and the conclusion was the problem existed only against 
pgsql 16 no matter the pgbouncer version. Also the problem existed only 
with pool_mode = transaction .

The scenario goes like that :

Client C1 connects and issues :

SET application_name TO 'TEST';

-- some other short SQL

-- sleeps


then immediately after,

Client C2 connects and issues :

SET application_name TO 'TEST';

-- some other short SQL

-- sleeps


By looking at pgbouncer sockets (show sockets) we verified that client 
C1 runs against server S1 and gets back the application_name correctly. 
However client C2 only gets the correct application name if it is 
assigned to a new server. If C2 happens to be assigned to S1, then 
although it issues SET application_name TO 'TEST'; and this is executed 
by S1 (which has the application_name='TEST' already set), S1 does not 
report application_name back to C2, leaving with empty application_name. 
If now S1 closes due to server idle timeout, when later C2 wakes app to 
do some more work, it will send application_name= (empty) to the new 
server  reported as "unknown" , breaking our application (which depends 
on application_name).

Our suspicion was that pgsql backend does not report the 
application_name back to the client if the value sent by the client with 
the SET command is the same as the already existing value on the backend.

So, we worked around this by defining an non empty dummy application 
name = '' with the startup packet (on the URL), thus making the server 
to report back the second correct app name set with the SET command.

So I would like to ask has anything changed in this regard between 
PostgreSQL 10.* and 16.* ?

Thank you!

Achilleas Mantzios - cloud <a.mantzios@cloud.gatewaynet.com> writes:
> For the past few days now we were investigating a strange issue that 
> affected our new test environment  : PostgreSQL 16.1 with pgbouncer 
> 1.21.0 . We tested with previous versions of pgbouncer against PgSQL 
> 16.1 and 10.23 and the conclusion was the problem existed only against 
> pgsql 16 no matter the pgbouncer version. Also the problem existed only 
> with pool_mode = transaction .

Surely this is a pgbouncer issue that you need to discuss with the
pgbouncer authors.  PG does not keep multiple values of application_name
per session, so you must not be connecting to the session you think
you are.

            regards, tom lane

Achilleas Mantzios - cloud <a.mantzios@cloud.gatewaynet.com> writes:

For the past few days now we were investigating a strange issue that 
affected our new test environment  : PostgreSQL 16.1 with pgbouncer 
1.21.0 . We tested with previous versions of pgbouncer against PgSQL 
16.1 and 10.23 and the conclusion was the problem existed only against 
pgsql 16 no matter the pgbouncer version. Also the problem existed only 
with pool_mode = transaction .

Surely this is a pgbouncer issue that you need to discuss with the
pgbouncer authors.  PG does not keep multiple values of application_name
per session, so you must not be connecting to the session you think
you are.

Hello Tom,

I would very much like this to have been a pgbouncer issue but it is not. I was hoping I expressed the situation clearly, I am sorry if I didn't. This is not about any multiple values per session, I send a simple test below that reproduces the problem very easily (against *any* pgbouncer 1.18+). The behavior of pgsql 16.1 is that it does not report a SET application_name=... back to the client if the new value is the same as the current one. This wasn't the behavior in pgsql 10. So I am asking if there has been any change in the backend with regards to application_name, GUC_REPORT params and the like. Unfortunately I have no pgsql 12, 13, 14, or 15 handy in order to test with them as well.

The test script that demonstrates the issue is :

prob.sh

#!/usr/local/bin/bash
if [ $# -ne 2 ]
then
 echo "Usage: `basename $0` pipename application_name"
 exit 1
fi
PIPENAME=$1
APPLICATION_NAME=$2
mkfifo -m "a=rw" /tmp/$PIPENAME
sleep 10000 > /tmp/$PIPENAME &
#psql "postgresql://amantzio@localhost:6432/dynacom?application_name=''" -f /tmp/$PIPENAME &
psql "postgresql://amantzio@localhost:6432/dynacom?application_name=" -f /tmp/$PIPENAME &
# application_name on the URL must be set as application_name= (empty), setting to e.g. ='' does defeats teh problem
echo "SET application_name='$APPLICATION_NAME';"  > /tmp/$PIPENAME
sleep 10
echo "\q"  > /tmp/$PIPENAME
rm /tmp/$PIPENAME

We open psql on the pgbouncer and give show sockets , followed by \watch 1

Then on one terminal we give :

./prob.sh myfifo "TEST"

and immediately after, on a second terminal :

./prob.sh myfifo2 "TEST"

We will see that the second client has empty application_name in show sockets.

*if* however, one changes the connection in the script to read like :

psql "postgresql://amantzio@localhost:6432/dynacom?application_name=''" -f /tmp/$PIPENAME &

i.e. give an initial non empty application_name (which will be reported back to the client btw), then the subsequent : SET application_name='$APPLICATION_NAME';

will change the backend's application_name (from '' to $APPLICATION_NAME ) and always trigger a reporting back to the client, thus solving the problem. From this point on, the client as long as it does not issue a new SET application_name=, will always carry this correct application_name inside the client's state (pgbouncer).

I hope I was clearer this time.

Thank you!

			regards, tom lane

Achilleas Mantzios - cloud <a.mantzios@cloud.gatewaynet.com> writes:
> I would very much like this to have been a pgbouncer issue but it is 
> not. I was hoping I expressed the situation clearly, I am sorry if I 
> didn't. This is not about any multiple values per session, I send a 
> simple test below that reproduces the problem very easily (against *any* 
> pgbouncer 1.18+). The behavior of pgsql 16.1 is that it does not report 
> a SET application_name=... back to the client if the new value is the 
> same as the current one. This wasn't the behavior in pgsql 10.

No, but it's been true since v14 (cf commit 2432b1a04).  In any case,
the test case you're showing doesn't look like it'd exercise that
behavior, since the SET is installing a new value.

I did a bit of testing of the behavior of "application_name=" in the
connection string followed by an explicit SET, and AFAICS we do send
a ParameterStatus report from the SET, with no apparent change in
behavior from quite far back (I tried 9.5 for comparison).  So I
continue to maintain that this is a pgbouncer problem.  Maybe it
has not been updated for the no-duplicate-reports server behavior?
Although it's still hard to see why that would matter here.

            regards, tom lane

Achilleas Mantzios - cloud <a.mantzios@cloud.gatewaynet.com> writes:

I would very much like this to have been a pgbouncer issue but it is 
not. I was hoping I expressed the situation clearly, I am sorry if I 
didn't. This is not about any multiple values per session, I send a 
simple test below that reproduces the problem very easily (against *any* 
pgbouncer 1.18+). The behavior of pgsql 16.1 is that it does not report 
a SET application_name=... back to the client if the new value is the 
same as the current one. This wasn't the behavior in pgsql 10.

No, but it's been true since v14 (cf commit 2432b1a04).  In any case,

Thanks!! This : https://github.com/postgres/postgres/commit/2432b1a04087edc2fd9536c7c9aa4ca03fd1b363

looks like exactly the explanation I was looking for!

the test case you're showing doesn't look like it'd exercise that
behavior, since the SET is installing a new value.

Our app is java, and our jdbc driver by default reports no application_name, I dont dare to tell the jdbc version tho, its old :( . So if the connection string is like in :

psql "postgresql://amantzio@localhost:6432/dynacom?application_name="

then no application_name is set on the server with the startup packet (just like with our jdbc), so if the subsequent SET from the client runs against a server backend with this application_name already set by a previous client (pgbouncer in transaction mode), and is found to be equal, the backend will not report back to the client, as per the commit 2432b1a . *But* if the connection string is like

psql "postgresql://amantzio@localhost:6432/dynacom?application_name=' '" or even

psql "postgresql://amantzio@localhost:6432/dynacom?application_name=''" 

Then the server will accept this as non null/empty value, will set the application_name, and a subsequent SET (with a real application name) will cause the server to report back no matter what.

At least this is my theory.

I did a bit of testing of the behavior of "application_name=" in the
connection string followed by an explicit SET, and AFAICS we do send

a ParameterStatus report from the SET, with no apparent change in
behavior from quite far back (I tried 9.5 for comparison).  So I
continue to maintain that this is a pgbouncer problem.  Maybe it
has not been updated for the no-duplicate-reports server behavior?
Although it's still hard to see why that would matter here.

Hm so, you think pgbouncer in transaction mode, should somehow "hack" application name in order to enforce a subsequent report from the server ? But how can pgbouncer predict the future ? And AFAIK, pgbouncer does not parse or reads any statements (well before the prepared statement feature, I mean)

Please check the scenario

Client C1 connects to S1, sets application_name. BEGINS, COMMITS, the server gets freed to server the next client.

Client C2 connects to the same S1, sets application_name, and gets no report back. So it stays with application_name empty. Then this breaks the application.

How could pgbouncer prevent this from happening ?

			regards, tom lane

-- 
Achilleas Mantzios IT DEV - HEAD IT DEPT Dynacom Tankers Mgmt

Achilleas Mantzios <a.mantzios@cloud.gatewaynet.com> writes:
> the trick is to have "application_name=" with no value.  This causes the 
> server to not set application_name initially.

No, that sets it to an empty string, while application_name='' sets
it to two single quotes, according to the testing I did.  In either
case, that value will be reported to the client as the active value
during connection start.  Then the subsequent SET causes a new
report, but (since v14) only if the value being set is different.

> Please check the scenario

> Client C1 connects to S1, sets application_name. BEGINS, COMMITS, the 
> server gets freed to server the next client.

> Client C2 connects to the same S1, sets application_name, and gets no 
> report back. So it stays with application_name empty. Then this breaks 
> the application.

> How could pgbouncer prevent this from happening ?

pgbouncer would have to regurgitate the latest ParameterStatus
messages to the new client (during its faked-up initial connection
handshake) to ensure everything's synchronized correctly.
If for some reason it's not doing that, that would be a pretty
serious bug if you ask me, since clients might be relying on
hearing the truth about settings like client_encoding.  Since
the whole point of pgbouncer is that the backend doesn't know
a new client has been slotted in, it's not clear to me how or
why the backend should solve this.

            regards, tom lane

Στις 9/12/23 00:54, ο/η Tom Lane έγραψε:
> Achilleas Mantzios <a.mantzios@cloud.gatewaynet.com> writes:
>> the trick is to have "application_name=" with no value.  This causes the
>> server to not set application_name initially.
> No, that sets it to an empty string, while application_name='' sets
> it to two single quotes, according to the testing I did.  In either
> case, that value will be reported to the client as the active value
> during connection start.  Then the subsequent SET causes a new
> report, but (since v14) only if the value being set is different.

Thank you Tom, now I see we have a different behavior, I have uploaded a 
video that demonstrates my case : https://youtu.be/qcrVsFszV0Y

I didn't have the time to fire up wireshark/tcpdump or debugger thought 
(I should).

>
>> Please check the scenario
>> Client C1 connects to S1, sets application_name. BEGINS, COMMITS, the
>> server gets freed to server the next client.
>> Client C2 connects to the same S1, sets application_name, and gets no
>> report back. So it stays with application_name empty. Then this breaks
>> the application.
>> How could pgbouncer prevent this from happening ?
> pgbouncer would have to regurgitate the latest ParameterStatus
> messages to the new client (during its faked-up initial connection
> handshake) to ensure everything's synchronized correctly.
> If for some reason it's not doing that, that would be a pretty
> serious bug if you ask me, since clients might be relying on
> hearing the truth about settings like client_encoding.  Since
> the whole point of pgbouncer is that the backend doesn't know
> a new client has been slotted in, it's not clear to me how or
> why the backend should solve this.
You helped a great deal! It is time I open an issue on the pgbouncer 
project.
>
>             regards, tom lane

-- 
Achilleas Mantzios
  IT DEV - HEAD
  IT DEPT
  Dynacom Tankers Mgmt

Στις 9/12/23 00:54, ο/η Tom Lane έγραψε:

Achilleas Mantzios <a.mantzios@cloud.gatewaynet.com> writes:

the trick is to have "application_name=" with no value.  This causes the
server to not set application_name initially.

No, that sets it to an empty string, while application_name='' sets
it to two single quotes, according to the testing I did.  In either
case, that value will be reported to the client as the active value
during connection start.  Then the subsequent SET causes a new
report, but (since v14) only if the value being set is different.

Hi again, I am puzzled with your observations, this is what I get with psql straight against PostgreSQL no pgbouncer involved :

command :

psql "postgresql://amantzio@localhost:5432/dynacom?application_name="

output of

tcpdump -A -i lo0 port 5432

23:29:00.415684 IP localhost.31933 > localhost.postgresql: Flags [S], seq 3719751018, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 1343970026 ecr 0], length 0
E..<..@.@...........|..8...j.........0....?........
P.Z.....
23:29:00.415709 IP localhost.postgresql > localhost.31933: Flags [S.], seq 853757380, ack 3719751019, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 3656173586 ecr 134397
0026], length 0
E..<..@.@............8|.2.M....k.....0....?........
....P.Z.
23:29:00.415715 IP localhost.31933 > localhost.postgresql: Flags [.], ack 1, win 1277, options [nop,nop,TS val 1343970026 ecr 3656173586], length 0
E..4..@.@...........|..8...k2.M......(.....
P.Z.....
23:29:00.415726 IP localhost.31933 > localhost.postgresql: Flags [P.], seq 1:62, ack 1, win 1277, options [nop,nop,TS val 1343970026 ecr 3656173586], length 61
E..q..@.@...........|..8...k2.M......e.....
P.Z........=....user.amantzio.database.dynacom.client_encoding.UTF8..
23:29:00.422757 IP localhost.postgresql > localhost.31933: Flags [P.], seq 1:25, ack 62, win 1277, options [nop,nop,TS val 3656173593 ecr 1343970026], length 24
E..L..@.@............8|.2.M..........@.....
....P.Z.R.......
SCRAM-SHA-256..
23:29:00.422823 IP localhost.31933 > localhost.postgresql: Flags [P.], seq 62:117, ack 25, win 1277, options [nop,nop,TS val 1343970033 ecr 3656173593], length 55
E..k..@.@...........|..8....2.M......_.....
P.Z.....p...6SCRAM-SHA-256.... n,,n=,r=xLI34cA0s3ulrSX41qzrzJNE
23:29:00.422848 IP localhost.postgresql > localhost.31933: Flags [P.], seq 25:118, ack 117, win 1277, options [nop,nop,TS val 3656173593 ecr 1343970033], length 93
E.....@.@............8|.2.M................
....P.Z.R...\....r=xLI34cA0s3ulrSX41qzrzJNEw0094sbRThtReDwT6vPnaWkp,s=XM8Nr2tZlFupSjKagSRfoA==,i=4096
23:29:00.426522 IP localhost.31933 > localhost.postgresql: Flags [P.], seq 117:226, ack 118, win 1277, options [nop,nop,TS val 1343970037 ecr 3656173593], length 109
E.....@.@...........|..8....2.N:...........
P.Z.....p...lc=biws,r=xLI34cA0s3ulrSX41qzrzJNEw0094sbRThtReDwT6vPnaWkp,p=kw91XX5R0KaMJdhbflhGnqMrcMOLUcXMgQahtbRcvjo=
23:29:00.427387 IP localhost.postgresql > localhost.31933: Flags [P.], seq 118:628, ack 226, win 1277, options [nop,nop,TS val 3656173598 ecr 1343970037], length 510
E..2..@.@............8|.2.N:...L.....'.....
....P.Z.R...6....v=+WtTPDH2DwVEhjUsUdUeuj74aFk7DyEVIU93ZlBV+pM=R........S....in_hot_standby.off.S....integer_datetimes.on.S....TimeZone.Europe/Athens.S....IntervalStyle.postgres.S.
.. search_path."$user", public.S....is_superuser.on.S....application_name..S...&default_transaction_read_only.off.S....scram_iterations.4096.S....DateStyle.ISO, MDY.S...#standard_c
onforming_strings.on.S...#session_authorization.amantzio.S....client_encoding.UTF8.S....server_version.16.1.S....server_encoding.SQL_ASCII.K.......7b9..Z....I
23:29:00.467550 IP localhost.31933 > localhost.postgresql: Flags [.], ack 628, win 1277, options [nop,nop,TS val 1343970078 ecr 3656173598], length 0
E..4..@.@...........|..8...L2.P8.....(.....
P.[.....

the client does not send the application_name

whereas with :

psql "postgresql://amantzio@localhost:5432/dynacom?application_name=''"

output of

tcpdump -A -i lo0 port 5432

23:31:45.583442 IP localhost.13693 > localhost.postgresql: Flags [S], seq 2640334946, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 300427204 ecr 0], length 0
E..<..@.@...........5}.8.`Pb.........0....?........
..'.....
23:31:45.583468 IP localhost.postgresql > localhost.13693: Flags [S.], seq 3340481072, ack 2640334947, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 2261783934 ecr 30042
7204], length 0
E..<..@.@............85}...0.`Pc.....0....?........
...~..'.
23:31:45.583475 IP localhost.13693 > localhost.postgresql: Flags [.], ack 1, win 1277, options [nop,nop,TS val 300427204 ecr 2261783934], length 0
E..4..@.@...........5}.8.`Pc...1.....(.....
..'....~
23:31:45.583486 IP localhost.13693 > localhost.postgresql: Flags [P.], seq 1:82, ack 1, win 1277, options [nop,nop,TS val 300427204 ecr 2261783934], length 81
E.....@.@...........5}.8.`Pc...1.....y.....
..'....~...Q....user.amantzio.database.dynacom.application_name.''.client_encoding.UTF8..
23:31:45.590522 IP localhost.postgresql > localhost.13693: Flags [P.], seq 1:25, ack 82, win 1277, options [nop,nop,TS val 2261783941 ecr 300427204], length 24
E..L..@.@............85}...1.`P......@.....
......'.R.......
SCRAM-SHA-256..
23:31:45.590584 IP localhost.13693 > localhost.postgresql: Flags [P.], seq 82:137, ack 25, win 1277, options [nop,nop,TS val 300427211 ecr 2261783941], length 55
E..k..@.@...........5}.8.`P....I....._.....
..'.....p...6SCRAM-SHA-256.... n,,n=,r=LAq5jZmt0f+ctvHXopjbPPjG
23:31:45.590609 IP localhost.postgresql > localhost.13693: Flags [P.], seq 25:118, ack 137, win 1277, options [nop,nop,TS val 2261783941 ecr 300427211], length 93
E.....@.@............85}...I.`P............
......'.R...\....r=LAq5jZmt0f+ctvHXopjbPPjGjTRnO+1qZXj04XCbh+soRT0h,s=XM8Nr2tZlFupSjKagSRfoA==,i=4096
23:31:45.594310 IP localhost.13693 > localhost.postgresql: Flags [P.], seq 137:246, ack 118, win 1277, options [nop,nop,TS val 300427215 ecr 2261783941], length 109
E.....@.@...........5}.8.`P................
..'.....p...lc=biws,r=LAq5jZmt0f+ctvHXopjbPPjGjTRnO+1qZXj04XCbh+soRT0h,p=a9lhA0XYHDiwFwOVAUzm0eznroj0R1WD9Fd+DQXfuns=
23:31:45.595130 IP localhost.postgresql > localhost.13693: Flags [P.], seq 118:630, ack 246, win 1277, options [nop,nop,TS val 2261783946 ecr 300427215], length 512
E..4..@.@............85}.....`QX.....).....
......'.R...6....v=WezHjvAUp5Rq8fBZFVGmgaxewdiIGClYMtVVUTyc5lQ=R........S....in_hot_standby.off.S....integer_datetimes.on.S....TimeZone.Europe/Athens.S....IntervalStyle.postgres.S.
.. search_path."$user", public.S....is_superuser.on.S....application_name.''.S...&default_transaction_read_only.off.S....scram_iterations.4096.S....DateStyle.ISO, MDY.S...#standard
_conforming_strings.on.S...#session_authorization.amantzio.S....client_encoding.UTF8.S....server_version.16.1.S....server_encoding.SQL_ASCII.K.......a.).HZ....I
23:31:45.637878 IP localhost.13693 > localhost.postgresql: Flags [.], ack 630, win 1277, options [nop,nop,TS val 300427259 ecr 2261783946], length 0
E..4..@.@...........5}.8.`QX.........(.....
..'.....

In this case I see that the client sends the application name. Please tell me what may I missing here.

It does not solve or even alleviate the severity of the problem, but I think this behavior is part of the picture.

thank you.

            regards, tom lane

-- 
Achilleas Mantzios IT DEV - HEAD IT DEPT Dynacom Tankers Mgmt

Achilleas Mantzios <a.mantzios@cloud.gatewaynet.com> writes:
> Hi again, I am puzzled with your observations, this is what I get with
> psql straight against PostgreSQL no pgbouncer involved :

> command :
> psql "postgresql://amantzio@localhost:5432/dynacom?application_name="

> ...
>
public.S....is_superuser.on.S....application_name..S...&default_transaction_read_only.off.S....scram_iterations.4096.S....DateStyle.ISO,

                              ^^^^^^^^^^^^^^^^^^^^^^^

I see the report of application_name with an empty-string value right
there.

> the client does not send the application_name

I do not know what you mean by that, but maybe your client code has
some special-case behavior for an empty string?

            regards, tom lane

Achilleas Mantzios <a.mantzios@cloud.gatewaynet.com> writes:

Hi again, I am puzzled with your observations, this is what I get with 
psql straight against PostgreSQL no pgbouncer involved :

command :
psql "postgresql://amantzio@localhost:5432/dynacom?application_name="

...
public.S....is_superuser.on.S....application_name..S...&default_transaction_read_only.off.S....scram_iterations.4096.S....DateStyle.ISO, 

                              ^^^^^^^^^^^^^^^^^^^^^^^

I see the report of application_name with an empty-string value right
there.

the client does not send the application_name

I do not know what you mean by that, but maybe your client code has
some special-case behavior for an empty string?

The above  was plain vanilla psql, nothing special. Let me show the two startup packets (psql -> pgsql) in each case :

case 1:  psql "postgresql://amantzio@localhost:5432/dynacom?application_name="

23:29:00.415726 IP localhost.31933 > localhost.postgresql: Flags [P.], seq 1:62, ack 1, win 1277, options [nop,nop,TS val 1343970026 ecr 3656173586], length 61
E..q..@.@...........|..8...k2.M......e.....
P.Z........=....user.amantzio.database.dynacom.client_encoding.UTF8..

case 2:  psql "postgresql://amantzio@localhost:5432/dynacom?application_name=''" 

23:31:45.583486 IP localhost.13693 > localhost.postgresql: Flags [P.], seq 1:82, ack 1, win 1277, options [nop,nop,TS val 300427204 ecr 2261783934], length 81
E.....@.@...........5}.8.`Pc...1.....y.....
..'....~...Q....user.amantzio.database.dynacom.application_name.''.client_encoding.UTF8..

So, in the first case (application_name=) , there is not explicit setting of application_name by the client in the startup packet, whereas in the second case (application_name='') there is. 

On this observation we based our temporary solution for the core problem described in this thread : Our trick to workaround this , is to define a dummy string e.g. '' in the startup packet, followed by an explicit SET application_name='OurApplicationName' so that the backend always receives two consecutive settings, and always understands the 2nd as a changed value, so it always reports the correct application_name back to the pgbouncer .

			regards, tom lane

-- 
Achilleas Mantzios IT DEV - HEAD IT DEPT Dynacom Tankers Mgmt

For the record this is the issue report for pgbouncer :
https://github.com/pgbouncer/pgbouncer/issues/993

-- 
Achilleas Mantzios
  IT DEV - HEAD
  IT DEPT
  Dynacom Tankers Mgmt