View Issue Details

IDProjectCategoryView StatusLast Update
0000168Pgpool-IIBugpublic2016-03-03 15:03
Reportertest11Assigned Tot-ishii 
PriorityurgentSeveritymajorReproducibilityalways
Status resolvedResolutionopen 
Product Version 
Target VersionFixed in Version 
Summary0000168: 3.5.0 issues with php-pdo
DescriptionIf you run a syntactically erroneous query with a php-pdo client, pgpool-II 3.5.0 will not forward the error message to the frontend, and the client will wait for it infinitely.
This bug appeared in version 3.5, in stream replication mode.

It's something correlated with this block of code:
        else if (STREAM)
        {
                /* XXX fix me:even with streaming replication mode, couldn't we have a deadlock */
                pool_set_query_in_progress();
                pool_extended_send_and_wait(query_context, "P", len, contents, 1, MASTER_NODE_ID, true);
                pool_extended_send_and_wait(query_context, "P", len, contents, -1, MASTER_NODE_ID, true);
                pool_add_sent_message(session_context->uncompleted_message);
                pool_unset_query_in_progress();
        }


if you comment out the line pool_unset_query_in_progress();, everything works as expected, but i'm not sure about the drawbacks of this change.
Steps To Reproducephp -r '$p = new PDO("pgsql:host=127.0.0.1","postgres","your_pw");try{$s=$p->prepare("blah");$s->execute();}catch(Exception $e){var_dump($e);}'
Additional Information2016-03-02 19:06:22: pid 146308: DETAIL: received kind 'P'(50) from frontend
2016-03-02 19:06:22: pid 146308: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: Parse: statement name <pdo_stmt_00000001>
2016-03-02 19:06:22: pid 146308: LOG: Unable to parse the query: "insert blah" from client 10.0.0.30(51264)
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting query in progress. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: decide where to send the queries
2016-03-02 19:06:22: pid 146308: DETAIL: destination = 0 for query= "insert blah"
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting query in progress. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: pool_write: to backend: kind:P
2016-03-02 19:06:22: pid 146308: DEBUG: called by pool_add_sent_message: sent message: address: 1d6e7e0 kind: P name: =pdo_stmt_00000001=
2016-03-02 19:06:22: pid 146308: DEBUG: session context: unsetting query in progress. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: processing frontend response
2016-03-02 19:06:22: pid 146308: DETAIL: received kind 'S'(53) from frontend
2016-03-02 19:06:22: pid 146308: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting query in progress. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: pool_write: to backend: kind:S
2016-03-02 19:06:22: pid 146308: DEBUG: pool_read: read 86 bytes from backend 0
2016-03-02 19:06:22: pid 146308: DEBUG: reading backend data packet kind
2016-03-02 19:06:22: pid 146308: DETAIL: master node id: 0
2016-03-02 19:06:22: pid 146308: DEBUG: reading backend data packet kind
2016-03-02 19:06:22: pid 146308: DETAIL: backend:0 of 3 kind = 'E'
2016-03-02 19:06:22: pid 146308: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1
2016-03-02 19:06:22: pid 146308: DEBUG: processing backend response
2016-03-02 19:06:22: pid 146308: DETAIL: received kind 'E'(45) from backend
2016-03-02 19:06:22: pid 146308: DEBUG: SimpleForwardToFrontend: packet:E length:81
2016-03-02 19:06:22: pid 146308: DEBUG: session context: clearing transaction isolation. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: session context: setting ignore till sync. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: session context: unsetting query in progress. DONE
2016-03-02 19:06:22: pid 146308: DEBUG: pool_read: read 6 bytes from backend 0
2016-03-02 19:06:22: pid 146308: DEBUG: detect error: kind: Z
2016-03-02 19:06:22: pid 146308: DEBUG: detect error: kind: Z
2016-03-02 19:06:22: pid 146308: DEBUG: detect error: kind: Z
TagsNo tags attached.

Activities

t-ishii

2016-03-03 07:39

developer   ~0000664

