0000190: PgPool hangs in load balance mode, when using JDBC driver and sending empty query.

ID	Project	Category	View Status	Date Submitted	Last Update

0000190	Pgpool-II	Bug	public	2016-04-11 14:57	2016-04-21 12:03

Reporter	eflopez123	Assigned To	t-ishii
Priority	high	Severity	major	Reproducibility	always
Status	resolved	Resolution	open
Platform	Linux	OS	Centos/RHEL	OS Version	6.7
Product Version	3.5.1
Target Version	3.5.1

Summary	0000190: PgPool hangs in load balance mode, when using JDBC driver and sending empty query.
Description	We're using hibernate/liquibase for our application database management, and these libraries send various commands to check schema and capabilities. One of these seems to be an empty query, and at the point where its expecting a response nothing happens.
Steps To Reproduce	After extracting the archive, you can execute the program with: java -jar target/emptyquerybug.jar <jdbc url> <username> <password> If need to compile mvn assembly:single will recreate the jar file in the target directory.
Additional Information	Sample output: DriverManager.getConnection("jdbc:postgresql://192.168.205.146:5433/eliasdb?loglevel=2") trying org.postgresql.Driver 15:36:28.555 (1) PostgreSQL 9.4.1208.jre7 15:36:28.562 (1) Trying to establish a protocol version 3 connection to 192.168.205.146:5433 15:36:28.577 (1) Receive Buffer Size is 131768 15:36:28.577 (1) Send Buffer Size is 131768 15:36:28.579 (1) FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2) 15:36:28.591 (1) <=BE AuthenticationReqMD5(salt=ac91807b) 15:36:28.599 (1) FE=> Password(md5digest=md5d70da8c6f739674408af82dc89a21400) 15:36:28.601 (1) <=BE AuthenticationOk 15:36:28.612 (1) <=BE ParameterStatus(application_name = ) 15:36:28.612 (1) <=BE ParameterStatus(client_encoding = UTF8) 15:36:28.612 (1) <=BE ParameterStatus(DateStyle = ISO, DMY) 15:36:28.612 (1) <=BE ParameterStatus(integer_datetimes = on) 15:36:28.612 (1) <=BE ParameterStatus(IntervalStyle = postgres) 15:36:28.612 (1) <=BE ParameterStatus(is_superuser = on) 15:36:28.612 (1) <=BE ParameterStatus(server_encoding = UTF8) 15:36:28.612 (1) <=BE ParameterStatus(server_version = 9.5.1) 15:36:28.613 (1) <=BE ParameterStatus(session_authorization = elias) 15:36:28.613 (1) <=BE ParameterStatus(standard_conforming_strings = on) 15:36:28.613 (1) <=BE ParameterStatus(TimeZone = Australia/Melbourne) 15:36:28.613 (1) <=BE BackendKeyData(pid=39102,ckey=1068716146) 15:36:28.613 (1) <=BE ReadyForQuery(I) 15:36:28.615 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@6e8cf4c6, maxRows=0, fetchSize=0, flags=23 15:36:28.615 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 15:36:28.615 (1) FE=> Bind(stmt=null,portal=null) 15:36:28.620 (1) FE=> Execute(portal=null,limit=1) 15:36:28.621 (1) FE=> Sync 15:36:28.622 (1) <=BE ParseComplete [null] 15:36:28.622 (1) <=BE BindComplete [unnamed] 15:36:28.623 (1) <=BE CommandStatus(SET) 15:36:28.623 (1) <=BE ReadyForQuery(I) 15:36:28.624 (1) compatible = 90400 15:36:28.624 (1) loglevel = 2 15:36:28.624 (1) prepare threshold = 5 15:36:28.626 (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 15:36:28.627 (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 15:36:28.627 (1) integer date/time = true getConnection returning org.postgresql.Driver ***** sending empty statement ********** 15:36:28.640 (1) simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@254989ff, maxRows=0, fetchSize=0, flags=17 15:36:28.653 (1) FE=> Parse(stmt=null,query="",oids={}) 15:36:28.653 (1) FE=> Bind(stmt=null,portal=null) 15:36:28.654 (1) FE=> Describe(portal=null) 15:36:28.654 (1) FE=> Execute(portal=null,limit=0) 15:36:28.654 (1) FE=> Sync 15:36:28.656 (1) <=BE ParseComplete [null] 15:36:28.656 (1) <=BE BindComplete [unnamed] 15:36:28.656 (1) <=BE NoData 15:36:28.656 (1) <=BE EmptyQuery ==================== [root@postgresC pgpool-II]# pgpool -f pgpool.conf -n -d -D 2016-04-11 15:36:14: pid 46418: DEBUG: loading hba configuration 2016-04-11 15:36:14: pid 46418: DETAIL: loading file :"/etc/pgpool-II/pool_hba.conf" for client authentication configuration file 2016-04-11 15:36:14: pid 46418: LOCATION: pool_hba.c:118 2016-04-11 15:36:14: pid 46418: LOG: Backend status file /var/run/pgpool/pgpool_status discarded 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2951 2016-04-11 15:36:14: pid 46418: DEBUG: pool_coninfo_size: num_init_children (120) * max_pool (1) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 2088960 bytes requested for shared memory 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_context.c:109 2016-04-11 15:36:14: pid 46418: DEBUG: ProcessInfo: num_init_children (120) * sizeof(ProcessInfo) (32) = 3840 bytes requested for shared memory 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2822 2016-04-11 15:36:14: pid 46418: DEBUG: Request info are: sizeof(POOL_REQUEST_INFO) 5224 bytes requested for shared memory 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2837 2016-04-11 15:36:14: pid 46418: DEBUG: Recovery management area: sizeof(int) 4 bytes requested for shared memory 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2860 2016-04-11 15:36:14: pid 46418: LOG: Setting up socket for 0.0.0.0:5433 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:797 2016-04-11 15:36:14: pid 46418: LOG: Setting up socket for :::5433 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:797 2016-04-11 15:36:14: pid 46422: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46422: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46421: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46421: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46423: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46423: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46420: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46420: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46424: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46424: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46425: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46425: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46426: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46426: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46419: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46419: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46427: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46427: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46428: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46428: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46429: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46429: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46430: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46430: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46431: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46431: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46432: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46432: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46433: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46433: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46434: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46434: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46435: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46435: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46436: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46436: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46437: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46437: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46438: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46438: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46439: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46439: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46440: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46440: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46442: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46442: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46441: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46441: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46446: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46446: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46447: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46447: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46445: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46445: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46448: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46448: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46444: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46444: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46449: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46449: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46450: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46450: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46451: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46451: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46452: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46452: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46453: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46453: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46454: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46454: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46455: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46455: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46456: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46456: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46457: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46457: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46458: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46458: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46459: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46459: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46460: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46460: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46461: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46461: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46443: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46443: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46462: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46462: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46464: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46464: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46465: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46465: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46466: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46466: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46467: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46467: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46468: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46468: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46469: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46469: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46470: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46470: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46471: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46471: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46472: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46472: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46473: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46473: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46463: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46463: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46474: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46474: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46475: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46475: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46476: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46476: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46477: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46477: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46478: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46478: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46479: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46479: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46480: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46480: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46481: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46481: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46482: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46482: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46483: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46483: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46487: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46487: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46488: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46488: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46486: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46486: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46489: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46489: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46490: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46490: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46491: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46491: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46485: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46485: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46492: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46492: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46493: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46493: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46494: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46494: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46495: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46495: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46496: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46496: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46497: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46497: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46498: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46498: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46484: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46484: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46500: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46500: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46501: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46501: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46502: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46502: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46503: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46503: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46504: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46504: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46505: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46505: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46506: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46506: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46499: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46499: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46507: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46507: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46508: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46508: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46509: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46509: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46510: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46510: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46511: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46511: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46512: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46512: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46513: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46513: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46514: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46514: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46515: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46515: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46519: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46519: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46520: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46520: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46518: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46518: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46521: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46521: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46522: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46522: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46517: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46517: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46516: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46516: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46523: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46523: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46418: LOG: pgpool-II successfully started. version 3.5.1 (ekieboshi) 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:370 2016-04-11 15:36:14: pid 46418: LOG: find_primary_node: checking backend no 0 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2693 2016-04-11 15:36:14: pid 46524: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46524: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46525: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46525: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46526: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46526: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46527: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46527: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46528: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46528: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46529: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46529: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46530: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46530: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46531: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46531: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46532: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46532: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46533: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46533: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46534: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46534: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46535: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46535: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46536: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46536: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46537: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46537: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46538: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46538: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46539: DEBUG: I am PCP child with pid:46539 2016-04-11 15:36:14: pid 46539: LOCATION: pcp_child.c:105 2016-04-11 15:36:14: pid 46540: DEBUG: I am 46540 2016-04-11 15:36:14: pid 46540: LOCATION: pool_worker_child.c:100 2016-04-11 15:36:14: pid 46540: DEBUG: initializing backend status 2016-04-11 15:36:14: pid 46540: LOCATION: child.c:1759 2016-04-11 15:36:14: pid 46418: DEBUG: pool_read: read 13 bytes from backend 0 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:190 2016-04-11 15:36:14: pid 46418: DEBUG: authenticate kind = 5 2016-04-11 15:36:14: pid 46418: LOCATION: child.c:1376 2016-04-11 15:36:14: pid 46418: DEBUG: pool_write: to backend: kind:p 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:431 2016-04-11 15:36:14: pid 46418: DEBUG: pool_read: read 330 bytes from backend 0 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:190 2016-04-11 15:36:14: pid 46418: DEBUG: authenticate kind = 0 2016-04-11 15:36:14: pid 46418: LOCATION: child.c:1376 2016-04-11 15:36:14: pid 46418: DEBUG: authenticate backend: key data received 2016-04-11 15:36:14: pid 46418: LOCATION: child.c:1466 2016-04-11 15:36:14: pid 46418: DEBUG: authenticate backend: transaction state: I 2016-04-11 15:36:14: pid 46418: LOCATION: child.c:1500 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()" 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:1936 2016-04-11 15:36:14: pid 46418: DEBUG: pool_write: to backend: kind:Q 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:431 2016-04-11 15:36:14: pid 46418: DEBUG: pool_read: read 75 bytes from backend 0 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:190 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: kind: 'T' 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2149 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2260 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: row description: num_fileds: 1 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2282 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: kind: 'D' 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2149 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: received DATA ROW ('D') 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2337 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: kind: 'C' 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2149 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2219 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: kind: 'Z' 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2149 2016-04-11 15:36:14: pid 46418: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-04-11 15:36:14: pid 46418: LOCATION: pool_process_query.c:2212 2016-04-11 15:36:14: pid 46418: DEBUG: pool_write: to backend: kind:X 2016-04-11 15:36:14: pid 46418: LOCATION: pool_stream.c:431 2016-04-11 15:36:14: pid 46418: LOG: find_primary_node: primary node id is 0 2016-04-11 15:36:14: pid 46418: LOCATION: pgpool_main.c:2723 2016-04-11 15:36:28: pid 46538: DEBUG: I am 46538 accept fd 7 2016-04-11 15:36:28: pid 46538: LOCATION: child.c:2097 2016-04-11 15:36:28: pid 46538: LOG: new connection received 2016-04-11 15:36:28: pid 46538: DETAIL: connecting host=192.168.205.1 port=55921 2016-04-11 15:36:28: pid 46538: LOCATION: child.c:2110 2016-04-11 15:36:28: pid 46538: DEBUG: reading startup packet 2016-04-11 15:36:28: pid 46538: DETAIL: Protocol Major: 3 Minor: 0 database: eliasdb user: elias 2016-04-11 15:36:28: pid 46538: LOCATION: child.c:614 2016-04-11 15:36:28: pid 46538: DEBUG: creating new connection to backend 2016-04-11 15:36:28: pid 46538: DETAIL: connecting 0 backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_connection_pool.c:830 2016-04-11 15:36:28: pid 46538: DEBUG: creating new connection to backend 2016-04-11 15:36:28: pid 46538: DETAIL: connecting 1 backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_connection_pool.c:830 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 13 bytes from backend 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 13 bytes from backend 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 0 length: 12 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1107 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 1 length: 12 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1126 2016-04-11 15:36:28: pid 46538: DEBUG: authentication backend 2016-04-11 15:36:28: pid 46538: DETAIL: auth kind:5 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:142 2016-04-11 15:36:28: pid 46538: DEBUG: authentication backend 2016-04-11 15:36:28: pid 46538: DETAIL: trying md5 authentication 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:239 2016-04-11 15:36:28: pid 46538: DEBUG: performing md5 authentication 2016-04-11 15:36:28: pid 46538: DETAIL: DB node id: 0 salt: d2303db4 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:855 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:p 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 331 bytes from backend 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: authentication backend 2016-04-11 15:36:28: pid 46538: DETAIL: trying md5 authentication 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:239 2016-04-11 15:36:28: pid 46538: DEBUG: performing md5 authentication 2016-04-11 15:36:28: pid 46538: DETAIL: DB node id: 1 salt: 91ae8149 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:855 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:p 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 331 bytes from backend 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 22 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 22 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"application_name" value:"" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"application_name" value:"" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"client_encoding" value:"UTF8" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"client_encoding" value:"UTF8" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 23 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 23 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"DateStyle" value:"ISO, DMY" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"DateStyle" value:"ISO, DMY" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"integer_datetimes" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"integer_datetimes" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 27 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 27 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"IntervalStyle" value:"postgres" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"IntervalStyle" value:"postgres" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 20 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 20 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"is_superuser" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"is_superuser" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"server_encoding" value:"UTF8" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"server_encoding" value:"UTF8" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 25 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"server_version" value:"9.5.1" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"server_version" value:"9.5.1" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 32 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 32 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"session_authorization" value:"elias" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"session_authorization" value:"elias" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 35 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 35 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"standard_conforming_strings" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"standard_conforming_strings" value:"on" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 0 length: 33 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1161 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: master slot: 1 length: 33 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1172 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 name:"TimeZone" value:"Australia/Melbourne" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: process parameter status 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 name:"TimeZone" value:"Australia/Melbourne" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:921 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 0 length: 12 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1107 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 1 length: 12 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1126 2016-04-11 15:36:28: pid 46538: DEBUG: authentication backend 2016-04-11 15:36:28: pid 46538: DETAIL: cp->info[i]:0x7f1eae536c00 pid:61493 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:391 2016-04-11 15:36:28: pid 46538: DEBUG: authentication backend 2016-04-11 15:36:28: pid 46538: DETAIL: cp->info[i]:0x7f1eae536c88 pid:39102 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:391 2016-04-11 15:36:28: pid 46538: DEBUG: sending backend key data 2016-04-11 15:36:28: pid 46538: DETAIL: send pid 39102 to frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:519 2016-04-11 15:36:28: pid 46538: DEBUG: selecting load balance node 2016-04-11 15:36:28: pid 46538: DETAIL: selected backend id is 1 2016-04-11 15:36:28: pid 46538: LOCATION: child.c:1720 2016-04-11 15:36:28: pid 46538: DEBUG: initializing session context 2016-04-11 15:36:28: pid 46538: DETAIL: selected load balancing node: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:90 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing transaction isolation. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:723 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing writing transaction. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:557 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing failed transaction. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:586 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing failed transaction. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:616 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing skip reading from backends. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:242 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing ignore till sync. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:302 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 0 doing extended query: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 of 2 kind = 'Z' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = 'Z' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'Z'(5a) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: Ready For Query received 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2442 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing ignore till sync. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:302 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 0 doing extended query: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 0 doing extended query: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 0 doing extended query: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 0 length: 5 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1107 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 1 length: 5 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1126 2016-04-11 15:36:28: pid 46538: DEBUG: processing ReadyForQuery 2016-04-11 15:36:28: pid 46538: DETAIL: transaction state ' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1612 2016-04-11 15:36:28: pid 46538: DEBUG: processing ReadyForQuery 2016-04-11 15:36:28: pid 46538: DETAIL: transaction state 'I'(49) 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1612 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'P'(50) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: Parse: statement name <> 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:817 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: DEBUG: decide where to send the queries 2016-04-11 15:36:28: pid 46538: DETAIL: destination = 3 for query= "SET extra_float_digits = 3" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:370 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 0 backend pid: 61493 statement: Parse: SET extra_float_digits = 3 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:P 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: Parse: SET extra_float_digits = 3 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:P 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557a40 kind: P name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'B'(42) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: Bind: waiting for master completing the query 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1237 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 0 backend pid: 61493 statement: B message 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:B 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: B message 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:B 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557ad8 kind: B name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'E'(45) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 0 backend pid: 61493 statement: Execute: SET extra_float_digits = 3 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:E 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: Execute: SET extra_float_digits = 3 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:E 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:H 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:H 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 19 bytes from backend 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 of 2 kind = '1' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 19 bytes from backend 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = '1' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind '1'(31) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557ad8 kind: B name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: adding sent message to list 2016-04-11 15:36:28: pid 46538: DETAIL: adding exactly same message is prohibited 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:493 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:1 length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting command success. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:733 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 of 2 kind = '2' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = '2' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind '2'(32) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:2 length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting command success. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:733 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 of 2 kind = 'C' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = 'C' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'C'(43) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting command success. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:733 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'S'(53) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:S 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:S 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 6 bytes from backend 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:0 of 2 kind = 'Z' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 6 bytes from backend 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = 'Z' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'Z'(5a) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: Ready For Query received 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2442 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing ignore till sync. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:302 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 0 length: 5 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1107 2016-04-11 15:36:28: pid 46538: DEBUG: reading message length 2016-04-11 15:36:28: pid 46538: DETAIL: slot: 1 length: 5 2016-04-11 15:36:28: pid 46538: LOCATION: pool_auth.c:1126 2016-04-11 15:36:28: pid 46538: DEBUG: processing ReadyForQuery 2016-04-11 15:36:28: pid 46538: DETAIL: transaction state 'I'(49) 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1612 2016-04-11 15:36:28: pid 46538: DEBUG: processing ReadyForQuery 2016-04-11 15:36:28: pid 46538: DETAIL: transaction state 'I'(49) 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1612 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'P'(50) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: Parse: statement name <> 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:817 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: DEBUG: checking if query has INSERT INTO, FOR SHARE or FOR UPDATE 2016-04-11 15:36:28: pid 46538: DETAIL: result = 0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_select_walker.c:155 2016-04-11 15:36:28: pid 46538: DEBUG: decide where to send the queries 2016-04-11 15:36:28: pid 46538: DETAIL: destination = 2 for query= "" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:370 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: Parse: 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:P 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557b58 kind: P name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: adding sent message to list 2016-04-11 15:36:28: pid 46538: DETAIL: prepared statement "" already exists 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:508 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_sent_message_destroy: sent message: address: 2557a40 kind: P name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: checking if query context can be safely destroyed 2016-04-11 15:36:28: pid 46538: DETAIL: query context 0x2559e10 is still used 2 times. query:"SET extra_float_digits = 3" 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:865 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'B'(42) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: Bind: waiting for master completing the query 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1237 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: B message 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:B 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557a40 kind: B name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: adding sent message to list 2016-04-11 15:36:28: pid 46538: DETAIL: portal "" already exists 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:504 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_sent_message_destroy: sent message: address: 2557ad8 kind: B name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'D'(44) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: Describe: waiting for master completing the query 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:1310 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: D message 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:D 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: session context: unsetting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:211 2016-04-11 15:36:28: pid 46538: DEBUG: processing frontend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'E'(45) from frontend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2188 2016-04-11 15:36:28: pid 46538: DEBUG: session context: clearing doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:272 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting doing extended query messaging. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:261 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting query in progress. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:200 2016-04-11 15:36:28: pid 46538: LOG: DB node id: 1 backend pid: 39102 statement: Execute: 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2959 2016-04-11 15:36:28: pid 46538: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_query_context.c:854 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:E 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_write: to backend: kind:H 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:431 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: pool_read: read 20 bytes from backend 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_stream.c:190 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = '1' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind '1'(31) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: called by pool_add_sent_message: sent message: address: 2557a40 kind: B name: == 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:428 2016-04-11 15:36:28: pid 46538: DEBUG: adding sent message to list 2016-04-11 15:36:28: pid 46538: DETAIL: adding exactly same message is prohibited 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:493 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:1 length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting command success. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:733 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = '2' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind '2'(32) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:2 length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: session context: setting command success. DONE 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:733 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = 'n' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'n'(6e) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:n length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: master node id: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3240 2016-04-11 15:36:28: pid 46538: DEBUG: reading backend data packet kind 2016-04-11 15:36:28: pid 46538: DETAIL: backend:1 of 2 kind = 'I' 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3348 2016-04-11 15:36:28: pid 46538: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:3364 2016-04-11 15:36:28: pid 46538: DEBUG: processing backend response 2016-04-11 15:36:28: pid 46538: DETAIL: received kind 'I'(49) from backend 2016-04-11 15:36:28: pid 46538: LOCATION: pool_proto_modules.c:2424 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961 2016-04-11 15:36:28: pid 46538: DEBUG: SimpleForwardToFrontend: packet:I length:0 2016-04-11 15:36:28: pid 46538: LOCATION: pool_process_query.c:792 2016-04-11 15:36:28: pid 46538: DEBUG: pool_use_sync_map: we cannot use sync map because STREAM: 1 query in progress: 1 doing extended query: 1 2016-04-11 15:36:28: pid 46538: LOCATION: pool_session_context.c:961
Tags	No tags attached.

eflopez123 2016-04-11 14:57 reporter	emptyquerybug.tgz (638,944 bytes)

t-ishii 2016-04-11 15:18 developer ~0000771	I have updated the pgpool-II version to 3.5.1 (Mantis lacked 3.5.1 version and I have just added). If it's different, please let me know.

eflopez123 2016-04-11 15:22 reporter ~0000772	This is correct, I am using the SRPM from the pgpool repo, built against postgresql95-devel from pgpdg.

t-ishii 2016-04-12 08:29 developer ~0000777	I tried your program but failed: t-ishii@localhost: LANG=C ls -l target/ total 632 drwxr-xr-x 2 t-ishii t-ishii 4096 Apr 11 14:55 archive-tmp -rw-r--r-- 1 t-ishii t-ishii 639751 Apr 12 08:21 emptyquerybug.jar t-ishii@localhost: LANG=C java -jar target/emptyquerybug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii "" Error: Could not find or load main class pgpoolbug.EmptyQueryBug I tried also recompile using mvn but I got same errors.

eflopez123 2016-04-12 08:52 reporter	emptyquerybug2.tgz (642,440 bytes)

eflopez123 2016-04-12 08:56 reporter ~0000778	I misunderstood how to use the mvn assembly plugin. If need to recompile, need to use "mvn clean compile assembly:single" I have attached a new version with a working jar file. Also, after some more testing it appears that load_balance mode has no effect and it fails regardless of this setting. However if I switch master_slave mode off then it works.

t-ishii 2016-04-12 13:08 developer ~0000779	Thank you for your prompt reply. I will try the new test program.

t-ishii 2016-04-12 13:34 developer ~0000780	I was able to reproduce the problem. Thanks.

t-ishii 2016-04-13 08:56 developer	bug190fix.diff (2,220 bytes) bug190fix.diff (2,220 bytes)

t-ishii 2016-04-13 08:58 developer ~0000781	Attached patch (bug190fix.diff) should solve the problem. Could you please try it out?

eflopez123 2016-04-13 14:59 reporter ~0000782	Thankyou! This works in both the big application and the test case.

t-ishii 2016-04-13 16:48 developer ~0000783	Thank you for your cooperation!

Date Modified	Username	Field	Change
2016-04-11 14:57	eflopez123	New Issue
2016-04-11 14:57	eflopez123	File Added: emptyquerybug.tgz
2016-04-11 15:05	t-ishii	Assigned To	=> t-ishii
2016-04-11 15:05	t-ishii	Status	new => assigned
2016-04-11 15:18	t-ishii	Note Added: 0000771
2016-04-11 15:18	t-ishii	Product Version	=> 3.5.1
2016-04-11 15:18	t-ishii	Target Version	=> 3.5.1
2016-04-11 15:22	eflopez123	Note Added: 0000772
2016-04-12 08:29	t-ishii	Note Added: 0000777
2016-04-12 08:52	eflopez123	File Added: emptyquerybug2.tgz
2016-04-12 08:56	eflopez123	Note Added: 0000778
2016-04-12 13:08	t-ishii	Note Added: 0000779
2016-04-12 13:34	t-ishii	Note Added: 0000780
2016-04-13 08:56	t-ishii	File Added: bug190fix.diff
2016-04-13 08:56	t-ishii	Status	assigned => feedback
2016-04-13 08:58	t-ishii	Note Added: 0000781
2016-04-13 14:59	eflopez123	Note Added: 0000782
2016-04-13 14:59	eflopez123	Status	feedback => assigned
2016-04-13 16:48	t-ishii	Note Added: 0000783
2016-04-13 16:49	t-ishii	Status	assigned => resolved

View Issue Details

Activities

Issue History