View Issue Details

IDProjectCategoryView StatusLast Update
0000231Pgpool-IIBugpublic2016-12-20 11:24
ReporternomirAssigned Tot-ishii 
PrioritynormalSeveritymajorReproducibilityrandom
Status resolvedResolutionopen 
Product Version3.5.3 
Target Version3.5.5Fixed in Version 
Summary0000231: packet kind of backend 1 ['3'] does not match with master/majority nodes packet kind ['2']
DescriptionThis report is follow up of issue 221.

pgpool-II log
-------------
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: B message
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: D message
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: Execute: select shortdescr0_.epg_id as epg_id1_83_1_, shortdescr0_.epg_id as epg_id1_90_1_, shortdescr0_.language_id as language2_90_1_, shortdescr0_.language_id as formula7_1_, shortdescr0_.epg_id as epg_id1_90_0_, shortdescr0_.language_id as language2_90_0_, shortdescr0_.localized_text as localize3_90_0_ from epg_short_description_l10n shortdescr0_ where shortdescr0_.epg_id in ($1, $2, $3, $4)
Aug 9 15:08:51 db02 pgpool[13553]: [6765-1] 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: C message
Aug 9 15:08:51 db02 pgpool[13553]: [6766-1] 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 0 backend pid: 29300 statement: B message
Aug 9 15:08:51 db02 pgpool[13553]: [6767-1] 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: B message
Aug 9 15:08:51 db02 pgpool[13553]: [6768-1] 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 0 backend pid: 29300 statement: Execute: BEGIN
Aug 9 15:08:51 db02 pgpool[13553]: [6769-1] 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: Execute: BEGIN
Aug 9 15:08:51 db02 pgpool[13553]: [6770-1] 2016-08-09 15:08:51: pid 13553: db: tve WARNING: packet kind of backend 1 ['3'] does not match with master/majority nodes packet kind ['2']
Aug 9 15:08:51 db02 pgpool[13553]: [6771-1] 2016-08-09 15:08:51: pid 13553: db: tve FATAL: failed to read kind from backend
Aug 9 15:08:51 db02 pgpool[13553]: [6771-2] 2016-08-09 15:08:51: pid 13553: db: tve DETAIL: kind mismatch among backends. Possible last query was: "BEGIN" kind details are: 0[2] 1[3]
Aug 9 15:08:51 db02 pgpool[13553]: [6771-3] 2016-08-09 15:08:51: pid 13553: db: tve HINT: check data consistency among db nodes
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: C message
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 0 backend pid: 29300 statement: B message
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: B message
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 0 backend pid: 29300 statement: Execute: BEGIN
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve LOG: DB node id: 1 backend pid: 13702 statement: Execute: BEGIN
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve WARNING: packet kind of backend 1 ['3'] does not match with master/majority nodes packet kind ['2']
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve FATAL: failed to read kind from backend
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve DETAIL: kind mismatch among backends. Possible last query was: "BEGIN" kind details are: 0[2] 1[3]
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13553: db: tve HINT: check data consistency among db nodes
Aug 9 15:08:51 db02 pgpool[13368]: [7-1] 2016-08-09 15:08:51: pid 13368: db: [No Connection] LOG: child process with pid: 13553 exits with status 512
Aug 9 15:08:51 db02 pgpool[13368]: 2016-08-09 15:08:51: pid 13368: db: [No Connection] LOG: child process with pid: 13553 exits with status 512

pgpool.conf
-----------

backend_hostname0 = '....'
backend_port0 = 5432
backend_weight0 = 0
backend_flag0 = 'ALLOW_TO_FAILOVER'

backend_hostname1 = '.....'
backend_port1 = 5432
backend_weight1 = 1
backend_flag1 = 'ALLOW_TO_FAILOVER'

replication_mode = off
replicate_select = off
load_balance_mode = on
master_slave_mode = on
parallel_mode = off

log_connections = on
log_hostname = on
log_statement = on
log_per_node_statement = on
log_standby_delay = 'always'
debug_level = 110


there is working synchronous streaming replication between backend_hostname0 and backend_hostname1.

postgresql.conf on backend_hostname0
------------------------------------

synchronous_commit = remote_write
synchronous_standby_names = 'backend_hostname1'


Our goal was to direct all select queries to backend_hostname1 (synchronous replica) and all write queries to backend_hostname0 (master).
Steps To ReproduceWe are not able to provide steps to reproduce this problem. This error appears randomly during application run.
Tagsstreaming replication

Activities

t-ishii

2016-08-15 10:08

developer   ~0000991

Please let me know if you find a way to reproduce the problem.

nomir

2016-08-15 20:14

reporter   ~0000999

I am trying to find a simple way to reproduce the problem but no luck so far. When I run stress test on our java application, the error appears during first 20 seconds but the sequence of queries before crash is different. I am not able to reproduce in different application.

I made tcpdump of tcp stream before the crash. If it helps.

pgpool.pcap (2,013 bytes)

nomir

2016-08-15 20:16

reporter   ~0001000

Tcpdump between the application and pgpool before the crash

t-ishii

2016-08-16 07:48

developer   ~0001002

pgpool.dump removed.

BTW, tcpdump is not very helpful for me. Is it possible to share JDBC debug trace right before the error? That shows what kind of protocol messages were sent to pgpool.

nomir

2016-08-17 21:18

reporter  

jdbc.debug.log (558,749 bytes)

nomir

2016-08-17 21:18

reporter   ~0001008

There is JDBC debug trace before the error.

nomir

2016-08-17 21:34

reporter   ~0001009

> There is JDBC debug trace before the error.

It looks like the debug is not complete. We need to made some adjustment in application to be able to follow individual threads.

nomir

2016-08-17 21:56

reporter   ~0001010

>> There is JDBC debug trace before the error.

>It looks like the debug is not complete. We need to made some adjustment in >application to be able to follow individual threads.

Sorry for confusing. The trace is complete.

t-ishii

2016-08-18 15:12

developer   ~0001011

It seems Pgpool-II was confused by the close statement.

2016-07-16 20:29:03,679 INFO [stdout] (default task-296) 20:29:03.678 (12) FE=> CloseStatement(S_19)

Can you please attached patch?

t-ishii

2016-08-18 15:13

developer  

close.diff (589 bytes)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index c833f48..1f52406 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -2415,8 +2415,11 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
 			break;
 
 		case 'C':	/* Close */