Sounds like a similar problem in:
http://www.pgpool.net/mantisbt/view.php?id=167

Can you please try the fix attached to above (bug167.diff)?

test11

2016-03-03 13:49

reporter   ~0000665

Last edited: 2016-03-03 13:51

View 2 revisions

In my case, the load_balancing mode on/off, is irrelevant (the query cannot be parsed, why should it be load balanced?).
Anyway, i've tried the bug167.diff, and the behaviour (and the debug output) is the same in all of scenarios: with or without path, with or without load balancing.

It's really easy to reproduce, just run that cli command against pgpool 3.5 or against 3.4/raw postgres
php -r '$p = new PDO("pgsql:host=127.0.0.1 port=5432","postgres","pass");$s=$p->prepare("blah");$s->execute();var_dump($s->errorInfo());'

the result should be (3.4/raw postgres):
array(3) {
  [0]=>
  string(5) "42601"
  [1]=>
  int(7)
  [2]=>
  string(61) "ERROR: syntax error at or near "blah"
LINE 1: blah
        ^"
}

but in 3.5 the client will hang up waiting for pgpool response

t-ishii

2016-03-03 14:19

developer  

pdo.diff (10,879 bytes)
diff --git a/src/auth/pool_auth.c b/src/auth/pool_auth.c
index 597d56b..2f259df 100644
--- a/src/auth/pool_auth.c
+++ b/src/auth/pool_auth.c
@@ -5,7 +5,7 @@
  * pgpool: a language independent connection pool server for PostgreSQL
  * written by Tatsuo Ishii
  *
- * Copyright (c) 2003-2015	PgPool Global Development Group
+ * Copyright (c) 2003-2016	PgPool Global Development Group
  *
  * Permission to use, copy, modify, and distribute this software and
  * its documentation for any purpose and without fee is hereby
@@ -23,6 +23,7 @@
 */
 
 #include "pool.h"
+#include "context/pool_session_context.h"
 #include "utils/pool_stream.h"
 #include "pool_config.h"
 #include "auth/pool_passwd.h"
