[pgpool-general: 6814] Re: Inconsistency between DB nodes with native replication
Bo Peng
pengbo at sraoss.co.jp
Mon Jan 20 17:06:46 JST 2020
Hello,
On Sun, 19 Jan 2020 15:12:06 +0000
Láznička Vladimír <Vladimir.Laznicka at cca.cz> wrote:
> Hello,
>
> I have enabled mentioned parameter for a few minutes (I am still letting the script run every one minute to see if the error pops up again...). I am sending the messages log (pgpool creates logs there in our case) with logged statements - the important part starts at mark "Jan 19 15:52:53" (configuration reload...), look for the first connection from the host "dbstest.cca.cz" (the script runs from there)...
>
> and also the test script, so you can see exactly, what it does. Let me know if I should let the parameter on for a longer time - in case we actually catch the error with it - due to heavy activity on the database it creates a lot of records in a very short time... Thank you for your time.
Thank you for providing the message log.
But I couldn't see any "kind mismatch" error of pgpool.
Could you reproduce this issue to record the errors and statements in pgpool log?
> Vladimír Láznička
> ________________________________________
> Od: Bo Peng <pengbo at sraoss.co.jp>
> Odesláno: 18. ledna 2020 3:18
> Komu: Láznička Vladimír
> Kopie: pgpool-general at pgpool.net
> Předmět: Re: [pgpool-general: 6811] Re: Inconsistency between DB nodes with native replication
>
> hello,
>
> On Thu, 16 Jan 2020 15:44:01 +0900
> Bo Peng <pengbo at sraoss.co.jp> wrote:
>
> > Hello,
> >
> > On Wed, 15 Jan 2020 10:53:02 +0000
> > Láznička Vladimír <Vladimir.Laznicka at cca.cz> wrote:
> >
> > > Hello pgPool team,
> > >
> > > We have built a pgpool cluster consisting of 2 servers with pgpool service (using Watchdog, one MASTER with virtual IP address and one STANDBY in case of a disaster) and 2 servers with PostgreSQL back-end working both in read-write mode. Replication is set to native replication from pgpool itself, since customer insists on having both DB servers in read-write mode and effectively using them both as masters. Configuration is as follows:
>
> I would like to confirm the statements issued by pgpool.
> Could you enable the following pgpool parameter and run the test script again?
>
> ----
> log_per_node_statement = on
> ----
>
> Then, please show me the pgpool log.
>
> > I will look into this one.
> >
> > > PGP1 - MASTER pgpool server
> > > PGP2 - STANDBY pgpool server
> > > DBD1 - first PostgreSQL server
> > > DBD2 - second PostgreSQl server
> > >
> > > pgPool version - 4.0.6
> > > PostgreSQL version - 11.5
> > >
> > > Recently we have encountered a serious problem with replicating some DML commands:
> > >
> > > One of our programmers reported a problem, when he issued a DELETE statement against one table (on all data in the table) and that statement was performed on DBD1, but not on DBD2, pgpool didn't report any issue in the log. He then tried to perform another DML statement on another table connected to the first one via foreign key and then pgpool correctly issued an error about data inconsistency, since first table on DBD2 server still had the rows that should have been deleted, while the table on DBD1 was empty as expected.
> > >
> > >
> > > Because of that error I created a simple testing script that is called from remote server and issues these commands in a sequence:
> > >
> > > INSERT one row in testing table.
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > > INSERT one row in testing table.
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > > UPDATE all rows in the table.
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > > INSERT one row in testing table.
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > > DELETE all rows from the table.
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > > UPDATE all rows in the table (should UPDATE 0 rows).
> > >
> > > SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT ...
> > >
> > >
> > > Every command is issued in its own session by calling PSQL client connecting on virtual adress (by default on PGP1 server) and port 9999. Script is ran every one minute (via cron scheduler). After a week without any problem, the error happened again in the execution of this test script. From what I gathered from the logs and the content of the test table, the second INSERT was executed on the DBD1 server but not on the DBD2 server, pgpool, again, did not return any error for that specific command. The first SELECT after that INSERT returned to client with this error:
> > >
> > >
> > > WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']
> > >
> > > FATAL: failed to read kind from backend
> > >
> > > DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]
> > >
> > > HINT: check data consistency among db nodes server closed the connection unexpectedly
> > >
> > > This probably means the server terminated abnormally
> > >
> > > before or while processing the request.
> > > connection to server was lost
> > >
> > > Oddly enough the next command - the UPDATE was also performed only on the DBD1 (did not return any errors). Any subsequent command (apart from INSERT commands...) returned with the same error. The content of the table on DBD1 had one more row than on DBD2.
> > >
> > > Here is a piece of the log from pgpool in that time:
> > >
> > > Jan 9 10:11:00 AISGPGP01 pgpool[10489]: [88971-1] 2020-01-09 10:11:00 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:00 AISGPGP01 pgpool[10489]: [88971-2] 2020-01-09 10:11:00 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57797
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88968-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88968-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57798
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88014-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88014-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57799
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88969-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88969-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57800
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88970-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88971-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |FATAL: failed to read kind from backend
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88971-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10459]: [88971-3] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |HINT: check data consistency among db nodes
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88971-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: child process with pid: 10459 exits with status 512
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88972-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: fork a new child process with pid: 10554
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88015-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88015-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57801
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88967-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88967-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57802
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88968-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88969-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |FATAL: failed to read kind from backend
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88969-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10436]: [88969-3] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |HINT: check data consistency among db nodes
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88973-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: child process with pid: 10436 exits with status 512
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88974-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: fork a new child process with pid: 10555
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88940-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88940-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57803
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88975-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: child process with pid: 9925 exits with status 256
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88976-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: fork a new child process with pid: 10556
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88941-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88941-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57804
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88942-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88943-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |FATAL: failed to read kind from backend
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88943-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10162]: [88943-3] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |HINT: check data consistency among db nodes
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88977-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: child process with pid: 10162 exits with status 512
> > > Jan 9 10:11:01 AISGPGP01 pgpool[27689]: [88978-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: fork a new child process with pid: 10557
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88932-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88932-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57805
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88933-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |LOG: pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "DELETE FROM replication_test;"
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88934-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |LOG: processing command complete
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88934-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: CommandComplete: Number of affected tuples are: 3 2
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88016-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[1071]: [88016-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57806
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10112]: [88939-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10112]: [88939-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57807
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10112]: [88940-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |LOG: pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "UPDATE replication_test SET custom_date = now();"
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10112]: [88941-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |LOG: processing command complete
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10112]: [88941-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: CommandComplete: Number of affected tuples are: 3 2
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88935-1] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |LOG: new connection received
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88935-2] 2020-01-09 10:11:01 ::: APP - [No Connection] :A: DB - [No Connection] :D: USER - [No Connection] :U: |DETAIL: connecting host=dbstest.cca.cz port=57808
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88936-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88937-1] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |FATAL: failed to read kind from backend
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88937-2] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]
> > > Jan 9 10:11:01 AISGPGP01 pgpool[10056]: [88937-3] 2020-01-09 10:11:01 ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: |HINT: check data consistency among db nodes
> > >
> > >
> > > The log from DBD1 is as follows (actions are being logged with pgAudit extension):
> > >
> > > 2020-01-09 10:11:01.507 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,1,1,READ,SELECT,,,"SELECT count(*) from (SELECT has_function_privilege('aisg', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s",<not logged>
> > > 2020-01-09 10:11:01.509 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,2,1,READ,SELECT,,,SELECT version(),<not logged>
> > > 2020-01-09 10:11:01.513 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,3,1,READ,SELECT,,,"SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND pg_get_expr(d.adbin, d.adrelid) ~ 'nextval' AND c.oid = pg_catalog.to_regclass('""replication_test""')",<not logged>
> > > 2020-01-09 10:11:01.516 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,4,1,READ,SELECT,,,SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpool_catalog' AND relname = 'insert_lock',<not logged>
> > > 2020-01-09 10:11:01.517 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,5,1,READ,SELECT,,,"SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pg_catalog.to_regclass('""replication_test""') FOR UPDATE",<not logged>
> > > 2020-01-09 10:11:01.521 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,6,1,READ,SELECT,,,"SELECT attname, pg_get_expr(d.adbin, d.adrelid), coalesce((pg_get_expr(d.adbin, d.adrelid) LIKE '%now()%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%''now''::text%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIMESTAMP%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_DATE%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIMESTAMP%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum =
d
> .a
> > dnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = to_regclass('""replication_test""') ORDER BY a.attnum",<not logged>
> > > 2020-01-09 10:11:01.522 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,7,1,READ,SELECT,,,SELECT now(),<not logged>
> > > 2020-01-09 10:11:01.524 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - INSERT :C: |LOG: AUDIT: SESSION,8,1,WRITE,INSERT,,,"INSERT INTO ""replication_test""(""int_number"", ""custom_text"", ""custom_date"") VALUES (""pg_catalog"".""date_part""('dow',""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text)), ('Current date/time is '||""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text) ),""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text))",<not logged>
> > > 2020-01-09 10:11:01.543 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,11,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.578 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,1,1,READ,SELECT,,,"SELECT count(*) from (SELECT has_function_privilege('aisg', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s",<not logged>
> > > 2020-01-09 10:11:01.579 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,2,1,READ,SELECT,,,SELECT version(),<not logged>
> > > 2020-01-09 10:11:01.583 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,3,1,READ,SELECT,,,"SELECT attname, pg_get_expr(d.adbin, d.adrelid), coalesce((pg_get_expr(d.adbin, d.adrelid) LIKE '%now()%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%''now''::text%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIMESTAMP%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_DATE%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIMESTAMP%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum =
d
> .a
> > dnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = to_regclass('""replication_test""') ORDER BY a.attnum",<not logged>
> > > 2020-01-09 10:11:01.584 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,4,1,READ,SELECT,,,SELECT now(),<not logged>
> > > 2020-01-09 10:11:01.585 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - INSERT :C: |LOG: AUDIT: SESSION,5,1,WRITE,INSERT,,,"INSERT INTO ""replication_test""(""int_number"", ""custom_text"", ""custom_date"") VALUES (""pg_catalog"".""date_part""('dow',""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.584626+01'::text)), ('Current date/time is '||""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.584626+01'::text) ),""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.584626+01'::text))",<not logged>
> > > 2020-01-09 10:11:01.599 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,12,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.612 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,6,1,READ,SELECT,,,SELECT now(),<not logged>
> > > 2020-01-09 10:11:01.613 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - UPDATE :C: |LOG: AUDIT: SESSION,7,1,WRITE,UPDATE,,,"UPDATE ""replication_test"" SET ""custom_date"" = ""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.612096+01'::text)",<not logged>
> > > 2020-01-09 10:11:01.666 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,1,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.723 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,1,1,READ,SELECT,,,"SELECT count(*) from (SELECT has_function_privilege('aisg', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s",<not logged>
> > > 2020-01-09 10:11:01.724 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,2,1,READ,SELECT,,,SELECT version(),<not logged>
> > > 2020-01-09 10:11:01.727 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,3,1,READ,SELECT,,,"SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND pg_get_expr(d.adbin, d.adrelid) ~ 'nextval' AND c.oid = pg_catalog.to_regclass('""replication_test""')",<not logged>
> > > 2020-01-09 10:11:01.729 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,4,1,READ,SELECT,,,SELECT count(*) FROM pg_catalog.pg_class c JOIN pg_catalog.pg_namespace n ON (c.relnamespace = n.oid) WHERE nspname = 'pgpool_catalog' AND relname = 'insert_lock',<not logged>
> > > 2020-01-09 10:11:01.730 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,5,1,READ,SELECT,,,"SELECT 1 FROM pgpool_catalog.insert_lock WHERE reloid = pg_catalog.to_regclass('""replication_test""') FOR UPDATE",<not logged>
> > > 2020-01-09 10:11:01.732 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,6,1,READ,SELECT,,,"SELECT attname, pg_get_expr(d.adbin, d.adrelid), coalesce((pg_get_expr(d.adbin, d.adrelid) LIKE '%now()%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%''now''::text%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIMESTAMP%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_TIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%CURRENT_DATE%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIME%' OR pg_get_expr(d.adbin, d.adrelid) LIKE '%LOCALTIMESTAMP%') AND (a.atttypid = 'timestamp'::regtype::oid OR a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid = 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid = 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum =
d
> .a
> > dnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.oid = to_regclass('""replication_test""') ORDER BY a.attnum",<not logged>
> > > 2020-01-09 10:11:01.733 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,7,1,READ,SELECT,,,SELECT now(),<not logged>
> > > 2020-01-09 10:11:01.734 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - INSERT :C: |LOG: AUDIT: SESSION,8,1,WRITE,INSERT,,,"INSERT INTO ""replication_test""(""int_number"", ""custom_text"", ""custom_date"") VALUES (""pg_catalog"".""date_part""('dow',""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text)), ('Current date/time is '||""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text) ),""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text))",<not logged>
> > > 2020-01-09 10:11:01.756 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,9,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.772 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - DELETE :C: |LOG: AUDIT: SESSION,14,1,WRITE,DELETE,,,DELETE FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.773 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |ERROR: syntax error at or near "send" at character 1
> > > 2020-01-09 10:11:01.773 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |STATEMENT: send invalid query from pgpool to abort transaction
> > > 2020-01-09 10:11:01.785 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,8,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.798 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,13,1,READ,SELECT,,,SELECT now(),<not logged>
> > > 2020-01-09 10:11:01.799 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - UPDATE :C: |LOG: AUDIT: SESSION,14,1,WRITE,UPDATE,,,"UPDATE ""replication_test"" SET ""custom_date"" = ""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.798139+01'::text)",<not logged>
> > > 2020-01-09 10:11:01.800 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |ERROR: syntax error at or near "send" at character 1
> > > 2020-01-09 10:11:01.800 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |STATEMENT: send invalid query from pgpool to abort transaction
> > > 2020-01-09 10:11:01.815 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,15,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > >
> > > The log from DBD2 (which seems to be much shorter):
> > >
> > > 2020-01-09 10:11:00.988 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - INSERT :C: |LOG: AUDIT: SESSION,1,1,WRITE,INSERT,,,"INSERT INTO ""replication_test""(""int_number"", ""custom_text"", ""custom_date"") VALUES (""pg_catalog"".""date_part""('dow',""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text)), ('Current date/time is '||""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text) ),""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.503056+01'::text))",<not logged>
> > > 2020-01-09 10:11:01.005 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,3,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.061 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,4,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.129 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,1,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.200 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - INSERT :C: |LOG: AUDIT: SESSION,1,1,WRITE,INSERT,,,"INSERT INTO ""replication_test""(""int_number"", ""custom_text"", ""custom_date"") VALUES (""pg_catalog"".""date_part""('dow',""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text)), ('Current date/time is '||""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text) ),""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.719824+01'::text))",<not logged>
> > > 2020-01-09 10:11:01.218 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,2,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.233 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - DELETE :C: |LOG: AUDIT: SESSION,5,1,WRITE,DELETE,,,DELETE FROM replication_test;,<not logged>
> > > 2020-01-09 10:11:01.235 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |ERROR: syntax error at or near "send" at character 1
> > > 2020-01-09 10:11:01.235 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |STATEMENT: send invalid query from pgpool to abort transaction
> > > 2020-01-09 10:11:01.261 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - UPDATE :C: |LOG: AUDIT: SESSION,4,1,WRITE,UPDATE,,,"UPDATE ""replication_test"" SET ""custom_date"" = ""pg_catalog"".""timestamptz""('2020-01-09 10:11:01.798139+01'::text)",<not logged>
> > > 2020-01-09 10:11:01.263 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |ERROR: syntax error at or near "send" at character 1
> > > 2020-01-09 10:11:01.263 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - idle in transaction :C: |STATEMENT: send invalid query from pgpool to abort transaction
> > > 2020-01-09 10:11:01.277 CET ::: APP - psql :A: DB - aisgdvyv :D: USER - aisg :U: HOST - 172.20.15.64 :H: CMD - SELECT :C: |LOG: AUDIT: SESSION,6,1,READ,SELECT,,,/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;,<not logged>
> > >
> > >
> > > I am also sending our pgpool configuration as an attachment.
> > >
> > >
> > > Any idea what could be the cause of this behavior? From what I gather, pgpool should be replicating commands on both DBD servers and check if both returned successfully and if not it should cancel/rollback the command on both, yet here it seems that does not happen. Can this be some kind of bug or do we have some incorrect setting in the pgpool configuration file? Let me know, if you need some more information on the settings or circumstances of the error... Thank you for your time.
> > >
> > > Vladimír Láznička, DBA, CCA Group a.s.
> >
> >
> > --
> > Bo Peng <pengbo at sraoss.co.jp>
> > SRA OSS, Inc. Japan
> > _______________________________________________
> > pgpool-general mailing list
> > pgpool-general at pgpool.net
> > http://www.pgpool.net/mailman/listinfo/pgpool-general
>
>
> --
> Bo Peng <pengbo at sraoss.co.jp>
> SRA OSS, Inc. Japan
--
Bo Peng <pengbo at sraoss.co.jp>
SRA OSS, Inc. Japan
More information about the pgpool-general
mailing list