View Issue Details

IDProjectCategoryView StatusLast Update
0000167Pgpool-IIBugpublic2016-03-30 09:15
Reportereflopez123Assigned Tot-ishii 
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionreopened 
PlatformLinuxOSCentosOS VersionCentos 6.7
Product Version 
Target VersionFixed in Version 
Summary0000167: PgPool does not return during Hibernate initialisation, stuck on "Parsing"
DescriptionWhen starting our application, which uses Hibernate and c3p0, pgPool 3.5.0 appears to get stuck at the parsing during a query. This happens when using load balance mode, but turning off load balance mode it appears to work.

This problem is not present in 3.4.3
Steps To ReproduceDifficult to provide a small test case, however I've provided the logs and our pgpool.conf
TagsNo tags attached.

Activities

eflopez123

2016-02-22 14:48

reporter  

conf-and-logfile.txt (2,639,211 bytes)

t-ishii

2016-02-23 08:20

developer   ~0000647

Hard to chase the problem if it cannot be reproduced here. Anyway, can you provide the log with debug mode enabled?

eflopez123

2016-02-23 13:41

reporter   ~0000648

Thankyou, I've produced a small test case which I've attached. It requires Apache maven to compile and run. In the archive is 'eliasdb.sql' which is a pg_dump of the database I used.


Compile:
mvn compile

Run:
mvn exec:java -Dexec.mainClass="pgpoolbug.SimpleEntityMain"

You can edit main/resources/hibernate.cfg.xml to change connection parameters. It needs to be recompiled if this is changed.

When working, it should print out at the end:

Hibernate: select simpleenti0_.simple_entity_id as simple_e1_0_, simpleenti0_.simple_entity_name as simple_e2_0_ from simple_entity simpleenti0_
Hello: SimpleEntity{simple_name_id=1, simple_name='hello'}
Hello: SimpleEntity{simple_name_id=2, simple_name='hello 2'}
Finished

Instead it waits for a response from pgPool which appears to be stuck on "Parse:". I've set debug_level to 99 but there doesn't appear to be much output:

root@postgresC log]# cat pgpool-II-95.log
2016-02-23 23:35:48: pid 17967: LOG: Setting up socket for 0.0.0.0:5433
2016-02-23 23:35:48: pid 17967: LOG: Setting up socket for :::5433
2016-02-23 23:35:48: pid 17967: LOG: pgpool-II successfully started. version 3.5.0 (ekieboshi)
2016-02-23 23:35:48: pid 17967: LOG: find_primary_node: checking backend no 0
2016-02-23 23:35:48: pid 17967: LOG: find_primary_node: primary node id is 0
2016-02-23 23:37:04: pid 18083: LOG: new connection received
2016-02-23 23:37:04: pid 18083: DETAIL: connecting host=192.168.205.1 port=62047
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: SET extra_float_digits = 3
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Parse: SET extra_float_digits = 3
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: B message
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: B message
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Execute: SET extra_float_digits = 3
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Execute: SET extra_float_digits = 3
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: BEGIN
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Parse: BEGIN
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: B message
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: B message
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Execute: BEGIN
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Execute: BEGIN
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'
[root@postgresC log]#

eflopez123

2016-02-23 13:44

reporter  

pgpoolbug.tgz (18,419 bytes)

t-ishii

2016-02-27 19:51

developer   ~0000649

I couldn't download the tar ball. Not sure but I suspect it is related the view status is set "private". Can we set to public?

eflopez123

2016-02-27 20:13

reporter   ~0000650

Ok please set it to public.

t-ishii

2016-02-27 20:32

developer   ~0000651

I can now download the file. Will look at it tomorrow.

t-ishii

2016-02-29 11:27

developer   ~0000652

Unfortunately, I got this while executing "mvn exec:java -Dexec.mainClass="pgpoolbug.SimpleEntityMain"

[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 31.285s
[INFO] Finished at: Mon Feb 29 11:23:25 JST 2016
[INFO] Final Memory: 11M/239M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.codehaus.mojo:exec-maven-plugin:1.3.2:java (default-cli) on project pgpoolbug: An exception occured while executing the Java class. null: InvocationTargetException: ExceptionInInitializerError: org/postgresql/Driver : Unsupported major.minor version 52.0 -> [Help 1]

eflopez123

2016-02-29 12:54

reporter   ~0000653

Thankyou for looking into it,

This error is probably due to a java version conflict. I used java 1.8 and this seemed to work without problems. Let me know which version of java you are using and I'll try and make a version that is compatible.

t-ishii

2016-03-01 09:04

developer   ~0000654

java version "1.7.0_95"
OpenJDK Runtime Environment (IcedTea 2.6.4) (7u95-2.6.4-0ubuntu0.14.04.1)
OpenJDK 64-Bit Server VM (build 24.95-b01, mixed mode)

eflopez123

2016-03-01 10:09

reporter   ~0000655

Hello,

I used the postgresql jdbc driver compiled for 1.8. If you edit the pom.xml file and change the "9.4-1202-jdbc42" in the dependencies section to "9.4-1202-jdbc41" it should use the 1.7 driver.

t-ishii

2016-03-02 09:32

developer   ~0000656

Thanks. I succeeded in reproducing the problem. It will take a while to find the cause...

eflopez123

2016-03-02 09:37

reporter   ~0000657

Thankyou.

t-ishii

2016-03-02 10:16

developer   ~0000658

Is it possible to take JDBC driver debug log which produces protocol message log. I mean "org.postgresql.Driver.DEBUG" here.

eflopez123

2016-03-02 11:40

reporter   ~0000659

Yes, in the src/main/resources/hibernate.cfg.xml, add "?loglevel=2".

then recompile with mvn compile, and then run it again.

It should spit out things to stdout:
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
13:38:24.855 (1) PostgreSQL 9.4 JDBC4.2 (build 1202)
13:38:24.862 (1) Trying to establish a protocol version 3 connection to 192.168.205.146:5433
13:38:24.871 (1) Receive Buffer Size is 131768
13:38:24.871 (1) Send Buffer Size is 131768
13:38:24.874 (1) FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2)
13:38:24.890 (1) <=BE AuthenticationReqMD5(salt=1beb96a3)
13:38:24.901 (1) FE=> Password(md5digest=md5a76dd4c29cbaeecc07d303eafb3cd597)
13:38:24.903 (1) <=BE AuthenticationOk
13:38:24.910 (1) <=BE ParameterStatus(application_name = )
13:38:24.910 (1) <=BE ParameterStatus(client_encoding = UTF8)
13:38:24.911 (1) <=BE ParameterStatus(DateStyle = ISO, DMY)
13:38:24.911 (1) <=BE ParameterStatus(integer_datetimes = on)
13:38:24.911 (1) <=BE ParameterStatus(IntervalStyle = postgres)
13:38:24.911 (1) <=BE ParameterStatus(is_superuser = on)
13:38:24.911 (1) <=BE ParameterStatus(server_encoding = UTF8)
13:38:24.911 (1) <=BE ParameterStatus(server_version = 9.5.1)
13:38:24.911 (1) <=BE ParameterStatus(session_authorization = elias)
13:38:24.911 (1) <=BE ParameterStatus(standard_conforming_strings = on)
13:38:24.911 (1) <=BE ParameterStatus(TimeZone = Australia/Melbourne)
13:38:24.911 (1) <=BE BackendKeyData(pid=48250,ckey=1183488946)
13:38:24.911 (1) <=BE ReadyForQuery(I)
13:38:24.913 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@5579bb86, maxRows=0, fetchSize=0, flags=23
13:38:24.914 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={})
13:38:24.914 (1) FE=> Bind(stmt=null,portal=null)
13:38:24.914 (1) FE=> Execute(portal=null,limit=1)
13:38:24.914 (1) FE=> Sync
13:38:24.916 (1) <=BE ParseComplete [null]
13:38:24.916 (1) <=BE BindComplete [unnamed]
13:38:24.916 (1) <=BE CommandStatus(SET)
13:38:24.916 (1) <=BE ReadyForQuery(I)
13:38:24.917 (1) compatible = 90400
13:38:24.917 (1) loglevel = 2
13:38:24.917 (1) prepare threshold = 5
13:38:24.919 (1) types using binary send = TIMESTAMPTZ,UUID,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY
13:38:24.920 (1) types using binary receive = TIMESTAMPTZ,UUID,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,DATE,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY
13:38:24.920 (1) integer date/time = true
13:38:24.946 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@7181ae3f, maxRows=0, fetchSize=0, flags=1
13:38:24.947 (1) FE=> Parse(stmt=null,query="BEGIN",oids={})
13:38:24.947 (1) FE=> Bind(stmt=null,portal=null)
13:38:24.947 (1) FE=> Execute(portal=null,limit=0)
13:38:24.948 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={})
13:38:24.948 (1) FE=> Bind(stmt=null,portal=null)
13:38:24.948 (1) FE=> Describe(portal=null)
13:38:24.948 (1) FE=> Execute(portal=null,limit=0)
13:38:24.948 (1) FE=> Sync

t-ishii

2016-03-02 11:43

developer   ~0000660

Thanks. It helps me a lot.

eflopez123

2016-03-02 11:45

reporter   ~0000661

No problem.

Oops I didn't specify it needs to be added to the driver URL, but I'm sure you're familiar with it already if you've dealt with jdbc and postgres before.

eg:
jdbc:postgresql://192.168.205.146:5433/eliasdb?loglevel=2

t-ishii

2016-03-02 14:11

developer   ~0000662

Last edited: 2016-03-02 14:22

View 2 revisions

Just for a record, this is the log when connected to PostgreSQL:

INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
14:04:14.826 (1) PostgreSQL 9.4 JDBC4.1 (build 1202)
14:04:14.833 (1) Trying to establish a protocol version 3 connection to localhost:11002
14:04:14.847 (1) Receive Buffer Size is 530904
14:04:14.847 (1) Send Buffer Size is 1313280
14:04:14.850 (1) FE=> StartupPacket(user=t-ishii, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Asia/Tokyo, extra_float_digits=2)
14:04:14.851 (1) <=BE AuthenticationOk
14:04:14.861 (1) <=BE ParameterStatus(application_name = )
14:04:14.862 (1) <=BE ParameterStatus(client_encoding = UTF8)
14:04:14.862 (1) <=BE ParameterStatus(DateStyle = ISO, MDY)
14:04:14.862 (1) <=BE ParameterStatus(integer_datetimes = on)
14:04:14.862 (1) <=BE ParameterStatus(IntervalStyle = postgres)
14:04:14.862 (1) <=BE ParameterStatus(is_superuser = on)
14:04:14.862 (1) <=BE ParameterStatus(server_encoding = UTF8)
14:04:14.862 (1) <=BE ParameterStatus(server_version = 9.5.0)
14:04:14.862 (1) <=BE ParameterStatus(session_authorization = t-ishii)
14:04:14.862 (1) <=BE ParameterStatus(standard_conforming_strings = on)
14:04:14.862 (1) <=BE ParameterStatus(TimeZone = Asia/Tokyo)
14:04:14.862 (1) <=BE BackendKeyData(pid=16201,ckey=1582227834)
14:04:14.862 (1) <=BE ReadyForQuery(I)
14:04:14.865 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@5591a832, maxRows=0, fetchSize=0, flags=23
14:04:14.866 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={})
14:04:14.866 (1) FE=> Bind(stmt=null,portal=null)
14:04:14.866 (1) FE=> Execute(portal=null,limit=1)
14:04:14.866 (1) FE=> Sync
14:04:14.867 (1) <=BE ParseComplete [null]
14:04:14.867 (1) <=BE BindComplete [unnamed]
14:04:14.867 (1) <=BE CommandStatus(SET)
14:04:14.867 (1) <=BE ReadyForQuery(I)
14:04:14.867 (1) compatible = 90400
14:04:14.867 (1) loglevel = 2
14:04:14.867 (1) prepare threshold = 5
14:04:14.869 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
14:04:14.870 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
14:04:14.870 (1) integer date/time = true
14:04:14.908 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@438c0862, maxRows=0, fetchSize=0, flags=1
14:04:14.909 (1) FE=> Parse(stmt=null,query="BEGIN",oids={})
14:04:14.909 (1) FE=> Bind(stmt=null,portal=null)
14:04:14.909 (1) FE=> Execute(portal=null,limit=0)
14:04:14.909 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={})
14:04:14.910 (1) FE=> Bind(stmt=null,portal=null)
14:04:14.910 (1) FE=> Describe(portal=null)
14:04:14.910 (1) FE=> Execute(portal=null,limit=0)
14:04:14.910 (1) FE=> Sync
14:04:14.913 (1) <=BE ParseComplete [null]
14:04:14.913 (1) <=BE BindComplete [unnamed]
14:04:14.913 (1) <=BE CommandStatus(BEGIN)
14:04:14.913 (1) <=BE ParseComplete [null]
14:04:14.913 (1) <=BE BindComplete [unnamed]
14:04:14.913 (1) <=BE RowDescription(2)
14:04:14.913 (1) Field(,NAME,64,T)
14:04:14.913 (1) Field(,OID,4,T)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=7)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=12)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.914 (1) <=BE DataRow(len=9)
14:04:14.914 (1) <=BE DataRow(len=6)
14:04:14.915 (1) <=BE DataRow(len=5)
14:04:14.915 (1) <=BE DataRow(len=5)
14:04:14.915 (1) <=BE DataRow(len=5)
14:04:14.915 (1) <=BE DataRow(len=5)
14:04:14.915 (1) <=BE DataRow(len=11)
14:04:14.915 (1) <=BE DataRow(len=9)
[snip]

t-ishii

2016-03-02 17:17

developer   ~0000663

Last edited: 2016-03-02 17:20

View 2 revisions

Ok, I have created a patch against V3.5 stable tree to fix the problem. Can you please try it out?

It appeared that pgpool-II is confused by the particular sequence of messages generated by the application and tried to read from a PostgreSQL server which will not response because no query was sent to it.

t-ishii

2016-03-02 17:17

developer  