@@ -1092,6 +1093,10 @@ int pool_read_message_length(POOL_CONNECTION_POOL *cp)
 {
 	int length, length0;
 	int i;
+	POOL_SYNC_MAP_STATE use_sync_map = pool_use_sync_map();
+
+	/* Check whether we can use the sync map or not */
+	use_sync_map = pool_use_sync_map();
 
 	/* read message from master node */
 	pool_read(CONNECTION(cp, MASTER_NODE_ID), &length0, sizeof(length0));
@@ -1103,7 +1108,12 @@ int pool_read_message_length(POOL_CONNECTION_POOL *cp)
 
 	for (i=0;i<NUM_BACKENDS;i++)
 	{
-		if (!VALID_BACKEND(i) || IS_MASTER_NODE_ID(i))
+		if (!VALID_BACKEND(i) || IS_MASTER_NODE_ID(i) || use_sync_map == POOL_SYNC_MAP_EMPTY)
+		{
+			continue;
+		}
+
+		if (use_sync_map == POOL_SYNC_MAP_IS_VALID && !pool_is_set_sync_map(i))
 		{
 			continue;
 		}
diff --git a/src/context/pool_query_context.c b/src/context/pool_query_context.c
index 6a631b7..c240162 100644
--- a/src/context/pool_query_context.c
+++ b/src/context/pool_query_context.c
@@ -848,15 +848,15 @@ POOL_STATUS pool_extended_send_and_wait(POOL_QUERY_CONTEXT *query_context,
 			per_node_statement_log(backend, i, msgbuf);
 		}
 
+		/* Set sync map so that we could wait for response from appropreate node */
+		pool_set_sync_map(i);
+		ereport(DEBUG1,
+				(errmsg("pool_send_and_wait: pool_set_sync_map: %d", i)));
+
 		/* if Execute message, count up stats count */
 		if (*kind == 'E')
 		{
 			stat_count_up(i, query_context->parse_tree);
-
-			/* Set sync map so that we could wait for response from appropreate node */
-			pool_set_sync_map(i);
-			ereport(DEBUG1,
-					(errmsg("pool_send_and_wait: pool_set_sync_map: %d", i)));
 		}
 
 		send_extended_protocol_message(backend, i, kind, str_len, str);
diff --git a/src/context/pool_session_context.c b/src/context/pool_session_context.c
index 5221577..8fd95a8 100644
--- a/src/context/pool_session_context.c
+++ b/src/context/pool_session_context.c
@@ -930,6 +930,34 @@ void pool_clear_sync_map(void)
 }
 
 /*
+ * Check whether we should 1) ignore sync map, 2) consult sync map, or 3) we
+ * cannot use sync map because it's empty.
+ */
+bool pool_use_sync_map(void)
+{
+	int i;
+
+	if (!session_context)
+		return POOL_IGNORE_SYNC_MAP;
+
+	if (STREAM && !pool_is_query_in_progress() && pool_is_doing_extended_query_message())
+	{
+		for (i=0;i<NUM_BACKENDS;i++)
+		{
+			if (pool_is_set_sync_map(i))
+			{
+				ereport(DEBUG1,
+						(errmsg("pool_use_sync_map: set use sync map: %d", i)));
+				return POOL_SYNC_MAP_IS_VALID;	/* yes, we can use sync map */
+			}
+		}
+		return POOL_SYNC_MAP_EMPTY;	/* no, we cannot use sync map */
+	}
+
+	return POOL_IGNORE_SYNC_MAP;
+}
+
+/*
  * Set pending response
  */
 void pool_set_pending_response(void)
diff --git a/src/include/context/pool_session_context.h b/src/include/context/pool_session_context.h
index 8251215..5a44865 100644
--- a/src/include/context/pool_session_context.h
+++ b/src/include/context/pool_session_context.h
@@ -6,7 +6,7 @@
  * pgpool: a language independent connection pool server for PostgreSQL 
  * written by Tatsuo Ishii
  *
- * Copyright (c) 2003-2011	PgPool Global Development Group
+ * Copyright (c) 2003-2016	PgPool Global Development Group
  *
  * Permission to use, copy, modify, and distribute this software and
  * its documentation for any purpose and without fee is hereby
@@ -45,6 +45,15 @@ typedef enum {
 } POOL_TRANSACTION_ISOLATION;
 
 /*
+ * Return values for pool_use_sync_map
+ */
+typedef enum {
+	POOL_IGNORE_SYNC_MAP,		/* Please ignore sync map */
+	POOL_SYNC_MAP_IS_VALID,		/* Sync map is valid */
+	POOL_SYNC_MAP_EMPTY,		/* Sync map is empty */
+} POOL_SYNC_MAP_STATE;
+
+/*
  * Message content of extended query
  */
 typedef struct {
@@ -246,6 +255,7 @@ extern void pool_set_sync_map(int node_id);
 extern bool pool_is_set_sync_map(int node_id);
 extern int pool_get_nth_sync_map(int nth);
 extern void pool_clear_sync_map(void);
+extern bool pool_use_sync_map(void);
 extern void pool_set_pending_response(void);
 extern void pool_unset_pending_response(void);
 extern bool pool_is_pending_response(void);
diff --git a/src/include/pool.h b/src/include/pool.h
index 5c6202b..ee8b110 100644
--- a/src/include/pool.h
+++ b/src/include/pool.h
@@ -517,6 +517,8 @@ extern POOL_STATUS pool_process_query(POOL_CONNECTION *frontend,
 extern int pool_do_auth(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend);
 extern int pool_do_reauth(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *cp);
 
+extern bool is_backend_cache_empty(POOL_CONNECTION_POOL *backend);
+
 /* SSL functionality */
 extern void pool_ssl_negotiate_serverclient(POOL_CONNECTION *cp);
 extern void pool_ssl_negotiate_clientserver(POOL_CONNECTION *cp);
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index a6eb352..fd3b76f 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -191,7 +191,7 @@ POOL_STATUS pool_process_query(POOL_CONNECTION *frontend,
 
 		/*
 		 * If we are not processing a query, now is the time to
-		 * extract retrieve pending data from buffer stack if any.
+		 * extract pending data from buffer stack if any.
 		 */
 		if (!pool_is_query_in_progress())
 		{
@@ -204,9 +204,11 @@ POOL_STATUS pool_process_query(POOL_CONNECTION *frontend,
 		}
 
 		/*
-		 * If we are prcessing query, process it.
+		 * If we are processing query, process it.  Even if we are not
+		 * processing query, process backend response if there's pending data
+		 * in backend cache.
 		 */
-		if (pool_is_query_in_progress())
+		if (pool_is_query_in_progress() || !is_backend_cache_empty(backend))
 		{
 			status = ProcessBackendResponse(frontend, backend, &state, &num_fields);
 			if (status != POOL_CONTINUE)
@@ -712,6 +714,7 @@ POOL_STATUS SimpleForwardToFrontend(char kind, POOL_CONNECTION *frontend,
 	char *p1 = NULL;
 	int sendlen;
 	int i;
+	POOL_SYNC_MAP_STATE use_sync_map = pool_use_sync_map();
 
 #ifdef NOT_USED
 	/* 
@@ -748,8 +751,16 @@ POOL_STATUS SimpleForwardToFrontend(char kind, POOL_CONNECTION *frontend,
 	{
 		for (i=0;i<NUM_BACKENDS;i++)
 		{
+			if (use_sync_map == POOL_SYNC_MAP_EMPTY)
+				continue;
+
 			if (VALID_BACKEND(i) && !IS_MASTER_NODE_ID(i))
 			{
+				if (use_sync_map == POOL_SYNC_MAP_IS_VALID && !pool_is_set_sync_map(i))
+				{
+						continue;
+				}
+
 				pool_read(CONNECTION(backend, i), &len, sizeof(len));
 
 				len = ntohl(len);
@@ -3001,22 +3012,12 @@ int is_drop_database(Node *node)
 }
 
 /*
- * check if any pending data remains.
+ * check if any pending data remains in backend.
 */
-static bool is_cache_empty(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend)
+bool is_backend_cache_empty(POOL_CONNECTION_POOL *backend)
 {
 	int i;
 
-	/*
-	 * If SSL is enabled, we need to check SSL internal buffer
-	 * is empty or not first.
-	 */
-	if (pool_ssl_pending(frontend))
-		return false;
-
-	if (!pool_read_buffer_is_empty(frontend))
-		return false;
-
 	for (i=0;i<NUM_BACKENDS;i++)
 	{
 		if (!VALID_BACKEND(i))
@@ -3037,6 +3038,24 @@ static bool is_cache_empty(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *back
 }
 
 /*
+ * check if any pending data remains.
+*/
+static bool is_cache_empty(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend)
+{
+	/*
+	 * If SSL is enabled, we need to check SSL internal buffer
+	 * is empty or not first.
+	 */
+	if (pool_ssl_pending(frontend))
+		return false;
+
+	if (!pool_read_buffer_is_empty(frontend))
+		return false;
+
+	return is_backend_cache_empty(backend);
+}
+
+/*
  * check if query is needed to wait completion
  */
 bool is_strict_query(Node *node)
@@ -3178,9 +3197,10 @@ void read_kind_from_backend(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *bac
 	double max_count = 0;
 	int degenerate_node_num = 0;                /* number of backends degeneration requested */
 	int degenerate_node[MAX_NUM_BACKENDS];      /* degeneration requested backend list */
-
+	bool doing_extended_message = false;		/* are we doing extended protocol? */
 	POOL_SESSION_CONTEXT *session_context = pool_get_session_context(false);
 	POOL_QUERY_CONTEXT *query_context = session_context->query_context;
+	POOL_SYNC_MAP_STATE use_sync_map = pool_use_sync_map();
 
 	int num_executed_nodes = 0;
 	int first_node = -1;
@@ -3218,8 +3238,19 @@ void read_kind_from_backend(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *bac
 		/* initialize degenerate record */
 		degenerate_node[i] = 0;
 
+		if (!VALID_BACKEND(i) || use_sync_map == POOL_SYNC_MAP_EMPTY)
+		{
+			kind_list[i] = 0;
+			continue;
+		}
+
 		if (VALID_BACKEND(i))
 		{
+			if (use_sync_map == POOL_SYNC_MAP_IS_VALID && !pool_is_set_sync_map(i))
+			{
+				continue;
+			}
+
 			num_executed_nodes++;
 
 			if (first_node < 0)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 756bb2f..8c2deb4 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -1419,9 +1419,11 @@ POOL_STATUS ReadyForQuery(POOL_CONNECTION *frontend,
 	POOL_SESSION_CONTEXT *session_context;
 	Node *node = NULL;
 	char *query = NULL;
+	POOL_SYNC_MAP_STATE use_sync_map;
 
 	/* Get session context */
 	session_context = pool_get_session_context(false);
+	use_sync_map = pool_use_sync_map();
 
 	/*
 	 * If the numbers of update tuples are differ and
@@ -1559,9 +1561,14 @@ POOL_STATUS ReadyForQuery(POOL_CONNECTION *frontend,
 
 		for (i=0;i<NUM_BACKENDS;i++)
 		{
-			if (!VALID_BACKEND(i))
+			if (!VALID_BACKEND(i) || use_sync_map == POOL_SYNC_MAP_EMPTY)
 				continue;
 
+			if (use_sync_map == POOL_SYNC_MAP_IS_VALID && !pool_is_set_sync_map(i))
+			{
+				continue;
+			}
+
 			if (pool_read(CONNECTION(backend, i), &kind, sizeof(kind)))
 				return POOL_END;
 
@@ -2349,7 +2356,16 @@ POOL_STATUS ProcessBackendResponse(POOL_CONNECTION *frontend,
 	{
 		if (pool_is_query_in_progress())
 			pool_unset_query_in_progress();
-		return POOL_CONTINUE;
+
+		/*
+		 * Check if If we have pending data in backend connection cache. If we
+		 * do, it is likely that a sync message has been sent to backend and the
+		 * backend replied back to us. So we need to process it.
+		 */
+		if (is_backend_cache_empty(backend))
+		{
+			return POOL_CONTINUE;
+		}
 	}
 
 	if (pool_is_skip_reading_from_backends())
pdo.diff (10,879 bytes)

t-ishii

2016-03-03 14:22

developer   ~0000666

I found different cause of your problem.
Can you please try attached patch (pdo.diff) against V3_5_STABLE?
You need the latest V3_5_STABLE head source.
If you don't have that, you can try the patch:
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=d8a8eb83e735734895a4def9a96a7ff83dd56517

test11

2016-03-03 14:47

reporter   ~0000667

Yes, it works. Thank you!

t-ishii

2016-03-03 15:02

developer   ~0000668

Glad to hear that. Thanks for the feedback!

Issue History

Date Modified Username Field Change
2016-03-03 03:11 test11 New Issue
2016-03-03 07:35 t-ishii Assigned To => t-ishii
2016-03-03 07:35 t-ishii Status new => feedback
2016-03-03 07:39 t-ishii Note Added: 0000664
2016-03-03 13:49 test11 Note Added: 0000665
2016-03-03 13:49 test11 Status feedback => assigned
2016-03-03 13:51 test11 Note Edited: 0000665 View Revisions
2016-03-03 14:19 t-ishii File Added: pdo.diff
2016-03-03 14:22 t-ishii Note Added: 0000666
2016-03-03 14:42 t-ishii Status assigned => feedback
2016-03-03 14:47 test11 Note Added: 0000667
2016-03-03 14:47 test11 Status feedback => assigned
2016-03-03 15:02 t-ishii Note Added: 0000668
2016-03-03 15:03 t-ishii Status assigned => resolved