Queries SET DateStyle='ISO'; appeared in every transaction after migration to pg 14

[zurikus]

Hi, I'm not sure if I'm opening discussion in correct place, but I will really appreciate any help, advice or guidance.

We are using pgbouncer in transaction pooling mode in our setup and it's looking like following : app ---> pgbouncer ---> Postgres.
Postgres and pgbouncer are running on same server on Rocky OS.

Applications are using PostgreSQL JDBC Driver 42.2.24 or 42.3.3 mainly.
Pgbouncer package is used 1.16.1-10.rhel8.
And Postgres was migrated from 12 version to 14 version.

After Migration to Postgres 14 we are starting to observe queries: SET DateStyle='ISO'; on Postgres side.
So, because of this situation we are getting additional Query calls to our Postgres 14 cluster from pgbouncer side.

Can you please tell us if it is intended to be so? On Postgres 12 we didn't monitor such Queries.
So, after migration to Postgres 14 version nothing was changed on pgbouncer configuration side. Non default parameters that we are using are:

[databases]
* = host=127.0.0.1


[pgbouncer]
logfile = /var/log/postgresql/pgbouncer.log
pidfile = /var/run/postgresql/pgbouncer.pid
listen_addr = *
listen_port = 6432
unix_socket_dir = /var/run/postgresql
auth_type = md5
auth_file = /etc/pgbouncer/userlist.txt
admin_users = pgbouncer
stats_users = pgbouncer,okagent
pool_mode = transaction
server_reset_query = DISCARD ALL
server_connect_timeout = 300
ignore_startup_parameters = extra_float_digits
max_client_conn = 10000
default_pool_size = 10
query_wait_timeout = 300
log_connections = 0
log_disconnections = 0

DateStyle parameter on Postgres side after migration was not changed as well and it is:

$ psql
psql (14.5)
Type "help" for help.

13:50:42 [postgres] # show datestyle;
 DateStyle
-----------
 ISO, MDY
(1 row)

I was trying to use datestyle parameter in pgbouncer.ini file explicitly

[databases]
* = host=127.0.0.1 datestyle='ISO, MDY'

but this didn't changed anything.

Also I was trying to upgrade pgbouncer to 1.17.0-10.rhel8, this didn't worked either. Query SET DateStyle='ISO'; remains.

With verbose=2 parameter in pgbouncer.ini we are able to see records like these in the pgbouncer.log:

2022-11-09 16:24:05.811 MSK [2997433] DEBUG S-0x563a4975b8d0: dbuser/dbname@127.0.0.1:5432 varcache_apply: SET DateStyle='ISO';

On database side logs it's looking like so:

2022-11-09 14:53:01.199 UTC,"dbuser","dbname",3182464,"127.0.0.1:19074",636bb713.308f80,748,"SET",2022-11-09 14:20:03 UTC,14/0,0,LOG,00000,"duration: 0.090 ms  statement: SET DateStyle='ISO';",,,,,,,,,"PostgreSQL JDBC Driver","client backend",,-7713842022241034850

Just in case this is also matter pg_stat_statements extension is used.
After postgres upgrade from version 12 to 14 it's updated from 1.6 to 1.9.

[eulerto]

Can you please tell us if it is intended to be so? On Postgres 12 we didn't monitor such Queries.

That's because client parameters diverge from server parameters. In this case, the JDBC driver set DateStyle:

https://github.com/pgjdbc/pgjdbc/blob/ec0ff893ebd0390bd9af38a9a1e67b606df79503/pgjdbc/src/main/java/org/postgresql/core/v3/ConnectionFactoryImpl.java#L373-L380

but Postgres has DateStyle = 'ISO, MDY' as you said.

PgBouncer applies a new setting to use what client provides.

pgbouncer/src/varcache.c