+			pool_set_doing_extended_query_message();
+#ifdef NOT_USED
 			if (!pool_is_query_in_progress() && !pool_is_ignore_till_sync())
 				pool_set_query_in_progress();
+#endif
 			status = Close(frontend, backend, len, contents);
 			pool_set_pending_response();
 			break;
close.diff (589 bytes)

nomir

2016-08-18 18:18

reporter   ~0001012

Thanks for the patch. Unfortunately, the error appears again.

server_20160818.log (600,355 bytes)

t-ishii

2016-08-18 19:44

developer   ~0001013

Is is possible to share pgpool log when the error occurs?

nomir

2016-08-18 20:25

reporter   ~0001014

Yes. I attached logs from 4 crashes.

pgpool_logs.tar.gz (150,064 bytes)

t-ishii

2016-08-19 11:40

developer   ~0001016

Thanks. It seems Pgpool-II sent the close message to node 1 only (this is correct because the statement about to closed was SELECT and it was sent to node 1).
Problem is, subsequent messages is BEGIN, which was sent to both node 0 and 1 (this is correct too). Pgpool-II tried to read the response from node 1, which was "3", this is ok because it is "Close complete". But returned response from node 0 was "2" ("bind complete").

So Pgpool-II needs to be smart in that it should recognize "Close complete" message only comes from node 1.

It may take while to fix this since I am pretty busy now...

t-ishii

2016-08-22 11:09

developer   ~0001017

Last edited: 2016-08-22 11:11

View 2 revisions

Ok, here is new patch trying to solve the problem. Can you please try it out? Note that you need to apply the patch *without* previous patch.

t-ishii

2016-08-22 11:11

developer  

