[pgpool-general: 3779] Unable to get connections by tomcat common dbcp or c3p0 connection pooling from pgpool host/port

Thu Jun 4 02:09:26 JST 2015

Hi,

We are observing weird pattern that tomcat connection pooling framework not able to get connections from pgpool and it is failing with below exceptions. But we are successfully able to connect thru PSQL on same pgpool host/port and execute all SQL commands.

Just to let you all know options tried and still end up with same exception

1.  Switched from common dbcp to c3p0 pooling framework.
2. Confirmed pgpool port is listening with domain “*” and able to telnet from other servers.
3. Turn off pgpool connection cache attribute
4. Checked encoding on tomcat server which is UTF-8.

ANY HELP GREATLY APPRECIATED…..

Application server Exception log:

threw exception; Error retrieving data from switch_currenty_key table: Could not get JDBC Connection; nested exception is java.sql.SQLException: Connections could not be acquired from the underlying database!
at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBean(BeanDefinitionValueResolver.java:282) ~[spring-beans-3.2.3.RELEASE.jar:3.2.3.RELEASE]
at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:121) ~[spring-beans-3.2.3.RELEASE.jar:3.2.3.RELEASE]

Pgpool logs:

2015-06-02 21:57:19 DEBUG: pid 17752: 0 th backend: name: TimeZone value: US/Central
2015-06-02 21:57:19 DEBUG: pid 17752: 1 th backend: name: TimeZone value: US/Central
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 0 length: 12
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 1 length: 12
2015-06-02 21:57:19 DEBUG: pid 17752: pool_do_auth: cp->info[i]:0x7f8637ec9000 pid:17756
2015-06-02 21:57:19 DEBUG: pid 17752: pool_do_auth: cp->info[i]:0x7f8637ec9088 pid:12502
2015-06-02 21:57:19 DEBUG: pid 17752: pool_send_auth_ok: send pid 12502 to frontend
2015-06-02 21:57:19 DEBUG: pid 17752: select_load_balancing_node: selected backend id is 0
2015-06-02 21:57:19 DEBUG: pid 17752: selected load balancing node: 0
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_command_success: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_writing_transaction: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_failed_transaction: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_transaction_isolation: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_skip_reading_from_backends: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_ignore_till_sync: done
2015-06-02 21:57:19 DEBUG: pid 17752: read_kind_from_backend: kind: Z from 0 th backend
2015-06-02 21:57:19 DEBUG: pid 17752: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2015-06-02 21:57:19 DEBUG: pid 17752: read_kind_from_backend: kind: Z from 1 th backend
2015-06-02 21:57:19 DEBUG: pid 17752: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
2015-06-02 21:57:19 DEBUG: pid 17752: ProcessBackendResponse: kind from backend: Z
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 0 length: 5
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 1 length: 5
2015-06-02 21:57:19 DEBUG: pid 17752: ReadyForQuery: transaction state:
2015-06-02 21:57:19 DEBUG: pid 17752: ReadyForQuery: transaction state:I
2015-06-02 21:57:19 DEBUG: pid 17752: ProcessBackendResponse: Ready For Query
2015-06-02 21:57:19 DEBUG: pid 17752: ProcessFrontendResponse: kind from frontend P(50)
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_doing_extended_query_message: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_set_doing_extended_query_message: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_set_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: Parse: statement name <>
2015-06-02 21:57:19 DEBUG: pid 17752: pool_set_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 0 length: 5
2015-06-02 21:57:19 DEBUG: pid 17752: pool_read_message_length: slot: 1 length: 5
2015-06-02 21:57:19 DEBUG: pid 17752: ReadyForQuery: transaction state:I
2015-06-02 21:57:19 DEBUG: pid 17752: ReadyForQuery: transaction state:I
2015-06-02 21:57:19 DEBUG: pid 17752: can_query_context_destroy: query context 0x769e10 is still used. query:SET extra_float_digits = 3
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_set_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_unset_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: pool_set_query_in_progress: done
2015-06-02 21:57:19 DEBUG: pid 17752: Parse: waiting for master completing the query
2015-06-02 21:57:19 LOG:   pid 17752: DB node id: 0 backend pid: 17756 statement: Parse: ���;�
2015-06-02 21:57:19 DEBUG: pid 17752: wait_for_query_response: waiting for backend 0 completing the query
2015-06-02 21:57:19 DEBUG: pid 17752: detect_error: kind: 1
2015-06-02 21:57:19 DEBUG: pid 11464: reap_handler called
2015-06-02 21:57:19 DEBUG: pid 11464: reap_handler: call wait3
2015-06-02 21:57:19 ERROR: pid 11464: Child process 17752 was terminated by segmentation fault
2015-06-02 21:57:19 DEBUG: pid 11464: child 17752 exits with status 11 by signal 11
2015-06-02 21:57:19 DEBUG: pid 11464: fork a new child pid 17757
2015-06-02 21:57:19 DEBUG: pid 11464: reap_handler: normally exited
2015-06-02 21:57:19 DEBUG: pid 17757: I am 17757
2015-06-02 21:57:19 DEBUG: pid 17757: pool_initialize_private_backend_status: initialize backend status
2015-06-02 21:57:27 DEBUG: pid 17729: I am 17729 accept fd 6
2015-06-02 21:57:27 LOG:   pid 17729: connection received: host=<<XXXXX hostname>> port=37844
2015-06-02 21:57:27 DEBUG: pid 17729: Protocol Major: 3 Minor: 0 database: <<databasename>> user: <<username>>
2015-06-02 21:57:27 DEBUG: pid 17729: new_connection: connecting 0 backend
2015-06-02 21:57:27 DEBUG: pid 17729: new_connection: connecting 1 backend
2015-06-02 21:57:27 DEBUG: pid 17729: pool_ssl: SSL requested but SSL support is not available
2015-06-02 21:57:27 DEBUG: pid 17729: pool_ssl: SSL requested but SSL support is not available
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 0 length: 12
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 1 length: 12
2015-06-02 21:57:27 DEBUG: pid 17729: pool_do_auth: auth kind:5
2015-06-02 21:57:27 DEBUG: pid 17729: trying md5 authentication
2015-06-02 21:57:27 DEBUG: pid 17729: DB node id: 0 salt: 16bcf7b8
2015-06-02 21:57:27 DEBUG: pid 17729: trying md5 authentication
2015-06-02 21:57:27 DEBUG: pid 17729: DB node id: 1 salt: ac25a3ff
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 22
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 22
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: application_name value:
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: application_name value:
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: client_encoding value: UTF8
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: client_encoding value: UTF8
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 23
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 23
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: DateStyle value: ISO, MDY
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: DateStyle value: ISO, MDY
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: integer_datetimes value: on
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: integer_datetimes value: on
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 27
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 27
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: IntervalStyle value: postgres
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: IntervalStyle value: postgres
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 21
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 21
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: is_superuser value: off
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: is_superuser value: off
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 25
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: server_encoding value: UTF8
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: server_encoding value: UTF8
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 26
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 26
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: server_version value: 9.2.10
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: server_version value: 9.2.10
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 34
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 34
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: session_authorization value: <<user>>
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: session_authorization value: <<user>>
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 35
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 35
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: standard_conforming_strings value: on
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: standard_conforming_strings value: on
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 0 length: 24
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length2: master slot: 1 length: 24
2015-06-02 21:57:27 DEBUG: pid 17729: 0 th backend: name: TimeZone value: US/Central
2015-06-02 21:57:27 DEBUG: pid 17729: 1 th backend: name: TimeZone value: US/Central
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 0 length: 12
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 1 length: 12
2015-06-02 21:57:27 DEBUG: pid 17729: pool_do_auth: cp->info[i]:0x7f8637bff000 pid:17758
2015-06-02 21:57:27 DEBUG: pid 17729: pool_do_auth: cp->info[i]:0x7f8637bff088 pid:12504
2015-06-02 21:57:27 DEBUG: pid 17729: pool_send_auth_ok: send pid 12504 to frontend
2015-06-02 21:57:27 DEBUG: pid 17729: select_load_balancing_node: selected backend id is 0
2015-06-02 21:57:27 DEBUG: pid 17729: selected load balancing node: 0
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_command_success: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_writing_transaction: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_failed_transaction: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_transaction_isolation: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_skip_reading_from_backends: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_ignore_till_sync: done
2015-06-02 21:57:27 DEBUG: pid 17729: read_kind_from_backend: kind: Z from 0 th backend
2015-06-02 21:57:27 DEBUG: pid 17729: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2015-06-02 21:57:27 DEBUG: pid 17729: read_kind_from_backend: kind: Z from 1 th backend
2015-06-02 21:57:27 DEBUG: pid 17729: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
2015-06-02 21:57:27 DEBUG: pid 17729: ProcessBackendResponse: kind from backend: Z
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 0 length: 5
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 1 length: 5
2015-06-02 21:57:27 DEBUG: pid 17729: ReadyForQuery: transaction state:
2015-06-02 21:57:27 DEBUG: pid 17729: ReadyForQuery: transaction state:I
2015-06-02 21:57:27 DEBUG: pid 17729: ProcessBackendResponse: Ready For Query
2015-06-02 21:57:27 DEBUG: pid 17729: ProcessFrontendResponse: kind from frontend P(50)
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_doing_extended_query_message: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_set_doing_extended_query_message: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_set_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: Parse: statement name <>
2015-06-02 21:57:27 DEBUG: pid 17729: pool_set_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 0 length: 5
2015-06-02 21:57:27 DEBUG: pid 17729: pool_read_message_length: slot: 1 length: 5
2015-06-02 21:57:27 DEBUG: pid 17729: ReadyForQuery: transaction state:I
2015-06-02 21:57:27 DEBUG: pid 17729: ReadyForQuery: transaction state:I
2015-06-02 21:57:27 DEBUG: pid 17729: can_query_context_destroy: query context 0x769e10 is still used. query:SET extra_float_digits = 3
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_set_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_unset_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: pool_set_query_in_progress: done
2015-06-02 21:57:27 DEBUG: pid 17729: Parse: waiting for master completing the query
2015-06-02 21:57:27 LOG:   pid 17729: DB node id: 0 backend pid: 17758 statement: Parse: ���;�
2015-06-02 21:57:27 DEBUG: pid 17729: wait_for_query_response: waiting for backend 0 completing the query
2015-06-02 21:57:27 DEBUG: pid 17729: detect_error: kind: 1
2015-06-02 21:57:27 DEBUG: pid 11464: reap_handler called
2015-06-02 21:57:27 DEBUG: pid 11464: reap_handler: call wait3
2015-06-02 21:57:27 ERROR: pid 11464: Child process 17729 was terminated by segmentation fault
2015-06-02 21:57:27 DEBUG: pid 11464: child 17729 exits with status 11 by signal 11
2015-06-02 21:57:27 DEBUG: pid 11464: fork a new child pid 17759
2015-06-02 21:57:27 DEBUG: pid 11464: reap_handler: normally exited
2015-06-02 21:57:27 DEBUG: pid 17759: I am 17759
2015-06-02 21:57:27 DEBUG: pid 17759: pool_initialize_private_backend_status: initialize backend status

Postgres log samples:

I do see connections authorized/established but immediately disconnections are happening with in milliseconds.

~Suresh
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20150603/cb006b79/attachment-0001.html>