pgcat icon indicating copy to clipboard operation
pgcat copied to clipboard

Published 20 hours ago • verified publisher icon postgresml

pgbench fails with error "cannot execute UPDATE in a read-only transaction"

Open swchangdev opened this issue 1 year ago • 7 comments

Describe the bug We configured pgcat to be pooling on a PostgreSQL cluster (1 primary, 1 standby). When we run pgbench we get the following error:

pgbench: error: client 1 script 0 aborted in command 5 query 0: ERROR:  cannot execute UPDATE in a read-only transaction

It looks like the update statement was forwarded to the standby instance, which shouldn't happen because we configured "query_parser_enabled = true" in pgcat.toml.

Looking at the pgcat log (with RUST_LOG=debug), it keeps saying "Query parser enable: false" so I'm kind of confused whether this is a user fault or a bug in the program. Please check the attachments to see if this is a bug.

To Reproduce Steps to reproduce the behavior:

  1. Create an active-standby cluster of PostgreSQL.
  2. Configure pgCat to be pooling the active-standby cluster and set query_parser_enabled = true
  3. Use pgbench to shoot mix of queries and commands
pgbench postgres -h [PG primary hostname] -p [PG primary port number] -i -s 100
pgbench postgres -h [pgCat hostname] -p [pgCaat port number] -c 2 -T 1 -r -n

Expected behavior The commands should be redirected to primary so that "cannot execute UPDATE in a read-only transaction" error is not thrown.

Attachments Here's what happens when we run pgbench

pgbench (14.2)
pgbench: error: client 1 script 0 aborted in command 5 query 0: ERROR:  cannot execute UPDATE in a read-only transaction
pgbench: error: client 0 script 0 aborted in command 5 query 0: ERROR:  cannot execute UPDATE in a read-only transaction
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 100
query mode: simple
number of clients: 2
number of threads: 1
duration: 1 s
number of transactions actually processed: 0
pgbench: fatal: Run was aborted; the above results are incomplete.

Here's the log and pgcat.toml on the pgcat side.

[root@sv345 pgcat-1.0.0]# RUST_LOG=debug cargo run --release
    Finished release [optimized] target(s) in 0.12s
     Running `target/release/pgcat`