bug167.diff (3,053 bytes)
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index a6eb352..5b1ca42 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -730,6 +730,7 @@ POOL_STATUS SimpleForwardToFrontend(char kind, POOL_CONNECTION *frontend,
 	len = ntohl(len);
 	len -= 4;
 	len1 = len;
+	bool use_sync_map = false;
 
 	p = pool_read2(MASTER(backend), len);
 	if (p == NULL)
@@ -748,8 +749,26 @@ POOL_STATUS SimpleForwardToFrontend(char kind, POOL_CONNECTION *frontend,
 	{
 		for (i=0;i<NUM_BACKENDS;i++)
 		{
+			if (pool_is_set_sync_map(i))
+			{
+				use_sync_map = true;
+				ereport(DEBUG1,
+						(errmsg("set use sync map: %d", i)));
+				break;
+			}
+		}
+
+		for (i=0;i<NUM_BACKENDS;i++)
+		{
 			if (VALID_BACKEND(i) && !IS_MASTER_NODE_ID(i))
 			{
+				if (!pool_is_query_in_progress() && pool_is_doing_extended_query_message() &&
+					use_sync_map)
+				{
+					if (!pool_is_set_sync_map(i))
+						continue;
+				}
+
 				pool_read(CONNECTION(backend, i), &len, sizeof(len));
 
 				len = ntohl(len);
@@ -3178,6 +3197,8 @@ 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;
+	bool use_sync_map = false;
 
 	POOL_SESSION_CONTEXT *session_context = pool_get_session_context(false);
 	POOL_QUERY_CONTEXT *query_context = session_context->query_context;
@@ -3213,11 +3234,37 @@ void read_kind_from_backend(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *bac
 		pool_unread(CONNECTION(backend, MASTER_NODE_ID), &kind, sizeof(kind));
 	}
 
+	if (!pool_is_query_in_progress() &&
+		pool_get_session_context(true) && pool_is_doing_extended_query_message())
+	{
+		doing_extended_message = true;
+
+		for (i=0;i<NUM_BACKENDS;i++)
+		{
+			if (pool_is_set_sync_map(i))
+			{
+				use_sync_map = true;
+				ereport(DEBUG1,
+						(errmsg("set use sync map: %d", i)));
+				break;
+			}
+		}
+	}
+
 	for (i=0;i<NUM_BACKENDS;i++)
 	{
 		/* initialize degenerate record */
 		degenerate_node[i] = 0;
 
+		if (!pool_is_query_in_progress() && doing_extended_message && use_sync_map)
+		{
+			if (!VALID_BACKEND(i) || !pool_is_set_sync_map(i))
+			{
+				kind_list[i] = 0;
+				continue;
+			}
+		}
+
 		if (VALID_BACKEND(i))
 		{
 			num_executed_nodes++;
diff --git a/src/utils/pool_stream.c b/src/utils/pool_stream.c
index ad97125..f96c5bb 100644
--- a/src/utils/pool_stream.c
+++ b/src/utils/pool_stream.c
@@ -1030,9 +1030,12 @@ int pool_push(POOL_CONNECTION *cp, void *data, int len)
 {
 	char *p;
 
-	ereport(DEBUG1,
-		(errmsg("pushing data of len: %d", len)));
-
+	if (len == 1)
+		ereport(DEBUG1,
+				(errmsg("pushing data of len: %d kind: %c", len, *((char *)data))));
+	else
+		ereport(DEBUG1,
+				(errmsg("pushing data of len: %d", len)));
 
     MemoryContext oldContext = SwitchToConnectionContext(cp->isbackend);
 
bug167.diff (3,053 bytes)

t-ishii

2016-03-03 15:09

developer   ~0000669

I have modified the fix attached here to deal with bug 168, which shares the necessary changes and committed to 3.5 stable tree. Please grab 3.5 stable head and try.

eflopez123

2016-03-04 09:16

reporter   ~0000670

Thankyou, I hope to get a chance to look at this early next week.

eflopez123

2016-03-08 10:25

reporter   ~0000678

hello, I've tried the version from the stable branch (ie git clone git://git.postgresql.org/git/pgpool2.git --branch V3_5_STABLE) , but I am still have the same problems.

t-ishii

2016-03-08 13:08

developer  

log-20160308.txt (349,389 bytes)

t-ishii

2016-03-10 13:04

developer   ~0000679

When I fixed it and pushed I tried again your test case and it seems the Java application hangs beyond the point you reported. From the log it seems it was caused by some reasons which are not related to pgpool-II.
So I cannot confirm you report about the hang up.
Can you please take a look at the attached log (log-20160308.txt)?

eflopez123

2016-03-10 13:14

reporter   ~0000680

Thanks,

It looks like hibernate is upset because the table its looking for is missing. However, if its gotten to that point it means its querying the database and getting results (in this case errors..) so I would say its working.

I will try again, maybe I did something wrong.

eflopez123

2016-03-10 13:51

reporter  

debug-20160310.txt (90,862 bytes)
[root@postgresC etc]# /usr/local/pgpool2/bin/pgpool -n -d
2016-03-10 20:32:31: pid 39236: DEBUG:  loading hba configuration
2016-03-10 20:32:31: pid 39236: DETAIL:  loading file :"/usr/local/pgpool2/etc/pool_hba.conf" for client authentication configuration file
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_coninfo_size: num_init_children (115) * max_pool (1) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 2001920 bytes requested for shared memory
2016-03-10 20:32:31: pid 39236: DEBUG:  ProcessInfo: num_init_children (115) * sizeof(ProcessInfo) (32) = 3680 bytes requested for shared memory
2016-03-10 20:32:31: pid 39236: DEBUG:  Request info are: sizeof(POOL_REQUEST_INFO) 5224 bytes requested for shared memory
2016-03-10 20:32:31: pid 39236: DEBUG:  Recovery management area: sizeof(int) 4 bytes requested for shared memory
2016-03-10 20:32:31: pid 39236: LOG:  Setting up socket for 0.0.0.0:5433
2016-03-10 20:32:31: pid 39236: LOG:  Setting up socket for :::5433
2016-03-10 20:32:31: pid 39240: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39239: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39241: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39238: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39242: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39243: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39244: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39245: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39237: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39246: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39247: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39248: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39249: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39250: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39251: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39252: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39253: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39254: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39255: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39256: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39257: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39258: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39259: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39260: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39264: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39263: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39265: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39266: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39262: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39261: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39267: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39268: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39269: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39270: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39271: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39272: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39273: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39274: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39275: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39276: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39277: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39278: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39279: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39280: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39281: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39282: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39283: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39284: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39285: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39286: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39287: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39288: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39292: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39291: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39293: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39294: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39290: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39295: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39296: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39297: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39289: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39298: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39299: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39300: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39301: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39302: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39303: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39304: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39305: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39306: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39307: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39308: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39309: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39310: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39311: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39312: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39313: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39314: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39315: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39316: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39317: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39321: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39320: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39322: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39323: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39319: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39324: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39318: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39325: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39326: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39327: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39328: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39329: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39330: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39331: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39332: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39333: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39334: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39335: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39336: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39337: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39338: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39339: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39340: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39341: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39342: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39343: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39344: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39345: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39346: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39347: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39348: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39349: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39350: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39351: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39236: LOG:  pgpool-II successfully started. version 3.5.0 (ekieboshi)
2016-03-10 20:32:31: pid 39236: LOG:  find_primary_node: checking backend no 0
2016-03-10 20:32:31: pid 39353: DEBUG:  I am 39353
2016-03-10 20:32:31: pid 39353: DEBUG:  initializing backend status
2016-03-10 20:32:31: pid 39352: DEBUG:  I am PCP child with pid:39352
2016-03-10 20:32:31: pid 39236: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:31: pid 39353: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 5
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:Q
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate kind = 5
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 75 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: kind: 'T'
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: received ROW DESCRIPTION ('T')
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: row description: num_fileds: 1
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: kind: 'Z'
2016-03-10 20:32:31: pid 39236: DEBUG:  do_query: received READY FOR QUERY ('Z')
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:31: pid 39236: LOG:  find_primary_node: primary node id is 0
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate kind = 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:31: pid 39236: DEBUG:  starting health check
2016-03-10 20:32:31: pid 39236: DEBUG:  health check: clearing alarm
2016-03-10 20:32:31: pid 39236: DEBUG:  doing health check against database:postgres user:elias
2016-03-10 20:32:31: pid 39236: DEBUG:  Backend DB node 0 status is 2
2016-03-10 20:32:31: pid 39236: DEBUG:  Trying to make persistent DB connection to backend node 0 having status 2
2016-03-10 20:32:31: pid 39353: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:31: pid 39236: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate kind = 5
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 5
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate kind = 0
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:31: pid 39353: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:Q
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:31: pid 39236: DEBUG:  persistent DB connection to backend node 0 having status 2 is successful
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:31: pid 39236: DEBUG:  Backend DB node 1 status is 2
2016-03-10 20:32:31: pid 39236: DEBUG:  Trying to make persistent DB connection to backend node 1 having status 2
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 91 bytes from backend 0
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'T'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received ROW DESCRIPTION ('T')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: row description: num_fileds: 1
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'Z'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received READY FOR QUERY ('Z')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:Q
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39236: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_read: read 95 bytes from backend 0
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'T'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received ROW DESCRIPTION ('T')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: row description: num_fileds: 1
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: kind: 'Z'
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  do_query: received READY FOR QUERY ('Z')
2016-03-10 20:32:31: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:31: pid 39353: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 5
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate kind = 0
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:31: pid 39236: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:31: pid 39236: DEBUG:  persistent DB connection to backend node 1 having status 2 is successful
2016-03-10 20:32:31: pid 39236: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:31: pid 39236: DEBUG:  health check: clearing alarm
2016-03-10 20:32:31: pid 39236: DEBUG:  health check: clearing alarm
2016-03-10 20:32:38: pid 39351: DEBUG:  I am 39351 accept fd 7
2016-03-10 20:32:38: pid 39351: LOG:  new connection received
2016-03-10 20:32:38: pid 39351: DETAIL:  connecting host=postgresC port=43390
2016-03-10 20:32:38: pid 39351: DEBUG:  reading startup packet
2016-03-10 20:32:38: pid 39351: DETAIL:  Protocol Major: 3 Minor: 0 database: eliasdb user: elias
2016-03-10 20:32:38: pid 39351: DEBUG:  creating new connection to backend
2016-03-10 20:32:38: pid 39351: DETAIL:  connecting 0 backend
2016-03-10 20:32:38: pid 39351: DEBUG:  creating new connection to backend
2016-03-10 20:32:38: pid 39351: DETAIL:  connecting 1 backend
2016-03-10 20:32:38: pid 39351: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:38: pid 39351: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 13 bytes from backend 1
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 0 length: 12
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 1 length: 12
2016-03-10 20:32:38: pid 39351: DEBUG:  authentication backend
2016-03-10 20:32:38: pid 39351: DETAIL:  auth kind:5
2016-03-10 20:32:38: pid 39351: DEBUG:  authentication backend
2016-03-10 20:32:38: pid 39351: DETAIL:  trying md5 authentication
2016-03-10 20:32:38: pid 39351: DEBUG:  performing md5 authentication
2016-03-10 20:32:38: pid 39351: DETAIL:  DB node id: 0 salt: 649b3e95
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 331 bytes from backend 0
2016-03-10 20:32:38: pid 39351: DEBUG:  authentication backend
2016-03-10 20:32:38: pid 39351: DETAIL:  trying md5 authentication
2016-03-10 20:32:38: pid 39351: DEBUG:  performing md5 authentication
2016-03-10 20:32:38: pid 39351: DETAIL:  DB node id: 1 salt: 3072bee9
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 331 bytes from backend 1
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 22
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 22
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"application_name" value:""
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"application_name" value:""
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"client_encoding" value:"UTF8"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"client_encoding" value:"UTF8"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 23
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 23
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"DateStyle" value:"ISO, DMY"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"DateStyle" value:"ISO, DMY"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"integer_datetimes" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"integer_datetimes" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 27
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 27
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"IntervalStyle" value:"postgres"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"IntervalStyle" value:"postgres"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 20
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 20
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"is_superuser" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"is_superuser" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"server_encoding" value:"UTF8"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"server_encoding" value:"UTF8"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 25
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"server_version" value:"9.5.1"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"server_version" value:"9.5.1"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 32
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 32
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"session_authorization" value:"elias"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"session_authorization" value:"elias"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 35
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 35
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"standard_conforming_strings" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"standard_conforming_strings" value:"on"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 0 length: 33
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  master slot: 1 length: 33
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 name:"TimeZone" value:"Australia/Melbourne"
2016-03-10 20:32:38: pid 39351: DEBUG:  process parameter status
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 name:"TimeZone" value:"Australia/Melbourne"
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 0 length: 12
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 1 length: 12
2016-03-10 20:32:38: pid 39351: DEBUG:  authentication backend
2016-03-10 20:32:38: pid 39351: DETAIL:  cp->info[i]:0x7f953c963800 pid:57630
2016-03-10 20:32:38: pid 39351: DEBUG:  authentication backend
2016-03-10 20:32:38: pid 39351: DETAIL:  cp->info[i]:0x7f953c963888 pid:40007
2016-03-10 20:32:38: pid 39351: DEBUG:  sending backend key data
2016-03-10 20:32:38: pid 39351: DETAIL:  send pid 40007 to frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  selecting load balance node
2016-03-10 20:32:38: pid 39351: DETAIL:  selected backend id is 1
2016-03-10 20:32:38: pid 39351: DEBUG:  initializing session context
2016-03-10 20:32:38: pid 39351: DETAIL:  selected load balancing node: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing transaction isolation. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing writing transaction. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing failed transaction. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing failed transaction. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing skip reading from backends. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing ignore till sync. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = 'Z'
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 of 2 kind = 'Z'
2016-03-10 20:32:38: pid 39351: DEBUG:  read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'Z'(5a) from backend
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  Ready For Query received
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing ignore till sync. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 0 length: 5
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 1 length: 5
2016-03-10 20:32:38: pid 39351: DEBUG:  processing ReadyForQuery
2016-03-10 20:32:38: pid 39351: DETAIL:  transaction state '
2016-03-10 20:32:38: pid 39351: DEBUG:  processing ReadyForQuery
2016-03-10 20:32:38: pid 39351: DETAIL:  transaction state 'I'(49)
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'P'(50) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  Parse: statement name <>
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  decide where to send the queries
2016-03-10 20:32:38: pid 39351: DETAIL:  destination = 3 for query= "SET extra_float_digits = 3"
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: Parse: SET extra_float_digits = 3
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: Parse: SET extra_float_digits = 3
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56980 kind: P name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'B'(42) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  Bind: waiting for master completing the query
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: B message
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: B message
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56a18 kind: B name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'E'(45) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: Execute: SET extra_float_digits = 3
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: Execute: SET extra_float_digits = 3
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'S'(53) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 25 bytes from backend 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = '1'
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 25 bytes from backend 1
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 of 2 kind = '1'
2016-03-10 20:32:38: pid 39351: DEBUG:  read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind '1'(31) from backend
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56a18 kind: B name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  adding sent message to list
2016-03-10 20:32:38: pid 39351: DETAIL:  adding exactly same message is prohibited
2016-03-10 20:32:38: pid 39351: DEBUG:  SimpleForwardToFrontend: packet:1 length:0
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting command success. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = '2'
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 of 2 kind = '2'
2016-03-10 20:32:38: pid 39351: DEBUG:  read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind '2'(32) from backend
2016-03-10 20:32:38: pid 39351: DEBUG:  SimpleForwardToFrontend: packet:2 length:0
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting command success. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = 'C'
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 of 2 kind = 'C'
2016-03-10 20:32:38: pid 39351: DEBUG:  read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'C'(43) from backend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting command success. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = 'Z'
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:1 of 2 kind = 'Z'
2016-03-10 20:32:38: pid 39351: DEBUG:  read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'Z'(5a) from backend
2016-03-10 20:32:38: pid 39351: DEBUG:  processing backend response
2016-03-10 20:32:38: pid 39351: DETAIL:  Ready For Query received
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing ignore till sync. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 0 length: 5
2016-03-10 20:32:38: pid 39351: DEBUG:  reading message length
2016-03-10 20:32:38: pid 39351: DETAIL:  slot: 1 length: 5
2016-03-10 20:32:38: pid 39351: DEBUG:  processing ReadyForQuery
2016-03-10 20:32:38: pid 39351: DETAIL:  transaction state 'I'(49)
2016-03-10 20:32:38: pid 39351: DEBUG:  processing ReadyForQuery
2016-03-10 20:32:38: pid 39351: DETAIL:  transaction state 'I'(49)
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'P'(50) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  Parse: statement name <>
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  decide where to send the queries
2016-03-10 20:32:38: pid 39351: DETAIL:  destination = 3 for query= "BEGIN"
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: Parse: BEGIN
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: Parse: BEGIN
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56a98 kind: P name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  adding sent message to list
2016-03-10 20:32:38: pid 39351: DETAIL:  prepared statement "" already exists
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_sent_message_destroy: sent message: address: 1f56980 kind: P name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  checking if query context can be safely destroyed
2016-03-10 20:32:38: pid 39351: DETAIL:  query context 0x1f58d50 is still used 2 times. query:"SET extra_float_digits = 3"
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'B'(42) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  Bind: waiting for master completing the query
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: B message
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: B message
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56980 kind: B name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  adding sent message to list
2016-03-10 20:32:38: pid 39351: DETAIL:  portal "" already exists
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_sent_message_destroy: sent message: address: 1f56a18 kind: B name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'E'(45) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: Execute: BEGIN
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 1 backend pid: 40007 statement: Execute: BEGIN
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 1
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  processing frontend response
2016-03-10 20:32:38: pid 39351: DETAIL:  received kind 'P'(50) from frontend
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: clearing doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting doing extended query messaging. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  Parse: statement name <>
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
2016-03-10 20:32:38: pid 39351: DETAIL:  result = 0
2016-03-10 20:32:38: pid 39351: DEBUG:  decide where to send the queries
2016-03-10 20:32:38: pid 39351: DETAIL:  destination = 2 for query= "SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid)  WHERE n.nspname != 'pg_toast'"
2016-03-10 20:32:38: pid 39351: DEBUG:  system catalog walker, checking relation "pg_type"
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: extended:1 query:"SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s"
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 21 bytes from backend 0
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 6
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: no pending data
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 46 bytes from backend 0
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '1'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received PARSE COMPLETE ('1')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '2'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received BIND COMPLETE ('2')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: all state completed. returning
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pop data of len: 21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: popped data len:21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: extended:1 query:"SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'"
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 6
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: no pending data
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 46 bytes from backend 0
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '1'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received PARSE COMPLETE ('1')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '2'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received BIND COMPLETE ('2')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: all state completed. returning
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pop data of len: 21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: popped data len:21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'"
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 6
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: no pending data
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 46 bytes from backend 0
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '1'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received PARSE COMPLETE ('1')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '2'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received BIND COMPLETE ('2')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: all state completed. returning
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pop data of len: 21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: popped data len:21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  system catalog walker, checking relation "pg_namespace"
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'"
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 1
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 4
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pushing data of len: 6
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: no pending data
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:B
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:S
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:E
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:C
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:H
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_read: read 46 bytes from backend 0
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '1'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received PARSE COMPLETE ('1')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '2'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received BIND COMPLETE ('2')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: kind: '3'
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: received CLOSE COMPLETE ('3')
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: all state completed. returning
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  pop data of len: 21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  do_query: popped data len:21
2016-03-10 20:32:38: pid 39351: CONTEXT:  while searching system catalog, When relcache is missed
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: setting query in progress. DONE
2016-03-10 20:32:38: pid 39351: LOG:  DB node id: 0 backend pid: 57630 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid)  WHERE n.nspname != 'pg_toast'
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_send_and_wait: pool_set_sync_map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_write: to backend: kind:P
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_add_sent_message: sent message: address: 1f56a18 kind: P name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  adding sent message to list
2016-03-10 20:32:38: pid 39351: DETAIL:  prepared statement "" already exists
2016-03-10 20:32:38: pid 39351: DEBUG:  called by pool_sent_message_destroy: sent message: address: 1f56a98 kind: P name: ==
2016-03-10 20:32:38: pid 39351: DEBUG:  checking if query context can be safely destroyed
2016-03-10 20:32:38: pid 39351: DETAIL:  query context 0x1f59d70 is still used 2 times. query:"BEGIN"
2016-03-10 20:32:38: pid 39351: DEBUG:  session context: unsetting query in progress. DONE
2016-03-10 20:32:38: pid 39351: DEBUG:  pool_use_sync_map: set use sync map: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  master node id: 0
2016-03-10 20:32:38: pid 39351: DEBUG:  reading backend data packet kind
2016-03-10 20:32:38: pid 39351: DETAIL:  backend:0 of 2 kind = '1'
2016-03-10 20:32:41: pid 39353: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate kind = 5
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate kind = 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:41: pid 39353: DEBUG:  SSL is requested but SSL support is not available
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 13 bytes from backend 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate kind = 5
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:p
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 330 bytes from backend 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate kind = 0
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate backend: key data received
2016-03-10 20:32:41: pid 39353: DEBUG:  authenticate backend: transaction state: I
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:Q
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 91 bytes from backend 0
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'T'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received ROW DESCRIPTION ('T')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: row description: num_fileds: 1
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'Z'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received READY FOR QUERY ('Z')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:Q
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_read: read 95 bytes from backend 0
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'T'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received ROW DESCRIPTION ('T')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: row description: num_fileds: 1
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'D'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received DATA ROW ('D')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'C'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received COMMAND COMPLETE ('C')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: kind: 'Z'
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  do_query: received READY FOR QUERY ('Z')
2016-03-10 20:32:41: pid 39353: CONTEXT:  while checking replication time lag
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:41: pid 39353: DEBUG:  pool_write: to backend: kind:X
^C2016-03-10 20:32:47: pid 39352: DEBUG:  PCP child receives shutdown request signal 2, Forwarding to all children
2016-03-10 20:32:47: pid 39352: DEBUG:  PCP child receives fast shutdown request
2016-03-10 20:32:47: pid 39351: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39351: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:47: pid 39351: DEBUG:  pool_write: to backend: kind:X
2016-03-10 20:32:47: pid 39350: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39349: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39348: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39347: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39346: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39345: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39344: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39343: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39342: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39341: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39340: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39339: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39338: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39337: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39336: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39335: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39334: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39333: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39332: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39331: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39330: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39329: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39328: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39327: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39326: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39325: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39324: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39323: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39322: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39321: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39320: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39319: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39318: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39317: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39316: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39315: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39314: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39313: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39312: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39311: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39310: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39309: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39308: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39307: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39306: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39305: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39304: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39303: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39302: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39301: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39300: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39299: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39298: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39297: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39296: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39295: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39294: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39293: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39292: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39291: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39290: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39289: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39288: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39287: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39286: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39285: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39284: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39283: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39282: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39281: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39280: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39279: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39278: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39277: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39276: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39275: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39274: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39273: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39272: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39271: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39270: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39269: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39268: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39267: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39266: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39265: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39264: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39263: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39262: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39261: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39260: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39259: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39258: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39257: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39256: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39255: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39254: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39253: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39252: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39251: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39250: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39249: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39248: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39247: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39246: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39245: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39244: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39243: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39242: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39241: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39240: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39239: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39238: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39237: LOG:  child process received shutdown request signal 2
2016-03-10 20:32:47: pid 39236: LOG:  received fast shutdown request
2016-03-10 20:32:47: pid 39236: LOG:  shutdown request. closing listen socket
[root@postgresC etc]#

[elias@postgresC pgpoolbug]$ mvn exec:java -Dexec.mainClass="pgpoolbug.SimpleEntityMain"
[INFO] Scanning for projects...
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Building pgpoolbug 1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO]
[INFO] --- exec-maven-plugin:1.3.2:java (default-cli) @ pgpoolbug ---
[WARNING] Warning: killAfter is now deprecated. Do you need it ? Please comment on MEXEC-6.
Mar 10, 2016 8:32:37 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.5.Final}
Mar 10, 2016 8:32:37 PM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.10.Final}
Mar 10, 2016 8:32:37 PM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Mar 10, 2016 8:32:37 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Mar 10, 2016 8:32:37 PM org.hibernate.cfg.Configuration configure
INFO: HHH000043: Configuring from resource: hibernate.cfg.xml
Mar 10, 2016 8:32:37 PM org.hibernate.cfg.Configuration getConfigurationInputStream
INFO: HHH000040: Configuration resource: hibernate.cfg.xml
Mar 10, 2016 8:32:38 PM org.hibernate.cfg.Configuration doConfigure
INFO: HHH000041: Configured SessionFactory: null
Mar 10, 2016 8:32:38 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Mar 10, 2016 8:32:38 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.205.146:5433/eliasdb?loglevel=2]
Mar 10, 2016 8:32:38 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=elias, password=****}
Mar 10, 2016 8:32:38 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Mar 10, 2016 8:32:38 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
20:32:38.216 (1) PostgreSQL 9.4 JDBC4.1 (build 1202)
20:32:38.228 (1) Trying to establish a protocol version 3 connection to 192.168.205.146:5433
20:32:38.347 (1) Receive Buffer Size is 87379
20:32:38.347 (1) Send Buffer Size is 330075
20:32:38.361 (1)  FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2)
20:32:38.391 (1)  <=BE AuthenticationReqMD5(salt=4eeca57a)
20:32:38.397 (1)  FE=> Password(md5digest=md5dee10d2f99d2ab48822a2b3de92d4cd8)
20:32:38.400 (1)  <=BE AuthenticationOk
20:32:38.457 (1)  <=BE ParameterStatus(application_name = )
20:32:38.457 (1)  <=BE ParameterStatus(client_encoding = UTF8)
20:32:38.457 (1)  <=BE ParameterStatus(DateStyle = ISO, DMY)
20:32:38.457 (1)  <=BE ParameterStatus(integer_datetimes = on)
20:32:38.458 (1)  <=BE ParameterStatus(IntervalStyle = postgres)
20:32:38.458 (1)  <=BE ParameterStatus(is_superuser = on)
20:32:38.458 (1)  <=BE ParameterStatus(server_encoding = UTF8)
20:32:38.458 (1)  <=BE ParameterStatus(server_version = 9.5.1)
20:32:38.458 (1)  <=BE ParameterStatus(session_authorization = elias)
20:32:38.458 (1)  <=BE ParameterStatus(standard_conforming_strings = on)
20:32:38.458 (1)  <=BE ParameterStatus(TimeZone = Australia/Melbourne)
20:32:38.458 (1)  <=BE BackendKeyData(pid=40007,ckey=857652130)
20:32:38.458 (1)  <=BE ReadyForQuery(I)
20:32:38.467 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@8227089, maxRows=0, fetchSize=0, flags=23
20:32:38.473 (1)  FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={})
20:32:38.473 (1)  FE=> Bind(stmt=null,portal=null)
20:32:38.473 (1)  FE=> Execute(portal=null,limit=1)
20:32:38.473 (1)  FE=> Sync
20:32:38.477 (1)  <=BE ParseComplete [null]
20:32:38.477 (1)  <=BE BindComplete [unnamed]
20:32:38.477 (1)  <=BE CommandStatus(SET)
20:32:38.477 (1)  <=BE ReadyForQuery(I)
20:32:38.478 (1)     compatible = 90400
20:32:38.478 (1)     loglevel = 2
20:32:38.478 (1)     prepare threshold = 5
20:32:38.485 (1)     types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
20:32:38.486 (1)     types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
20:32:38.486 (1)     integer date/time = true
20:32:38.687 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@4f437cf9, maxRows=0, fetchSize=0, flags=1
20:32:38.687 (1)  FE=> Parse(stmt=null,query="BEGIN",oids={})
20:32:38.687 (1)  FE=> Bind(stmt=null,portal=null)
20:32:38.687 (1)  FE=> Execute(portal=null,limit=0)
20:32:38.689 (1)  FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid)  WHERE n.nspname != 'pg_toast'",oids={})
20:32:38.689 (1)  FE=> Bind(stmt=null,portal=null)
20:32:38.689 (1)  FE=> Describe(portal=null)
20:32:38.689 (1)  FE=> Execute(portal=null,limit=0)
20:32:38.689 (1)  FE=> Sync
^C[elias@postgresC pgpoolbug]$
debug-20160310.txt (90,862 bytes)