close-v2.diff (522 bytes)
diff --git a/src/context/pool_query_context.c b/src/context/pool_query_context.c
index 49431ac..efeeb48 100644
--- a/src/context/pool_query_context.c
+++ b/src/context/pool_query_context.c
@@ -920,7 +920,7 @@ POOL_STATUS pool_extended_send_and_wait(POOL_QUERY_CONTEXT *query_context,
 
 		send_extended_protocol_message(backend, i, kind, str_len, str);
 
-		if (*kind == 'E' && STREAM)
+		if ((*kind == 'E' || *kind == 'C') && STREAM)
 		{
 			/*
 			 * Send flush message to backend to make sure that we get any response
close-v2.diff (522 bytes)

nomir

2016-08-22 18:57

reporter   ~0001018

Still the same error.

Pgpool log attached.

pgpool.log.gz (1,611,538 bytes)

sergey.s.sazonov

2016-10-27 18:58

reporter   ~0001139

Hi! We have the same issue here. PostgreSQL and Pgpool configs are equal. Could you please fix that?

feudenfer

2016-10-28 00:26

reporter   ~0001140

Hi all, if this helps, I got the same pgpool message exactly at the time when the application received "too many clients" error from pgpool.

t-ishii

2016-11-10 14:25

developer   ~0001159

To fix the issue, we need a self contained test case.

supp_k

2016-11-20 05:13

reporter   ~0001178

Hi,
we are constantly randomly face this error.
It is possible to fix the issue?

supp_k

2016-11-22 02:04

reporter   ~0001181

Here is the message which caught recently:
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17209]: [6107-3] LOCATION: child.c:2123
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6754-1] LOG: new connection received
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6754-2] DETAIL: connecting host=10.192.36.35 port=50129
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6754-3] LOCATION: child.c:2123
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6755-1] LOG: pool_read_kind: error message from master backend:sorry, too many clients already
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6755-2] LOCATION: pool_auth.c:1227
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6756-1] ERROR: unable to read message kind
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6756-2] DETAIL: kind does not match between master(45) slot[1] (52)
Nov 21 19:58:10 srv-60b2f6e99b9b pgpool[17554]: [6756-3] LOCATION: pool_auth.c:1242
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17213]: [6107-1] LOG: new connection received
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17213]: [6107-2] DETAIL: connecting host=10.192.36.35 port=50131
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17213]: [6107-3] LOCATION: child.c:2123
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17214]: [6107-1] LOG: new connection received
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17214]: [6107-2] DETAIL: connecting host=10.192.36.35 port=50132
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17214]: [6107-3] LOCATION: child.c:2123
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6756-1] LOG: new connection received
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6756-2] DETAIL: connecting host=10.192.36.35 port=50133
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6756-3] LOCATION: child.c:2123
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6757-1] LOG: pool_read_kind: error message from master backend:sorry, too many clients already
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6757-2] LOCATION: pool_auth.c:1227
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6758-1] ERROR: unable to read message kind
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6758-2] DETAIL: kind does not match between master(45) slot[1] (52)
Nov 21 19:58:25 srv-60b2f6e99b9b pgpool[17558]: [6758-3] LOCATION: pool_auth.c:1242
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6787-1] ERROR: failed to authenticate
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6787-2] DETAIL: invalid authentication message response type, Expecting 'R' and received 'E'
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6787-3] LOCATION: child.c:1375
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6788-1] ERROR: failed to authenticate
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6788-2] DETAIL: invalid authentication message response type, Expecting 'R' and received 'E'
Nov 21 19:58:27 srv-60b2f6e99b9b pgpool[9207]: [6788-3] LOCATION: child.c:1375
Nov 21 19:58:28 srv-60b2f6e99b9b pgpool[9207]: [6789-1] LOG: health checking retry count 1
Nov 21 19:58:28 srv-60b2f6e99b9b pgpool[9207]: [6789-2] LOCATION: pgpool_main.c:467
Nov 21 19:58:28 srv-60b2f6e99b9b pgpool[9207]: [6790-1] ERROR: failed to authenticate
Nov 21 19:58:28 srv-60b2f6e99b9b pgpool[9207]: [6790-2] DETAIL: invalid authentication message response type, Expecting 'R' and received 'E'
Nov 21 19:58:28 srv-60b2f6e99b9b pgpool[9207]: [6790-3] LOCATION: child.c:1375
Nov 21 19:58:29 srv-60b2f6e99b9b pgpool[9207]: [6791-1] LOG: health checking retry count 2
Nov 21 19:58:29 srv-60b2f6e99b9b pgpool[9207]: [6791-2] LOCATION: pgpool_main.c:467
Nov 21 19:58:29 srv-60b2f6e99b9b pgpool[9207]: [6792-1] ERROR: failed to authenticate
Nov 21 19:58:29 srv-60b2f6e99b9b pgpool[9207]: [6792-2] DETAIL: invalid authentication message response type, Expecting 'R' and received 'E'

supp_k

2016-11-22 02:47

reporter   ~0001182

Can you please describe the true reason of the problem? Probably we need to tune the postgresql or linux itself?
For instance we could manage how it closes network connections.

supp_k

2016-11-22 03:10

reporter   ~0001183

Dear Pgpool Developers - Mr T-ishii,

If you cannot detect the error in your environment than let me propose you to use Our QA environment!!

We can setup screen sharing and/or grant you remote control, even setup build environment. So you will be able to trace the requests. We reproduce it locally with very high probability.

I think it will useful and productive, much more efficient than send messages and wait for one which reproduces the issue.


If you are interested in solving of the problem please provive me contacts to "resolvepool@gmail.com" and I will contact you using my corporate email.


Here is one more error message which observe:

Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20218]: [47-3] LOCATION: child.c:2123
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20219]: [45-1] LOG: new connection received
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20219]: [45-2] DETAIL: connecting host=10.28.64.197 port=44444
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20219]: [45-3] LOCATION: child.c:2123
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20221]: [46-1] LOG: new connection received
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20221]: [46-2] DETAIL: connecting host=10.28.64.197 port=44445
Nov 21 20:58:14 srv-60b2f6e99b9b pgpool[20221]: [46-3] LOCATION: child.c:2123
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [14-1] WARNING: packet kind of backend 1 ['3'] does not match with master/majority nodes packet kind ['2']
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [14-2] LOCATION: pool_process_query.c:3571
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [15-1] FATAL: failed to read kind from backend
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [15-2] DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[2] 1[3]
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [15-3] HINT: check data consistency among db nodes
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20748]: [15-4] LOCATION: pool_process_query.c:3676
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20070]: [114-1] LOG: child process with pid: 20748 exits with status 512
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20070]: [114-2] LOCATION: pgpool_main.c:2243
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20070]: [115-1] LOG: fork a new child process with pid: 21068
Nov 21 20:58:50 srv-60b2f6e99b9b pgpool[20070]: [115-2] LOCATION: pgpool_main.c:2329
Nov 21 20:59:15 srv-60b2f6e99b9b pgpool[20222]: [46-1] LOG: new connection received

supp_k

2016-11-23 02:58

reporter   ~0001186

Hi,

we have analyzed the pgpool's code. And want to propose you the following fix:

diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index 58e75e9..ee8cdec 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -3701,7 +3701,7 @@ void read_kind_from_backend(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *bac
                        degenerate_backend_set(degenerate_node, degenerate_node_num, false, 0);
             retcode = 1;
                }
- ereport(FATAL,
+ ereport(WARNING,
             (return_code(retcode),
                  errmsg("failed to read kind from backend"),
                     errdetail("%s",msg->data),


We see that to the moment the message above is returned to the client the sql request is already processed and data is returned. Even the decided_kind variable already contains the response status choosen by the majority. So we need just inform the db client on the status and the facts that have been taken into the consideration.

The proposed patch was tested under loading and it is still being verified.

Please consider it!

supp_k

2016-11-25 15:56

reporter   ~0001191

Hi,


It seems we could solve the problem. The issue was not in pgpool but in old version of the postgresql lib. After upgrading of the library the problem disappeared.

We are still testing it, but please try to review the used postgres client lib. It's version should correspond to postgresql-server version.

supp_k

2016-11-29 00:10

reporter   ~0001192

No, I was wrong we still face the error.
Is anybody among pgpool developers can help us?
Please respond!

t-ishii

2016-11-30 22:09

developer   ~0001193

I am now writing a tool which allows to send an arbitrarily message stream to Pgpool-II to reproduce the problem. Without reliably reproducing the problem, it is not very productive to debug and create a patch. It will take a while though...

supp_k

2016-12-04 04:28

reporter   ~0001194

We did deep investigation of the problem and revealed that the problem’s root is in "Prepared statements" and only if load balancing on pgpool is activated.

Steps to reproduce:
- configure pgpool's load balancing proportion like master/slave : 1/999. The idea engaged here is to route the absolute number of read-only requests to SLAVE postgres (in our case its synchronous standby with Master Postgres 9.6)
- in DB client create "prepared statement" and execute it many times (e.g. 100) in one transaction and then COMMIT.


Result: on commit the following error appears:
 
org.postgresql.util.PSQLException: FATAL: failed to read kind from backend
  Detail: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[1] 1[3]
  Hint: check data consistency among db nodes

 

The following java code which reproduces the problem was used:
import java.sql.*;

public class TestReplGap {

public static void main(String[] args) throws SQLException, InterruptedException {

try (Connection conn = DriverManager.getConnection("jdbc:postgresql://10.28.78.80:5432/postgres", "user", "password")) {

conn.setAutoCommit(false);
// Note: It is supposed that the database postgres contains table "table".
try (PreparedStatement stmt = conn.prepareStatement("select * from table where id = ? ")) {

for (int i = 0; i < 100; i++) {
stmt.setInt(1, i);
stmt.executeQuery().close();

System.out.println(i);
}
}

conn.commit();
conn.close();

System.out.println("DONE");
} catch (SQLException ex) {
ex.printStackTrace();
}
}
}


We did conclusion that the problem appears because the parse request is not distributed to all backends.

t-ishii

2016-12-05 07:58

developer   ~0001195

No. For load balancing queries (mostly SELECTs), the parse message is only sent to the node which is in charge of executing the query.

supp_k

2016-12-05 15:55

reporter   ~0001196

But can you please confirm the attached code reproduces the problem? It seems this is what yo need to investigate the problem and fix it.

t-ishii

2016-12-05 15:59

developer   ~0001197

Yes, I can confirm that the sample program reliably reproduce the problem.
Now I'm trying to fix the problem.

t-ishii

2016-12-05 16:40

developer  

bug231.diff (4,210 bytes)
diff --git a/src/context/pool_query_context.c b/src/context/pool_query_context.c
index fabc4d7..15a5fe3 100644
--- a/src/context/pool_query_context.c
+++ b/src/context/pool_query_context.c
@@ -920,7 +920,7 @@ POOL_STATUS pool_extended_send_and_wait(POOL_QUERY_CONTEXT *query_context,
 
 		send_extended_protocol_message(backend, i, kind, str_len, str);
 
-		if (*kind == 'E' && STREAM)
+		if ((*kind == 'E' || *kind == 'C') && STREAM)
 		{
 			/*
 			 * Send flush message to backend to make sure that we get any response
@@ -933,6 +933,9 @@ POOL_STATUS pool_extended_send_and_wait(POOL_QUERY_CONTEXT *query_context,
 			pool_write(cp, "H", 1);
 			len = htonl(sizeof(len));
 			pool_write_and_flush(cp, &len, sizeof(len));
+
+			ereport(DEBUG1,
+					(errmsg("pool_send_and_wait: send flush message to %d", i)));
 		}
 	}
 
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index c4115f8..d9bbca4 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -1510,8 +1510,8 @@ POOL_STATUS Close(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
 		POOL_PENDING_MESSAGE *pmsg;
 
 		pool_clear_sync_map();
-		pool_extended_send_and_wait(query_context, "C", len, contents, 1, MASTER_NODE_ID, true);
-		pool_extended_send_and_wait(query_context, "C", len, contents, -1, MASTER_NODE_ID, true);
+		pool_extended_send_and_wait(query_context, "C", len, contents, 1, MASTER_NODE_ID, false);
+		pool_extended_send_and_wait(query_context, "C", len, contents, -1, MASTER_NODE_ID, false);
 
 		pmsg = pool_pending_messages_create('C', len, contents);
 		pool_pending_message_add(pmsg);
@@ -2415,6 +2415,7 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
 			break;
 
 		case 'C':	/* Close */
+			pool_set_doing_extended_query_message();
 			if (!pool_is_query_in_progress() && !pool_is_ignore_till_sync())
 				pool_set_query_in_progress();
 			status = Close(frontend, backend, len, contents);
diff --git a/src/test/regression/tests/067.bug231/TestReplGap.java b/src/test/regression/tests/067.bug231/TestReplGap.java
new file mode 100644
index 0000000..2aaa17d
--- /dev/null
+++ b/src/test/regression/tests/067.bug231/TestReplGap.java
@@ -0,0 +1,29 @@
+import java.sql.*;
+
+public class TestReplGap {
+
+    public static void main(String[] args) throws SQLException, InterruptedException {
+
+	try (Connection conn = DriverManager.getConnection("jdbc:postgresql://localhost:11000/test?loglevel=2", "t-ishii", "")) {
+
+		conn.setAutoCommit(false);
+		// Note: It is supposed that the database postgres contains table "t1".
+		try (PreparedStatement stmt = conn.prepareStatement("select * from t1 where id = ? ")) {
+
+			for (int i = 0; i < 100; i++) {
+			    stmt.setInt(1, i);
+			    stmt.executeQuery().close();
+
+			    System.out.println(i);
+			}
+		    }
+
+		conn.commit();
+		conn.close();
+
+		System.out.println("DONE");
+	    } catch (SQLException ex) {
+	    ex.printStackTrace();
+	}
+    }
+}
diff --git a/src/test/regression/tests/067.bug231/test.sh b/src/test/regression/tests/067.bug231/test.sh
new file mode 100755
index 0000000..6e27224
--- /dev/null
+++ b/src/test/regression/tests/067.bug231/test.sh
@@ -0,0 +1,41 @@
+#!/usr/bin/env bash
+#-------------------------------------------------------------------
+# test script for for bug 231 (packet kind of backend 1 ['3'] does not
+# match with master/majority nodes packet kind ['2']).
+#
+source $TESTLIBS
+TESTDIR=testdir
+PSQL=$PGBIN/psql
+export CLASSPATH=.:$JDBC_DRIVER
+
+rm -fr $TESTDIR
+mkdir $TESTDIR
+cd $TESTDIR
+
+# create test environment
+echo -n "creating test environment..."
+$PGPOOL_SETUP -m s -n 2 || exit 1
+echo "done."
+echo "backend_weight0 = 0" >> etc/pgpool.conf
+echo "backend_weight1 = 1" >> etc/pgpool.conf
+
+source ./bashrc.ports
+./startall
+export PGPORT=$PGPOOL_PORT
+wait_for_pgpool_startup
+
+export PGPORT=11000
+psql -c "DROP TABLE IF EXISTS t1" test
+psql -c "CREATE TABLE t1 (id int);" test
+psql -c "INSERT INTO t1 VALUES(1)" test
+
+TestProg=TestReplGap
+cp ../$TestProg.java .
+javac $TestProg.java
+java $TestProg > $TestProg.log  2>&1
+if [ $? != 0 ];then
+    ./shutdownall; exit 1;
+fi
+./shutdownall
+
+exit 0
bug231.diff (4,210 bytes)

t-ishii

2016-12-05 16:41

developer   ~0001198

I have uploaded fix for the problem as "bug231.diff". Please try if you like.

supp_k

2016-12-07 05:08

reporter   ~0001205

The primary problem disappeared but the other strange behavior detected.

After reactivation of the cache for preparing statements in jboss (see the link below) we observe that time from the time SQL requests are hang. pg_stat_activity view in postgres doesnt reflect any requests but from the client side it seems that requests are still being executed.

If we deactivate load balancing in pgpool then the "hang" disappears.


(https://access.redhat.com/documentation/en-US/JBoss_Enterprise_Application_Platform/5/html/Performance_Tuning_Guide/sect-Performance_Tuning_Guide-Entity_Beans-Prepared_Statements.html)

t-ishii

2016-12-07 07:40

developer   ~0001206

A JDBC debug log please.

supp_k

2016-12-09 01:40

reporter   ~0001208

These days we are trying to identify requests and pattern that lead to this behaviour. If we activate JDBC debug (loglevel=2 in jdbc connection string) then it creates log of hundreds megabytes.


Fighting how to reproduce the issue.

Again, we observe the problem if awe activate cashing of prepared statements in jboss and load balancing in pgpool.

supp_k

2016-12-09 02:21

reporter   ~0001209

We identified one strange case... Please have a look if a suspicious case or not from your perspective.

The first item represents normal behaviour when we not observe any problems with requests. The 2nd case demonstrates case when we see the logic "hangs" and the caching of prepared statements is activated in jboss.


1)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.427 (23) FE=> Parse(stmt=null,query="select uifavorite0_.item_id as item_id1_182_, uifavorite0_.user_id as user_id2_182_ from ui_favorite_items uifavorite0_ where uifavorite0_.user_id=$1",oids={23})
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.427 (23) FE=> Bind(stmt=null,portal=null,$1=<1>)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.427 (23) FE=> Describe(portal=null)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.427 (23) FE=> Execute(portal=null,limit=0)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.427 (23) FE=> Sync
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.428 (23) <=BE ParseComplete [null]
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.428 (23) <=BE BindComplete [null]
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.428 (23) <=BE RowDescription(2)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.428 (23) Field(,VARCHAR,65535,T)
161208 20:07:33 INFO [stdout] (default task-101) 20:07:33.428 (23) Field(,INT4,4,T)


2)

161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.011 (3) FE=> Parse(stmt=null,query="select uifavorite0_.item_id as item_id1_182_, uifavorite0_.user_id as user_id2_182_ from ui_favorite_items uifavorite0_ where uifavorite0_.user_id=$1",oids={23})
161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.012 (3) FE=> Bind(stmt=null,portal=null,$1=<1>)
161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.012 (3) FE=> Describe(portal=null)
161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.012 (3) FE=> Execute(portal=null,limit=0)
161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.012 (3) FE=> Sync
161208 20:04:36 INFO [stdout] (default task-98) 20:04:36.012 (3) <=BE CloseComplete


The database has the "ui_favorite_items" table and in sample the request returns 0 records.

t-ishii

2016-12-09 08:23

developer   ~0001210

Thanks. However, I need more JDBC log for 2) because I am interested in why CloseComplete message appears. There should be a Close message from FE before the Parse message in 2).

