View Issue Details

IDProjectCategoryView StatusLast Update
0000190Pgpool-IIBugpublic2016-04-21 12:03
Reportereflopez123Assigned Tot-ishii 
PriorityhighSeveritymajorReproducibilityalways
Status resolvedResolutionopen 
PlatformLinuxOSCentos/RHELOS Version6.7
Product Version3.5.1 
Target Version3.5.1Fixed in Version 
Summary0000190: PgPool hangs in load balance mode, when using JDBC driver and sending empty query.
DescriptionWe'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 ReproduceAfter 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 InformationSample 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
TagsNo tags attached.

Activities

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)
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index 934cc33..19f6b82 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -745,7 +745,7 @@ POOL_STATUS SimpleForwardToFrontend(char kind, POOL_CONNECTION *frontend,
 	/*
 	 * If we received a notification message in master/slave mode,
 	 * other backends will not receive the message.
-	 * So we should skip other nodes otherwise we will hung in pool_read.
+	 * So we should skip other nodes otherwise we will hang in pool_read.
 	 */
 	if (!MASTER_SLAVE || kind != 'A')
 	{
@@ -3233,15 +3233,16 @@ void read_kind_from_backend(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *bac
 
 	if (MASTER_SLAVE)
 	{
-		read_kind_from_one_backend(frontend, backend, (char *)&kind, MASTER_NODE_ID);
-
-			ereport(DEBUG1,
+		ereport(DEBUG1,
 				(errmsg("reading backend data packet kind"),
 				 errdetail("master node id: %d", MASTER_NODE_ID)));
+
+		read_kind_from_one_backend(frontend, backend, (char *)&kind, MASTER_NODE_ID);
+
 		/*
 		 * If we received a notification message in master/slave mode,
 		 * other backends will not receive the message.
-		 * So we should skip other nodes otherwise we will hung in pool_read.
+		 * So we should skip other nodes otherwise we will hang in pool_read.
 		 */
 		if (kind == 'A')
 		{
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 242799e..d937387 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -2490,7 +2490,13 @@ POOL_STATUS ProcessBackendResponse(POOL_CONNECTION *frontend,
 
 			case 'I':	/* EmptyQueryResponse */
 				status = SimpleForwardToFrontend(kind, frontend, backend);
-				if ((REPLICATION || RAW_MODE) && pool_is_doing_extended_query_message())
+				/* Empty query response message should be treated same as
+				 * Command complete message. When we receive the Command
+				 * complete message, we unset the query in progress flag if
+				 * operated in streaming replication mode. So we unset the
+				 * flag as well. See bug 190 for more details.
+				 */
+				if (pool_is_doing_extended_query_message())
 					pool_unset_query_in_progress();
 				break;
 
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!

Issue History

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