eflopez123

2016-03-10 13:54

reporter   ~0000681

I double checked things and I am still getting the problem. I attached the debug output from both pgpool and the postgresql driver.

eflopez123

2016-03-10 14:13

reporter   ~0000682

ok.. I've tried it a few more times. I noticed that my postgres VMs were out of time sync, so I fixed that in case that was a factor.

 It also seems maybe I was too quick to run the test program. This time I waited until I saw:

2016-03-10 16:12:09: pid 2560: DEBUG: do_query: received READY FOR QUERY ('Z')

in the debugging output and now the test program seems to work. Thankyou :)

t-ishii

2016-03-10 14:16

developer   ~0000683

Thank you for the quick response. Glad to hear that!

eflopez123

2016-03-11 12:24

reporter   ~0000684

Its started happening again, though this time it appears to be intermittent.

Sometimes it works, sometimes it doesn't. Can still use the same test program, try and run a few times. Sometimes it works, then run again and it will block. There doesn't seem to be a pattern to it.

t-ishii

2016-03-11 16:25

developer   ~0000685

Can you provide a test program which hibernte is not upset about?
I want to run the program repeatedly so that I can reproduce the problem.

eflopez123

2016-03-14 08:26

reporter   ~0000686

I have produced a slightly more user friendly program, and packaged in a single jar (to avoid the need for maven), and can just run on command line. Unfortunately its rather large because of the hibernate dependencies so I was unable to attach it to this issue so I have uploaded it to my webhost

