[Pgpool-general] Error in pgpool

Tue Mar 24 15:11:17 UTC 2009

Thanks but I'm looking for the PostgreSQL *when* and *how* the
prepared statement (in this case S_4) was created. Probably that can be
found a little bit earlier in the PostgreSQL log.
--
Tatsuo Ishii
SRA OSS, Inc. Japan

> Tatsuo,
> 
> Here are the db and pgpool logs at the time of failure. (Pgpool finds
> the prepared statement S-4 on one server but fails to find one on the
> other server. As a result pgpool exits the child with Kind mis-match
> error) Let us know if this helps or you need further information.
> 
> Db log on master:
> 
> 2009-03-23 09:49:42 PDT [13934]: [165-1] LOG:  duration: 0.054 ms
> statement:  RESET ALL
> 2009-03-23 09:49:42 PDT [13934]: [166-1] LOG:  duration: 0.021 ms
> statement:  SET SESSION AUTHORIZATION DEFAULT
> 2009-03-23 09:49:42 PDT [13934]: [167-1] LOG:  duration: 0.025 ms
> statement: DEALLOCATE "S_1"
> 2009-03-23 09:49:42 PDT [13934]: [168-1] LOG:  duration: 0.014 ms
> statement: DEALLOCATE "S_4"
> 2009-03-23 09:49:42 PDT [13934]: [169-1] LOG:  unexpected EOF on
> client connection
> 2009-03-23 09:49:42 PDT [13934]: [170-1] LOG:  disconnection: session
> time: 1:12:54.620 user=aaaa database=test host=xx.xx.xx.xx port=53261
> 
> Db log on slave:
> 
> 2009-03-23 09:49:42 PDT [8827]: [9-1] LOG:  duration: 0.037 ms
> statement:  RESET ALL
> 2009-03-23 09:49:42 PDT [8827]: [10-1] LOG:  duration: 0.034 ms
> statement:  SET SESSION AUTHORIZATION DEFAULT
> 2009-03-23 09:49:42 PDT [2838]: [192-1] LOG:  duration: 0.042 ms
> statement:  RESET ALL
> 2009-03-23 09:49:42 PDT [2838]: [193-1] LOG:  duration: 0.030 ms
> statement:  SET SESSION AUTHORIZATION DEFAULT
> 2009-03-23 09:49:42 PDT [2838]: [194-1] LOG:  duration: 0.028 ms
> statement: DEALLOCATE "S_1"
> 2009-03-23 09:49:42 PDT [2838]: [195-1] ERROR:  prepared statement
> "S_4" does not exist
> 2009-03-23 09:49:42 PDT [2838]: [196-1] STATEMENT:  DEALLOCATE "S_4"
> 2009-03-23 09:49:42 PDT [2838]: [197-1] LOG:  unexpected EOF on client
> connection
> 2009-03-23 09:49:42 PDT [2838]: [198-1] LOG:  disconnection: session
> time: 1:12:54.619 user=aaaa database=test host=xx.xx.xx.zz port=52815
> 
> pgpool logs:
> 2009-03-23 09:49:42 DEBUG: pid 1218: statement2: DEALLOCATE "S_1"
> 2009-03-23 09:49:42 DEBUG: pid 1218: SimpleQuery: set master_slave_dml
> query: DEALLOCATE "S_1"
> 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for backend 0 completing the query
> 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for backend 1 completing the query
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 0 th backend C NUM_BACKENDS: 2
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 1 th backend C NUM_BACKENDS: 2
> 2009-03-23 09:49:42 DEBUG: pid 1218: pool_process_query: kind from backend: C
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 0 th backend Z NUM_BACKENDS: 2
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 1 th backend Z NUM_BACKENDS: 2
> 2009-03-23 09:49:42 DEBUG: pid 1218: pool_process_query: kind from backend: Z
> 2009-03-23 09:49:42 DEBUG: pid 1218: pool_read_message_length: slot: 0 length: 5
> 2009-03-23 09:49:42 DEBUG: pid 1218: pool_read_message_length: slot: 1 length: 5
> 2009-03-23 09:49:42 DEBUG: pid 1218: ReadyForQuery: message length: 5
> 2009-03-23 09:49:42 DEBUG: pid 1218: ReadyForQuery: transaction state: I
> 2009-03-23 09:49:42 DEBUG: pid 1218: statement2: DEALLOCATE "S_4"
> 2009-03-23 09:49:42 DEBUG: pid 1218: SimpleQuery: set master_slave_dml
> query: DEALLOCATE "S_4"
> 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for backend 0 completing the query
> 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for backend 1 completing the query
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 0 th backend C NUM_BACKENDS: 2
> 2009-03-23 09:49:42 DEBUG: pid 1218: read_kind_from_backend: read kind
> from 1 th backend E NUM_BACKENDS: 2
> 2009-03-23 09:49:42 ERROR: pid 1218: pool_process_query: 1 th kind E
> does not match with master connection kind C
> 
> Regards,
> Nimesh.
> 
> 
> 
> On Tue, Mar 24, 2009 at 6:12 AM, Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> >> All
> >>
> >> We are facing problem with pgpool where the java application fails in
> >> certain situation I/o problem.
> >>
> >> When we see these problem we see in the db logs error statement like:
> >>
> >> "ERROR:  prepared statement "S_3" does not exist".
> >> "LOG:  unexpected EOF on client connection"
> >>
> >> We get the following log output in the pgpool log files:
> >>
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: Z
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: pool_read_message_length: slot:
> >> 0 length: 5
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: pool_read_message_length: slot:
> >> 1 length: 5
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: ReadyForQuery: message length: 5
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: ReadyForQuery: transaction state: I
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: statement2: DEALLOCATE "S_3"
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: SimpleQuery: set
> >> master_slave_dml query: DEALLOCATE "S_3"
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: Query: BEGIN
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: Z
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: transaction state: T
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: Query: BEGIN
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: kind: Z
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: do_command: transaction state: T
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: waiting for backend 0 completing the query
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: detect_error: kind: C
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: waiting for backend 1 completing the query
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: read_kind_from_backend: read
> >> kind from 0 th backend C NUM_BACKENDS: 2
> >> 2009-03-17 12:24:56 DEBUG: pid 27834: read_kind_from_backend: read
> >> kind from 1 th backend E NUM_BACKENDS: 2
> >> 2009-03-17 12:24:56 ERROR: pid 27834: read_kind_from_backend: 1 th
> >> kind E does not match with master or majority connection k
> >> ind C
> >> 2009-03-17 12:24:56 ERROR: pid 27834: kind mismatch among backends.
> >> Possible last query was: "DEALLOCATE "S_3"" kind details
> >> are: 0[C] 1[E]
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: I am 27834 accept fd 5
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: Protocol Major: 3 Minor: 0
> >> database: rpt_production user: chakra
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: new_connection: connecting 0 backend
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: new_connection: connecting 1 backend
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: pool_read_message_length: slot:
> >> 0 length: 8
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: pool_read_message_length: slot:
> >> 1 length: 8
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: pool_read_message_length2:
> >> master slot: 0 length: 28
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: pool_read_message_length2:
> >> master slot: 1 length: 28
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: 0 th backend: name:
> >> client_encoding value: UNICODE
> >> 2009-03-17 12:24:58 DEBUG: pid 27834: 1 th backend: name:
> >> client_encoding value: UNICODE
> >>
> >> Why does pgpool try to DEALLOCATE a prepare statement on both the
> >> database servers, when pgpool is set in Matser/slave mode. Can any
> >> body high light how this issue can be solved. Will really appreciate
> >> your inputs in this.
> >
> > Even if you are in master/slave mode, you need to send prepare to both
> > nodes for BEGIN statement. That's the reason why DEALLOCATE has been
> > sent to both nodes.
> >
> > BTW, can you send us PostgreSQL log with statement logging enabled? It
> > will help to investigate why you are seeing error regarding S_3.
> > --
> > Tatsuo Ishii
> > SRA OSS, Inc. Japan
> >