[2023-04-20T00:14:09.460286Z INFO  pgcat] Welcome to PgCat! Meow. (Version 1.0.0)
[2023-04-20T00:14:09.467078Z INFO  pgcat] Running on 0.0.0.0:6432
[2023-04-20T00:14:09.467135Z INFO  pgcat::config] Ban time: 60s
[2023-04-20T00:14:09.467166Z INFO  pgcat::config] Idle client in transaction timeout: 0ms
[2023-04-20T00:14:09.467183Z INFO  pgcat::config] Worker threads: 4
[2023-04-20T00:14:09.467209Z INFO  pgcat::config] Healthcheck timeout: 1000ms
[2023-04-20T00:14:09.467230Z INFO  pgcat::config] Connection timeout: 5000ms
[2023-04-20T00:14:09.467253Z INFO  pgcat::config] Idle timeout: 30000ms
[2023-04-20T00:14:09.467282Z INFO  pgcat::config] Log client connections: true
[2023-04-20T00:14:09.467302Z INFO  pgcat::config] Log client disconnections: true
[2023-04-20T00:14:09.467322Z INFO  pgcat::config] Shutdown timeout: 60000ms
[2023-04-20T00:14:09.467344Z INFO  pgcat::config] Healthcheck delay: 30000ms
[2023-04-20T00:14:09.467364Z INFO  pgcat::config] TLS support is disabled
[2023-04-20T00:14:09.467174Z INFO  pgcat::prometheus] Exposing prometheus metrics on http://0.0.0.0:9930/metrics.
[2023-04-20T00:14:09.467389Z INFO  pgcat::config] [pool: postgres] Maximum user connections: 1010
[2023-04-20T00:14:09.467447Z INFO  pgcat::config] [pool: postgres] Pool mode: Session
[2023-04-20T00:14:09.467464Z INFO  pgcat::config] [pool: postgres] Load Balancing mode: LeastOutstandingConnections
[2023-04-20T00:14:09.467482Z INFO  pgcat::config] [pool: postgres] Connection timeout: 5000ms
[2023-04-20T00:14:09.467509Z INFO  pgcat::config] [pool: postgres] Idle timeout: 30000ms
[2023-04-20T00:14:09.467525Z INFO  pgcat::config] [pool: postgres] Sharding function: pg_bigint_hash
[2023-04-20T00:14:09.467550Z INFO  pgcat::config] [pool: postgres] Primary reads: false
[2023-04-20T00:14:09.467567Z INFO  pgcat::config] [pool: postgres] Query router: true
[2023-04-20T00:14:09.467587Z INFO  pgcat::config] [pool: postgres] Number of shards: 1
[2023-04-20T00:14:09.467608Z INFO  pgcat::config] [pool: postgres] Number of users: 1
[2023-04-20T00:14:09.467625Z INFO  pgcat::config] [pool: postgres][user: postgres] Pool size: 1010
[2023-04-20T00:14:09.467644Z INFO  pgcat::config] [pool: postgres][user: postgres] Statement timeout: 0
[2023-04-20T00:14:09.467733Z INFO  pgcat::pool] [pool: postgres][user: postgres] creating new pool
[2023-04-20T00:14:09.467882Z INFO  pgcat] Config autoreloader: false
[2023-04-20T00:14:09.467973Z INFO  pgcat] Waiting for clients
[2023-04-20T00:31:34.543514Z DEBUG pgcat::client] Password authentication successful
[2023-04-20T00:31:34.543667Z INFO  pgcat::client] Client xxx.xxx.xxx.xxx:yyyyy connected (plain)
[2023-04-20T00:31:34.583334Z DEBUG pgcat::query_router] Query parser enabled: false
[2023-04-20T00:31:34.583363Z DEBUG pgcat::query_router] Regular query, not a command
[2023-04-20T00:31:34.583371Z DEBUG pgcat::client] Waiting for connection from pool
[2023-04-20T00:31:34.583380Z DEBUG pgcat::pool] Address { id: 0, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.583405Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.583421Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } is ok
[2023-04-20T00:31:34.583461Z INFO  pgcat::pool] Creating a new server connection Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T00:31:34.590947Z DEBUG pgcat::server] Server connection marked for clean up
[2023-04-20T00:31:34.590995Z DEBUG pgcat::client] Got connection from pool
[2023-04-20T00:31:34.591006Z DEBUG pgcat::client] Client xxx.xxx.xxx.xxx:yyyyy talking to server Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T00:31:34.591237Z DEBUG pgcat::server] Server connection marked for clean up
[2023-04-20T00:31:34.591254Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.591261Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.593815Z DEBUG pgcat::server] Server in transaction: false
[2023-04-20T00:31:34.593975Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.593985Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.598955Z DEBUG pgcat::server] Server in transaction: false
[2023-04-20T00:31:34.599109Z DEBUG pgcat::server] Server in transaction: false
[2023-04-20T00:31:34.599177Z INFO  pgcat] Client xxx.xxx.xxx.xxx:yyyyy disconnected, session duration: 0d 00:00:00.058
[2023-04-20T00:31:34.600468Z DEBUG pgcat::client] Password authentication successful
[2023-04-20T00:31:34.600507Z INFO  pgcat::client] Client xxx.xxx.xxx.xxx:yyyyy connected (plain)
[2023-04-20T00:31:34.641557Z DEBUG pgcat::client] Password authentication successful
[2023-04-20T00:31:34.641607Z INFO  pgcat::client] Client xxx.xxx.xxx.xxx:yyyyy connected (plain)
[2023-04-20T00:31:34.681252Z DEBUG pgcat::query_router] Query parser enabled: false
[2023-04-20T00:31:34.681278Z DEBUG pgcat::query_router] Regular query, not a command
[2023-04-20T00:31:34.681286Z DEBUG pgcat::client] Waiting for connection from pool
[2023-04-20T00:31:34.681290Z DEBUG pgcat::query_router] Query parser enabled: false
[2023-04-20T00:31:34.681294Z DEBUG pgcat::pool] Address { id: 0, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.681352Z DEBUG pgcat::query_router] Regular query, not a command
[2023-04-20T00:31:34.681363Z DEBUG pgcat::client] Waiting for connection from pool
[2023-04-20T00:31:34.681354Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.681373Z DEBUG pgcat::pool] Address { id: 0, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.681390Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } is ok
[2023-04-20T00:31:34.681398Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } has 0 busy connections
[2023-04-20T00:31:34.681420Z DEBUG pgcat::client] Got connection from pool
[2023-04-20T00:31:34.681417Z DEBUG pgcat::pool] Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] } is ok
[2023-04-20T00:31:34.681432Z DEBUG pgcat::client] Client xxx.xxx.xxx.xxx:yyyy talking to server Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T00:31:34.681456Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.681463Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.681457Z INFO  pgcat::pool] Creating a new server connection Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T00:31:34.681793Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.681919Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.681930Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.684145Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.684327Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.684337Z WARN  pgcat::server] Server returned while still in transaction, rolling back transaction
[2023-04-20T00:31:34.684600Z INFO  pgcat] Client xxx.xxx.xxx.xxx:yyyyy disconnected, session duration: 0d 00:00:00.044
[2023-04-20T00:31:34.684632Z DEBUG pgcat::client] Got connection from pool
[2023-04-20T00:31:34.684641Z DEBUG pgcat::client] Client xxx.xxx.xxx.xxx:yyyyy talking to server Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T00:31:34.684675Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.684682Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.684860Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.685043Z DEBUG pgcat::client] Sending query to server
[2023-04-20T00:31:34.685053Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T00:31:34.685435Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.685593Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T00:31:34.685606Z WARN  pgcat::server] Server returned while still in transaction, rolling back transaction
[2023-04-20T00:31:34.685794Z INFO  pgcat] Client xxx.xxx.xxx.xxx:yyyyy disconnected, session duration: 0d 00:00:00.086
[2023-04-20T00:31:34.688317Z DEBUG pgcat::server] Server connection marked for clean up
[2023-04-20T00:32:09.468980Z INFO  pgcat::server] Server connection closed Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }, session duration: 0d 00:00:34.878
[2023-04-20T00:32:09.468980Z INFO  pgcat::server] Server connection closed Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }, session duration: 0d 00:00:34.878
[2023-04-20T00:32:09.469084Z INFO  pgcat::server] Server connection closed Address { id: 1, host: "xxx.xxx.xxx.xxx", port: yyyy, shard: 0, database: "postgres", role: Replica, replica_number: 0, address_index: 1, username: "postgres", pool_name: "postgres", mirrors: [] }, session duration: 0d 00:00:34.781