wget -c http://eliaslopez.net/hidden/pgpoolbug.jar

As the problem only presents itself during the hibernate initialisation, all the program does is run a select query after hibernate initialises and exits, and you can supply the connection details on the command line.

usage: java -jar pgpoolbug.jar <jdbc url> <username> <password>
    eg: java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5432/eliasdb?loglevel2 elias foobar

When the problem happens, the program locks up at this output:
Mar 14, 2016 10:23:31 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)

waiting for a response from pgpool.

When it works, when you see that output line, you can also see debug information in the pgpool console as hibernate is querying the database schema etc and eventually the program will return:

Mar 14, 2016 10:24:30 AM org.hibernate.dialect.Dialect <init>
INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL9Dialect
Mar 14, 2016 10:24:30 AM org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation
INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
Mar 14, 2016 10:24:30 AM org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService
INFO: HHH000399: Using default transaction strategy (direct JDBC transactions)
Mar 14, 2016 10:24:30 AM org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory <init>
INFO: HHH000397: Using ASTQueryTranslatorFactory
Mar 14, 2016 10:24:30 AM org.hibernate.tool.hbm2ddl.SchemaValidator validate
INFO: HHH000229: Running schema validator
Mar 14, 2016 10:24:30 AM org.hibernate.tool.hbm2ddl.SchemaValidator validate
INFO: HHH000102: Fetching database metadata
Opening Session
Received Result: If you can see this it worked
Finished

and should exit with 0 status. If theres any errors or connection problems it should exit with 1.

Let me know if you need anymore information.

t-ishii

2016-03-14 13:42

developer   ~0000687

Thanks for the new test program. I will try and get back to you.

t-ishii

2016-03-14 14:17

developer   ~0000688

Last edited: 2016-03-14 14:18

View 2 revisions

Even if ?loglevel2 is added, no protocol level log is shown.
Am I missing something?

eflopez123

2016-03-14 15:53

reporter   ~0000689

My apologies, I made a typo, the JDBC driver parameter is loglevel=2.

t-ishii

2016-03-14 16:04

developer   ~0000690

Last edited: 2016-03-15 14:35

View 2 revisions

Thanks. I should have noticed myself. Just for a record, here is the log:

java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii ""

t-ishii@localhost: LANG=C java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii ""
Initialising Hibernate
Mar 14, 2016 4:05:38 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
Mar 14, 2016 4:05:39 PM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.4.Final}
Mar 14, 2016 4:05:39 PM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Mar 14, 2016 4:05:39 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://localhost:11000/test?loglevel=2]
Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=t-ishii, password=****}
Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
16:05:39.168 (1) PostgreSQL 9.4 JDBC4.1 (build 1202)
16:05:39.175 (1) Trying to establish a protocol version 3 connection to localhost:11000
16:05:39.189 (1) Receive Buffer Size is 530904
16:05:39.189 (1) Send Buffer Size is 1313280
16:05:39.192 (1) FE=> StartupPacket(user=t-ishii, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Asia/Tokyo, extra_float_digits=2)
16:05:39.197 (1) <=BE AuthenticationOk
16:05:39.205 (1) <=BE ParameterStatus(application_name = )
16:05:39.205 (1) <=BE ParameterStatus(client_encoding = UTF8)
16:05:39.206 (1) <=BE ParameterStatus(DateStyle = ISO, MDY)
16:05:39.206 (1) <=BE ParameterStatus(integer_datetimes = on)
16:05:39.206 (1) <=BE ParameterStatus(IntervalStyle = postgres)
16:05:39.206 (1) <=BE ParameterStatus(is_superuser = on)
16:05:39.206 (1) <=BE ParameterStatus(server_encoding = UTF8)
16:05:39.206 (1) <=BE ParameterStatus(server_version = 9.5.0)
16:05:39.206 (1) <=BE ParameterStatus(session_authorization = t-ishii)
16:05:39.206 (1) <=BE ParameterStatus(standard_conforming_strings = on)
16:05:39.206 (1) <=BE ParameterStatus(TimeZone = Asia/Tokyo)
16:05:39.206 (1) <=BE BackendKeyData(pid=28624,ckey=525395529)
16:05:39.207 (1) <=BE ReadyForQuery(I)
16:05:39.210 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@3680bc43, maxRows=0, fetchSize=0, flags=23
16:05:39.211 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={})
16:05:39.211 (1) FE=> Bind(stmt=null,portal=null)
16:05:39.211 (1) FE=> Execute(portal=null,limit=1)
16:05:39.211 (1) FE=> Sync
16:05:39.212 (1) <=BE ParseComplete [null]
16:05:39.213 (1) <=BE BindComplete [unnamed]
16:05:39.213 (1) <=BE CommandStatus(SET)
16:05:39.213 (1) <=BE ReadyForQuery(I)
16:05:39.214 (1) compatible = 90400
16:05:39.214 (1) loglevel = 2
16:05:39.214 (1) prepare threshold = 5
16:05:39.216 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
16:05:39.218 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
16:05:39.218 (1) integer date/time = true
16:05:39.248 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@609acf2c, maxRows=0, fetchSize=0, flags=1
16:05:39.248 (1) FE=> Parse(stmt=null,query="BEGIN",oids={})
16:05:39.248 (1) FE=> Bind(stmt=null,portal=null)
16:05:39.248 (1) FE=> Execute(portal=null,limit=0)
16:05:39.248 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={})
16:05:39.248 (1) FE=> Bind(stmt=null,portal=null)
16:05:39.249 (1) FE=> Describe(portal=null)
16:05:39.249 (1) FE=> Execute(portal=null,limit=0)
16:05:39.249 (1) FE=> Sync
[hang]

