<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-2">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;
mso-fareast-language:EN-US;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
p.MsoPlainText, li.MsoPlainText, div.MsoPlainText
{mso-style-priority:99;
mso-style-link:"Prostý text Char";
margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;
mso-fareast-language:EN-US;}
span.StylE-mailovZprvy17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
span.ProsttextChar
{mso-style-name:"Prostý text Char";
mso-style-priority:99;
mso-style-link:"Prostý text";
font-family:"Calibri",sans-serif;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;
mso-fareast-language:EN-US;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:70.85pt 70.85pt 70.85pt 70.85pt;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="CS" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal"><span lang="EN-US">Hello pgPool team,<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">PGP1 – MASTER pgpool server<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">PGP2 – STANDBY pgpool server<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">DBD1 – first PostgreSQL server<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">DBD2 – second PostgreSQl server<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">pgPool version – 4.0.6<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">PostgreSQL version – 11.5<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Recently we have encountered a serious problem with replicating some DML commands:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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. <o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Because of that error I created a simple testing script that is called from remote server and issues these commands in a sequence:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">INSERT one row in testing table.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">INSERT one row in testing table.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">UPDATE all rows in the table.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">INSERT one row in testing table.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">DELETE all rows from the table.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">UPDATE all rows in the table (should UPDATE 0 rows).<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">SELECT all rows from the table. Command uses commentary like so: /* NO LOAD-BALANCE */ SELECT …
<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US">WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['D']<o:p></o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US">FATAL: failed to read kind from backend<o:p></o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US">DETAIL: kind mismatch among backends. Possible last query was: "/*NO LOAD-BALANCE*/ SELECT * FROM replication_test;" kind details are: 0[D] 1[C]<o:p></o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US">HINT: check data consistency among db nodes server closed the connection unexpectedly<o:p></o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US"> This probably means the server terminated abnormally<o:p></o:p></span></p>
<p class="MsoPlainText"><span lang="EN-US"> before or while processing the request.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">connection to server was lost<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Here is a piece of the log from pgpool in that time:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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']<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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]<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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']<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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]<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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']<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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]<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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;"<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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();"<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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']<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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]<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">The log from DBD1 is as follows (actions are being logged with pgAudit extension):<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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.adnum) 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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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.adnum) 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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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.adnum) 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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">The log from DBD2 (which seems to be much shorter):<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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><o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">I am also sending our pgpool configuration as an attachment.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><b><span lang="EN-US">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?</span></b><span lang="EN-US"> Let me know, if you need some more information on the settings or circumstances
of the error… Thank you for your time.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Vladimír Láznička, DBA, CCA Group a.s.</span><o:p></o:p></p>
</div>
</body>
</html>