[pgpool-general: 2451] Re: Segfault in pgpool triggered by a background query
Tatsuo Ishii
ishii at postgresql.org
Mon Jan 20 11:05:11 JST 2014
Could you please provide pgpool-II version, pgpool.conf, PostgreSQL
version and backtrace of pgpool when the sefault occured?
Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp
> Sorry, my previous e-mail was sort of useless, I really did have an invalid
> query, so my description was misleading.
>
> I did some more digging and found this:
>
> 2014-01-17 13:34:04 DEBUG: pid 3668: ProcessFrontendResponse: kind from
> frontend Q(51)
> 2014-01-17 13:34:04 DEBUG: pid 3668:
> pool_unset_doing_extended_query_message: done
> 2014-01-17 13:34:04 DEBUG: pid 3668: statement2: insert into account (id,
> bid, balance, filler) values (1, 1, 0.0, "FRESH ACCOUNT");
> 2014-01-17 13:34:04 DEBUG: pid 3668: pool_set_query_in_progress: done
> 2014-01-17 13:34:04 DEBUG: pid 3668: do_query: extended:0 query:SELECT
> count(*) from (SELECT has_function_privilege('kristjan',
> 'pgpool_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM
> pg_catalog.pg_proc AS p WHERE p.proname = 'pgpool_regclass')) AS s
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: do_query: error while reading message
> kind
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_search_relcache: do_query failed
> 2014-01-17 13:34:04 DEBUG: pid 3668: do_query: extended:0 query:SELECT
> attname, d.adsrc, coalesce((d.adsrc LIKE '%now()%' OR d.adsrc LIKE
> '%''now''::text%') AND (a.atttypid = 'timestamp'::regtype::oid OR
> a.atttypid = 'timestamp with time zone'::regtype::oid OR a.atttypid =
> 'date'::regtype::oid OR a.atttypid = 'time'::regtype::oid OR a.atttypid =
> 'time with time zone'::regtype::oid) , false) FROM pg_catalog.pg_class c,
> pg_catalog.pg_attribute a LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid
> = d.adrelid AND a.attnum = d.adnum) WHERE c.oid = a.attrelid AND a.attnum
>>= 1 AND a.attisdropped = 'f' AND c.relname = 'account' ORDER BY a.attnum
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: do_query: error while reading message
> kind
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_search_relcache: do_query failed
> 2014-01-17 13:34:04 DEBUG: pid 3668: wait_for_query_response: waiting for
> backend 1 completing the query
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_read: EOF encountered with
> backend
> 2014-01-17 13:34:04 ERROR: pid 3668: read_kind_from_backend: failed to read
> kind from 1 th backend
> 2014-01-17 13:34:04 LOG: pid 3668: do_child: exits with status 1 due to
> error
> 2014-01-17 13:34:04 ERROR: pid 3668: pool_flush_it: write failed to backend
> (1). reason: Broken pipe offset: 0 wlen: 5
> 2014-01-17 13:34:04 DEBUG: pid 3671: I am 3671 accept fd 6
> 2014-01-17 13:34:04 DEBUG: pid 3671: read_startup_packet: application_name:
> psql
> 2014-01-17 13:34:04 DEBUG: pid 3671: Protocol Major: 3 Minor: 0 database:
> bench_parallel user: kristjan
> 2014-01-17 13:34:04 DEBUG: pid 3671: new_connection: connecting 0 backend
> 2014-01-17 13:34:04 DEBUG: pid 3671: new_connection: skipping slot 0
> because backend_status = 3
> 2014-01-17 13:34:04 DEBUG: pid 3671: new_connection: connecting 1 backend
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_ssl: SSL requested but SSL
> support is not available
> 2014-01-17 13:34:04 DEBUG: pid 3639: reap_handler called
> 2014-01-17 13:34:04 DEBUG: pid 3639: reap_handler: call wait3
> 2014-01-17 13:34:04 DEBUG: pid 3639: child 3668 exits with status 256
> 2014-01-17 13:34:04 DEBUG: pid 3639: fork a new child pid 3675
> 2014-01-17 13:34:04 DEBUG: pid 3639: reap_handler: normally exited
> 2014-01-17 13:34:04 DEBUG: pid 3675: I am 3675
> 2014-01-17 13:34:04 DEBUG: pid 3675:
> pool_initialize_private_backend_status: initialize backend status
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length: slot: 1
> length: 8
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_do_auth: auth kind:0
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 26
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: application_name
> value: psql
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: client_encoding
> value: UTF8
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 23
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: DateStyle value:
> ISO, MDY
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: integer_datetimes
> value: on
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 27
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: IntervalStyle
> value: postgres
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 20
> 2014-01-17 13:34:04 DEBUG: pid 3671: 1 th backend: name: is_superuser
> value: on
> 2014-01-17 13:34:04 DEBUG: pid 3671: pool_read_message_length2: master
> slot: 1 length: 25
>
> And with more digging I found that pgpool really does not "like" the
> following query regardless of whether the backend was another instance of
> pgpool or a Postgre server:
>
> Query:
>
> bench_parallel=# SELECT count(*) from (SELECT
> has_function_privilege('kristjan', 'pgpool_regclass(cstring)', 'execute')
> WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname =
> 'pgpool_regclass')) AS s;
> The connection to the server was lost. Attempting reset: Succeeded.
>
> Output from pgpool daemon in debug mode, note the segfault:
>
> 2014-01-17 15:01:52 DEBUG: pid 3569: ProcessFrontendResponse: kind from
> frontend Q(51)
> 2014-01-17 15:01:52 DEBUG: pid 3569:
> pool_unset_doing_extended_query_message: done
> 2014-01-17 15:01:52 DEBUG: pid 3569: statement2: SELECT count(*) from
> (SELECT has_function_privilege('kristjan', 'pgpool_regclass(cstring)',
> 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE
> p.proname = 'pgpool_regclass')) AS s;
> 2014-01-17 15:01:52 DEBUG: pid 3569: pool_set_query_in_progress: done
> 2014-01-17 15:01:52 DEBUG: pid 3569: initSelectStmt: ANALYZE now(0)
> 2014-01-17 15:01:52 DEBUG: pid 3569: initSelectStmt: ANALYZE now(1)
> 2014-01-17 15:01:52 DEBUG: pid 3569: inside build_range_info num= 1
> current_select=1
> 2014-01-17 15:01:52 DEBUG: pid 3569: inside build_range_info const or func
> 1
> 2014-01-17 15:01:52 DEBUG: pid 3569: initSelectStmt: ANALYZE now(2)
> 2014-01-17 15:01:52 DEBUG: pid 3569: inside build_range_info num= 1
> current_select=2
> 2014-01-17 15:01:52 DEBUG: pid 3569: inside build_range_info const or func
> 2
> 2014-01-17 15:01:52 DEBUG: pid 3569: inside build_virtual_info no dist
> state=E p
> 2014-01-17 15:01:52 DEBUG: pid 3556: I am 3556 accept fd 10
> 2014-01-17 15:01:52 DEBUG: pid 3556: read_startup_packet: application_name:
> psql
> 2014-01-17 15:01:52 DEBUG: pid 3556: Protocol Major: 3 Minor: 0 database:
> bench_parallel user: kristjan
> 2014-01-17 15:01:52 DEBUG: pid 3556: new_connection: connecting 0 backend
> 2014-01-17 15:01:52 DEBUG: pid 3556: new_connection: connecting 1 backend
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_ssl: SSL requested but SSL
> support is not available
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_ssl: SSL requested but SSL
> support is not available
> 2014-01-17 15:01:52 DEBUG: pid 3516: reap_handler called
> 2014-01-17 15:01:52 DEBUG: pid 3516: reap_handler: call wait3
> 2014-01-17 15:01:52 ERROR: pid 3516: Child process 3569 was terminated by
> segmentation fault
> 2014-01-17 15:01:52 DEBUG: pid 3516: child 3569 exits with status 11 by
> signal 11
> 2014-01-17 15:01:52 DEBUG: pid 3516: fork a new child pid 3570
> 2014-01-17 15:01:52 DEBUG: pid 3516: reap_handler: normally exited
> 2014-01-17 15:01:52 DEBUG: pid 3570: I am 3570
> 2014-01-17 15:01:52 DEBUG: pid 3570:
> pool_initialize_private_backend_status: initialize backend status
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 0
> length: 8
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 1
> length: 8
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_do_auth: auth kind:0
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 26
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 26
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: application_name
> value: psql
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: application_name
> value: psql
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: client_encoding
> value: UTF8
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: client_encoding
> value: UTF8
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 23
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 23
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: DateStyle value:
> ISO, MDY
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: DateStyle value:
> ISO, MDY
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: integer_datetimes
> value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: integer_datetimes
> value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 27
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 27
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: IntervalStyle
> value: postgres
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: IntervalStyle
> value: postgres
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 20
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 20
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: is_superuser
> value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: is_superuser
> value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: server_encoding
> value: UTF8
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: server_encoding
> value: UTF8
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 25
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: server_version
> value: 9.3.2
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: server_version
> value: 9.3.2
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 35
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 35
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name:
> session_authorization value: kristjan
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name:
> session_authorization value: kristjan
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 35
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 35
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name:
> standard_conforming_strings value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name:
> standard_conforming_strings value: on
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 0 length: 28
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length2: master
> slot: 1 length: 28
> 2014-01-17 15:01:52 DEBUG: pid 3556: 0 th backend: name: TimeZone value:
> Europe/Tallinn
> 2014-01-17 15:01:52 DEBUG: pid 3556: 1 th backend: name: TimeZone value:
> Europe/Tallinn
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 0
> length: 12
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 1
> length: 12
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_do_auth:
> cp->info[i]:0x7f5eca6b7000 pid:10951
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_do_auth:
> cp->info[i]:0x7f5eca6b7088 pid:10298
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_send_auth_ok: send pid 10298 to
> frontend
> 2014-01-17 15:01:52 DEBUG: pid 3556: select_load_balancing_node: selected
> backend id is 1
> 2014-01-17 15:01:52 DEBUG: pid 3556: selected load balancing node: 1
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_query_in_progress: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_command_success: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_writing_transaction: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_failed_transaction: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_transaction_isolation: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_skip_reading_from_backends:
> done
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_unset_ignore_till_sync: done
> 2014-01-17 15:01:52 DEBUG: pid 3556: read_kind_from_backend: kind: Z from 0
> th backend
> 2014-01-17 15:01:52 DEBUG: pid 3556: read_kind_from_backend: read kind from
> 0 th backend Z NUM_BACKENDS: 2
> 2014-01-17 15:01:52 DEBUG: pid 3556: read_kind_from_backend: kind: Z from 1
> th backend
> 2014-01-17 15:01:52 DEBUG: pid 3556: read_kind_from_backend: read kind from
> 1 th backend Z NUM_BACKENDS: 2
> 2014-01-17 15:01:52 DEBUG: pid 3556: ProcessBackendResponse: kind from
> backend: Z
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 0
> length: 5
> 2014-01-17 15:01:52 DEBUG: pid 3556: pool_read_message_length: slot: 1
> length: 5
> 2014-01-17 15:01:52 DEBUG: pid 3556: ReadyForQuery: transaction state:
> 2014-01-17 15:01:52 DEBUG: pid 3556: ReadyForQuery: transaction state:I
> 2014-01-17 15:01:52 DEBUG: pid 3556: ProcessBackendResponse: Ready For
> Query
> 2014-01-17 15:01:52 DEBUG: pid 3570: pool_ssl: SSL requested but SSL
> support is not available
> 2014-01-17 15:01:52 DEBUG: pid 3570: s_do_auth: auth kind: 0
> 2014-01-17 15:01:52 DEBUG: pid 3570: s_do_auth: backend key data received
> 2014-01-17 15:01:52 DEBUG: pid 3570: s_do_auth: transaction state: I
>
> The nodes output the following. The error happened also before installation
> of pgpool_regclass plus I was able to run 'CREATE EXTENSION'
> pgpool_regclass through pgpool.
>
> bench_parallel=# SELECT count(*) from (SELECT
> has_function_privilege('kristjan', 'pgpool_regclass(cstring)', 'execute')
> WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname =
> 'pgpool_regclass')) AS s;
> count
> -------
> 1
> (1 row)
More information about the pgpool-general
mailing list