pgcat.toml

worker_threads = 4
auth_query="SELECT usename, passwd FROM pg_shadow WHERE usename = $1"
auth_query_user="postgres"
auth_query_password="xxxxxxxxxxx"
[pools.postgres]
pool_mode = "session"
default_role = "any"
load_balancing_mode = "loc"
query_parser_enabled = true
primary_reads_enabled = false
sharding_function = "pg_bigint_hash"

[pools.postgres.users.0]
username = "postgres"
password = "xxxxxxxxxxx"
pool_size = 1010
statement_timeout = 0

[pools.postgres.shards.0]
servers = [
["xxx.xxx.xxx.xxx", yyyy, "primary"],
["xxx.xxx.xxx.xxx", yyyy, "replica"]
]
database = "postgres"

Additional context ON A SIDE NOTE, i did some tests to see what might be the problem here. I noticed that if I log in to psql and execute a transaction, pgcat does differentiate query and commands, and route to the right PG instance. However, if I make the transaction into a single line query, pgcat cannot differentiate it anymore and the error above is reproduced. For example, if you do

psql -h [pgcat hostname] -p [pgcat port number] -c "begin; update ... ; end;"

with 50% chance, you get the same error as above. I don't know how pgbench shoots its queries to the target, but MAYBE if single line query is the way it shoots then that's the problem. FYI, pgpool documentation includes the edge case like above and it always redirects single line query to the primary instance.

swchangdev avatar Apr 20 '23 00:04 swchangdev

Hi there. Change the pool_mode to transaction. In session mode, the query parser can't work because the client is bound to the first server it gets attached to, and I believe the first pgbench statement is a SELECT.

levkk avatar Apr 20 '23 06:04 levkk

Sorry for the confusion. The same error keeps occurring even if we set pool_mode to transaction. The debug log is too long but the following excerpt repeats. There isn't any log with different query other than 'BEGIN;':