supp_k

2016-12-09 17:15

reporter   ~0001211

We revealed one more strange case. Please have a look at following message.
We don't state it is a pgpool bug. But can you please clarify what the last CloseMessage correspond to?




161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> CloseStatement(S_6)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> Parse(stmt=null,query="select account0_.account_id as account_1_3_0_, address1_.address_id as address_1_4_1_, account0_.address_id as address21_3_0_, account0_.adm_contact_id as adm_con22_3_0_, account0_.aps_uuid as aps_uuid2_3_0_, account0_.ext_system_id as ext_sys23_3_0_, account0_.bill_contact_id as bill_co24_3_0_, account0_.brand_name as brand_na3_3_0_, account0_.ccp_version as ccp_vers4_3_0_, account0_.company_name as company_5_3_0_, account0_.customers_quantity as customer6_3_0_, account0_.l_country_code_default as l_countr7_3_0_, account0_.l_language_code_default as l_langua8_3_0_, account0_.l_variant_default as l_varian9_3_0_, account0_.ext_account_id as ext_acc10_3_0_, account0_.c_time as c_time11_3_0_, account0_.l_country_code as l_count12_3_0_, account0_.l_language_code as l_langu13_3_0_, account0_.l_variant as l_varia14_3_0_, account0_.is_locked as is_lock15_3_0_, account0_.note as note16_3_0_, account0_.owner_id as owner_i25_3_0_, account0_.path as path17_3_0_, account0_.is_personal as is_pers18_3_0_, account0_.rt_instance_id as rt_inst19_3_0_, account0_.tech_contact_id as tech_co26_3_0_, account0_.account_type as account20_3_0_, address1_.address as address2_4_1_, address1_.address2 as address3_4_1_, address1_.address3 as address4_4_1_, address1_.city as city5_4_1_, address1_.country as country6_4_1_, address1_.postal_code as postal_c7_4_1_, address1_.state as state8_4_1_ from accounts account0_ left outer join addresses address1_ on account0_.address_id=address1_.address_id where account0_.account_id=$1",oids={23})
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> Bind(stmt=null,portal=null,$1=<1>)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Describe(portal=null)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Execute(portal=null,limit=0)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Sync
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.537 (17) <=BE CloseComplete

