[pgpool-general: 1432] Re: Segfault on pgpool2-3.2.3 ""*** glibc detected *** double free or corruption (!prev)"

[Marcin Mirosław]

W dniu 26.02.2013 00:14, Tatsuo Ishii pisze:

Hi
>> If I can provide more information please let me know.
> 
> Do you know how to reproduce the problem?
I don't know how. It looks the crash happens usually when SpamAssassin
connects to postgres (and it tries to use bayes). I'm attaching debug
log from pgpool2, maybe it brings some light in this case.
Thanks,
Marcin



-------------- next part --------------
2013-02-26T12:54:28.683369+01:00 pgpool[13297]: fork a new child pid 14857
2013-02-26T12:54:28.686195+01:00 pgpool[14857]: I am 14857
2013-02-26T12:54:28.686243+01:00 pgpool[14857]: pool_initialize_private_backend_status: initialize backend status
2013-02-26T12:54:30.134197+01:00 pgpool[14857]: I am 14857 accept fd 7
2013-02-26T12:54:30.134827+01:00 pgpool[14857]: connection received: host=data-serwer port=42368
2013-02-26T12:54:30.135230+01:00 pgpool[14857]: Protocol Major: 3 Minor: 0 database: poczta user: listonosz
2013-02-26T12:54:30.135483+01:00 pgpool[14857]: new_connection: connecting 0 backend
2013-02-26T12:54:30.136826+01:00 pgpool[14857]: pool_ssl: sending client->server SSL request
2013-02-26T12:54:30.139654+01:00 pgpool[14857]: pool_ssl: client->server SSL response: S
2013-02-26T12:54:30.151129+01:00 pgpool[14857]: pool_read_message_length: slot: 0 length: 12
2013-02-26T12:54:30.151186+01:00 pgpool[14857]: pool_do_auth: auth kind:5
2013-02-26T12:54:30.151228+01:00 pgpool[14857]: trying md5 authentication
2013-02-26T12:54:30.151261+01:00 pgpool[14857]: DB node id: 0 salt: 5f5fce1a
2013-02-26T12:54:30.157358+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 22
2013-02-26T12:54:30.157425+01:00 pgpool[14857]: 0 th backend: name: application_name value: 
2013-02-26T12:54:30.157451+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 25
2013-02-26T12:54:30.157474+01:00 pgpool[14857]: 0 th backend: name: client_encoding value: UTF8
2013-02-26T12:54:30.157498+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 23
2013-02-26T12:54:30.157521+01:00 pgpool[14857]: 0 th backend: name: DateStyle value: ISO, DMY
2013-02-26T12:54:30.157545+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 25
2013-02-26T12:54:30.157568+01:00 pgpool[14857]: 0 th backend: name: integer_datetimes value: on
2013-02-26T12:54:30.157592+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 27
2013-02-26T12:54:30.157616+01:00 pgpool[14857]: 0 th backend: name: IntervalStyle value: postgres
2013-02-26T12:54:30.157668+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 21
2013-02-26T12:54:30.158571+01:00 pgpool[14857]: 0 th backend: name: is_superuser value: off
2013-02-26T12:54:30.158608+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 25
2013-02-26T12:54:30.158638+01:00 pgpool[14857]: 0 th backend: name: server_encoding value: UTF8
2013-02-26T12:54:30.158679+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 25
2013-02-26T12:54:30.158704+01:00 pgpool[14857]: 0 th backend: name: server_version value: 9.2.3
2013-02-26T12:54:30.158728+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 36
2013-02-26T12:54:30.158751+01:00 pgpool[14857]: 0 th backend: name: session_authorization value: listonosz
2013-02-26T12:54:30.158775+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 35
2013-02-26T12:54:30.158799+01:00 pgpool[14857]: 0 th backend: name: standard_conforming_strings value: on
2013-02-26T12:54:30.158822+01:00 pgpool[14857]: pool_read_message_length2: master slot: 0 length: 20
2013-02-26T12:54:30.158931+01:00 pgpool[14857]: 0 th backend: name: TimeZone value: Poland
2013-02-26T12:54:30.159574+01:00 pgpool[14857]: pool_read_message_length: slot: 0 length: 12
2013-02-26T12:54:30.159634+01:00 pgpool[14857]: pool_do_auth: cp->info[i]:0x30168420800 pid:14858
2013-02-26T12:54:30.159686+01:00 pgpool[14857]: pool_send_auth_ok: send pid 14858 to frontend
2013-02-26T12:54:30.159722+01:00 pgpool[14857]: pool_unset_query_in_progress: done
2013-02-26T12:54:30.159758+01:00 pgpool[14857]: pool_unset_command_success: done
2013-02-26T12:54:30.159861+01:00 pgpool[14857]: pool_unset_writing_transaction: done
2013-02-26T12:54:30.159930+01:00 pgpool[14857]: pool_unset_failed_transaction: done
2013-02-26T12:54:30.159964+01:00 pgpool[14857]: pool_unset_transaction_isolation: done
2013-02-26T12:54:30.160000+01:00 pgpool[14857]: pool_unset_skip_reading_from_backends: done
2013-02-26T12:54:30.160093+01:00 pgpool[14857]: pool_unset_ignore_till_sync: done
2013-02-26T12:54:30.160144+01:00 pgpool[14857]: read_kind_from_backend: kind: Z from 0 th backend
2013-02-26T12:54:30.160502+01:00 pgpool[14857]: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 1
2013-02-26T12:54:30.160560+01:00 pgpool[14857]: ProcessBackendResponse: kind from backend: Z
2013-02-26T12:54:30.160628+01:00 pgpool[14857]: pool_read_message_length: slot: 0 length: 5
2013-02-26T12:54:30.160663+01:00 pgpool[14857]: ReadyForQuery: transaction state:
2013-02-26T12:54:30.160699+01:00 pgpool[14857]: ProcessBackendResponse: Ready For Query
2013-02-26T12:54:30.162338+01:00 pgpool[14857]: ProcessFrontendResponse: kind from frontend Q(51)
2013-02-26T12:54:30.162400+01:00 pgpool[14857]: pool_unset_doing_extended_query_message: done
2013-02-26T12:54:30.162432+01:00 pgpool[14857]: statement: begin
2013-02-26T12:54:30.162466+01:00 pgpool[14857]: pool_set_query_in_progress: done
2013-02-26T12:54:30.162499+01:00 pgpool[14857]: pool_extract_table_oids: other than INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER TABLE statement
2013-02-26T12:54:30.162533+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: begin
2013-02-26T12:54:30.162567+01:00 pgpool[14857]: wait_for_query_response: waiting for backend 0 completing the query
2013-02-26T12:54:30.163461+01:00 pgpool[14857]: read_kind_from_backend: kind: C from 0 th backend
2013-02-26T12:54:30.163525+01:00 pgpool[14857]: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 1
2013-02-26T12:54:30.163557+01:00 pgpool[14857]: ProcessBackendResponse: kind from backend: C
2013-02-26T12:54:30.163739+01:00 pgpool[14857]: pool_unset_writing_transaction: done
2013-02-26T12:54:30.163994+01:00 pgpool[14857]: pool_unset_failed_transaction: done
2013-02-26T12:54:30.164248+01:00 pgpool[14857]: pool_unset_transaction_isolation: done
2013-02-26T12:54:30.164505+01:00 pgpool[14857]: pool_set_command_success: done
2013-02-26T12:54:30.164759+01:00 pgpool[14857]: read_kind_from_backend: kind: Z from 0 th backend
2013-02-26T12:54:30.164926+01:00 pgpool[14857]: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 1
2013-02-26T12:54:30.165091+01:00 pgpool[14857]: ProcessBackendResponse: kind from backend: Z
2013-02-26T12:54:30.165431+01:00 pgpool[14857]: pool_read_message_length: slot: 0 length: 5
2013-02-26T12:54:30.165597+01:00 pgpool[14857]: ReadyForQuery: transaction state:T
2013-02-26T12:54:30.166127+01:00 pgpool[14857]: pool_unset_writing_transaction: done
2013-02-26T12:54:30.166292+01:00 pgpool[14857]: pool_unset_failed_transaction: done
2013-02-26T12:54:30.166457+01:00 pgpool[14857]: pool_unset_transaction_isolation: done
2013-02-26T12:54:30.166621+01:00 pgpool[14857]: pool_unset_query_in_progress: done
2013-02-26T12:54:30.166786+01:00 pgpool[14857]: pool_unset_query_in_progress: done
2013-02-26T12:54:30.168550+01:00 pgpool[14857]: ProcessBackendResponse: Ready For Query
2013-02-26T12:54:30.168716+01:00 pgpool[14857]: ProcessFrontendResponse: kind from frontend P(50)
2013-02-26T12:54:30.168906+01:00 pgpool[14857]: pool_unset_doing_extended_query_message: done
2013-02-26T12:54:30.169075+01:00 pgpool[14857]: pool_set_doing_extended_query_message: done
2013-02-26T12:54:30.169241+01:00 pgpool[14857]: pool_set_query_in_progress: done
2013-02-26T12:54:30.169405+01:00 pgpool[14857]: Parse: statement name <dbdpg_p22624_1>
2013-02-26T12:54:30.169570+01:00 pgpool[14857]: pool_set_query_in_progress: done
2013-02-26T12:54:30.169605+01:00 pgpool[14857]: pool_has_insertinto_or_locking_clause: returns 0
2013-02-26T12:54:30.169629+01:00 pgpool[14857]: pool_has_non_immutable_function_call: 0
2013-02-26T12:54:30.169653+01:00 pgpool[14857]: temp_table_walker: relname: bayes_vars
2013-02-26T12:54:30.169676+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
2013-02-26T12:54:30.169939+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
2013-02-26T12:54:30.176268+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.176513+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.176751+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.177050+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.178642+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.178932+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.179112+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.179172+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.179204+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.179239+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.179274+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.179365+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.179399+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.179433+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.179466+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.179499+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.179561+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'bayes_vars' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
2013-02-26T12:54:30.179596+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'bayes_vars' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
2013-02-26T12:54:30.181588+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.181653+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.181685+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.181716+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.181883+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.182144+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.182393+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.182638+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.182883+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.183129+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.183373+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.183617+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.183950+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.184190+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.184428+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.184671+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.184909+01:00 pgpool[14857]: system_catalog_walker: relname: bayes_vars
2013-02-26T12:54:30.185147+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_catalog.pg_proc AS p WHERE p.proname = 'pgpool_regclass'
2013-02-26T12:54:30.185385+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_catalog.pg_proc AS p WHERE p.proname = 'pgpool_regclass'
2013-02-26T12:54:30.185623+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.185869+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.186106+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.186343+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.187921+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.188160+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.188445+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.188684+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.188942+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.189182+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.189484+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.189723+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.189960+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.190197+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.190440+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.190678+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.190915+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'pg_namespace' AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2013-02-26T12:54:30.191154+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'pg_namespace' AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2013-02-26T12:54:30.191392+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.191633+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.191871+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.192108+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.193690+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.193929+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.194211+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.194450+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.194697+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.194946+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.195255+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.195494+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.195742+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.195983+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.196220+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.196464+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.196702+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'bayes_vars' AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2013-02-26T12:54:30.196941+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.relname = 'bayes_vars' AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2013-02-26T12:54:30.197179+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.197417+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.197654+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.197892+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.198132+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.198370+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.200049+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.200293+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.200577+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.200819+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.201064+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.201306+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.201612+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.201860+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.202107+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.202354+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.202601+01:00 pgpool[14857]: make_table_name_from_rangevar: tablename:bayes_vars
2013-02-26T12:54:30.202848+01:00 pgpool[14857]: view_walker: relname: bayes_vars
2013-02-26T12:54:30.203094+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'bayes_vars' AND c.relkind = 'v'
2013-02-26T12:54:30.203342+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'bayes_vars' AND c.relkind = 'v'
2013-02-26T12:54:30.203590+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.203836+01:00 pgpool[14857]: do_query: Parse complete received
2013-02-26T12:54:30.204083+01:00 pgpool[14857]: do_query: kind: 2
2013-02-26T12:54:30.204329+01:00 pgpool[14857]: do_query: Bind complete received
2013-02-26T12:54:30.204579+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.204825+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.206432+01:00 pgpool[14857]: do_query: kind: T
2013-02-26T12:54:30.206685+01:00 pgpool[14857]: do_query: row description received
2013-02-26T12:54:30.206979+01:00 pgpool[14857]: num_fileds: 1
2013-02-26T12:54:30.207235+01:00 pgpool[14857]: do_query: kind: D
2013-02-26T12:54:30.207477+01:00 pgpool[14857]: do_query: data row received
2013-02-26T12:54:30.207733+01:00 pgpool[14857]: do_query: kind: C
2013-02-26T12:54:30.207987+01:00 pgpool[14857]: do_query: Command complete received
2013-02-26T12:54:30.208296+01:00 pgpool[14857]: do_query: kind: 3
2013-02-26T12:54:30.208545+01:00 pgpool[14857]: do_query: Close complete received
2013-02-26T12:54:30.208792+01:00 pgpool[14857]: do_qyery: all state completed
2013-02-26T12:54:30.209075+01:00 pgpool[14857]: make_table_name_from_rangevar: tablename:bayes_vars
2013-02-26T12:54:30.209324+01:00 pgpool[14857]: unlogged_table_walker: relname: bayes_vars
2013-02-26T12:54:30.209571+01:00 pgpool[14857]: DB node id: 0 backend pid: 14858 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relpersistence'
2013-02-26T12:54:30.209820+01:00 pgpool[14857]: do_query: extended:1 query:SELECT count(*) FROM pg_catalog.pg_class AS c, pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relpersistence'
2013-02-26T12:54:30.210068+01:00 pgpool[14857]: do_query: kind: 1
2013-02-26T12:54:30.497375+01:00 pgpool[13297]: child 14857 exits with status 134 by signal 6