search

pgpool / pgpool2

This is the official mirror of git://git.postgresql.org/git/pgpool2.git. Note that this is just a *mirror* - we don't work with pull requests on github. Please subscribe to pgpool-hackers mailing list from our website and submit your patch to this mailing list.
https://www.pgpool.net
Other
326 stars 88 forks source link

Snapshot isolation mode: difference of the number of inserted, updated or deleted tuples. #69

Open SLedunois opened 3 weeks ago

SLedunois commented 3 weeks ago

Hello,

I am currently encountering an issue with PgPool2 in Snapshot isolation mode. I followed the example provided here: https://www.pgpool.net/docs/latest/en/html/example-replication-mode.html

I have 3 PostgreSQL servers, each with PgPool installed on them:

# pcp_watchdog_info -p 9898 -h pgpool -U pgpool -W
3 3 YES bdd01:9999 Linux bdd01 bdd01

bdd01:9999 Linux bdd01 bdd01 9999 9000 4 LEADER 0 MEMBER
bdd02:9999 Linux bdd02 bdd02 9999 9000 7 STANDBY 0 MEMBER
bdd03:9999 Linux bdd03 bdd03 9999 9000 7 STANDBY 0 MEMBER
# psql -h pgpool -p 9999 -U pgpool postgres -c "show pool_nodes"
Password for user pgpool:
 node_id |     hostname     | port | status | pg_status | lb_weight |  role   | pg_role | select_cnt | load_balance_node | replication_delay | replication_state | replication_sync_state | last_status_change
---------+------------------+------+--------+-----------+-----------+---------+---------+------------+-------------------+-------------------+-------------------+------------------------+---------------------
 0       | bdd01            | 5432 | up     | up        | 0.333333  | main    | main    | 26682      | false             | 0                 |                   |                        | 2024-09-03 07:42:16
 1       | bdd02            | 5432 | up     | up        | 0.333333  | replica | replica | 5163       | true              | 0                 |                   |                        | 2024-09-03 09:33:54
 2       | bdd03            | 5432 | up     | up        | 0.333333  | replica | replica | 21882      | false             | 0                 |                   |                        | 2024-09-03 09:13:17
(3 rows)

However, while using my application, I frequently receive the following error message:

ERROR: pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query > > was: "UPDATE ..." HINT: check data consistency between main and other db node.

2024-09-03 09:42:15.717: pcp_main pid 1271850: LOG:  PCP process with pid: 1272269 exit with SUCCESS.
2024-09-03 09:42:15.717: pcp_main pid 1271850: LOG:  PCP process with pid: 1272269 exits with status 0
2024-09-03 09:42:39.507: [unknown] pid 1271819: LOG:  pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "UPDATE mdl_sessions SET timemodified = $1 WHERE id=$2"
2024-09-03 09:42:39.507: [unknown] pid 1271819: LOG:  processing command complete
2024-09-03 09:42:39.507: [unknown] pid 1271819: DETAIL:  CommandComplete: Number of affected tuples are: 1 1 0

This error message consistently occurs when the cluster contains 3 PostgreSQL instances, whereas it seems to work correctly with 2 PostgreSQL instances.

It seems that the nodes desynchronize very quickly. However, it is PgPool's responsibility to maintain this synchronization. That is why I chose the snapshot isolation mode.

I have indeed added the following configuration in the PostgreSQL instances:

default_transaction_isolation = 'repeatable read'

My PgPool2 configuration:

# - BACKEND CLUSTERING MODE
backend_clustering_mode = 'snapshot_isolation'

# - pgpool Connection Settings -
listen_addresses = '*'
port = 9999

# - pgpool Communication Manager Connection Settings -
pcp_listen_addresses = '*'

# - Backend Connection Settings -
backend_hostname0 = 'bdd01'
backend_port0 = 5432
backend_weight0 = 1
backend_data_directory0 = '/xxx/xxx/xxx/xxx'
backend_flag0 = 'ALLOW_TO_FAILOVER'

backend_hostname1 = 'bdd02'
backend_port1 = 5432
backend_weight1 = 1
backend_data_directory1 = '/xxx/xxx/xxx/xxx'
backend_flag1 = 'ALLOW_TO_FAILOVER'

