[Pgpool-general] Error in pgpool

Sun Mar 29 11:14:52 UTC 2009

> It would appear that switching reset_query_list back from 'ABORT; DISCARD ALL' to 'ABORT; RESET ALL; SET SESSION AUTHORIZATION DEFAULT' stops this happening for us.  I'm not 100% sure yet, but since I changed this parameter and reloaded the configuration I've not seen any more of these deallocate errors.

That's expected behavior. DISCARD ALL conflicts pgpool-II's automatic
DEALLOCATE prepapred statements.

> After I reloaded pgpool I gradually saw less of the errors until they (appear to have) stopped, so I assume the updated parameter is only read by the backend when a client connects? 

Yes. Probably it should be documented somewhere though.

> I.e. I presume everyone connected before I reloaded issued an 'ABORT; DISCARD ALL', and anyone connecting afterwards would use 'ABORT; RESET ALL; SET SESSION AUTHORIZATION DEFAULT' ?

Right.
--
Tatsuo Ishii
SRA OSS, Inc. Japan

> --- On Thu, 26/3/09, Glyn Astill <glynastill at yahoo.co.uk> wrote:
> 
> > From: Glyn Astill <glynastill at yahoo.co.uk>
> > Subject: Re: [Pgpool-general] Error in pgpool
> > To: nimesh.satam at gmail.com, "Tatsuo Ishii" <ishii at sraoss.co.jp>
> > Cc: pgpool-general at pgfoundry.org
> > Date: Thursday, 26 March, 2009, 5:01 PM
> > Hi Tatsuo,
> > 
> > I'm using pgpool 2.2 in connection pool mode, and I see
> > a similar problem with the deallocate errors. I appear to
> > get a deallocate error for every prepared statement that the
> > a particular client made. I've not done a thorough
> > investigation here however it appears to only be for some
> > users, perhaps it depends on how they dissconnected/ were
> > dissconnected?
> > 
> > E.g I'm seeing lots of the following in my logs since
> > going from 2.1 -> 2.2
> > 
> > 2009-03-26 16:51:03 GMT [12164]: [1-1]: [user=rutrupe]:
> > [host=192.168.1.98]: [db=SEE]:: ERROR:  prepared statement
> > "find_eq_f1_byindx_0_1" does not exist
> > 2009-03-26 16:51:03 GMT [12164]: [2-1]: [user=rutrupe]:
> > [host=192.168.1.98]: [db=SEE]:: STATEMENT:  DEALLOCATE
> > "find_eq_f1_byindx_0_1"
> > 
> > 
> > Any ideas?
> > 
> > Thanks
> > Glyn
> > 
> > 
> > --- On Tue, 24/3/09, Tatsuo Ishii
> > <ishii at sraoss.co.jp> wrote:
> > 
> > > From: Tatsuo Ishii <ishii at sraoss.co.jp>
> > > Subject: Re: [Pgpool-general] Error in pgpool
> > > To: nimesh.satam at gmail.com
> > > Cc: pgpool-general at pgfoundry.org
> > > Date: Tuesday, 24 March, 2009, 3:11 PM
> > > 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
> > > > >
> > > _______________________________________________
> > > Pgpool-general mailing list
> > > Pgpool-general at pgfoundry.org
> > > http://pgfoundry.org/mailman/listinfo/pgpool-general
> > 
> > 
> >       
> > _______________________________________________
> > Pgpool-general mailing list
> > Pgpool-general at pgfoundry.org
> > http://pgfoundry.org/mailman/listinfo/pgpool-general
> 