t-ishii

2016-12-09 17:19

developer   ~0001212

Probably this:

161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> CloseStatement(S_6)

supp_k

2016-12-09 17:34

reporter   ~0001213

Yes,
I mean I need your clarification whether the "161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.537 (17) <=BE CloseComplete" correspond to the "161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> CloseStatement(S_6)"? What does it mean from the pgpool's point of view?

Will it provide answer for the request (below)?
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> Bind(stmt=null,portal=null,$1=<1>)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Describe(portal=null)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Execute(portal=null,limit=0)
161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.536 (17) FE=> Sync

t-ishii

2016-12-09 17:56

developer   ~0001214

> I mean I need your clarification whether the "161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.537 (17) <=BE CloseComplete" correspond to the "161209 10:46:56 INFO [stdout] (default task-160) 10:46:56.535 (17) FE=> CloseStatement(S_6)"?

Yes.

More questions is, what is "S_6"? There must be parse/bind message using S_6 somewhere before the log. By looking at that, we can confirm what is the SQL corresponds to S_6. I think it is one of keys to understand the problem.

supp_k

2016-12-09 18:22

reporter  

console.log (6,509,845 bytes)

atan

2016-12-09 18:43

reporter   ~0001216

I can confirm such random behavior with a third-party Java application:

Dec 9 10:34:24 pgdb1 pgpool[28228]: [1174-1] 2016-12-09 10:34:24: pid 28228: FATAL: failed to read kind from backend
Dec 9 10:34:24 pgdb1 pgpool[28228]: [1174-2] 2016-12-09 10:34:24: pid 28228: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:24 pgdb1 pgpool[28228]: [1174-3] 2016-12-09 10:34:24: pid 28228: HINT: check data consistency among db nodes
Dec 9 10:34:24 pgdb1 pgpool[28208]: [716-1] 2016-12-09 10:34:24: pid 28208: FATAL: failed to read kind from backend
Dec 9 10:34:24 pgdb1 pgpool[28208]: [716-2] 2016-12-09 10:34:24: pid 28208: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:24 pgdb1 pgpool[28208]: [716-3] 2016-12-09 10:34:24: pid 28208: HINT: check data consistency among db nodes
Dec 9 10:34:25 pgdb1 pgpool[28222]: [134-1] 2016-12-09 10:34:25: pid 28222: FATAL: failed to read kind from backend
Dec 9 10:34:25 pgdb1 pgpool[28222]: [134-2] 2016-12-09 10:34:25: pid 28222: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:25 pgdb1 pgpool[28222]: [134-3] 2016-12-09 10:34:25: pid 28222: HINT: check data consistency among db nodes
Dec 9 10:34:25 pgdb1 pgpool[28215]: [756-1] 2016-12-09 10:34:25: pid 28215: FATAL: failed to read kind from backend
Dec 9 10:34:25 pgdb1 pgpool[28215]: [756-2] 2016-12-09 10:34:25: pid 28215: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:25 pgdb1 pgpool[28215]: [756-3] 2016-12-09 10:34:25: pid 28215: HINT: check data consistency among db nodes
Dec 9 10:34:25 pgdb1 pgpool[28230]: [5724-1] 2016-12-09 10:34:25: pid 28230: FATAL: failed to read kind from backend
Dec 9 10:34:25 pgdb1 pgpool[28230]: [5724-2] 2016-12-09 10:34:25: pid 28230: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:25 pgdb1 pgpool[28230]: [5724-3] 2016-12-09 10:34:25: pid 28230: HINT: check data consistency among db nodes
Dec 9 10:34:30 pgdb1 pgpool[28232]: [7580-1] 2016-12-09 10:34:30: pid 28232: FATAL: failed to read kind from backend
Dec 9 10:34:30 pgdb1 pgpool[28232]: [7580-2] 2016-12-09 10:34:30: pid 28232: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:34:30 pgdb1 pgpool[28232]: [7580-3] 2016-12-09 10:34:30: pid 28232: HINT: check data consistency among db nodes