backend_hostname2 = 'bdd03'
backend_port2 = 5432
backend_weight2 = 1
backend_data_directory2 = '/xxx/xxx/xxx/xxx'
backend_flag2 = 'ALLOW_TO_FAILOVER'

# - Authentication -
enable_pool_hba = on

# - LOGS
log_destination = 'stderr'
logging_collector = on
log_directory = '/var/log/pgpool_log'
log_filename = 'pgpool-%Y-%m-%d_%H%M%S.log'
log_truncate_on_rotation = on
log_rotation_age = 1d
log_rotation_size = 10MB

# - LOAD BALANCING MODE
load_balance_mode = on
ignore_leading_white_space = on
read_only_function_list = ''
write_function_list = 'nextval,setval,lastval,currval'
database_redirect_preference_list = 'xxx:standby,xxx:primary(0.3)'

statement_level_load_balance = off

# - HEALTH CHECK GLOBAL PARAMETERS
health_check_period = 5
health_check_timeout = 30
health_check_user = 'pgpool'
health_check_password = ''
health_check_max_retries = 3

# - ONLINE RECOVERY
recovery_user = 'postgres'
recovery_password = ''
recovery_1st_stage_command = 'recovery_1st_stage'
recovery_2nd_stage_command = 'recovery_2nd_stage'
recovery_timeout = 90
client_idle_limit_in_recovery = -1

# - WATCHDOG
use_watchdog = on

# - Watchdog communication Settings -
hostname0 = 'bdd01'
wd_port0 = 9000
pgpool_port0 = 9999

hostname1 = 'bdd02'
wd_port1 = 9000
pgpool_port1 = 9999

hostname2 = 'bdd03'
wd_port2 = 9000
pgpool_port2 = 9999

# - Virtual IP control Setting -

delegate_ip = 'xxx.xxx.xxx.xxx'
if_up_cmd = '/usr/bin/sudo /sbin/ip addr add $_IP_$/24 dev ens160 label ens160:0'
if_down_cmd = '/usr/bin/sudo /sbin/ip addr del $_IP_$/24 dev ens160'
arping_cmd = '/usr/bin/sudo /usr/sbin/arping -U $_IP_$ -w 1 -I ens160'

# - Behaivor on escalation Setting -
wd_escalation_command = '/etc/pgpool2/escalation.sh'

# - Lifecheck Setting -
wd_lifecheck_method = 'heartbeat'
wd_interval = 10

# -- heartbeat mode --
heartbeat_hostname0 = 'bdd01'
heartbeat_port0 = 9694
heartbeat_device0 = ''

heartbeat_hostname1 = 'bdd02'
heartbeat_port1 = 9694
heartbeat_device1 = ''

heartbeat_hostname2 = 'bdd03'
heartbeat_port2 = 9694
heartbeat_device2 = ''

wd_heartbeat_keepalive = 2
wd_heartbeat_deadtime = 30

Did I miss something? Could this be caused by a configuration related to the number of connections?

Thank you,

SLedunois

tatsuo-ishii commented 3 weeks ago

Can you share the definition of mdl_sessions table? I suspect there's something wrong with query rewriting in pgpool with the query because timemodified column sounds like a timestamp type or something like that, which needs rewriting so that the query is not confused by subtle time difference between those PostgreSQL servers.

SLedunois commented 3 weeks ago

The timemodified is a bigint. Please find below the table schema. I also check if there is some trigger on the table.

psql=# \d+ mdl_sessions;
                                                                  Table "public.mdl_sessions"
    Column    |          Type          | Collation | Nullable |                 Default                  | Storage  | Compression | Stats target | Description
--------------+------------------------+-----------+----------+------------------------------------------+----------+-------------+--------------+-------------
 id           | bigint                 |           | not null | nextval('mdl_sessions_id_seq'::regclass) | plain    |             |              |
 state        | bigint                 |           | not null | 0                                        | plain    |             |              |
 sid          | character varying(128) |           | not null | ''::character varying                    | extended |             |              |
 userid       | bigint                 |           | not null |                                          | plain    |             |              |
 sessdata     | text                   |           |          |                                          | extended |             |              |
 timecreated  | bigint                 |           | not null |                                          | plain    |             |              |
 timemodified | bigint                 |           | not null |                                          | plain    |             |              |
 firstip      | character varying(45)  |           |          |                                          | extended |             |              |
 lastip       | character varying(45)  |           |          |                                          | extended |             |              |