t-ishii

2016-03-24 14:38

developer   ~0000716

With attached patch (fix-bug167.diff, should be applied to 3.5_STABLE head), I have successfully run your test program with "LogLevel=2".

java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii ""

However, if I remove the LogLevel option, I got Java exception below. This means that my fix is not enough?

java.util.NoSuchElementException
    at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1728)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:615)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:465)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:350)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80)
    at org.hibernate.loader.Loader.getResultSet(Loader.java:2065)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
    at org.hibernate.loader.Loader.doQuery(Loader.java:909)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
    at org.hibernate.loader.Loader.doList(Loader.java:2553)
    at org.hibernate.loader.Loader.doList(Loader.java:2539)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
    at org.hibernate.loader.Loader.list(Loader.java:2364)
    at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:353)
    at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:1873)
    at org.hibernate.internal.AbstractSessionImpl.list(AbstractSessionImpl.java:311)
    at org.hibernate.internal.SQLQueryImpl.list(SQLQueryImpl.java:141)
    at pgpoolbug.BugMain.main(BugMain.java:69)

t-ishii

2016-03-24 14:39

developer  

fix-bug167.diff (3,093 bytes)
diff --git a/src/context/pool_session_context.c b/src/context/pool_session_context.c
index 8fd95a8..6e6c557 100644
--- a/src/context/pool_session_context.c
+++ b/src/context/pool_session_context.c
@@ -37,6 +37,7 @@ static void GetTranIsolationErrorCb(void *arg);
 static void init_sent_message_list(void);
 static POOL_PENDING_MESSAGE *copy_pending_message(POOL_PENDING_MESSAGE *messag);
 static void dump_sent_message(char *caller, POOL_SENT_MESSAGE *m);
+static char *dump_sync_map(void);
 
 /*
  * Initialize per session context
@@ -947,16 +948,35 @@ bool pool_use_sync_map(void)
 			if (pool_is_set_sync_map(i))
 			{
 				ereport(DEBUG1,
-						(errmsg("pool_use_sync_map: set use sync map: %d", i)));
+						(errmsg("pool_use_sync_map: we can use sync map: %s", dump_sync_map())));
 				return POOL_SYNC_MAP_IS_VALID;	/* yes, we can use sync map */
 			}
 		}
+		ereport(DEBUG1,
+				(errmsg("pool_use_sync_map: we cannot use sync map because all map entries are false")));
 		return POOL_SYNC_MAP_EMPTY;	/* no, we cannot use sync map */
 	}
 
+	ereport(DEBUG1,
+			(errmsg("pool_use_sync_map: we cannot use sync map because STREAM: %d query in progress: %d doing extended query: %d", STREAM, pool_is_query_in_progress(), pool_is_doing_extended_query_message())));
+
 	return POOL_IGNORE_SYNC_MAP;
 }
 
+static char *dump_sync_map(void)
+{
+	static char mapstr[MAX_NUM_BACKENDS+1];
+	int i;
+
+	memset(mapstr, 0, sizeof(mapstr));
+
+	for (i=0;i<NUM_BACKENDS;i++)
+	{
+		mapstr[i] = session_context->sync_map[i]?'1':'0';
+	}
+	return mapstr;
+}
+
 /*
  * Set pending response
  */
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index fd3b76f..5236e6e 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -1926,6 +1926,7 @@ void do_query(POOL_CONNECTION *backend, char *query, POOL_SELECT_RESULT **result
 	int num_close_complete;
 	int state;
 	bool data_pushed;
+	POOL_SESSION_CONTEXT *session_context;
 
 	data_pushed = false;
 
@@ -1970,6 +1971,29 @@ void do_query(POOL_CONNECTION *backend, char *query, POOL_SELECT_RESULT **result
 			pool_write(backend, "H", 1);
 			len = htonl(sizeof(len));
 			pool_write_and_flush(backend, &len, sizeof(len));
+			ereport(DEBUG1,
+					(errmsg("do_query: send flush message to %d", backend->db_node_id)));
+
+			/*
+			 * If we have not send the flush message to load balance node yet,
+			 * send a flush message to the load balance node. Otherwise only
+			 * the non load balance node (usually the master node) produces
+			 * response if we do not send sync message to it yet.
+			 */
+			session_context = pool_get_session_context(false);
+
+			if (backend->db_node_id != session_context->load_balance_node_id)
+			{
+				POOL_CONNECTION *con;
+
+				con = session_context->backend->slots[session_context->load_balance_node_id]->con;
+				pool_write(con, "H", 1);
+				len = htonl(sizeof(len));
+				pool_write_and_flush(con, &len, sizeof(len));
+				ereport(DEBUG1,
+						(errmsg("do_query: send flush message to %d", con->db_node_id)));
+
+			}
 
 			for(;;)
 			{
fix-bug167.diff (3,093 bytes)

eflopez123

2016-03-26 13:59

reporter   ~0000723

I'm not sure why that exception happened... but after applying the patch I'm still seeing the same behaviour. this is the output from 2 runs, one right after the other:

[root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb elias foobar
Initialising Hibernate
Mar 15, 2016 12:35:50 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
Mar 15, 2016 12:35:50 PM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.4.Final}
Mar 15, 2016 12:35:50 PM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Mar 15, 2016 12:35:50 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb]
Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=elias, password=****}
Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
Mar 15, 2016 12:35:53 PM org.hibernate.dialect.Dialect <init>
INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL9Dialect
Mar 15, 2016 12:35:53 PM org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation
INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
Mar 15, 2016 12:35:53 PM org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService
INFO: HHH000399: Using default transaction strategy (direct JDBC transactions)
Mar 15, 2016 12:35:53 PM org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory <init>
INFO: HHH000397: Using ASTQueryTranslatorFactory
Mar 15, 2016 12:35:53 PM org.hibernate.tool.hbm2ddl.SchemaValidator validate
INFO: HHH000229: Running schema validator
Mar 15, 2016 12:35:53 PM org.hibernate.tool.hbm2ddl.SchemaValidator validate
INFO: HHH000102: Fetching database metadata
Opening Session
Received Result: If you can see this it worked
Finished



[root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb elias foobar
Initialising Hibernate
Mar 15, 2016 12:35:54 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
Mar 15, 2016 12:35:54 PM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.4.Final}
Mar 15, 2016 12:35:54 PM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Mar 15, 2016 12:35:54 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb]
Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=elias, password=****}
Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
[hang]

eflopez123

2016-03-26 14:00

reporter   ~0000724

Even with loglevel=2 it still locks up sometimes:

[root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb?loglevel=2 elias foobar
Initialising Hibernate
Mar 15, 2016 12:39:17 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
Mar 15, 2016 12:39:17 PM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate Core {4.3.4.Final}
Mar 15, 2016 12:39:17 PM org.hibernate.cfg.Environment <clinit>
INFO: HHH000206: hibernate.properties not found
Mar 15, 2016 12:39:17 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: HHH000021: Bytecode provider name : javassist
Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!)
Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb?loglevel=2]
Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000046: Connection properties: {user=elias, password=****}
Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH000006: Autocommit mode: false
Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
INFO: HHH000115: Hibernate connection pool size: 10 (min=1)
12:39:18.113 (1) PostgreSQL 9.4 JDBC4.1 (build 1202)
12:39:18.119 (1) Trying to establish a protocol version 3 connection to 192.168.88.106:5433
12:39:18.129 (1) Receive Buffer Size is 87379
12:39:18.129 (1) Send Buffer Size is 330075
12:39:18.132 (1) FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2)
12:39:18.144 (1) <=BE AuthenticationOk
12:39:18.159 (1) <=BE ParameterStatus(application_name = )
12:39:18.159 (1) <=BE ParameterStatus(client_encoding = UTF8)
12:39:18.159 (1) <=BE ParameterStatus(DateStyle = ISO, DMY)
12:39:18.159 (1) <=BE ParameterStatus(integer_datetimes = on)
12:39:18.159 (1) <=BE ParameterStatus(IntervalStyle = postgres)
12:39:18.159 (1) <=BE ParameterStatus(is_superuser = off)
12:39:18.159 (1) <=BE ParameterStatus(server_encoding = UTF8)
12:39:18.159 (1) <=BE ParameterStatus(server_version = 9.5.1)
12:39:18.159 (1) <=BE ParameterStatus(session_authorization = elias)
12:39:18.160 (1) <=BE ParameterStatus(standard_conforming_strings = on)
12:39:18.160 (1) <=BE ParameterStatus(TimeZone = Australia/Melbourne)
12:39:18.160 (1) <=BE BackendKeyData(pid=2871,ckey=74287852)
12:39:18.160 (1) <=BE ReadyForQuery(I)
12:39:18.162 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@1f4a8824, maxRows=0, fetchSize=0, flags=23
12:39:18.162 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={})
12:39:18.163 (1) FE=> Bind(stmt=null,portal=null)
12:39:18.163 (1) FE=> Execute(portal=null,limit=1)
12:39:18.163 (1) FE=> Sync
12:39:18.166 (1) <=BE ParseComplete [null]
12:39:18.166 (1) <=BE BindComplete [unnamed]
12:39:18.166 (1) <=BE CommandStatus(SET)
12:39:18.166 (1) <=BE ReadyForQuery(I)
12:39:18.166 (1) compatible = 90400
12:39:18.166 (1) loglevel = 2
12:39:18.166 (1) prepare threshold = 5
12:39:18.169 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
12:39:18.170 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX
12:39:18.170 (1) integer date/time = true
12:39:18.208 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@2d6bcf8a, maxRows=0, fetchSize=0, flags=1
12:39:18.208 (1) FE=> Parse(stmt=null,query="BEGIN",oids={})
12:39:18.208 (1) FE=> Bind(stmt=null,portal=null)
12:39:18.208 (1) FE=> Execute(portal=null,limit=0)
12:39:18.209 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={})
12:39:18.209 (1) FE=> Bind(stmt=null,portal=null)
12:39:18.209 (1) FE=> Describe(portal=null)
12:39:18.209 (1) FE=> Execute(portal=null,limit=0)
12:39:18.209 (1) FE=> Sync

