View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000167 | Pgpool-II | Bug | public | 2016-02-22 14:48 | 2016-03-30 09:15 |
| Reporter | eflopez123 | Assigned To | t-ishii | ||
| Priority | normal | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | reopened | ||
| Platform | Linux | OS | Centos | OS Version | Centos 6.7 |
| Summary | 0000167: PgPool does not return during Hibernate initialisation, stuck on "Parsing" | ||||
| Description | When starting our application, which uses Hibernate and c3p0, pgPool 3.5.0 appears to get stuck at the parsing during a query. This happens when using load balance mode, but turning off load balance mode it appears to work. This problem is not present in 3.4.3 | ||||
| Steps To Reproduce | Difficult to provide a small test case, however I've provided the logs and our pgpool.conf | ||||
| Tags | No tags attached. | ||||
|
|
|
|
|
Hard to chase the problem if it cannot be reproduced here. Anyway, can you provide the log with debug mode enabled? |
|
|
Thankyou, I've produced a small test case which I've attached. It requires Apache maven to compile and run. In the archive is 'eliasdb.sql' which is a pg_dump of the database I used. Compile: mvn compile Run: mvn exec:java -Dexec.mainClass="pgpoolbug.SimpleEntityMain" You can edit main/resources/hibernate.cfg.xml to change connection parameters. It needs to be recompiled if this is changed. When working, it should print out at the end: Hibernate: select simpleenti0_.simple_entity_id as simple_e1_0_, simpleenti0_.simple_entity_name as simple_e2_0_ from simple_entity simpleenti0_ Hello: SimpleEntity{simple_name_id=1, simple_name='hello'} Hello: SimpleEntity{simple_name_id=2, simple_name='hello 2'} Finished Instead it waits for a response from pgPool which appears to be stuck on "Parse:". I've set debug_level to 99 but there doesn't appear to be much output: root@postgresC log]# cat pgpool-II-95.log 2016-02-23 23:35:48: pid 17967: LOG: Setting up socket for 0.0.0.0:5433 2016-02-23 23:35:48: pid 17967: LOG: Setting up socket for :::5433 2016-02-23 23:35:48: pid 17967: LOG: pgpool-II successfully started. version 3.5.0 (ekieboshi) 2016-02-23 23:35:48: pid 17967: LOG: find_primary_node: checking backend no 0 2016-02-23 23:35:48: pid 17967: LOG: find_primary_node: primary node id is 0 2016-02-23 23:37:04: pid 18083: LOG: new connection received 2016-02-23 23:37:04: pid 18083: DETAIL: connecting host=192.168.205.1 port=62047 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: SET extra_float_digits = 3 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Parse: SET extra_float_digits = 3 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: B message 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: B message 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Execute: SET extra_float_digits = 3 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Execute: SET extra_float_digits = 3 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: BEGIN 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Parse: BEGIN 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: B message 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: B message 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Execute: BEGIN 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 1 backend pid: 71990 statement: Execute: BEGIN 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace' 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog' 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog' 2016-02-23 23:37:04: pid 18083: LOG: DB node id: 0 backend pid: 100182 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast' [root@postgresC log]# |
|
|
|
|
|
I couldn't download the tar ball. Not sure but I suspect it is related the view status is set "private". Can we set to public? |
|
|
Ok please set it to public. |
|
|
I can now download the file. Will look at it tomorrow. |
|
|
Unfortunately, I got this while executing "mvn exec:java -Dexec.mainClass="pgpoolbug.SimpleEntityMain" [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 31.285s [INFO] Finished at: Mon Feb 29 11:23:25 JST 2016 [INFO] Final Memory: 11M/239M [INFO] ------------------------------------------------------------------------ [ERROR] Failed to execute goal org.codehaus.mojo:exec-maven-plugin:1.3.2:java (default-cli) on project pgpoolbug: An exception occured while executing the Java class. null: InvocationTargetException: ExceptionInInitializerError: org/postgresql/Driver : Unsupported major.minor version 52.0 -> [Help 1] |
|
|
Thankyou for looking into it, This error is probably due to a java version conflict. I used java 1.8 and this seemed to work without problems. Let me know which version of java you are using and I'll try and make a version that is compatible. |
|
|
java version "1.7.0_95" OpenJDK Runtime Environment (IcedTea 2.6.4) (7u95-2.6.4-0ubuntu0.14.04.1) OpenJDK 64-Bit Server VM (build 24.95-b01, mixed mode) |
|
|
Hello, I used the postgresql jdbc driver compiled for 1.8. If you edit the pom.xml file and change the "9.4-1202-jdbc42" in the dependencies section to "9.4-1202-jdbc41" it should use the 1.7 driver. |
|
|
Thanks. I succeeded in reproducing the problem. It will take a while to find the cause... |
|
|
Thankyou. |
|
|
Is it possible to take JDBC driver debug log which produces protocol message log. I mean "org.postgresql.Driver.DEBUG" here. |
|
|
Yes, in the src/main/resources/hibernate.cfg.xml, add "?loglevel=2". then recompile with mvn compile, and then run it again. It should spit out things to stdout: INFO: HHH000115: Hibernate connection pool size: 10 (min=1) 13:38:24.855 (1) PostgreSQL 9.4 JDBC4.2 (build 1202) 13:38:24.862 (1) Trying to establish a protocol version 3 connection to 192.168.205.146:5433 13:38:24.871 (1) Receive Buffer Size is 131768 13:38:24.871 (1) Send Buffer Size is 131768 13:38:24.874 (1) FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2) 13:38:24.890 (1) <=BE AuthenticationReqMD5(salt=1beb96a3) 13:38:24.901 (1) FE=> Password(md5digest=md5a76dd4c29cbaeecc07d303eafb3cd597) 13:38:24.903 (1) <=BE AuthenticationOk 13:38:24.910 (1) <=BE ParameterStatus(application_name = ) 13:38:24.910 (1) <=BE ParameterStatus(client_encoding = UTF8) 13:38:24.911 (1) <=BE ParameterStatus(DateStyle = ISO, DMY) 13:38:24.911 (1) <=BE ParameterStatus(integer_datetimes = on) 13:38:24.911 (1) <=BE ParameterStatus(IntervalStyle = postgres) 13:38:24.911 (1) <=BE ParameterStatus(is_superuser = on) 13:38:24.911 (1) <=BE ParameterStatus(server_encoding = UTF8) 13:38:24.911 (1) <=BE ParameterStatus(server_version = 9.5.1) 13:38:24.911 (1) <=BE ParameterStatus(session_authorization = elias) 13:38:24.911 (1) <=BE ParameterStatus(standard_conforming_strings = on) 13:38:24.911 (1) <=BE ParameterStatus(TimeZone = Australia/Melbourne) 13:38:24.911 (1) <=BE BackendKeyData(pid=48250,ckey=1183488946) 13:38:24.911 (1) <=BE ReadyForQuery(I) 13:38:24.913 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@5579bb86, maxRows=0, fetchSize=0, flags=23 13:38:24.914 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 13:38:24.914 (1) FE=> Bind(stmt=null,portal=null) 13:38:24.914 (1) FE=> Execute(portal=null,limit=1) 13:38:24.914 (1) FE=> Sync 13:38:24.916 (1) <=BE ParseComplete [null] 13:38:24.916 (1) <=BE BindComplete [unnamed] 13:38:24.916 (1) <=BE CommandStatus(SET) 13:38:24.916 (1) <=BE ReadyForQuery(I) 13:38:24.917 (1) compatible = 90400 13:38:24.917 (1) loglevel = 2 13:38:24.917 (1) prepare threshold = 5 13:38:24.919 (1) types using binary send = TIMESTAMPTZ,UUID,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY 13:38:24.920 (1) types using binary receive = TIMESTAMPTZ,UUID,INT2_ARRAY,INT4_ARRAY,BYTEA,TEXT_ARRAY,TIMETZ,INT8,INT2,INT4,VARCHAR_ARRAY,INT8_ARRAY,POINT,DATE,TIMESTAMP,TIME,BOX,FLOAT4,FLOAT8,FLOAT4_ARRAY,FLOAT8_ARRAY 13:38:24.920 (1) integer date/time = true 13:38:24.946 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@7181ae3f, maxRows=0, fetchSize=0, flags=1 13:38:24.947 (1) FE=> Parse(stmt=null,query="BEGIN",oids={}) 13:38:24.947 (1) FE=> Bind(stmt=null,portal=null) 13:38:24.947 (1) FE=> Execute(portal=null,limit=0) 13:38:24.948 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={}) 13:38:24.948 (1) FE=> Bind(stmt=null,portal=null) 13:38:24.948 (1) FE=> Describe(portal=null) 13:38:24.948 (1) FE=> Execute(portal=null,limit=0) 13:38:24.948 (1) FE=> Sync |
|
|
Thanks. It helps me a lot. |
|
|
No problem. Oops I didn't specify it needs to be added to the driver URL, but I'm sure you're familiar with it already if you've dealt with jdbc and postgres before. eg: jdbc:postgresql://192.168.205.146:5433/eliasdb?loglevel=2 |
|
|
Just for a record, this is the log when connected to PostgreSQL: INFO: HHH000115: Hibernate connection pool size: 10 (min=1) 14:04:14.826 (1) PostgreSQL 9.4 JDBC4.1 (build 1202) 14:04:14.833 (1) Trying to establish a protocol version 3 connection to localhost:11002 14:04:14.847 (1) Receive Buffer Size is 530904 14:04:14.847 (1) Send Buffer Size is 1313280 14:04:14.850 (1) FE=> StartupPacket(user=t-ishii, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Asia/Tokyo, extra_float_digits=2) 14:04:14.851 (1) <=BE AuthenticationOk 14:04:14.861 (1) <=BE ParameterStatus(application_name = ) 14:04:14.862 (1) <=BE ParameterStatus(client_encoding = UTF8) 14:04:14.862 (1) <=BE ParameterStatus(DateStyle = ISO, MDY) 14:04:14.862 (1) <=BE ParameterStatus(integer_datetimes = on) 14:04:14.862 (1) <=BE ParameterStatus(IntervalStyle = postgres) 14:04:14.862 (1) <=BE ParameterStatus(is_superuser = on) 14:04:14.862 (1) <=BE ParameterStatus(server_encoding = UTF8) 14:04:14.862 (1) <=BE ParameterStatus(server_version = 9.5.0) 14:04:14.862 (1) <=BE ParameterStatus(session_authorization = t-ishii) 14:04:14.862 (1) <=BE ParameterStatus(standard_conforming_strings = on) 14:04:14.862 (1) <=BE ParameterStatus(TimeZone = Asia/Tokyo) 14:04:14.862 (1) <=BE BackendKeyData(pid=16201,ckey=1582227834) 14:04:14.862 (1) <=BE ReadyForQuery(I) 14:04:14.865 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@5591a832, maxRows=0, fetchSize=0, flags=23 14:04:14.866 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 14:04:14.866 (1) FE=> Bind(stmt=null,portal=null) 14:04:14.866 (1) FE=> Execute(portal=null,limit=1) 14:04:14.866 (1) FE=> Sync 14:04:14.867 (1) <=BE ParseComplete [null] 14:04:14.867 (1) <=BE BindComplete [unnamed] 14:04:14.867 (1) <=BE CommandStatus(SET) 14:04:14.867 (1) <=BE ReadyForQuery(I) 14:04:14.867 (1) compatible = 90400 14:04:14.867 (1) loglevel = 2 14:04:14.867 (1) prepare threshold = 5 14:04:14.869 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 14:04:14.870 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 14:04:14.870 (1) integer date/time = true 14:04:14.908 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@438c0862, maxRows=0, fetchSize=0, flags=1 14:04:14.909 (1) FE=> Parse(stmt=null,query="BEGIN",oids={}) 14:04:14.909 (1) FE=> Bind(stmt=null,portal=null) 14:04:14.909 (1) FE=> Execute(portal=null,limit=0) 14:04:14.909 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={}) 14:04:14.910 (1) FE=> Bind(stmt=null,portal=null) 14:04:14.910 (1) FE=> Describe(portal=null) 14:04:14.910 (1) FE=> Execute(portal=null,limit=0) 14:04:14.910 (1) FE=> Sync 14:04:14.913 (1) <=BE ParseComplete [null] 14:04:14.913 (1) <=BE BindComplete [unnamed] 14:04:14.913 (1) <=BE CommandStatus(BEGIN) 14:04:14.913 (1) <=BE ParseComplete [null] 14:04:14.913 (1) <=BE BindComplete [unnamed] 14:04:14.913 (1) <=BE RowDescription(2) 14:04:14.913 (1) Field(,NAME,64,T) 14:04:14.913 (1) Field(,OID,4,T) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=7) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=12) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.914 (1) <=BE DataRow(len=9) 14:04:14.914 (1) <=BE DataRow(len=6) 14:04:14.915 (1) <=BE DataRow(len=5) 14:04:14.915 (1) <=BE DataRow(len=5) 14:04:14.915 (1) <=BE DataRow(len=5) 14:04:14.915 (1) <=BE DataRow(len=5) 14:04:14.915 (1) <=BE DataRow(len=11) 14:04:14.915 (1) <=BE DataRow(len=9) [snip] |
|
|
Ok, I have created a patch against V3.5 stable tree to fix the problem. Can you please try it out? It appeared that pgpool-II is confused by the particular sequence of messages generated by the application and tried to read from a PostgreSQL server which will not response because no query was sent to it. |
|
|
|
|
|
I have modified the fix attached here to deal with bug 168, which shares the necessary changes and committed to 3.5 stable tree. Please grab 3.5 stable head and try. |
|
|
Thankyou, I hope to get a chance to look at this early next week. |
|
|
hello, I've tried the version from the stable branch (ie git clone git://git.postgresql.org/git/pgpool2.git --branch V3_5_STABLE) , but I am still have the same problems. |
|
|
|
|
|
When I fixed it and pushed I tried again your test case and it seems the Java application hangs beyond the point you reported. From the log it seems it was caused by some reasons which are not related to pgpool-II. So I cannot confirm you report about the hang up. Can you please take a look at the attached log (log-20160308.txt)? |
|
|
Thanks, It looks like hibernate is upset because the table its looking for is missing. However, if its gotten to that point it means its querying the database and getting results (in this case errors..) so I would say its working. I will try again, maybe I did something wrong. |
|
|
|
|
|
I double checked things and I am still getting the problem. I attached the debug output from both pgpool and the postgresql driver. |
|
|
ok.. I've tried it a few more times. I noticed that my postgres VMs were out of time sync, so I fixed that in case that was a factor. It also seems maybe I was too quick to run the test program. This time I waited until I saw: 2016-03-10 16:12:09: pid 2560: DEBUG: do_query: received READY FOR QUERY ('Z') in the debugging output and now the test program seems to work. Thankyou :) |
|
|
Thank you for the quick response. Glad to hear that! |
|
|
Its started happening again, though this time it appears to be intermittent. Sometimes it works, sometimes it doesn't. Can still use the same test program, try and run a few times. Sometimes it works, then run again and it will block. There doesn't seem to be a pattern to it. |
|
|
Can you provide a test program which hibernte is not upset about? I want to run the program repeatedly so that I can reproduce the problem. |
|
|
I have produced a slightly more user friendly program, and packaged in a single jar (to avoid the need for maven), and can just run on command line. Unfortunately its rather large because of the hibernate dependencies so I was unable to attach it to this issue so I have uploaded it to my webhost wget -c http://eliaslopez.net/hidden/pgpoolbug.jar As the problem only presents itself during the hibernate initialisation, all the program does is run a select query after hibernate initialises and exits, and you can supply the connection details on the command line. usage: java -jar pgpoolbug.jar <jdbc url> <username> <password> eg: java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5432/eliasdb?loglevel2 elias foobar When the problem happens, the program locks up at this output: Mar 14, 2016 10:23:31 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure INFO: HHH000115: Hibernate connection pool size: 10 (min=1) waiting for a response from pgpool. When it works, when you see that output line, you can also see debug information in the pgpool console as hibernate is querying the database schema etc and eventually the program will return: Mar 14, 2016 10:24:30 AM org.hibernate.dialect.Dialect <init> INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL9Dialect Mar 14, 2016 10:24:30 AM org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException Mar 14, 2016 10:24:30 AM org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService INFO: HHH000399: Using default transaction strategy (direct JDBC transactions) Mar 14, 2016 10:24:30 AM org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory <init> INFO: HHH000397: Using ASTQueryTranslatorFactory Mar 14, 2016 10:24:30 AM org.hibernate.tool.hbm2ddl.SchemaValidator validate INFO: HHH000229: Running schema validator Mar 14, 2016 10:24:30 AM org.hibernate.tool.hbm2ddl.SchemaValidator validate INFO: HHH000102: Fetching database metadata Opening Session Received Result: If you can see this it worked Finished and should exit with 0 status. If theres any errors or connection problems it should exit with 1. Let me know if you need anymore information. |
|
|
Thanks for the new test program. I will try and get back to you. |
|
|
Even if ?loglevel2 is added, no protocol level log is shown. Am I missing something? |
|
|
My apologies, I made a typo, the JDBC driver parameter is loglevel=2. |
|
|
Thanks. I should have noticed myself. Just for a record, here is the log: java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii "" t-ishii@localhost: LANG=C java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii "" Initialising Hibernate Mar 14, 2016 4:05:38 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final} Mar 14, 2016 4:05:39 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {4.3.4.Final} Mar 14, 2016 4:05:39 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Mar 14, 2016 4:05:39 PM org.hibernate.cfg.Environment buildBytecodeProvider INFO: HHH000021: Bytecode provider name : javassist Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!) Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://localhost:11000/test?loglevel=2] Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000046: Connection properties: {user=t-ishii, password=****} Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000006: Autocommit mode: false Mar 14, 2016 4:05:39 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure INFO: HHH000115: Hibernate connection pool size: 10 (min=1) 16:05:39.168 (1) PostgreSQL 9.4 JDBC4.1 (build 1202) 16:05:39.175 (1) Trying to establish a protocol version 3 connection to localhost:11000 16:05:39.189 (1) Receive Buffer Size is 530904 16:05:39.189 (1) Send Buffer Size is 1313280 16:05:39.192 (1) FE=> StartupPacket(user=t-ishii, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Asia/Tokyo, extra_float_digits=2) 16:05:39.197 (1) <=BE AuthenticationOk 16:05:39.205 (1) <=BE ParameterStatus(application_name = ) 16:05:39.205 (1) <=BE ParameterStatus(client_encoding = UTF8) 16:05:39.206 (1) <=BE ParameterStatus(DateStyle = ISO, MDY) 16:05:39.206 (1) <=BE ParameterStatus(integer_datetimes = on) 16:05:39.206 (1) <=BE ParameterStatus(IntervalStyle = postgres) 16:05:39.206 (1) <=BE ParameterStatus(is_superuser = on) 16:05:39.206 (1) <=BE ParameterStatus(server_encoding = UTF8) 16:05:39.206 (1) <=BE ParameterStatus(server_version = 9.5.0) 16:05:39.206 (1) <=BE ParameterStatus(session_authorization = t-ishii) 16:05:39.206 (1) <=BE ParameterStatus(standard_conforming_strings = on) 16:05:39.206 (1) <=BE ParameterStatus(TimeZone = Asia/Tokyo) 16:05:39.206 (1) <=BE BackendKeyData(pid=28624,ckey=525395529) 16:05:39.207 (1) <=BE ReadyForQuery(I) 16:05:39.210 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@3680bc43, maxRows=0, fetchSize=0, flags=23 16:05:39.211 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 16:05:39.211 (1) FE=> Bind(stmt=null,portal=null) 16:05:39.211 (1) FE=> Execute(portal=null,limit=1) 16:05:39.211 (1) FE=> Sync 16:05:39.212 (1) <=BE ParseComplete [null] 16:05:39.213 (1) <=BE BindComplete [unnamed] 16:05:39.213 (1) <=BE CommandStatus(SET) 16:05:39.213 (1) <=BE ReadyForQuery(I) 16:05:39.214 (1) compatible = 90400 16:05:39.214 (1) loglevel = 2 16:05:39.214 (1) prepare threshold = 5 16:05:39.216 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 16:05:39.218 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 16:05:39.218 (1) integer date/time = true 16:05:39.248 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@609acf2c, maxRows=0, fetchSize=0, flags=1 16:05:39.248 (1) FE=> Parse(stmt=null,query="BEGIN",oids={}) 16:05:39.248 (1) FE=> Bind(stmt=null,portal=null) 16:05:39.248 (1) FE=> Execute(portal=null,limit=0) 16:05:39.248 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={}) 16:05:39.248 (1) FE=> Bind(stmt=null,portal=null) 16:05:39.249 (1) FE=> Describe(portal=null) 16:05:39.249 (1) FE=> Execute(portal=null,limit=0) 16:05:39.249 (1) FE=> Sync [hang] |
|
|
With attached patch (fix-bug167.diff, should be applied to 3.5_STABLE head), I have successfully run your test program with "LogLevel=2". java -jar pgpoolbug.jar jdbc:postgresql://localhost:11000/test?loglevel=2 t-ishii "" However, if I remove the LogLevel option, I got Java exception below. This means that my fix is not enough? java.util.NoSuchElementException at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1728) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:615) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:465) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:350) at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80) at org.hibernate.loader.Loader.getResultSet(Loader.java:2065) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838) at org.hibernate.loader.Loader.doQuery(Loader.java:909) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) at org.hibernate.loader.Loader.doList(Loader.java:2553) at org.hibernate.loader.Loader.doList(Loader.java:2539) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369) at org.hibernate.loader.Loader.list(Loader.java:2364) at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:353) at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:1873) at org.hibernate.internal.AbstractSessionImpl.list(AbstractSessionImpl.java:311) at org.hibernate.internal.SQLQueryImpl.list(SQLQueryImpl.java:141) at pgpoolbug.BugMain.main(BugMain.java:69) |
|
|
|
|
|
I'm not sure why that exception happened... but after applying the patch I'm still seeing the same behaviour. this is the output from 2 runs, one right after the other: [root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb elias foobar Initialising Hibernate Mar 15, 2016 12:35:50 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final} Mar 15, 2016 12:35:50 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {4.3.4.Final} Mar 15, 2016 12:35:50 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Mar 15, 2016 12:35:50 PM org.hibernate.cfg.Environment buildBytecodeProvider INFO: HHH000021: Bytecode provider name : javassist Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!) Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb] Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000046: Connection properties: {user=elias, password=****} Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000006: Autocommit mode: false Mar 15, 2016 12:35:51 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure INFO: HHH000115: Hibernate connection pool size: 10 (min=1) Mar 15, 2016 12:35:53 PM org.hibernate.dialect.Dialect <init> INFO: HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL9Dialect Mar 15, 2016 12:35:53 PM org.hibernate.engine.jdbc.internal.LobCreatorBuilder useContextualLobCreation INFO: HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException Mar 15, 2016 12:35:53 PM org.hibernate.engine.transaction.internal.TransactionFactoryInitiator initiateService INFO: HHH000399: Using default transaction strategy (direct JDBC transactions) Mar 15, 2016 12:35:53 PM org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory <init> INFO: HHH000397: Using ASTQueryTranslatorFactory Mar 15, 2016 12:35:53 PM org.hibernate.tool.hbm2ddl.SchemaValidator validate INFO: HHH000229: Running schema validator Mar 15, 2016 12:35:53 PM org.hibernate.tool.hbm2ddl.SchemaValidator validate INFO: HHH000102: Fetching database metadata Opening Session Received Result: If you can see this it worked Finished [root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb elias foobar Initialising Hibernate Mar 15, 2016 12:35:54 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final} Mar 15, 2016 12:35:54 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {4.3.4.Final} Mar 15, 2016 12:35:54 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Mar 15, 2016 12:35:54 PM org.hibernate.cfg.Environment buildBytecodeProvider INFO: HHH000021: Bytecode provider name : javassist Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!) Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb] Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000046: Connection properties: {user=elias, password=****} Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000006: Autocommit mode: false Mar 15, 2016 12:35:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure INFO: HHH000115: Hibernate connection pool size: 10 (min=1) [hang] |
|
|
Even with loglevel=2 it still locks up sometimes: [root@postgrestest ~]# java -jar pgpoolbug.jar jdbc:postgresql://192.168.88.106:5433/eliasdb?loglevel=2 elias foobar Initialising Hibernate Mar 15, 2016 12:39:17 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {4.0.4.Final} Mar 15, 2016 12:39:17 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {4.3.4.Final} Mar 15, 2016 12:39:17 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Mar 15, 2016 12:39:17 PM org.hibernate.cfg.Environment buildBytecodeProvider INFO: HHH000021: Bytecode provider name : javassist Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH000402: Using Hibernate built-in connection pool (not for production use!) Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000401: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://192.168.88.106:5433/eliasdb?loglevel=2] Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000046: Connection properties: {user=elias, password=****} Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH000006: Autocommit mode: false Mar 15, 2016 12:39:18 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure INFO: HHH000115: Hibernate connection pool size: 10 (min=1) 12:39:18.113 (1) PostgreSQL 9.4 JDBC4.1 (build 1202) 12:39:18.119 (1) Trying to establish a protocol version 3 connection to 192.168.88.106:5433 12:39:18.129 (1) Receive Buffer Size is 87379 12:39:18.129 (1) Send Buffer Size is 330075 12:39:18.132 (1) FE=> StartupPacket(user=elias, database=eliasdb, client_encoding=UTF8, DateStyle=ISO, TimeZone=Australia/Melbourne, extra_float_digits=2) 12:39:18.144 (1) <=BE AuthenticationOk 12:39:18.159 (1) <=BE ParameterStatus(application_name = ) 12:39:18.159 (1) <=BE ParameterStatus(client_encoding = UTF8) 12:39:18.159 (1) <=BE ParameterStatus(DateStyle = ISO, DMY) 12:39:18.159 (1) <=BE ParameterStatus(integer_datetimes = on) 12:39:18.159 (1) <=BE ParameterStatus(IntervalStyle = postgres) 12:39:18.159 (1) <=BE ParameterStatus(is_superuser = off) 12:39:18.159 (1) <=BE ParameterStatus(server_encoding = UTF8) 12:39:18.159 (1) <=BE ParameterStatus(server_version = 9.5.1) 12:39:18.159 (1) <=BE ParameterStatus(session_authorization = elias) 12:39:18.160 (1) <=BE ParameterStatus(standard_conforming_strings = on) 12:39:18.160 (1) <=BE ParameterStatus(TimeZone = Australia/Melbourne) 12:39:18.160 (1) <=BE BackendKeyData(pid=2871,ckey=74287852) 12:39:18.160 (1) <=BE ReadyForQuery(I) 12:39:18.162 (1) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@1f4a8824, maxRows=0, fetchSize=0, flags=23 12:39:18.162 (1) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 12:39:18.163 (1) FE=> Bind(stmt=null,portal=null) 12:39:18.163 (1) FE=> Execute(portal=null,limit=1) 12:39:18.163 (1) FE=> Sync 12:39:18.166 (1) <=BE ParseComplete [null] 12:39:18.166 (1) <=BE BindComplete [unnamed] 12:39:18.166 (1) <=BE CommandStatus(SET) 12:39:18.166 (1) <=BE ReadyForQuery(I) 12:39:18.166 (1) compatible = 90400 12:39:18.166 (1) loglevel = 2 12:39:18.166 (1) prepare threshold = 5 12:39:18.169 (1) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 12:39:18.170 (1) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 12:39:18.170 (1) integer date/time = true 12:39:18.208 (1) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@2d6bcf8a, maxRows=0, fetchSize=0, flags=1 12:39:18.208 (1) FE=> Parse(stmt=null,query="BEGIN",oids={}) 12:39:18.208 (1) FE=> Bind(stmt=null,portal=null) 12:39:18.208 (1) FE=> Execute(portal=null,limit=0) 12:39:18.209 (1) FE=> Parse(stmt=null,query="SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'",oids={}) 12:39:18.209 (1) FE=> Bind(stmt=null,portal=null) 12:39:18.209 (1) FE=> Describe(portal=null) 12:39:18.209 (1) FE=> Execute(portal=null,limit=0) 12:39:18.209 (1) FE=> Sync |
|
|
Can you please show me the pgpool debug log? |
|
|
I have committed the patch to 3.5 stable tree. You can try it if you like. |
|
|
Here it is, from the stable branch, it hangs at this point. [root@postgrestest bin]# /usr/local/pgpool2/bin/pgpool -n -d 2016-03-15 15:08:40: pid 18773: DEBUG: loading hba configuration 2016-03-15 15:08:40: pid 18773: DETAIL: loading file :"/usr/local/pgpool2/etc/pool_hba.conf" for client authentication configuration file 2016-03-15 15:08:40: pid 18773: DEBUG: pool_coninfo_size: num_init_children (30) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 1044480 bytes requested for shared memory 2016-03-15 15:08:40: pid 18773: DEBUG: ProcessInfo: num_init_children (30) * sizeof(ProcessInfo) (32) = 960 bytes requested for shared memory 2016-03-15 15:08:40: pid 18773: DEBUG: Request info are: sizeof(POOL_REQUEST_INFO) 5224 bytes requested for shared memory 2016-03-15 15:08:40: pid 18773: DEBUG: Recovery management area: sizeof(int) 4 bytes requested for shared memory 2016-03-15 15:08:40: pid 18773: LOG: Setting up socket for 0.0.0.0:5433 2016-03-15 15:08:40: pid 18773: LOG: Setting up socket for :::5433 2016-03-15 15:08:40: pid 18777: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18776: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18778: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18779: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18775: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18780: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18781: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18782: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18783: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18784: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18774: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18785: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18786: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18787: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18788: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18789: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18790: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18791: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18792: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18793: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18794: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18795: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18773: LOG: pgpool-II successfully started. version 3.5.0 (ekieboshi) 2016-03-15 15:08:40: pid 18773: LOG: find_primary_node: checking backend no 0 2016-03-15 15:08:40: pid 18796: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18799: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18800: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18798: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18801: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18802: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18797: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18803: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18804: DEBUG: I am PCP child with pid:18804 2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:40: pid 18805: DEBUG: I am 18805 2016-03-15 15:08:40: pid 18805: DEBUG: initializing backend status 2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()" 2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:08:40: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 75 bytes from backend 0 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'T' 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'D' 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'C' 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: kind: 'Z' 2016-03-15 15:08:40: pid 18773: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:40: pid 18773: LOG: find_primary_node: primary node id is 0 2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:40: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:40: pid 18773: DEBUG: starting health check 2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:08:40: pid 18773: DEBUG: doing health check against database:postgres user:postgres 2016-03-15 15:08:40: pid 18773: DEBUG: Backend DB node 0 status is 2 2016-03-15 15:08:40: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2 2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:08:40: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:40: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful 2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:40: pid 18773: DEBUG: Backend DB node 1 status is 2 2016-03-15 15:08:40: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2 2016-03-15 15:08:40: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:08:40: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:40: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:40: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:08:40: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:40: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful 2016-03-15 15:08:40: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:08:40: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:08:50: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:50: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:08:50: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:08:50: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:08:50: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:00: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:00: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:00: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:00: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:00: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:06: pid 18803: DEBUG: I am 18803 accept fd 7 2016-03-15 15:09:06: pid 18803: LOG: new connection received 2016-03-15 15:09:06: pid 18803: DETAIL: connecting host=postgrestest port=44033 2016-03-15 15:09:06: pid 18803: DEBUG: reading startup packet 2016-03-15 15:09:06: pid 18803: DETAIL: Protocol Major: 3 Minor: 0 database: eliasdb user: elias 2016-03-15 15:09:06: pid 18803: DEBUG: creating new connection to backend 2016-03-15 15:09:06: pid 18803: DETAIL: connecting 0 backend 2016-03-15 15:09:06: pid 18803: DEBUG: creating new connection to backend 2016-03-15 15:09:06: pid 18803: DETAIL: connecting 1 backend 2016-03-15 15:09:06: pid 18803: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:06: pid 18803: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 332 bytes from backend 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 332 bytes from backend 1 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 8 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 8 2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend 2016-03-15 15:09:06: pid 18803: DETAIL: auth kind:0 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 22 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 22 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"application_name" value:"" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"application_name" value:"" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"client_encoding" value:"UTF8" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"client_encoding" value:"UTF8" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 23 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 23 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"DateStyle" value:"ISO, DMY" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"DateStyle" value:"ISO, DMY" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"integer_datetimes" value:"on" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"integer_datetimes" value:"on" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 27 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 27 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"IntervalStyle" value:"postgres" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"IntervalStyle" value:"postgres" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 21 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 21 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"is_superuser" value:"off" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"is_superuser" value:"off" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"server_encoding" value:"UTF8" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"server_encoding" value:"UTF8" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 25 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"server_version" value:"9.5.1" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"server_version" value:"9.5.1" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 32 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 32 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"session_authorization" value:"elias" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"session_authorization" value:"elias" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 35 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 35 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"standard_conforming_strings" value:"on" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"standard_conforming_strings" value:"on" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 0 length: 33 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: master slot: 1 length: 33 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 name:"TimeZone" value:"Australia/Melbourne" 2016-03-15 15:09:06: pid 18803: DEBUG: process parameter status 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 name:"TimeZone" value:"Australia/Melbourne" 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 12 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 12 2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend 2016-03-15 15:09:06: pid 18803: DETAIL: cp->info[i]:0x7ffa0b486800 pid:4647 2016-03-15 15:09:06: pid 18803: DEBUG: authentication backend 2016-03-15 15:09:06: pid 18803: DETAIL: cp->info[i]:0x7ffa0b486888 pid:4121 2016-03-15 15:09:06: pid 18803: DEBUG: sending backend key data 2016-03-15 15:09:06: pid 18803: DETAIL: send pid 4121 to frontend 2016-03-15 15:09:06: pid 18803: DEBUG: selecting load balance node 2016-03-15 15:09:06: pid 18803: DETAIL: selected backend id is 1 2016-03-15 15:09:06: pid 18803: DEBUG: initializing session context 2016-03-15 15:09:06: pid 18803: DETAIL: selected load balancing node: 1 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing transaction isolation. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing writing transaction. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing failed transaction. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing failed transaction. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing skip reading from backends. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'Z' 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'Z' 2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'Z'(5a) from backend 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: Ready For Query received 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 5 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 5 2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery 2016-03-15 15:09:06: pid 18803: DETAIL: transaction state ' 2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery 2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49) 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <> 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries 2016-03-15 15:09:06: pid 18803: DETAIL: destination = 3 for query= "SET extra_float_digits = 3" 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: SET extra_float_digits = 3 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Parse: SET extra_float_digits = 3 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62be0 kind: P name: == 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'B'(42) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: Bind: waiting for master completing the query 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: B message 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: B message 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: B name: == 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'E'(45) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Execute: SET extra_float_digits = 3 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Execute: SET extra_float_digits = 3 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'S'(53) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 25 bytes from backend 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '1' 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 25 bytes from backend 1 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = '1' 2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind '1'(31) from backend 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: B name: == 2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list 2016-03-15 15:09:06: pid 18803: DETAIL: adding exactly same message is prohibited 2016-03-15 15:09:06: pid 18803: DEBUG: SimpleForwardToFrontend: packet:1 length:0 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '2' 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = '2' 2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind '2'(32) from backend 2016-03-15 15:09:06: pid 18803: DEBUG: SimpleForwardToFrontend: packet:2 length:0 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'C' 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'C' 2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'C'(43) from backend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting command success. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = 'Z' 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:1 of 2 kind = 'Z' 2016-03-15 15:09:06: pid 18803: DEBUG: read_kind_from_backend max_count:2.000000 num_executed_nodes:2 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'Z'(5a) from backend 2016-03-15 15:09:06: pid 18803: DEBUG: processing backend response 2016-03-15 15:09:06: pid 18803: DETAIL: Ready For Query received 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing ignore till sync. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 0 length: 5 2016-03-15 15:09:06: pid 18803: DEBUG: reading message length 2016-03-15 15:09:06: pid 18803: DETAIL: slot: 1 length: 5 2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery 2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49) 2016-03-15 15:09:06: pid 18803: DEBUG: processing ReadyForQuery 2016-03-15 15:09:06: pid 18803: DETAIL: transaction state 'I'(49) 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <> 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries 2016-03-15 15:09:06: pid 18803: DETAIL: destination = 3 for query= "BEGIN" 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: BEGIN 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Parse: BEGIN 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62cf8 kind: P name: == 2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list 2016-03-15 15:09:06: pid 18803: DETAIL: prepared statement "" already exists 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62be0 kind: P name: == 2016-03-15 15:09:06: pid 18803: DEBUG: checking if query context can be safely destroyed 2016-03-15 15:09:06: pid 18803: DETAIL: query context 0xc64fb0 is still used 2 times. query:"SET extra_float_digits = 3" 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'B'(42) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: Bind: waiting for master completing the query 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: B message 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: B message 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62be0 kind: B name: == 2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list 2016-03-15 15:09:06: pid 18803: DETAIL: portal "" already exists 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62c78 kind: B name: == 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'E'(45) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Execute: BEGIN 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 1 backend pid: 4121 statement: Execute: BEGIN 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 1 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: processing frontend response 2016-03-15 15:09:06: pid 18803: DETAIL: received kind 'P'(50) from frontend 2016-03-15 15:09:06: pid 18803: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: Parse: statement name <> 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: checking if query has INSERT INTO, FOR SHARE or FOR UPDATE 2016-03-15 15:09:06: pid 18803: DETAIL: result = 0 2016-03-15 15:09:06: pid 18803: DEBUG: decide where to send the queries 2016-03-15 15:09:06: pid 18803: DETAIL: destination = 2 for query= "SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'" 2016-03-15 15:09:06: pid 18803: DEBUG: system catalog walker, checking relation "pg_type" 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) from (SELECT has_function_privilege('elias', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s" 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 21 bytes from backend 0 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace' 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'" 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog' 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'" 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: system catalog walker, checking relation "pg_namespace" 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog' 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: extended:1 query:"SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"pg_namespace"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'" 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 1 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 4 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pushing data of len: 6 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: no pending data 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:B 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:S 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:E 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:C 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:H 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pool_read: read 46 bytes from backend 0 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '1' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received PARSE COMPLETE ('1') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '2' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received BIND COMPLETE ('2') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: kind: '3' 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: received CLOSE COMPLETE ('3') 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: all state completed. returning 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: pop data of len: 21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: do_query: popped data len:21 2016-03-15 15:09:06: pid 18803: CONTEXT: while searching system catalog, When relcache is missed 2016-03-15 15:09:06: pid 18803: DEBUG: session context: setting query in progress. DONE 2016-03-15 15:09:06: pid 18803: LOG: DB node id: 0 backend pid: 4647 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast' 2016-03-15 15:09:06: pid 18803: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: pool_write: to backend: kind:P 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_add_sent_message: sent message: address: c62c78 kind: P name: == 2016-03-15 15:09:06: pid 18803: DEBUG: adding sent message to list 2016-03-15 15:09:06: pid 18803: DETAIL: prepared statement "" already exists 2016-03-15 15:09:06: pid 18803: DEBUG: called by pool_sent_message_destroy: sent message: address: c62cf8 kind: P name: == 2016-03-15 15:09:06: pid 18803: DEBUG: checking if query context can be safely destroyed 2016-03-15 15:09:06: pid 18803: DETAIL: query context 0xc65fd0 is still used 2 times. query:"BEGIN" 2016-03-15 15:09:06: pid 18803: DEBUG: session context: unsetting query in progress. DONE 2016-03-15 15:09:06: pid 18803: DEBUG: pool_use_sync_map: set use sync map: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: master node id: 0 2016-03-15 15:09:06: pid 18803: DEBUG: reading backend data packet kind 2016-03-15 15:09:06: pid 18803: DETAIL: backend:0 of 2 kind = '1' 2016-03-15 15:09:10: pid 18773: DEBUG: starting health check 2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:10: pid 18773: DEBUG: doing health check against database:postgres user:postgres 2016-03-15 15:09:10: pid 18773: DEBUG: Backend DB node 0 status is 2 2016-03-15 15:09:10: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2 2016-03-15 15:09:10: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:10: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:10: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:10: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful 2016-03-15 15:09:10: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:10: pid 18773: DEBUG: Backend DB node 1 status is 2 2016-03-15 15:09:10: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2 2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:10: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:10: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:10: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:09:10: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:10: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful 2016-03-15 15:09:10: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:10: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:10: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:10: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:10: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:20: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:20: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:20: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:20: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:20: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:20: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:21: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:21: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:21: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:21: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:21: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:31: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:31: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:31: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:31: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:31: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:41: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:41: pid 18773: DEBUG: starting health check 2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:41: pid 18773: DEBUG: doing health check against database:postgres user:postgres 2016-03-15 15:09:41: pid 18773: DEBUG: Backend DB node 0 status is 2 2016-03-15 15:09:41: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 0 having status 2 2016-03-15 15:09:41: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:41: pid 18805: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:41: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:41: pid 18773: DEBUG: persistent DB connection to backend node 0 having status 2 is successful 2016-03-15 15:09:41: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:41: pid 18773: DEBUG: Backend DB node 1 status is 2 2016-03-15 15:09:41: pid 18773: DEBUG: Trying to make persistent DB connection to backend node 1 having status 2 2016-03-15 15:09:41: pid 18773: DEBUG: SSL is requested but SSL support is not available 2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate kind = 0 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: key data received 2016-03-15 15:09:41: pid 18805: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_current_xlog_location()" 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18773: DEBUG: pool_read: read 333 bytes from backend 0 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate kind = 0 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: key data received 2016-03-15 15:09:41: pid 18773: DEBUG: authenticate backend: transaction state: I 2016-03-15 15:09:41: pid 18773: DEBUG: persistent DB connection to backend node 1 having status 2 is successful 2016-03-15 15:09:41: pid 18773: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:41: pid 18773: DEBUG: health check: clearing alarm 2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 90 bytes from backend 0 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: extended:0 query:"SELECT pg_last_xlog_replay_location()" 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:Q 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: pool_read: read 94 bytes from backend 0 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'T' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received ROW DESCRIPTION ('T') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: row description: num_fileds: 1 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'D' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received DATA ROW ('D') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'C' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received COMMAND COMPLETE ('C') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: kind: 'Z' 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: do_query: received READY FOR QUERY ('Z') 2016-03-15 15:09:41: pid 18805: CONTEXT: while checking replication time lag 2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:X 2016-03-15 15:09:41: pid 18805: DEBUG: pool_write: to backend: kind:X |
|
|
I've been doing some more testing (got the latest stable just now) and I haven't been able to reproduce the hanging problem, which is good :) However, I did reproduce the java error you mentioned before. "java.util.NoSuchElementException at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278)" I can't reproduce it reliably though, I run the java program in an infinite loop script and eventually it randomly fails, but usually within a 30-60 seconds of running the program. |
|
|
If I change the child_max_connections to 1, then it doesn't seem to happen, however values such as 50 seem to make it error as mentioned in my previous note. The other settings (max_pool, num_init_children) don't seem to have any effect. |
|
|
Actually... num_init_children = 2 max_pool = 1 Seem to make the error happen far more easily. I still can't reproduce it with loglevel=2 for the JDBC driver however. I tested a direct postgres connection just in case the JDBC driver could be blamed but that seems to work even at loglevel=0 |
|
|
If I add &prepareThreshold=0 to the jdbc URL, it then appears to work. My test program is not doing any prepared statements, but hibernate does many queries during initialisation, mostly to probe the database schema definition. So while I run my program in a bash loop, it starts and shuts down many times, it would hit the relation cache pretty heavily. This is obvious as the first iteration is slow during initialisation, it the next runs are much faster. I get the array error just after hibernate initialisation finishes and I just run a simple sql query. Bug 152 looks very similar, since prepared statements are involved? |
|
|
I have gotten a Java exception after repeating several times your test program. My guess is pgpool-II mistakenly sends a CommandStatus(BEGIN) to frontend when it should sends CommandStatus(SELECT). I think the confusion is caused by that lots of prepared statements are used (by Hibernate). I have an idea fixing the problem in my mind and am working on it. I will keep you informed. 13:03:05.752 (1) <=BE ParseComplete [null] 13:03:05.752 (1) <=BE BindComplete [unnamed] 13:03:05.752 (1) <=BE CommandStatus(BEGIN) java.util.NoSuchElementException at java.util.ArrayDeque.removeFirst(ArrayDeque.java:278) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1728) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:615) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:465) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:350) at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80) at org.hibernate.loader.Loader.getResultSet(Loader.java:2065) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838) at org.hibernate.loader.Loader.doQuery(Loader.java:909) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) at org.hibernate.loader.Loader.doList(Loader.java:2553) at org.hibernate.loader.Loader.doList(Loader.java:2539) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369) at org.hibernate.loader.Loader.list(Loader.java:2364) at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:353) at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:1873) at org.hibernate.internal.AbstractSessionImpl.list(AbstractSessionImpl.java:311) at org.hibernate.internal.SQLQueryImpl.list(SQLQueryImpl.java:141) at pgpoolbug.BugMain.main(BugMain.java:69) |
|
|
Regarding the relationship with bug152 is not still clear, because I cannot reproduce the problem. I am waiting for a feedback from the reporter. |
|
|
Ok, I think I have made it. Could you please try 3.5 stable tree head? http://git.postgresql.org/gitweb/?p=pgpool2.git;a=shortlog;h=refs/heads/V3_5_STABLE |
|
|
Its looking good! My test program keeps happily working... and our big application also starts and works with load balancing. Thankyou! |
|
|
Thank you so much for cooperation! |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2016-02-22 14:48 | eflopez123 | New Issue | |
| 2016-02-22 14:48 | eflopez123 | File Added: conf-and-logfile.txt | |
| 2016-02-23 08:20 | t-ishii | Note Added: 0000647 | |
| 2016-02-23 08:20 | t-ishii | Assigned To | => t-ishii |
| 2016-02-23 08:20 | t-ishii | Status | new => assigned |
| 2016-02-23 13:41 | eflopez123 | Note Added: 0000648 | |
| 2016-02-23 13:44 | eflopez123 | File Added: pgpoolbug.tgz | |
| 2016-02-27 19:51 | t-ishii | Note Added: 0000649 | |
| 2016-02-27 20:13 | eflopez123 | Note Added: 0000650 | |
| 2016-02-27 20:30 | t-ishii | View Status | private => public |
| 2016-02-27 20:32 | t-ishii | Note Added: 0000651 | |
| 2016-02-29 11:27 | t-ishii | Note Added: 0000652 | |
| 2016-02-29 12:54 | eflopez123 | Note Added: 0000653 | |
| 2016-03-01 09:04 | t-ishii | Note Added: 0000654 | |
| 2016-03-01 10:09 | eflopez123 | Note Added: 0000655 | |
| 2016-03-02 09:32 | t-ishii | Note Added: 0000656 | |
| 2016-03-02 09:37 | eflopez123 | Note Added: 0000657 | |
| 2016-03-02 10:16 | t-ishii | Note Added: 0000658 | |
| 2016-03-02 11:40 | eflopez123 | Note Added: 0000659 | |
| 2016-03-02 11:43 | t-ishii | Note Added: 0000660 | |
| 2016-03-02 11:45 | eflopez123 | Note Added: 0000661 | |
| 2016-03-02 14:11 | t-ishii | Note Added: 0000662 | |
| 2016-03-02 14:22 | t-ishii | Note Edited: 0000662 | |
| 2016-03-02 17:17 | t-ishii | Note Added: 0000663 | |
| 2016-03-02 17:17 | t-ishii | File Added: bug167.diff | |
| 2016-03-02 17:20 | t-ishii | Note Edited: 0000663 | |
| 2016-03-02 17:22 | t-ishii | Status | assigned => feedback |
| 2016-03-03 15:09 | t-ishii | Note Added: 0000669 | |
| 2016-03-04 09:16 | eflopez123 | Note Added: 0000670 | |
| 2016-03-04 09:16 | eflopez123 | Status | feedback => assigned |
| 2016-03-08 10:25 | eflopez123 | Note Added: 0000678 | |
| 2016-03-08 13:08 | t-ishii | File Added: log-20160308.txt | |
| 2016-03-08 13:08 | t-ishii | Status | assigned => feedback |
| 2016-03-10 13:04 | t-ishii | Note Added: 0000679 | |
| 2016-03-10 13:14 | eflopez123 | Note Added: 0000680 | |
| 2016-03-10 13:14 | eflopez123 | Status | feedback => assigned |
| 2016-03-10 13:51 | eflopez123 | File Added: debug-20160310.txt | |
| 2016-03-10 13:54 | eflopez123 | Note Added: 0000681 | |
| 2016-03-10 14:13 | eflopez123 | Note Added: 0000682 | |
| 2016-03-10 14:16 | t-ishii | Note Added: 0000683 | |
| 2016-03-10 14:16 | t-ishii | Status | assigned => resolved |
| 2016-03-11 12:24 | eflopez123 | Note Added: 0000684 | |
| 2016-03-11 12:24 | eflopez123 | Status | resolved => feedback |
| 2016-03-11 12:24 | eflopez123 | Resolution | open => reopened |
| 2016-03-11 16:25 | t-ishii | Note Added: 0000685 | |
| 2016-03-14 08:26 | eflopez123 | Note Added: 0000686 | |
| 2016-03-14 08:26 | eflopez123 | Status | feedback => assigned |
| 2016-03-14 13:42 | t-ishii | Note Added: 0000687 | |
| 2016-03-14 14:17 | t-ishii | Note Added: 0000688 | |
| 2016-03-14 14:18 | t-ishii | Note Edited: 0000688 | |
| 2016-03-14 15:53 | eflopez123 | Note Added: 0000689 | |
| 2016-03-14 16:04 | t-ishii | Note Added: 0000690 | |
| 2016-03-15 14:35 | t-ishii | Note Edited: 0000690 | |
| 2016-03-24 14:38 | t-ishii | Note Added: 0000716 | |
| 2016-03-24 14:39 | t-ishii | File Added: fix-bug167.diff | |
| 2016-03-26 13:59 | eflopez123 | Note Added: 0000723 | |
| 2016-03-26 14:00 | eflopez123 | Note Added: 0000724 | |
| 2016-03-26 17:14 | t-ishii | Note Added: 0000725 | |
| 2016-03-26 17:15 | t-ishii | Status | assigned => feedback |
| 2016-03-28 11:13 | t-ishii | Note Added: 0000730 | |
| 2016-03-28 19:05 | eflopez123 | Note Added: 0000732 | |
| 2016-03-28 19:05 | eflopez123 | Status | feedback => assigned |
| 2016-03-29 14:42 | eflopez123 | Note Added: 0000736 | |
| 2016-03-29 15:02 | eflopez123 | Note Added: 0000737 | |
| 2016-03-29 15:11 | eflopez123 | Note Added: 0000738 | |
| 2016-03-29 15:32 | eflopez123 | Note Added: 0000739 | |
| 2016-03-29 16:02 | t-ishii | Note Added: 0000741 | |
| 2016-03-29 16:13 | t-ishii | Note Added: 0000744 | |
| 2016-03-29 21:17 | t-ishii | Note Added: 0000745 | |
| 2016-03-29 21:18 | t-ishii | Status | assigned => feedback |
| 2016-03-30 08:53 | eflopez123 | Note Added: 0000746 | |
| 2016-03-30 08:53 | eflopez123 | Status | feedback => assigned |
| 2016-03-30 09:14 | t-ishii | Note Added: 0000747 | |
| 2016-03-30 09:15 | t-ishii | Status | assigned => resolved |