Lines 117 to 144 in cffa192

	bool varcache_apply(PgSocket *server, PgSocket *client, bool *changes_p)
	{
	int changes = 0;
	struct PStr *cval, *sval;
	const struct var_lookup *lk;
	int sql_ofs;
	struct PktBuf *pkt = pktbuf_temp();
	pktbuf_start_packet(pkt, 'Q');
	/* grab query position inside pkt */
	sql_ofs = pktbuf_written(pkt);
	for (lk = lookup; lk->name; lk++) {
	sval = get_value(&server->vars, lk);
	cval = get_value(&client->vars, lk);
	changes += apply_var(pkt, lk->name, cval, sval);
	}
	*changes_p = changes > 0;
	if (!changes)
	return true;
	pktbuf_put_char(pkt, 0);
	pktbuf_finish_packet(pkt);
	slog_debug(server, "varcache_apply: %s", pkt->buf + sql_ofs);
	return pktbuf_send_immediate(pkt, server);
	}

[zurikus]

Hi, thank you for your response.
Yes, looks like client is setting ISO DateStyle by default, but it was no problem with postgresql 12.
pgjdbc/pgjdbc#1081

Also, why this query present even if we are setting datestyle in pgbouncer.ini file explicitly?

[databases]
* = host=127.0.0.1 datestyle='ISO, MDY'

[shirolimit]

I'm facing the same problem with PG 12. Here is what happens in my setup.

I set the parameter to ISO in [databases] config:

test = host=host.docker.internal port=15432 dbname=test datestyle='ISO' pool_size=2 min_pool_size=2 max_db_connections=2

I see that it is indeed used in pgbouncer logs:

2023-04-05 10:30:35.183 UTC [12] DEBUG parse_ini_file: [databases]
2023-04-05 10:30:35.183 UTC [12] DEBUG parse_ini_file: 'test' = 'host=host.docker.internal port=15432 dbname=test datestyle='ISO' pool_size=2 min_pool_size=2 max_db_connections=2'
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "host"="host.docker.internal"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "port"="15432"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "dbname"="test"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "datestyle"="ISO"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "pool_size"="2"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "min_pool_size"="2"
2023-04-05 10:30:35.183 UTC [12] NOISE cstr_get_pair: "max_db_connections"="2"

When pgbouncer creates new server connection it tries to set datestyle to ISO via starup packet, but postgresql answers with the value ISO, MDY:

2023-04-05 10:31:42.258 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='R', len=9
2023-04-05 10:31:42.258 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 calling login_answer
2023-04-05 10:31:42.258 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 S: auth ok
2023-04-05 10:31:42.258 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='S', len=23
2023-04-05 10:31:42.258 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 S: param: application_name =
2023-04-05 10:31:42.258 UTC [12] DEBUG pktbuf_dynamic(128): 0xffffa0721b10
2023-04-05 10:31:42.258 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='S', len=26
2023-04-05 10:31:42.258 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 S: param: client_encoding = UTF8
2023-04-05 10:31:42.258 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='S', len=24
2023-04-05 10:31:42.258 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 S: param: DateStyle = ISO, MDY

So, when new JDBC client comes with only ISO in startup packet, pgbouncer sees the difference and tries to set it:

2023-04-05 10:31:42.285 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 varcache_apply: SET DateStyle='ISO';SET TimeZone='Europe/Belgrade';SET application_name='PostgreSQL JDBC Driver';

In fact it gets ISO, MDY back from server:

2023-04-05 10:31:42.287 UTC [12] DEBUG S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 S: param: DateStyle = ISO, MDY
2023-04-05 10:31:42.287 UTC [12] DEBUG C-0xffffa012a4b0: test/postgres@127.0.0.1:50826 setting client var: DateStyle='ISO, MDY'
2023-04-05 10:31:42.287 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='C', len=9
2023-04-05 10:31:42.287 UTC [12] NOISE S-0xffffa00f00a0: test/postgres@192.168.65.2:15432 read pkt='S', len=30

I'm not 100% sure where this behaviour should be fixed. It seems that postgresql works correctly here. JDBC driver also expects to get ISO, MDY in the response. 🤔

Options:

• pgbouncer can use strncasecmp (or something similar) to only check prefix for DateStyle parameter.
• JDBC driver can provide full DateStyle on startup (e.g. ISO, MDY).

[zurikus]

IMHO, first option

pgbouncer can use strncasecmp (or something similar) to only check prefix for DateStyle parameter.

provided by @shirolimit is the right one.

There could be several different formats of DateStyle in ISO format (DMY, MDY, or YMD).
https://www.postgresql.org/docs/current/runtime-config-client.html#GUC-DATESTYLE