t-ishii

2016-03-26 17:14

developer   ~0000725

Can you please show me the pgpool debug log?

t-ishii

2016-03-28 11:13

developer   ~0000730

I have committed the patch to 3.5 stable tree. You can try it if you like.

eflopez123

2016-03-28 19:05

reporter   ~0000732

Here it is, from the stable branch, it hangs at this point.

[root@postgrestest bin]# /usr/local/pgpool2/bin/pgpool -n -d
2016-03-15 15:08:40: pid 18773: DEBUG: loading hba configuration
2016-03-15 15:08:40: pid 18773: DETAIL: loading file :"/usr/local/pgpool2/etc/pool_hba.conf" for client authentication configuration file
2016-03-15 15:08:40: pid 18773: DEBUG: pool_coninfo_size: num_init_children (30) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 1044480 bytes requested for shared memory
2016-03-15 15:08:40: pid 18773: DEBUG: ProcessInfo: num_init_children (30) * sizeof(ProcessInfo) (32) = 960 bytes requested for shared memory
2016-03-15 15:08:40: pid 18773: DEBUG: Request info are: sizeof(POOL_REQUEST_INFO) 5224 bytes requested for shared memory
2016-03-15 15:08:40: pid 18773: DEBUG: Recovery management area: sizeof(int) 4 bytes requested for shared memory
2016-03-15 15:08:40: pid 18773: LOG: Setting up socket for 0.0.0.0:5433
2016-03-15 15:08:40: pid 18773: LOG: Setting up socket for :::5433
2016-03-15 15:08:40: pid 18777: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18776: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18778: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18779: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18775: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18780: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18781: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18782: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18783: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18784: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18774: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18785: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18786: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18787: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18788: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18789: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18790: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18791: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18792: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18793: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18794: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18795: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18773: LOG: pgpool-II successfully started. version 3.5.0 (ekieboshi)
2016-03-15 15:08:40: pid 18773: LOG: find_primary_node: checking backend no 0
2016-03-15 15:08:40: pid 18796: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18799: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18800: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18798: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18801: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18802: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18797: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18803: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18804: DEBUG: I am PCP child with pid:18804
2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:40: pid 18805: DEBUG: I am 18805
2016-03-15 15:08:40: pid 18805: DEBUG: initializing backend status
2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:08:40: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 75 bytes from backend 0
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'T'
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'D'
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'C'
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'Z'
2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:40: pid 18773: LOG: find_primary_node: primary node id is 0
2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:40: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:40: pid 18773: DEBUG: starting health check
2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:08:40: pid 18773: DEBUG: doing health check against database:postgres user:postgres
2016-03-15 15:08:40: pid 18773: DEBUG: Backend DB node 0 status is 2
2016-03-15 15:08:40: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2
2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:40: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful
2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:40: pid 18773: DEBUG: Backend DB node 1 status is 2
2016-03-15 15:08:40: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2
2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:40: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful
2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:08:50: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:50: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:00: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:00: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:06: pid 18803: DEBUG: I am 18803 accept fd 7
2016-03-15 15:09:06: pid 18803: LOG: new connection received
2016-03-15 15:09:06: pid 18803: DETAIL: connecting host=postgrestest port=44033
2016-03-15 15:09:06: pid 18803: DEBUG: reading startup packet
2016-03-15 15:09:06: pid 18803: DETAIL: Protocol Major: 3 Minor: 0 database: eliasdb user: elias
2016-03-15 15:09:06: pid 18803: DEBUG: creating new connection to backend
2016-03-15 15:09:06: pid 18803: DETAIL: connecting 0 backend
2016-03-15 15:09:06: pid 18803: DEBUG: creating new connection to backend
2016-03-15 15:09:06: pid 18803: DETAIL: connecting 1 backend
2016-03-15 15:09:06: pid 18803: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:06: pid 18803: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 332 bytes from backend 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 332 bytes from backend 1
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 8
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 8
2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend
2016-03-15 15:09:06: pid 18803: DETAIL: auth kind:0
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 22
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 22
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"application_name" value:""
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"application_name" value:""
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"client_encoding" value:"UTF8"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"client_encoding" value:"UTF8"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 23
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 23
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"DateStyle" value:"ISO, DMY"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"DateStyle" value:"ISO, DMY"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"integer_datetimes" value:"on"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"integer_datetimes" value:"on"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 27
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 27
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"IntervalStyle" value:"postgres"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"IntervalStyle" value:"postgres"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 21
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 21
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"is_superuser" value:"off"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"is_superuser" value:"off"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"server_encoding" value:"UTF8"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"server_encoding" value:"UTF8"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"server_version" value:"9.5.1"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"server_version" value:"9.5.1"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 32
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 32
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"session_authorization" value:"elias"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"session_authorization" value:"elias"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 35
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 35
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"standard_conforming_strings" value:"on"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"standard_conforming_strings" value:"on"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 33
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 33
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"TimeZone" value:"Australia/Melbourne"
2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"TimeZone" value:"Australia/Melbourne"
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 12
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 12
2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend
2016-03-15 15:09:06: pid 18803: DETAIL: cp->info[i]:0x7ffa0b486800 pid:4647
2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend
2016-03-15 15:09:06: pid 18803: DETAIL: cp->info[i]:0x7ffa0b486888 pid:4121
2016-03-15 15:09:06: pid 18803: DEBUG: sending backend key data
2016-03-15 15:09:06: pid 18803: DETAIL: send pid 4121 to frontend
2016-03-15 15:09:06: pid 18803: DEBUG: selecting load balance node
2016-03-15 15:09:06: pid 18803: DETAIL: selected backend id is 1
2016-03-15 15:09:06: pid 18803: DEBUG: initializing session context
2016-03-15 15:09:06: pid 18803: DETAIL: selected load balancing node: 1
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing transaction isolation. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing writing transaction. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing failed transaction. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing failed transaction. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing skip reading from backends. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'Z'
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'Z'
2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'Z'(5a) from backend
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: Ready For Query received
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 5
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 5
2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery
2016-03-15 15:09:06: pid 18803: DETAIL: transaction state '
2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery
2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49)
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <>
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries
2016-03-15 15:09:06: pid 18803: DETAIL: destination = 3 for query= "SET extra_float_digits = 3"
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: SET extra_float_digits = 3
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Parse: SET extra_float_digits = 3
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62be0 kind: P name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'B'(42) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: Bind: waiting for master completing the query
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: B message
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: B message
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: B name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'E'(45) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Execute: SET extra_float_digits = 3
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Execute: SET extra_float_digits = 3
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'S'(53) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 25 bytes from backend 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '1'
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 25 bytes from backend 1
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = '1'
2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind '1'(31) from backend
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: B name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list
2016-03-15 15:09:06: pid 18803: DETAIL: adding exactly same message is prohibited
2016-03-15 15:09:06: pid 18803: DEBUG: SimpleForwardToFrontend: packet:1 length:0
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '2'
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = '2'
2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind '2'(32) from backend
2016-03-15 15:09:06: pid 18803: DEBUG: SimpleForwardToFrontend: packet:2 length:0
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'C'
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'C'
2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'C'(43) from backend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'Z'
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'Z'
2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'Z'(5a) from backend
2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response
2016-03-15 15:09:06: pid 18803: DETAIL: Ready For Query received
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 5
2016-03-15 15:09:06: pid 18803: DEBUG: reading message length
2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 5
2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery
2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49)
2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery
2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49)
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <>
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries
2016-03-15 15:09:06: pid 18803: DETAIL: destination = 3 for query= "BEGIN"
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: BEGIN
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Parse: BEGIN
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62cf8 kind: P name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list
2016-03-15 15:09:06: pid 18803: DETAIL: prepared statement "" already exists
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62be0 kind: P name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: checking if query context can be safely destroyed
2016-03-15 15:09:06: pid 18803: DETAIL: query context 0xc64fb0 is still used 2 times. query:"SET extra_float_digits = 3"
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'B'(42) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: Bind: waiting for master completing the query
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: B message
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: B message
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62be0 kind: B name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list
2016-03-15 15:09:06: pid 18803: DETAIL: portal "" already exists
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62c78 kind: B name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'E'(45) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Execute: BEGIN
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Execute: BEGIN
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response
2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend
2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <>
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
2016-03-15 15:09:06: pid 18803: DETAIL: result = 0
2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries
2016-03-15 15:09:06: pid 18803: DETAIL: destination = 2 for query= "SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'"
2016-03-15 15:09:06: pid 18803: DEBUG: system catalog walker, checking relation "pg_type"
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s"
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 21 bytes from backend 0
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'"
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'"
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: system catalog walker, checking relation "pg_namespace"
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'"
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3'
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3')
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21
2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed
2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE
2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'
2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: P name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list
2016-03-15 15:09:06: pid 18803: DETAIL: prepared statement "" already exists
2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62cf8 kind: P name: ==
2016-03-15 15:09:06: pid 18803: DEBUG: checking if query context can be safely destroyed
2016-03-15 15:09:06: pid 18803: DETAIL: query context 0xc65fd0 is still used 2 times. query:"BEGIN"
2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE
2016-03-15 15:09:06: pid 18803: DEBUG: pool_use_sync_map: set use sync map: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0
2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind
2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '1'
2016-03-15 15:09:10: pid 18773: DEBUG: starting health check
2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:10: pid 18773: DEBUG: doing health check against database:postgres user:postgres
2016-03-15 15:09:10: pid 18773: DEBUG: Backend DB node 0 status is 2
2016-03-15 15:09:10: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2
2016-03-15 15:09:10: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:10: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:10: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:10: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful
2016-03-15 15:09:10: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:10: pid 18773: DEBUG: Backend DB node 1 status is 2
2016-03-15 15:09:10: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2
2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:10: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:10: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:10: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:10: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful
2016-03-15 15:09:10: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:20: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:20: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:20: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:20: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:20: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:20: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:21: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:21: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:21: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:31: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:31: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:41: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:41: pid 18773: DEBUG: starting health check
2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:41: pid 18773: DEBUG: doing health check against database:postgres user:postgres
2016-03-15 15:09:41: pid 18773: DEBUG: Backend DB node 0 status is 2
2016-03-15 15:09:41: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2
2016-03-15 15:09:41: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:41: pid 18805: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:41: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:41: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful
2016-03-15 15:09:41: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:41: pid 18773: DEBUG: Backend DB node 1 status is 2
2016-03-15 15:09:41: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2
2016-03-15 15:09:41: pid 18773: DEBUG: SSL is requested but SSL support is not available
2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate kind = 0
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: key data received
2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()"
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate kind = 0
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: key data received
2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: transaction state: I
2016-03-15 15:09:41: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful
2016-03-15 15:09:41: pid 18773: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm
2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()"
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:Q
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'T'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: row description: num_fileds: 1
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'D'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received DATA ROW ('D')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'C'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'Z'
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z')
2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag
2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:X
2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:X