Indexes:
    "mdl_sess_id_pk" PRIMARY KEY, btree (id)
    "mdl_sess_sid_uix" UNIQUE, btree (sid)
    "mdl_sess_sta_ix" btree (state)
    "mdl_sess_tim2_ix" btree (timemodified)
    "mdl_sess_tim_ix" btree (timecreated)
    "mdl_sess_use_ix" btree (userid)
Access method: heap

psql =# SELECT event_object_table
      ,trigger_name
      ,event_manipulation
      ,action_statement
      ,action_timing
FROM  information_schema.triggers
WHERE event_object_table = 'mdl_sessions' -- Your table name comes here
ORDER BY event_object_table
     ,event_manipulation;
 event_object_table | trigger_name | event_manipulation | action_statement | action_timing
--------------------+--------------+--------------------+------------------+---------------
(0 rows)
SLedunois commented 3 weeks ago

This is really strange. I have no issues with two PostgreSQL servers, but as soon as I add the third one, I encounter errors.

I did run a synchronization that completed successfully:

# pcp_detach_node -h pgpool -p 9898 -U pgpool -W -n 1
Password:
pcp_detach_node -- Command Successful
# pcp_detach_node -h pgpool -p 9898 -U pgpool -W -n 2
Password:
pcp_detach_node -- Command Successful
# pcp_recovery_node -h pgpool -p 9898 -n 2 -U pgpool -W
Password:
pcp_recovery_node -- Command Successful
# pcp_recovery_node -h pgpool -p 9898 -n 1 -U pgpool -W
Password:
pcp_recovery_node -- Command Successful

But the issue persists.

tatsuo-ishii commented 3 weeks ago

psql=# \d+ mdl_sessions;

OK. No timestamp or similar data types are not used, which means no query rewriting is involved.

Have you enabled insert_lock?

SLedunois commented 3 weeks ago

By default, insert_lock is enabled.

I tried disabling it, but the issue still persists.

However, I noticed something interesting: I received this error log:

Debug info: ERROR: pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "UPDATE mdl_sessions SET timemodified = $1 WHERE id=$2"
HINT: check data consistency between main and other db node
UPDATE mdl_sessions SET timemodified = $1 WHERE id=$2
[array (
'timemodified' => 1725437846,
0 => '4139994',
)]

and the following pgpool log:

2024-09-04 07:50:04.583: [unknown] pid 1344002: LOG:  pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "UPDATE mdl_sessions SET timemodified = $1 WHERE id=$2"
2024-09-04 07:50:04.583: [unknown] pid 1344002: LOG:  processing command complete
2024-09-04 07:50:04.583: [unknown] pid 1344002: DETAIL:  CommandComplete: Number of affected tuples are: 1 0 1

We can see that the write operation is not the same on the second server. So I went to check the corresponding row on my three database servers:

bdd01

   id    | state |            sid             | userid | sessdata | timecreated | timemodified |    firstip     |     lastip
---------+-------+----------------------------+--------+----------+-------------+--------------+----------------+----------------
 4139994 |     0 | b00fji3fg20mv4d8mfktngc3mr |      2 |          |  1725437844 |   1725437844 | XXX.XXX.XXX.XX | XXX.XXX.XXX.XX
(1 row)

bdd02:

   id    | state |            sid             | userid | sessdata | timecreated | timemodified |    firstip     |     lastip
---------+-------+----------------------------+--------+----------+-------------+--------------+----------------+----------------
 4139994 |     0 | cdulq8jhgkij6irukhi75l6mq9 |      0 |          |  1725437846 |   1725437846 | XXX.XXX.XXX.XX | XXX.XXX.XXX.XX
(1 row)

bdd03:

   id    | state |            sid             | userid | sessdata | timecreated | timemodified |    firstip     |     lastip
---------+-------+----------------------------+--------+----------+-------------+--------------+----------------+----------------
 4139994 |     0 | b00fji3fg20mv4d8mfktngc3mr |      2 |          |  1725437844 |   1725437844 | XXX.XXX.XXX.XX |  XXX.XXX.XXX.XX
(1 row)

We can see that on the second PostgreSQL server, the timecreated, timemodified, and userid columns are different.

I found the same row on bdd02 by executing the following query:

SELECT * FROM mdl_sessions WHERE sid = 'b00fji3fg20mv4d8mfktngc3mr' AND userid = 2;
   id    | state |            sid             | userid | sessdata | timecreated | timemodified |    firstip     |     lastip
---------+-------+----------------------------+--------+----------+-------------+--------------+----------------+----------------
 4139993 |     0 | b00fji3fg20mv4d8mfktngc3mr |      2 |          |  1725437844 |   1725437844 | XXX.XXX.XXX.XX | XXX.XXX.XXX.XX
(1 row)

The identifier is different. The row was inserted earlier.

How could this happen?

tatsuo-ishii commented 3 weeks ago

Sorry I was not clear. I just wanted to make sure that insert_lock is enabled in your installation. If a target table for INSERT has SERIAL columns (your case), insert_lock needs to be enabled to acquire locking for consistent replication. However you already enable insert_lock...

tatsuo-ishii commented 3 weeks ago

We can see that on the second PostgreSQL server, the timecreated, timemodified, and userid columns are different.

How did you INSERT the row? Can you share the actual INSERT statement?

SLedunois commented 3 weeks ago

Sorry I was not clear. I just wanted to make sure that insert_lock is enabled in your installation. If a target table for INSERT has SERIAL columns (your case), insert_lock needs to be enabled to acquire locking for consistent replication. However you already enable insert_lock...

Just in case, I explicitly set insert_lock to true.

How did you INSERT the row? Can you share the actual INSERT statement?

Sure, the insert statement is:

LOG:  duration: 0.044 ms  bind <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
DETAIL:  parameters: $1 = '0', $2 = 'ntmh2rvpidgdittphj91bag350', $3 = NULL, $4 = '0', $5 = '1725453377', $6 = '1725453377', $7 = 'XXX.XXX.XXX.XX', $8 = 'XXX.XXX.XXX.XX'
tatsuo-ishii commented 3 weeks ago

How could this happen?

If insert_lock is disabled, it could happen because pgpool can't control concurrent INSERTs.

tatsuo-ishii commented 3 weeks ago

So when you enable insert_lock, did you see something like below in the postgresql log when you execute INSERT to the table? LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE This is an expected behavior and I want to make sure pgpool is working as expected.

In addition to this, I would like to know followings:

SLedunois commented 3 weeks ago

So when you enable insert_lock, did you see something like below in the postgresql log when you execute INSERT to the table? LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE This is an expected behavior and I want to make sure pgpool is working as expected.

In addition to this, I would like to know followings:

  • Exact pgpool version
  • Whether you had ERROR: could not serialize access due to concurrent update or not while executing your transaction

The insert_lock configuration is enabled on pgpool. I can see the LOCK TABLE in the logs:

2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.026 ms  statement: BEGIN
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.041 ms  parse pgpool1426415: SELECT current_setting('transaction_read_only')
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.022 ms  bind pgpool1426415/pgpool1426415: SELECT current_setting('transaction_read_only')
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.007 ms  execute pgpool1426415/pgpool1426415: SELECT current_setting('transaction_read_only')
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.014 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.002 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.067 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.007 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.002 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.005 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.003 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.001 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.002 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.097 ms  parse <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.010 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.002 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.008 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.005 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.001 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.003 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.004 ms  parse pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1427121]: LOG:  duration: 0.028 ms  statement: COMMIT
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.001 ms  bind pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.003 ms  execute pgpool1426415/pgpool1426415: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.058 ms  bind <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-05 09:38:12 CEST [1426630]: DETAIL:  parameters: $1 = '0', $2 = 'iqvlbuce6behoc0fngmgrm7hin', $3 = NULL, $4 = '0', $5 = '1725521892', $6 = '1725521892', $7 = '192.168.240.63', $8 = '192.168.240.63'
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.135 ms  execute <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-05 09:38:12 CEST [1426630]: DETAIL:  parameters: $1 = '0', $2 = 'iqvlbuce6behoc0fngmgrm7hin', $3 = NULL, $4 = '0', $5 = '1725521892', $6 = '1725521892', $7 = '192.168.240.63', $8 = '192.168.240.63'
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.026 ms  statement: COMMIT
2024-09-05 09:38:12 CEST [1427121]: LOG:  duration: 0.047 ms  statement: BEGIN
2024-09-05 09:38:12 CEST [1426630]: LOG:  duration: 0.046 ms  statement: DISCARD ALL

