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

[Muhammad Usama]

On Thu, Jun 4, 2015 at 9:28 PM, Suresh Tavvala <Suresh.Tavvala at mozido.com>
wrote:

>  Hi Muhammad,
>
>  Thank you for reply and sorry for delay in responding back. Here are
> requested details
>
>   pgpool-II. version 3.2.0
>

pgpool-II 3.2.0 is very old, Any specific reason you are using this very
old version. Can you check with a newer version of pgpool-II if the problem
still exists?

>
>  Here I am attaching core dump file. And also would you mind to let me
> know what core dump analyzer you are using ?
>

 I normally use GDB for debugging and analyzing core files.

Thanks
Muhammad Usama

>
>  ~Suresh
>
>   From: Muhammad Usama <m.usama at gmail.com>
> Date: Wednesday, June 3, 2015 at 2:31 PM
> To: suresh tavvala <Suresh.Tavvala at mozido.com>
> Cc: "pgpool-general at pgpool.net" <pgpool-general at pgpool.net>
> Subject: Re: [pgpool-general: 3779] Unable to get connections by tomcat
> common dbcp or c3p0 connection pooling from pgpool host/port
>
>   Hi
>
>  What version of pgpool-II are you using? Log suggests that a
> segmentation fault is causing the child process to crash.
>
>  Can you please share the core dump of crashing child process.
>
>  Thanks
> Best regards
> Muhammad Usama
>
>
> On Wed, Jun 3, 2015 at 10:09 PM, Suresh Tavvala <Suresh.Tavvala at mozido.com
> > wrote:
>
>>  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…..
>>
>>
>>
>>  *A**pplication 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
>>
>> _______________________________________________
>> pgpool-general mailing list
>> pgpool-general at pgpool.net
>> http://www.pgpool.net/mailman/listinfo/pgpool-general
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20150605/d8b0f25c/attachment-0001.html>