eflopez123

2016-03-29 14:42

reporter   ~0000736

I've been doing some more testing (got the latest stable just now) and I haven't been able to reproduce the hanging problem, which is good :)

However, I did reproduce the java error you mentioned before.

"java.util.NoSuchElementException
    at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278)"

I can't reproduce it reliably though, I run the java program in an infinite loop script and eventually it randomly fails, but usually within a 30-60 seconds of running the program.

eflopez123

2016-03-29 15:02

reporter   ~0000737

If I change the child_max_connections to 1, then it doesn't seem to happen, however values such as 50 seem to make it error as mentioned in my previous note.

The other settings (max_pool, num_init_children) don't seem to have any effect.

eflopez123

2016-03-29 15:11

reporter   ~0000738

Actually...

num_init_children = 2
max_pool = 1

Seem to make the error happen far more easily.

I still can't reproduce it with loglevel=2 for the JDBC driver however.

I tested a direct postgres connection just in case the JDBC driver could be blamed but that seems to work even at loglevel=0

eflopez123

2016-03-29 15:32

reporter   ~0000739

If I add &prepareThreshold=0 to the jdbc URL, it then appears to work.

My test program is not doing any prepared statements, but hibernate does many queries during initialisation, mostly to probe the database schema definition.

So while I run my program in a bash loop, it starts and shuts down many times, it would hit the relation cache pretty heavily. This is obvious as the first iteration is slow during initialisation, it the next runs are much faster.

I get the array error just after hibernate initialisation finishes and I just run a simple sql query. Bug 152 looks very similar, since prepared statements are involved?

t-ishii

2016-03-29 16:02

developer   ~0000741

I have gotten a Java exception after repeating several times your test program.

My guess is pgpool-II mistakenly sends a CommandStatus(BEGIN) to frontend when it should sends CommandStatus(SELECT). I think the confusion is caused by that lots of prepared statements are used (by Hibernate). I have an idea fixing the problem in my mind and am working on it. I will keep you informed.

13:03:05.752 (1) <=BE ParseComplete [null]
13:03:05.752 (1) <=BE BindComplete [unnamed]
13:03:05.752 (1) <=BE CommandStatus(BEGIN)
java.util.NoSuchElementException
    at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1728)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:615)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:465)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:350)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80)
    at org.hibernate.loader.Loader.getResultSet(Loader.java:2065)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
    at org.hibernate.loader.Loader.doQuery(Loader.java:909)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
    at org.hibernate.loader.Loader.doList(Loader.java:2553)
    at org.hibernate.loader.Loader.doList(Loader.java:2539)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
    at org.hibernate.loader.Loader.list(Loader.java:2364)
    at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:353)
    at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:1873)
    at org.hibernate.internal.AbstractSessionImpl.list(AbstractSessionImpl.java:311)
    at org.hibernate.internal.SQLQueryImpl.list(SQLQueryImpl.java:141)
    at pgpoolbug.BugMain.main(BugMain.java:69)

t-ishii

2016-03-29 16:13

developer   ~0000744

Regarding the relationship with bug152 is not still clear, because I cannot reproduce the problem. I am waiting for a feedback from the reporter.

t-ishii

2016-03-29 21:17

developer   ~0000745

Ok, I think I have made it. Could you please try 3.5 stable tree head?

http://git.postgresql.org/gitweb/?p=pgpool2.git;a=shortlog;h=refs/heads/V3_5_STABLE

eflopez123

2016-03-30 08:53

reporter   ~0000746

Its looking good! My test program keeps happily working... and our big application also starts and works with load balancing.

Thankyou!

t-ishii

2016-03-30 09:14

developer   ~0000747

Thank you so much for cooperation!

Issue History

Date Modified Username Field Change
2016-02-22 14:48 eflopez123 New Issue
2016-02-22 14:48 eflopez123 File Added: conf-and-logfile.txt
2016-02-23 08:20 t-ishii Note Added: 0000647
2016-02-23 08:20 t-ishii Assigned To => t-ishii
2016-02-23 08:20 t-ishii Status new => assigned
2016-02-23 13:41 eflopez123 Note Added: 0000648
2016-02-23 13:44 eflopez123 File Added: pgpoolbug.tgz
2016-02-27 19:51 t-ishii Note Added: 0000649
2016-02-27 20:13 eflopez123 Note Added: 0000650
2016-02-27 20:30 t-ishii View Status private => public
2016-02-27 20:32 t-ishii Note Added: 0000651
2016-02-29 11:27 t-ishii Note Added: 0000652
2016-02-29 12:54 eflopez123 Note Added: 0000653
2016-03-01 09:04 t-ishii Note Added: 0000654
2016-03-01 10:09 eflopez123 Note Added: 0000655
2016-03-02 09:32 t-ishii Note Added: 0000656
2016-03-02 09:37 eflopez123 Note Added: 0000657
2016-03-02 10:16 t-ishii Note Added: 0000658
2016-03-02 11:40 eflopez123 Note Added: 0000659
2016-03-02 11:43 t-ishii Note Added: 0000660
2016-03-02 11:45 eflopez123 Note Added: 0000661
2016-03-02 14:11 t-ishii Note Added: 0000662
2016-03-02 14:22 t-ishii Note Edited: 0000662 View Revisions
2016-03-02 17:17 t-ishii Note Added: 0000663
2016-03-02 17:17 t-ishii File Added: bug167.diff
2016-03-02 17:20 t-ishii Note Edited: 0000663 View Revisions
2016-03-02 17:22 t-ishii Status assigned => feedback
2016-03-03 15:09 t-ishii Note Added: 0000669
2016-03-04 09:16 eflopez123 Note Added: 0000670
2016-03-04 09:16 eflopez123 Status feedback => assigned
2016-03-08 10:25 eflopez123 Note Added: 0000678
2016-03-08 13:08 t-ishii File Added: log-20160308.txt
2016-03-08 13:08 t-ishii Status assigned => feedback
2016-03-10 13:04 t-ishii Note Added: 0000679
2016-03-10 13:14 eflopez123 Note Added: 0000680
2016-03-10 13:14 eflopez123 Status feedback => assigned
2016-03-10 13:51 eflopez123 File Added: debug-20160310.txt
2016-03-10 13:54 eflopez123 Note Added: 0000681
2016-03-10 14:13 eflopez123 Note Added: 0000682
2016-03-10 14:16 t-ishii Note Added: 0000683
2016-03-10 14:16 t-ishii Status assigned => resolved
2016-03-11 12:24 eflopez123 Note Added: 0000684
2016-03-11 12:24 eflopez123 Status resolved => feedback
2016-03-11 12:24 eflopez123 Resolution open => reopened
2016-03-11 16:25 t-ishii Note Added: 0000685
2016-03-14 08:26 eflopez123 Note Added: 0000686
2016-03-14 08:26 eflopez123 Status feedback => assigned
2016-03-14 13:42 t-ishii Note Added: 0000687
2016-03-14 14:17 t-ishii Note Added: 0000688
2016-03-14 14:18 t-ishii Note Edited: 0000688 View Revisions
2016-03-14 15:53 eflopez123 Note Added: 0000689
2016-03-14 16:04 t-ishii Note Added: 0000690
2016-03-15 14:35 t-ishii Note Edited: 0000690 View Revisions
2016-03-24 14:38 t-ishii Note Added: 0000716
2016-03-24 14:39 t-ishii File Added: fix-bug167.diff
2016-03-26 13:59 eflopez123 Note Added: 0000723
2016-03-26 14:00 eflopez123 Note Added: 0000724
2016-03-26 17:14 t-ishii Note Added: 0000725
2016-03-26 17:15 t-ishii Status assigned => feedback
2016-03-28 11:13 t-ishii Note Added: 0000730
2016-03-28 19:05 eflopez123 Note Added: 0000732
2016-03-28 19:05 eflopez123 Status feedback => assigned
2016-03-29 14:42 eflopez123 Note Added: 0000736
2016-03-29 15:02 eflopez123 Note Added: 0000737
2016-03-29 15:11 eflopez123 Note Added: 0000738
2016-03-29 15:32 eflopez123 Note Added: 0000739
2016-03-29 16:02 t-ishii Note Added: 0000741
2016-03-29 16:13 t-ishii Note Added: 0000744
2016-03-29 21:17 t-ishii Note Added: 0000745
2016-03-29 21:18 t-ishii Status assigned => feedback
2016-03-30 08:53 eflopez123 Note Added: 0000746
2016-03-30 08:53 eflopez123 Status feedback => assigned
2016-03-30 09:14 t-ishii Note Added: 0000747
2016-03-30 09:15 t-ishii Status assigned => resolved