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

[David Boreham]

>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)

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.

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 :(

Thanks !