[Pgpool-general] Error "kind does not match between backends"

[Tatsuo Ishii]

> >I'll be waiting for your test case. 
> >
> >The only case I can think of is SELECT without load balancing.
> >  
> >
> Hi, and apologies for the delay. I had three teeth pulled out on Friday
> and it's taken until today for me to get drug free. Anyway, I began
> working on reproducing the problem I previously described and have
> hit another similar issue first. I believe I've seen this one too before.
> 
> So, this is with postgresql 8.1.2, pgpool 3.0 and slony 1.1.5.
> I built and installed postgresql and slony on two machines:
> 'cougar' and buffalo'. buffalo is the master. pgpool is running
> on buffalo, configured to run in master_slave mode with or without
> load balancing (the results are the same in this case).
> 
> I see the problem with any select query, but it happens with
> 'psql -l' which nicely shows the result without needing to
> get into our tables and so on. Here I can query the
> two backends directly:
> 
> [david at buffalo ~]$ psql -h buffalo -p 6666  -l
>       List of databases
>    Name    | Owner | Encoding
> -----------+-------+----------
>  postgres  | david | UTF8
>  template0 | david | UTF8
>  template1 | david | UTF8
> (4 rows)
> 
> [david at buffalo ~]$ psql -h cougar -p 6666  -l
>       List of databases
>    Name    | Owner | Encoding
> -----------+-------+----------
>  postgres  | david | UTF8
>  template0 | david | UTF8
>  template1 | david | UTF8
> (4 rows)
> 
> Now, via pgpool:
> 
> [david at buffalo ~]$ psql -h buffalo -p 9999  -l
> psql: server closed the connection unexpectedly
>         This probably means the server terminated abnormally
>         before or while processing the request.
> 
> Here is the debug output from pgpool:
> 
> 2006-02-07 09:48:34 DEBUG: pid 14062: I am 14062 accept fd 6
> 2006-02-07 09:48:34 DEBUG: pid 14062: Protocol Major: 1234 Minor: 5679 
> database:  user:
> 2006-02-07 09:48:34 DEBUG: pid 14062: SSLRequest: sent N; retry startup
> 2006-02-07 09:48:34 DEBUG: pid 14062: Protocol Major: 3 Minor: 0 
> database: template1 user: david
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length: lenghth: 8
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 25
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: client_encoding value: UTF8
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: client_encoding 
> value: UTF8
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 23
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: DateStyle value: ISO, MDY
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: DateStyle value: 
> ISO, MDY
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 26
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: integer_datetimes value: off
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: integer_datetimes 
> value: off
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 20
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: is_superuser value: on
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: is_superuser value: on
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 25
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: server_encoding value: UTF8
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: server_encoding 
> value: UTF8
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 25
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: server_version value: 8.1.2
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: server_version 
> value: 8.1.2
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 32
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: session_authorization value: 
> david
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: 
> session_authorization value: david
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 36
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: standard_conforming_strings 
> value: off
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: 
> standard_conforming_strings value: off
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length2: master 
> lenghth: 20
> 2006-02-07 09:48:34 DEBUG: pid 14062: name: TimeZone value: Navajo
> 2006-02-07 09:48:34 DEBUG: pid 14062: secondary name: TimeZone value: Navajo
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length: lenghth: 12
> 2006-02-07 09:48:34 DEBUG: pid 14062: read kind from backend pending 
> data Z len: 5 po: 263
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_process_query: kind from 
> backend: Z
> 2006-02-07 09:48:34 DEBUG: pid 14062: pool_read_message_length: lenghth: 5
> 2006-02-07 09:48:34 ERROR: pid 14062: pool_read_message_length: length 
> does not match between backends master(5) secondary(1509949440)

Thanks for the test case. 

> I believe the call to pool_read_message_length() happens at a place in 
> pool_process_query() where
> nothing has been sent to the secondary, and hence the length read from 
> it is bogus.  I'm not sure why
> the poll_read() is succeeding though.

No. After connecting with the backend, backend sends Read for Query
packet *before* frontend issues any query. I think this is the case.

> Let me know if you need more information. I'd be happy to debug this myself
> but I really don't feel that I know how the code is supposed to work at 
> this point,
> which results in much time chasing red herrings :(

It seems 2.7.2 breaks master/slave mode. I will fix as soon as
possible.
--
Tatsuo Ishii
SRA OSS, Inc. Japan