[Pgpool-general] Logging / why was failover_handler called?

Thu May 15 15:32:41 UTC 2008

Hello!

We just had an failover event:

--------------------------------------------------------------------------------
2008-05-15 14:17:14 DEBUG: pid 24316: ReadyForQuery: message length: 5
2008-05-15 14:17:14 DEBUG: pid 24316: ReadyForQuery: transaction state: I
2008-05-15 14:17:14 DEBUG: pid 24316: read kind from frontend Q(51)
2008-05-15 14:17:14 LOG:   pid 24316: statement: SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS enc
oding, datlastsysoid
  FROM pg_database WHERE oid = 33100
2008-05-15 14:17:14 DEBUG: pid 24316: waiting for backend 0 completing the query
2008-05-15 14:17:14 DEBUG: pid 24316: waiting for backend 1 completing the query
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 0 th backend S NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 1 th backend S NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: pool_process_query: kind from backend: S
2008-05-15 14:17:14 DEBUG: pid 24316: pool_read_message_length2: master slot: 0 length: 23
2008-05-15 14:17:14 DEBUG: pid 24316: pool_read_message_length2: master slot: 1 length: 23
2008-05-15 14:17:14 DEBUG: pid 24316: 0 th backend: name: DateStyle value: ISO, MDY
2008-05-15 14:17:14 DEBUG: pid 24316: 1 th backend: name: DateStyle value: ISO, MDY
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: pool_process_query: kind from backend: C
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 1 th backend T NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: pool_process_query: kind from backend: T
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2008-05-15 14:17:14 DEBUG: pid 24316: read_kind_from_backend: read kind from 1 th backend D NUM_BACKENDS: 2
2008-05-15 14:17:14 ERROR: pid 24316: pool_process_query: 1 th kind D does not match with master connection kind C
2008-05-15 14:17:14 LOG:   pid 24316: notice_backend_error: 1 fail over request from pid 24316
2008-05-15 14:17:14 DEBUG: pid 30127: failover_handler called
2008-05-15 14:17:14 DEBUG: pid 30127: failover_handler: starting to select new master node
2008-05-15 14:17:14 LOG:   pid 30127: starting degeneration. shutdown host 62.65.130.180(6543)
2008-05-15 14:17:14 LOG:   pid 30127: failover_handler: do not restart pgpool. same master node 0 was selected
2008-05-15 14:17:14 LOG:   pid 30127: failover done. shutdown host 62.65.130.180(6543)
2008-05-15 14:17:14 DEBUG: pid 30127: reap_handler called
2008-05-15 14:17:14 DEBUG: pid 30127: reap_handler: call wait3
--------------------------------------------------------------------------------

- What is the cause for the failover? Is it caused by the multistatement query before?

- What I can see on the postgresql server itselt is:

--------------------------------------------------------------------------------
2008-05-15 14:17:13 CEST ERROR:  syntax error at or near "000" at character 413
[Big update query snippet]
2008-05-15 14:17:13 CEST LOG:  statement:  RESET ALL
2008-05-15 14:17:13 CEST LOG:  statement:  SET SESSION AUTHORIZATION DEFAULT
2008-05-15 14:17:14 CEST LOG:  connection received: host=62.65.130.181 port=58401
2008-05-15 14:17:14 CEST LOG:  connection authorized: user=postgres database=nello_test
2008-05-15 14:17:14 CEST LOG:  statement: SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS encoding, datlastsysoid FROM pg_database WHERE oid = 33100
2008-05-15 14:17:14 CEST LOG:  unexpected EOF on client connection
--------------------------------------------------------------------------------

-> no more connections coming in.

- Are there any news regarding the multistatement issue
  (last known status was in Message-Id: <20080319.174931.-1221529424.y-asaba at sraoss.co.jp>)?

It is interesting, that the same query worked before:

--------------------------------------------------------------------------------
2008-05-14 09:24:49 LOG:   pid 30462: statement: SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS encoding, datlastsysoid FROM pg_database WHERE datname='postgres'
2008-05-14 09:24:49 DEBUG: pid 30462: waiting for backend 0 completing the query
2008-05-14 09:24:49 DEBUG: pid 30462: waiting for backend 1 completing the query
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend S NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend S NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: S
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length2: master slot: 0 length: 23
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length2: master slot: 1 length: 23
2008-05-14 09:24:49 DEBUG: pid 30462: 0 th backend: name: DateStyle value: ISO, MDY
2008-05-14 09:24:49 DEBUG: pid 30462: 1 th backend: name: DateStyle value: ISO, MDY
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: C
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend T NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: T
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend D NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend D NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: D
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: C
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: Z
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length: slot: 0 length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length: slot: 1 length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: ReadyForQuery: message length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: ReadyForQuery: transaction state: I
2008-05-14 09:24:49 DEBUG: pid 30462: read kind from frontend Q(51)
2008-05-14 09:24:49 LOG:   pid 30462: statement: set client_encoding to 'UNICODE'
2008-05-14 09:24:49 DEBUG: pid 30462: waiting for backend 0 completing the query
2008-05-14 09:24:49 DEBUG: pid 30462: waiting for backend 1 completing the query
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend S NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend S NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: S
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length2: master slot: 0 length: 28
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length2: master slot: 1 length: 28
2008-05-14 09:24:49 DEBUG: pid 30462: 0 th backend: name: client_encoding value: UNICODE
2008-05-14 09:24:49 DEBUG: pid 30462: 1 th backend: name: client_encoding value: UNICODE
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: C
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
2008-05-14 09:24:49 DEBUG: pid 30462: pool_process_query: kind from backend: Z
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length: slot: 0 length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: pool_read_message_length: slot: 1 length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: ReadyForQuery: message length: 5
2008-05-14 09:24:49 DEBUG: pid 30462: ReadyForQuery: transaction state: I
2008-05-14 09:24:49 DEBUG: pid 30462: read kind from frontend Q(51)
2008-05-14 09:24:49 LOG:   pid 30462: statement: SELECT version();
2008-05-14 09:24:49 DEBUG: pid 30462: waiting for backend 1 completing the query
--------------------------------------------------------------------------------

Regarding the logging:

- What does NUM_BACKENDS mean? It is 1 or 2 here. Even after the failover event it changes
  from 1 to 2 and back:

--------------------------------------------------------------------------------
2008-05-15 14:17:14 DEBUG: pid 24881: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
...
2008-05-15 14:17:14 DEBUG: pid 24433: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 1
--------------------------------------------------------------------------------

Sincerly,

Nico

-- 
Think about Free and Open Source Software (FOSS).
http://nico.schottelius.org/documentations/foss/the-term-foss/

PGP: BFE4 C736 ABE5 406F 8F42  F7CF B8BE F92A 9885 188C
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
Url : http://pgfoundry.org/pipermail/pgpool-general/attachments/20080515/2cbf87a9/attachment.bin 