atan

2016-12-09 19:05

reporter   ~0001217

This part of debug log looks incomplete:
Dec 9 10:48:21 pgdb1 pgpool[29119]: [603-2] nastaveni0_.EanTvorbaSkl as EanTvor19_74_0_, nastaveni0_.EetLimit as EetLimit74_0_, nastaveni0_.EetModK as EetModK74_0_, nastaveni0_.EetProvozovna as EetProv22_74_0_, nastaveni0_.EetTypK as EetTypK74_0_, nastave

Full debug log:

Dec 9 10:48:21 pgdb1 pgpool[29119]: [499-1] 2016-12-09 10:48:21: pid 29119: LOG: new connection received
Dec 9 10:48:21 pgdb1 pgpool[29119]: [499-2] 2016-12-09 10:48:21: pid 29119: DETAIL: connecting host=x.x.x.x port=48348
Dec 9 10:48:21 pgdb1 pgpool[29119]: [500-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: SHOW TRANSACTION ISOLATION LEVEL
Dec 9 10:48:21 pgdb1 pgpool[29119]: [501-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [502-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [503-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: SHOW TRANSACTION ISOLATION LEVEL
Dec 9 10:48:21 pgdb1 pgpool[29119]: [504-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [505-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [506-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [507-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [508-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [509-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [510-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [511-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [512-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [513-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [514-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [515-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [516-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [517-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [518-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [519-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [520-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [521-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [522-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [523-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [524-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [525-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [526-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: /* SELECT a FROM DataPrava AS a WHERE a.idUzivatel = 2 ORDER BY a.id */ select dataprava0_.IdDataPrava as IdDataPr1_126_, dataprava0_.Editovat as Editovat126_, dataprava0_.IdObjektu as IdObjektu126_, dataprava0_.IdUzivatel as IdUzivatel126_, dataprava0_.ModulK as ModulK126_, dataprava0_.TypDatK as TypDatK126_ from wDataPrava dataprava0_ where dataprava0_.IdUzivatel=2 order by dataprava0_.IdDataPrava
Dec 9 10:48:21 pgdb1 pgpool[29119]: [527-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [528-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [529-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: /* SELECT a FROM DataPrava AS a WHERE a.idUzivatel = 2 ORDER BY a.id */ select dataprava0_.IdDataPrava as IdDataPr1_126_, dataprava0_.Editovat as Editovat126_, dataprava0_.IdObjektu as IdObjektu126_, dataprava0_.IdUzivatel as IdUzivatel126_, dataprava0_.ModulK as ModulK126_, dataprava0_.TypDatK as TypDatK126_ from wDataPrava dataprava0_ where dataprava0_.IdUzivatel=2 order by dataprava0_.IdDataPrava
Dec 9 10:48:21 pgdb1 pgpool[29119]: [530-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [531-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [532-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [533-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [534-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [535-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [536-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [537-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [538-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [539-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [540-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [541-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [542-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [543-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [544-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [545-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [546-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [547-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [548-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [549-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [550-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [551-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [552-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [553-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [554-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [555-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [556-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [557-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [558-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [559-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [560-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [561-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [562-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [563-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [564-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: /* SELECT a FROM UcetniObdobi AS a WHERE date_trunc('day', a.platiDoData) >= '2016-12-09' AND date_trunc('day', a.platiOdData) <= '2016-12-09' ORDER BY a.platiOdData asc, a.id */ select ucetniobdo0_.IdUcetObdobi as IdUcetOb1_76_, ucetniobdo0_.LastUpdate as LastUpdate76_, ucetniobdo0_.ChybaPreceneni as ChybaPre3_76_, ucetniobdo0_.Kod as Kod76_, ucetniobdo0_.PlatiDoData as PlatiDoD5_76_, ucetniobdo0_.PlatiOdData as PlatiOdD6_76_, ucetniobdo0_.Popis as Popis76_, ucetniobdo0_.Poznam as Poznam76_, ucetniobdo0_.RokProRadu as RokProRadu76_, ucetniobdo0_.ZmenaZaver as ZmenaZaver76_ from nUcetObdobi ucetniobdo0_ where date_trunc('day', ucetniobdo0_.PlatiDoData)>='2016-12-09' and date_trunc('day', ucetniobdo0_.PlatiOdData)<='2016-12-09' order by ucetniobdo0_.PlatiOdData asc, ucetniobdo0_.IdUcetObdobi
Dec 9 10:48:21 pgdb1 pgpool[29119]: [565-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [566-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [567-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: /* SELECT a FROM UcetniObdobi AS a WHERE date_trunc('day', a.platiDoData) >= '2016-12-09' AND date_trunc('day', a.platiOdData) <= '2016-12-09' ORDER BY a.platiOdData asc, a.id */ select ucetniobdo0_.IdUcetObdobi as IdUcetOb1_76_, ucetniobdo0_.LastUpdate as LastUpdate76_, ucetniobdo0_.ChybaPreceneni as ChybaPre3_76_, ucetniobdo0_.Kod as Kod76_, ucetniobdo0_.PlatiDoData as PlatiDoD5_76_, ucetniobdo0_.PlatiOdData as PlatiOdD6_76_, ucetniobdo0_.Popis as Popis76_, ucetniobdo0_.Poznam as Poznam76_, ucetniobdo0_.RokProRadu as RokProRadu76_, ucetniobdo0_.ZmenaZaver as ZmenaZaver76_ from nUcetObdobi ucetniobdo0_ where date_trunc('day', ucetniobdo0_.PlatiDoData)>='2016-12-09' and date_trunc('day', ucetniobdo0_.PlatiOdData)<='2016-12-09' order by ucetniobdo0_.PlatiOdData asc, ucetniobdo0_.IdUcetObdobi
Dec 9 10:48:21 pgdb1 pgpool[29119]: [568-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [569-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [570-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [571-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29119]: [572-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [573-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [574-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [575-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [576-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [577-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [578-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [579-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [580-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [581-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [582-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [583-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [584-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [585-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [586-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [587-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29119]: [588-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [589-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [590-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [591-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [592-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [593-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [594-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [595-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29119]: [596-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [597-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [598-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [599-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 1 backend pid: 17662 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29119]: [600-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Parse: /* load cz.winstrom.vo.nast.Nastaveni */ select nastaveni0_.IdNastav as IdNastav74_0_, nastaveni0_.LastUpdate as LastUpdate74_0_, nastaveni0_.AdrKontrolovatFirmy as AdrKontr3_74_0_, nastaveni0_.AutoSendMailBccEmail as AutoSend4_74_0_, nastaveni0_.AutoSendMailModK as AutoSend5_74_0_, nastaveni0_.AutoZakazka as AutoZaka6_74_0_, nastaveni0_.AvSmerKod as AvSmerKod74_0_, nastaveni0_.AvTranKod as AvTranKod74_0_, nastaveni0_.Cinnost as Cinnost74_0_, nastaveni0_.CisOr as CisOr74_0_, nastaveni0_.CisPop as CisPop74_0_, nastaveni0_.DatovaSchranka as DatovaS12_74_0_, nastaveni0_.DenniKurzK as DenniKurzK74_0_, nastaveni0_.Dic as Dic74_0_, nastaveni0_.DoplnText as DoplnText74_0_, nastaveni0_.EanKod as EanKod74_0_, nastaveni0_.EanRealizaceObj as EanReal17_74_0_, nastaveni0_.EanTvorbaFak as EanTvor18_74_0_,
Dec 9 10:48:21 pgdb1 pgpool[29119]: [600-2] nastaveni0_.EanTvorbaSkl as EanTvor19_74_0_, nastaveni0_.EetLimit as EetLimit74_0_, nastaveni0_.EetModK as EetModK74_0_, nastaveni0_.EetProvozovna as EetProv22_74_0_, nastaveni0_.EetTypK as EetTypK74_0_, nastaveni
Dec 9 10:48:21 pgdb1 pgpool[29119]: [601-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [602-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29119]: [603-1] 2016-12-09 10:48:21: pid 29119: LOG: DB node id: 0 backend pid: 29471 statement: Execute: /* load cz.winstrom.vo.nast.Nastaveni */ select nastaveni0_.IdNastav as IdNastav74_0_, nastaveni0_.LastUpdate as LastUpdate74_0_, nastaveni0_.AdrKontrolovatFirmy as AdrKontr3_74_0_, nastaveni0_.AutoSendMailBccEmail as AutoSend4_74_0_, nastaveni0_.AutoSendMailModK as AutoSend5_74_0_, nastaveni0_.AutoZakazka as AutoZaka6_74_0_, nastaveni0_.AvSmerKod as AvSmerKod74_0_, nastaveni0_.AvTranKod as AvTranKod74_0_, nastaveni0_.Cinnost as Cinnost74_0_, nastaveni0_.CisOr as CisOr74_0_, nastaveni0_.CisPop as CisPop74_0_, nastaveni0_.DatovaSchranka as DatovaS12_74_0_, nastaveni0_.DenniKurzK as DenniKurzK74_0_, nastaveni0_.Dic as Dic74_0_, nastaveni0_.DoplnText as DoplnText74_0_, nastaveni0_.EanKod as EanKod74_0_, nastaveni0_.EanRealizaceObj as EanReal17_74_0_, nastaveni0_.EanTvorbaFak as EanTvor18_74_0_,
Dec 9 10:48:21 pgdb1 pgpool[29119]: [603-2] nastaveni0_.EanTvorbaSkl as EanTvor19_74_0_, nastaveni0_.EetLimit as EetLimit74_0_, nastaveni0_.EetModK as EetModK74_0_, nastaveni0_.EetProvozovna as EetProv22_74_0_, nastaveni0_.EetTypK as EetTypK74_0_, nastave
Dec 9 10:48:23 pgdb1 pgpool[29119]: [1773-1] 2016-12-09 10:48:23: pid 29119: FATAL: failed to read kind from backend
Dec 9 10:48:23 pgdb1 pgpool[29119]: [1773-2] 2016-12-09 10:48:23: pid 29119: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:48:23 pgdb1 pgpool[29119]: [1773-3] 2016-12-09 10:48:23: pid 29119: HINT: check data consistency among db nodes

atan

2016-12-09 19:15

reporter   ~0001218

Different query:

Dec 9 10:48:21 pgdb1 pgpool[29115]: [1721-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1722-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Parse: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1723-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1724-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1725-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1726-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1727-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1728-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Execute: set session authorization "test"
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1729-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1730-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1731-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1732-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Execute: BEGIN
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1733-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Parse: /* criteria query */ select this_.IdSazbyDph as IdSazbyDph75_0_, this_.LastUpdate as LastUpdate75_0_, this_.PlatiDoData as PlatiDoD3_75_0_, this_.PlatiOdData as PlatiOdD4_75_0_, this_.Popis as Popis75_0_, this_.Poznam as Poznam75_0_, this_.IdStatu as IdStatu75_0_, this_.SzbDph as SzbDph75_0_, this_.TypSzbDphK as TypSzbDphK75_0_ from uSazbyDph this_ where (this_.PlatiOdData is null or this_.PlatiOdData<=$1) and (this_.PlatiDoData is null or this_.PlatiDoData>=$2) and this_.IdStatu=$3
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1734-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1735-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1736-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Execute: /* criteria query */ select this_.IdSazbyDph as IdSazbyDph75_0_, this_.LastUpdate as LastUpdate75_0_, this_.PlatiDoData as PlatiDoD3_75_0_, this_.PlatiOdData as PlatiOdD4_75_0_, this_.Popis as Popis75_0_, this_.Poznam as Poznam75_0_, this_.IdStatu as IdStatu75_0_, this_.SzbDph as SzbDph75_0_, this_.TypSzbDphK as TypSzbDphK75_0_ from uSazbyDph this_ where (this_.PlatiOdData is null or this_.PlatiOdData<=$1) and (this_.PlatiDoData is null or this_.PlatiDoData>=$2) and this_.IdStatu=$3
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1737-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1738-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1739-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1740-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Execute: COMMIT
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1741-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1742-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Parse: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1743-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1744-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: B message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1745-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1746-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: D message
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1747-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 0 backend pid: 29458 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1748-1] 2016-12-09 10:48:21: pid 29115: LOG: DB node id: 1 backend pid: 17653 statement: Execute: set session authorization default
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1796-1] 2016-12-09 10:48:21: pid 29115: FATAL: failed to read kind from backend
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1796-2] 2016-12-09 10:48:21: pid 29115: DETAIL: kind mismatch among backends. Possible last query was: "COMMIT" kind details are: 0[3] 1[2]
Dec 9 10:48:21 pgdb1 pgpool[29115]: [1796-3] 2016-12-09 10:48:21: pid 29115: HINT: check data consistency among db nodes

atan

2016-12-09 19:17

reporter   ~0001219

Postgresql 9.6.1, Pgpool 3.5.4. Synchronous streaming replication with repmgr.

supp_k

2016-12-09 20:12

reporter   ~0001221

After replacement of the JDBC driver the problem of "hanged" SQLs disappeared. We no more observe the primary problem "kind mismatch among backends. Possible last query ....".

Would it be possible to apply the fix to the codebase?

t-ishii

2016-12-09 23:23

developer   ~0001222

Yes, that's my plan.

Thank you for cooperating to fix the problem!

supp_k

2016-12-19 15:58

reporter   ~0001232

Dear Tatsuo,

have you applied the fix to the current build? Can we obtain the binary for the testing?

t-ishii

2016-12-20 11:20

developer   ~0001236

Today I have committed the fix for maste and all affected branched (3.6 and 3.5).
We are going to release 3.6.1 and others by the end of this month.

Issue History

Date Modified Username Field Change
2016-08-09 22:30 nomir New Issue
2016-08-09 22:30 nomir Tag Attached: streaming replication
2016-08-15 10:08 t-ishii Assigned To => t-ishii
2016-08-15 10:08 t-ishii Status new => feedback
2016-08-15 10:08 t-ishii Note Added: 0000991
2016-08-15 20:14 nomir File Added: pgpool.pcap
2016-08-15 20:14 nomir Note Added: 0000999
2016-08-15 20:14 nomir Status feedback => assigned
2016-08-15 20:16 nomir File Added: pgpool.dump
2016-08-15 20:16 nomir Note Added: 0001000
2016-08-16 07:46 t-ishii File Deleted: pgpool.dump
2016-08-16 07:48 t-ishii Note Added: 0001002
2016-08-16 07:48 t-ishii Status assigned => feedback
2016-08-17 21:18 nomir File Added: jdbc.debug.log
2016-08-17 21:18 nomir Note Added: 0001008
2016-08-17 21:18 nomir Status feedback => assigned
2016-08-17 21:34 nomir Note Added: 0001009
2016-08-17 21:56 nomir Note Added: 0001010
2016-08-18 15:12 t-ishii Note Added: 0001011
2016-08-18 15:13 t-ishii File Added: close.diff
2016-08-18 15:13 t-ishii Status assigned => feedback
2016-08-18 18:18 nomir File Added: server_20160818.log
2016-08-18 18:18 nomir Note Added: 0001012
2016-08-18 18:18 nomir Status feedback => assigned
2016-08-18 19:44 t-ishii Note Added: 0001013
2016-08-18 20:25 nomir File Added: pgpool_logs.tar.gz
2016-08-18 20:25 nomir Note Added: 0001014
2016-08-19 11:40 t-ishii Note Added: 0001016
2016-08-22 11:09 t-ishii Note Added: 0001017
2016-08-22 11:11 t-ishii Note Edited: 0001017 View Revisions
2016-08-22 11:11 t-ishii File Added: close-v2.diff
2016-08-22 18:57 nomir File Added: pgpool.log.gz
2016-08-22 18:57 nomir Note Added: 0001018
2016-10-27 18:58 sergey.s.sazonov Note Added: 0001139
2016-10-28 00:26 feudenfer Note Added: 0001140
2016-11-10 14:25 t-ishii Note Added: 0001159
2016-11-10 14:28 t-ishii Status assigned => feedback
2016-11-20 05:13 supp_k Note Added: 0001178
2016-11-22 02:04 supp_k Note Added: 0001181
2016-11-22 02:47 supp_k Note Added: 0001182
2016-11-22 03:10 supp_k Note Added: 0001183
2016-11-23 02:58 supp_k Note Added: 0001186
2016-11-25 15:56 supp_k Note Added: 0001191
2016-11-29 00:10 supp_k Note Added: 0001192
2016-11-30 22:09 t-ishii Note Added: 0001193
2016-12-04 04:28 supp_k Note Added: 0001194
2016-12-05 07:58 t-ishii Note Added: 0001195
2016-12-05 15:55 supp_k Note Added: 0001196
2016-12-05 15:59 t-ishii Note Added: 0001197
2016-12-05 16:40 t-ishii File Added: bug231.diff
2016-12-05 16:41 t-ishii Note Added: 0001198
2016-12-07 05:08 supp_k Note Added: 0001205
2016-12-07 07:40 t-ishii Note Added: 0001206
2016-12-09 01:40 supp_k Note Added: 0001208
2016-12-09 02:21 supp_k Note Added: 0001209
2016-12-09 08:23 t-ishii Note Added: 0001210
2016-12-09 17:15 supp_k Note Added: 0001211
2016-12-09 17:19 t-ishii Note Added: 0001212
2016-12-09 17:34 supp_k Note Added: 0001213
2016-12-09 17:56 t-ishii Note Added: 0001214
2016-12-09 18:22 supp_k File Added: console.log
2016-12-09 18:43 atan Note Added: 0001216
2016-12-09 19:05 atan Note Added: 0001217
2016-12-09 19:15 atan Note Added: 0001218
2016-12-09 19:17 atan Note Added: 0001219
2016-12-09 20:12 supp_k Note Added: 0001221
2016-12-09 23:23 t-ishii Note Added: 0001222
2016-12-19 15:58 supp_k Note Added: 0001232
2016-12-20 11:20 t-ishii Note Added: 0001236
2016-12-20 11:24 t-ishii Status feedback => resolved
2016-12-20 11:24 t-ishii Target Version => 3.5.5