Don't think it's the right direction to hardcode all those variations on JDBC driver level.

I do not know why, but the problem also is, that pgbouncer is setting this 'ISO' DateStyle even if we are overriding it in configuration in [database] section.

[databases]
* = host=127.0.0.1 datestyle='ISO, MDY'
dbname = host=127.0.0.1 datestyle='ISO, MDY' pool_size=10

Output from pgbouncer admin console:

10:05:28 [pgbouncer] # show DateStyle;
 datestyle
-----------
 ISO
(1 row)

[vesvalo]

Postgres 12 sends 'DateStyle.ISO, MDY' in the reply to the command SET DateStyle='ISO'.
Postgres 15 doesn't send string like this in replies. Maybe this new behaviour breaks the varcache logic and apply_var() returns 1 every time.

[vesvalo]

Confirmed - postgres 14 and newer don't send ParameterStatus messages in reply to the command SET DateStyle='ISO':

Frame 134: 131 bytes on wire (1048 bits), 131 bytes captured (1048 bits) on interface any, id 0
...
Transmission Control Protocol, Src Port: 46694, Dst Port: 5432, Seq: 878, Ack: 1049, Len: 63
PostgreSQL
    Type: Parse
    Length: 27
    Statement:
    Query: SET DateStyle='ISO'
    Parameters: 0
PostgreSQL
    Type: Bind
    Length: 12
    Portal:
    Statement:
    Parameter formats: 0
    Parameter values: 0
    Result formats: 0
PostgreSQL
    Type: Describe
    Length: 6
    Portal:
PostgreSQL
    Type: Execute
    Length: 9
    Portal:
    Returns: 200 rows
PostgreSQL
    Type: Sync
    Length: 4

Frame 136: 98 bytes on wire (784 bits), 98 bytes captured (784 bits) on interface any, id 0
...
Transmission Control Protocol, Src Port: 5432, Dst Port: 46694, Seq: 1049, Ack: 941, Len: 30
PostgreSQL
    Type: Parse completion
    Length: 4
PostgreSQL
    Type: Bind completion
    Length: 4
PostgreSQL
    Type: No data
    Length: 4
PostgreSQL
    Type: Command completion
    Length: 8
    Tag: SET
PostgreSQL
    Type: Ready for query
    Length: 5
    Status: Idle (73)

This leaves client's varcache not being updated with the actual value of the DateStyle parameter after this command, and therefore client's varcache DateStyle ('ISO') value stays different with the server's varcache DateStyle value ('ISO, MDY') which leads to varcache_apply calls with set DateStyle='ISO' for every client's query.

[JelteF]

I do not know why, but the problem also is, that pgbouncer is setting this 'ISO' DateStyle even if we are overriding it in configuration in [database] section.

[databases]
* = host=127.0.0.1 datestyle='ISO, MDY'
dbname = host=127.0.0.1 datestyle='ISO, MDY' pool_size=10

Output from pgbouncer admin console:

10:05:28 [pgbouncer] # show DateStyle;
 datestyle
-----------
 ISO
(1 row)

The datestyle in the admin console is faked. It's hardcoded to ISO:
https://github.com/pgbouncer/pgbouncer/blob/master/src/admin.c#L160-L176

It's a completely different codepath than regular forwarding of configuration parameters.

[JelteF]

This leaves client's varcache not being updated with the actual value of the DateStyle parameter after this command, and therefore client's varcache DateStyle ('ISO') value stays different with the server's varcache DateStyle value ('ISO, MDY') which leads to varcache_apply calls with set DateStyle='ISO' for every client's query.

Hmmm, yeah. My guess is that is a side effect of this postgres commit. Postgres now won't report changes when a variable did not change at the end of a query: postgres/postgres@2432b1a

[JelteF]

A fix for this can be found in #879

Still it's better to actually have JDBC send DateStyle='ISO, MDY' too. Because it will still send a single SET DateStyle='ISO' per client connection (before the first transaction it does). But #879 does fix the problem where this SET command would be sent for every transaction.

[zurikus]

Thank you very much!
Waiting for these fixes to appear in next releases.

[JelteF]

Re-opening this until #879 is merged