For the PgPool version, we are using 4.5.2:

# pgpool --version
pgpool-II version 4.5.2 (hotooriboshi)

I do indeed have a serialization error:

LOG:  connection authenticated: identity="xxx" method=md5 (/etc/postgresql/15/main/pg_hba.conf:92)
LOG:  connection authorized: user=xxx database=xxx
ERROR:  could not serialize access due to concurrent update
STATEMENT:  UPDATE mdl_category_options SET categoryid = $1,name = $2,value = $3 WHERE id=$4
ERROR:  could not serialize access due to concurrent update
tatsuo-ishii commented 2 weeks ago

The PostgreSQL log looks really weird. Process 1426630 executed "LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE" over and over again. It is expected this executes only once after BEGIN. Can you share pgpool log when INSERT is executed with "log_per_node_statement" and "log_client_messages" enabled?

SLedunois commented 2 weeks ago

Here are the PgPool logs with the log_per_node_statement and log_client_messages configurations enabled:

Bdd01 pgpool leader: /var/log/pgpool_log/pgpool-2024-09-10_130753.log

[unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: Parse: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777143: LOG:  Sync message from frontend.
[unknown] pid 1777143: LOG:  DB node id: 0 backend pid: 1777454 statement: COMMIT
[unknown] pid 1777143: LOG:  DB node id: 1 backend pid: 1559714 statement: COMMIT
[unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: Parse: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: Parse: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: COMMIT
[unknown] pid 1777163: LOG:  Bind message from frontend.
[unknown] pid 1777163: DETAIL:  portal: "", statement: ""
[unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: Bind: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: Bind: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: Bind: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[unknown] pid 1777163: LOG:  Describe message from frontend.
[unknown] pid 1777163: DETAIL:  portal: ""
[unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: D message
[unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: D message
[unknown] pid 1777143: LOG:  Parse message from frontend.
58929[unknown] pid 1777143: DETAIL:  statement: "", query: "SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()"
[unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: D message
[unknown] pid 1777143: LOG:  DB node id: 0 backend pid: 1777454 statement: BEGIN
[unknown] pid 1777143: LOG:  DB node id: 1 backend pid: 1559714 statement: BEGIN
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  Execute message from frontend.
2024-09-10 13:07:57.169: [unknown] pid 1777163: DETAIL:  portal: ""
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: Execute: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: BEGIN
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 0 backend pid: 1777454 statement: SELECT current_setting('transaction_read_only')
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: Execute: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: Execute: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 1 backend pid: 1559714 statement: SELECT current_setting('transaction_read_only')
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: SELECT current_setting('transaction_read_only')
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: Parse: SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  Sync message from frontend.
2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  DB node id: 1 backend pid: 1559691 statement: COMMIT
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  Bind message from frontend.
2024-09-10 13:07:57.169: [unknown] pid 1777143: DETAIL:  portal: "", statement: ""
2024-09-10 13:07:57.169: [unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: Bind: SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()
        2024-09-10 13:07:57.169: [unknown] pid 1777163: LOG:  DB node id: 2 backend pid: 632818 statement: COMMIT
[unknown] pid 1777143: LOG:  Describe message from frontend.
[unknown] pid 1777143: DETAIL:  portal: ""
[unknown] pid 1777163: LOG:  DB node id: 0 backend pid: 1777406 statement: COMMIT
[unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: D message
[unknown] pid 1777143: LOG:  Execute message from frontend.
[unknown] pid 1777143: DETAIL:  portal: ""
[unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: Execute: SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()
[unknown] pid 1777143: LOG:  Sync message from frontend.
[unknown] pid 1777143: LOG:  DB node id: 0 backend pid: 1777454 statement: COMMIT
[unknown] pid 1777143: LOG:  DB node id: 1 backend pid: 1559714 statement: COMMIT
[unknown] pid 1777143: LOG:  DB node id: 2 backend pid: 632847 statement: COMMIT

However, I am also including the PostgreSQL logs because I just realized that the LOCK TABLE is present in the PostgreSQL logs only on BDD01: BDD01 logs Postgresql@15-main: /appli/postgresql/15/main/pg_log/postgresql-2024-09-10.log

[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.009 ms  statement: BEGIN
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.037 ms  parse pgpool1777163: SELECT current_setting('transaction_read_only')
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.016 ms  bind pgpool1777163/pgpool1777163: SELECT current_setting('transaction_read_only')
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.005 ms  execute pgpool1777163/pgpool1777163: SELECT current_setting('transaction_read_only')
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.015 ms  parse pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.003 ms  bind pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.081 ms  execute pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.006 ms  parse pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.002 ms  bind pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.004 ms  execute pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.004 ms  parse pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.002 ms  bind pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.002 ms  execute pgpool1777163/pgpool1777163: LOCK TABLE "mdl_sessions" IN SHARE ROW EXCLUSIVE MODE
[1777406]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.109 ms  parse <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[1777454]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.015 ms  statement: COMMIT

BDD02 logs postgresql@15-main: /appli/postgresql/15/main/pg_log/postgresql-2024-09-10.log

[1559714]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.010 ms  statement: BEGIN
[1559714]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.024 ms  parse pgpool1777143: SELECT current_setting('transaction_read_only')
[1559714]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.026 ms  bind pgpool1777143/pgpool1777143: SELECT current_setting('transaction_read_only')
[1559714]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.005 ms  execute pgpool1777143/pgpool1777143: SELECT current_setting('transaction_read_only')
[1559691]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.121 ms  execute <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[1559691]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX DETAIL:  parameters: $1 = '0', $2 = 's089pi37n21h2ujlfbdhl7dtdt', $3 = NULL, $4 = '0', $5 = '1725973677', $6 = '1725973677', $7 = '192.168.240.63', $8 = '192.168.240.63'
[1559691]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.023 ms  statement: COMMIT

BDD03 logs postgresql@15-main:/appli/postgresql/15/main/pg_log/postgresql-2024-09-10.log

[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.011 ms  statement: BEGIN
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.026 ms  parse pgpool1777143: SELECT current_setting('transaction_read_only')
[632818]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.114 ms  execute <unnamed>: INSERT INTO mdl_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
[632818]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX DETAIL:  parameters: $1 = '0', $2 = 's089pi37n21h2ujlfbdhl7dtdt', $3 = NULL, $4 = '0', $5 = '1725973677', $6 = '1725973677', $7 = '192.168.240.63', $8 = '192.168.240.63'
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.014 ms  bind pgpool1777143/pgpool1777143: SELECT current_setting('transaction_read_only')
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.004 ms  execute pgpool1777143/pgpool1777143: SELECT current_setting('transaction_read_only')
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.053 ms  parse <unnamed>: SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.110 ms  bind <unnamed>: SELECT id, scoid, element, value
                                FROM mdl_scorm_scoes_track
                               WHERE scormid = $1
                                 AND userid = $2 AND element IN (
                                  'cmi.core.lesson_status',
                                  'cmi.completion_status',
                                  'cmi.success_status'
                            )
        -- line 66 of /mod/scorm/classes/completion/custom_completion.php: call to pgsql_native_moodle_database->get_records_sql()
[632847]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX DETAIL:  parameters: $1 = '1597', $2 = '46673'
[632818]: db=XXX,user=XXX,app=[unknown],client=XX.XXX.XXX.XX LOG:  duration: 0.025 ms  statement: COMMIT
tatsuo-ishii commented 1 week ago

However, I am also including the PostgreSQL logs because I just realized that the LOCK TABLE is present in the PostgreSQL logs only on BDD01:

I was able to reproduce the issue. It seems Pgpool-II does not send LOCK TABLE to other than main node (that is node 0 in your case). This only happens in extended query protocol mode. I will fix this.

SLedunois commented 1 week ago

Awesome! thank you very much! Do you have an estimated date for the fix version?

tatsuo-ishii commented 1 week ago

I need 24 hours for this before I push the fix to git repository.

tatsuo-ishii commented 1 week ago

Done. Here is the commit link for 4.5 stable branch. https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=a4c15f4595fc2ab5b5ac58eedf96b5b5119e074e

SLedunois commented 1 week ago

Thank you so much ! Do you have a 4.5.5 release date ?

tatsuo-ishii commented 1 week ago

You are welcome. 4.5.5 release date will be November 21. https://pgpool.net/mediawiki/index.php/Roadmap