[2023-04-20T22:55:48.489159Z DEBUG pgcat::query_router] Query parser enabled: true
[2023-04-20T22:55:48.489188Z DEBUG pgcat::query_router] Inferring role
[2023-04-20T22:55:48.489209Z DEBUG pgcat::query_router] Query: 'BEGIN;'
[2023-04-20T22:55:48.489227Z DEBUG sqlparser::parser] Parsing sql 'BEGIN;'...
[2023-04-20T22:55:48.489255Z DEBUG pgcat::query_router] AST: [StartTransaction { modes: [] }]
[2023-04-20T22:55:48.489280Z DEBUG pgcat::query_router] Regular query, not a command
[2023-04-20T22:55:48.489301Z DEBUG pgcat::client] Waiting for connection from pool
[2023-04-20T22:55:48.489321Z DEBUG pgcat::pool] Address { id: 0, host: "xxxxxxxxxxxxx", port: xxxx, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "postgres", mirrors: [] } is ok
[2023-04-20T22:55:48.489352Z DEBUG pgcat::client] Got connection from pool
[2023-04-20T22:55:48.489370Z DEBUG pgcat::client] Client xxxxxxxxxxxxxxx:xxxxxx talking to server Address { id: 0, host: "xxxxxxxxxxxxx", port: xxxx, shard: 0, database: "postgres", role: Primary, replica_number: 0, address_index: 0, username: "postgres", pool_name: "postgres", mirrors: [] }
[2023-04-20T22:55:48.489403Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.489420Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.489567Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.489681Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.489707Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.490633Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.490762Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.490792Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.491159Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.491285Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.491309Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.491670Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.491796Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.491824Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.492148Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.492272Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.492301Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.492600Z DEBUG pgcat::server] Server in transaction: true
[2023-04-20T22:55:48.492725Z DEBUG pgcat::client] Sending query to server
[2023-04-20T22:55:48.492749Z DEBUG pgcat::client] Sending Q to server
[2023-04-20T22:55:48.493167Z DEBUG pgcat::server] Server in transaction: false
[2023-04-20T22:55:48.493196Z DEBUG pgcat::client] Releasing server back into the pool
[2023-04-20T22:55:48.493213Z DEBUG pgcat::server] Server in transaction: false

Here's the output of pgbench:

[opensql@sv344:~]$ pgbench postgres -h xxxxxxxxxxxxx-p xxxx -c 2 -T 1 -r -n
pgbench (14.2)
pgbench: error: client 1 script 0 aborted in command 5 query 0: ERROR:  cannot execute UPDATE in a read-only transaction
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 10
query mode: simple
number of clients: 2
number of threads: 1
duration: 1 s
number of transactions actually processed: 227
latency average = 8.101 ms
initial connection time = 82.338 ms
tps = 246.895856 (without initial connection time)
statement latencies in milliseconds:
         0.001  \set aid random(1, 100000 * :scale)
         0.001  \set bid random(1, 1 * :scale)
         0.001  \set tid random(1, 10 * :scale)
         0.000  \set delta random(-5000, 5000)
         0.591  BEGIN;
         0.941  UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
         0.504  SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
         0.512  UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
         0.484  UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
         0.450  INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
         0.567  END;
pgbench: fatal: Run was aborted; the above results are incomplete.

swchangdev avatar Apr 20 '23 23:04 swchangdev

I also encountered this problem，in last version

GPF199541 avatar Jun 16 '23 10:06 GPF199541

Hi @swchangdev @GPF199541, did either of you find a solution to this?

sidartha avatar Dec 31 '23 05:12 sidartha

@swchangdev @GPF199541 @sidartha Do you all have the query_parser_read_write_splitting = true config entry in the pgcat.toml? It will not even try to infer the query without that.

michaeljmonte avatar Jan 30 '24 14:01 michaeljmonte

We face the same issue with our PgCat deployment. And query_parser_read_write_splitting is set to true.

l0nax avatar Jan 31 '24 10:01 l0nax

An example of my very simple config, and it is working as expected. Also I am not using any postgres specific SQL. Simple updates and inserts.

# This is an example of the most basic config
# that will mimic what PgBouncer does in transaction mode with one server.

[general]

host = "xxx.xxx.xxx.xxx"
port = 6433
admin_username = "pgcat"
admin_password = "pgcat"

[pools.s5_dev]
query_parser_enabled = true
query_parser_read_write_splitting = true
primary_reads_enabled = true

[pools.s5_dev.users.0]
username = "pgcat"
password = "pgcat!@#$"
pool_size = 10
min_pool_size = 1
pool_mode = "transaction"


[pools.s5_dev.shards.0]
servers = [
  ["xxx.xxx.xxx.xxx", 5432, "primary"],
  ["xxx.xxx.xxx.xxx", 5432, "replica"]

]
database = "s5_dev"

michaeljmonte avatar Jan 31 '24 11:01 michaeljmonte