[Pgpool-general] pgpool not working with one of the db server upgraded from 8.4.4 to 9.0.4

Gary Fu gfu at sigmaspace.com
Thu Apr 28 21:07:35 UTC 2011 

Hi,

We are running pgpool 3.0.1 on a host with two other independent db 
servers.  It (psql) works for a long time with both db servers are 
running postgresql 8.4.4.  However, when we updated the secondary db 
server to 9.0.4 yesterday, the 'psql' is not working anymore (see below 
for the logs)

I tried to disconnect the 2nd db server (9.0.4) and restart the pgpool 
(in failover mode, connect to 1st db server 8.4.4), and in this case, 
'psql' has no problem.

Is this related to postgresql 9.0.4 or something else that I did wrong ?

Thanks,
Gary

----------------------------------------------------------------------
psql has no problem to connect directly to the 2nd db server :

8:46pm 309 gfu at sd3dev1:~/svn/Src/Install$ psql -h sd3db2
psql (8.4.4, server 9.0.4)
WARNING: psql version 8.4, server version 9.0.
          Some psql features might not work.
Type "help" for help.

[sd3db2.dev1_admin].sd3dev1>

------------------------------------------------------------------------
psql fails on pgpool connection:

8:56pm 310 gfu at sd3dev1:~/svn/Src/Install$ psql
psql: server closed the connection unexpectedly
         This probably means the server terminated abnormally
         before or while processing the request.
8:56pm 311 gfu at sd3dev1:~/svn/Src/Install$

----------------------------------------------------------------------------
The pgpool starts without any error:

[postgres at sd3dev1 gfu]$ pgpool -n -d -D
2011-04-28 20:47:22 DEBUG: pid 19130: key: listen_addresses
2011-04-28 20:47:22 DEBUG: pid 19130: value: '*' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: port
2011-04-28 20:47:22 DEBUG: pid 19130: value: 5432 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: pcp_port
2011-04-28 20:47:22 DEBUG: pid 19130: value: 9898 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: socket_dir
2011-04-28 20:47:22 DEBUG: pid 19130: value: '/var/run/pgpool-II-90' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: pcp_socket_dir
2011-04-28 20:47:22 DEBUG: pid 19130: value: '/tmp' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_socket_dir
2011-04-28 20:47:22 DEBUG: pid 19130: value: '/var/run/pgpool-II-90' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: pcp_timeout
2011-04-28 20:47:22 DEBUG: pid 19130: value: 10 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: num_init_children
2011-04-28 20:47:22 DEBUG: pid 19130: value: 60 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: max_pool
2011-04-28 20:47:22 DEBUG: pid 19130: value: 4 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: child_life_time
2011-04-28 20:47:22 DEBUG: pid 19130: value: 300 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: connection_life_time
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: child_max_connections
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: client_idle_limit
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: authentication_timeout
2011-04-28 20:47:22 DEBUG: pid 19130: value: 60 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: logdir
2011-04-28 20:47:22 DEBUG: pid 19130: value: '/var/log/pgpool-II' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: pid_file_name
2011-04-28 20:47:22 DEBUG: pid 19130: value: 
'/var/run/pgpool-II-90/pgpool.pid' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: replication_mode
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: load_balance_mode
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: replication_stop_on_mismatch
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: replication_stop_on_mismatch: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: 
failover_if_affected_tuples_mismatch
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: 
failover_if_affected_tuples_mismatch: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: replicate_select
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: replicate_select: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: reset_query_list
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'ABORT; DISCARD ALL' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: extract_string_tokens: token: ABORT
2011-04-28 20:47:22 DEBUG: pid 19130: extract_string_tokens: token:  
DISCARD ALL
2011-04-28 20:47:22 DEBUG: pid 19130: key: white_function_list
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: black_function_list
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'nextval,setval' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: extract_string_tokens: token: nextval
2011-04-28 20:47:22 DEBUG: pid 19130: extract_string_tokens: token: setval
2011-04-28 20:47:22 DEBUG: pid 19130: key: print_timestamp
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: master_slave_mode
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: master_slave_sub_mode
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'slony' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: delay_threshold
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: log_standby_delay
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'none' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: connection_cache
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: health_check_timeout
2011-04-28 20:47:22 DEBUG: pid 19130: value: 20 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: health_check_period
2011-04-28 20:47:22 DEBUG: pid 19130: value: 300 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: health_check_user
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'nobody' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: failover_command
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: failback_command
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: fail_over_on_backend_error
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: insert_lock
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: ignore_leading_white_space
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: log_statement
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: log_per_node_statement
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: log_connections
2011-04-28 20:47:22 DEBUG: pid 19130: value: true kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: log_hostname
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: parallel_mode
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: enable_query_cache
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: pgpool2_hostname
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_hostname0
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'sd3db1' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_port0
2011-04-28 20:47:22 DEBUG: pid 19130: value: 5432 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: pool_config: port slot number 0
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_weight0
2011-04-28 20:47:22 DEBUG: pid 19130: value: 1 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: pool_config: weight slot number 0 
weight: 1.000000
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_hostname1
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'sd3db2' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_port1
2011-04-28 20:47:22 DEBUG: pid 19130: value: 5432 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: pool_config: port slot number 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: backend_weight1
2011-04-28 20:47:22 DEBUG: pid 19130: value: 1 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: pool_config: weight slot number 1 
weight: 1.000000
2011-04-28 20:47:22 DEBUG: pid 19130: key: enable_pool_hba
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: recovery_user
2011-04-28 20:47:22 DEBUG: pid 19130: value: 'nobody' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: recovery_password
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: recovery_1st_stage_command
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: recovery_2nd_stage_command
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: recovery_timeout
2011-04-28 20:47:22 DEBUG: pid 19130: value: 90 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: client_idle_limit_in_recovery
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 DEBUG: pid 19130: key: lobj_lock_table
2011-04-28 20:47:22 DEBUG: pid 19130: value: '' kind: 4
2011-04-28 20:47:22 DEBUG: pid 19130: key: ssl
2011-04-28 20:47:22 DEBUG: pid 19130: value: false kind: 1
2011-04-28 20:47:22 DEBUG: pid 19130: key: debug_level
2011-04-28 20:47:22 DEBUG: pid 19130: value: 0 kind: 2
2011-04-28 20:47:22 LOG:   pid 19130: Backend status file 
/var/log/pgpool-II/pgpool_status discarded
2011-04-28 20:47:22 DEBUG: pid 19131: I am 19131
2011-04-28 20:47:22 DEBUG: pid 19132: I am 19132
2011-04-28 20:47:22 DEBUG: pid 19133: I am 19133
2011-04-28 20:47:22 DEBUG: pid 19134: I am 19134
....
.....

2011-04-28 20:47:22 LOG:   pid 19130: pgpool-II successfully started. 
version 3.0.1 (umiyameboshi)
2011-04-28 20:47:22 DEBUG: pid 19193: I am 19193
2011-04-28 20:47:22 DEBUG: pid 19130: starting health checking
2011-04-28 20:47:22 DEBUG: pid 19130: health_check: 0 th DB node status: 1
2011-04-28 20:47:22 DEBUG: pid 19130: health_check: 1 th DB node status: 1

---------------------------------------------------------------------------------------------------------------
pgpool log from the failed 'psql' command:

2011-04-28 20:48:01 DEBUG: pid 19189: I am 19189 accept fd 6
2011-04-28 20:48:01 LOG:   pid 19189: connection received: 
host=172.28.20.145 port=45734
2011-04-28 20:49:01 LOG:   pid 19189: authentication is timeout
2011-04-28 20:49:01 DEBUG: pid 19130: reap_handler called
2011-04-28 20:49:01 DEBUG: pid 19130: reap_handler: call wait3
2011-04-28 20:49:01 DEBUG: pid 19130: child 19189 exits with status 256
2011-04-28 20:49:01 DEBUG: pid 19130: fork a new child pid 19207
2011-04-28 20:49:01 DEBUG: pid 19130: reap_handler: normally exited
2011-04-28 20:49:01 DEBUG: pid 19207: I am 19207
2011-04-28 20:52:22 DEBUG: pid 19130: starting health checking
2011-04-28 20:52:22 DEBUG: pid 19130: health_check: 0 th DB node status: 1
2011-04-28 20:52:22 DEBUG: pid 19130: health_check: 1 th DB node status: 1
2011-04-28 20:56:33 DEBUG: pid 19185: I am 19185 accept fd 6
2011-04-28 20:56:33 LOG:   pid 19185: connection received: 
host=172.28.20.137 port=48311
2011-04-28 20:56:33 DEBUG: pid 19185: Protocol Major: 1234 Minor: 5679 
database:  user:
2011-04-28 20:56:33 DEBUG: pid 19185: SSLRequest from client
2011-04-28 20:56:33 DEBUG: pid 19185: pool_ssl: SSL requested but SSL 
support is not available
2011-04-28 20:56:33 DEBUG: pid 19185: Protocol Major: 3 Minor: 0 
database: sd3dev1 user: dev1_admin
2011-04-28 20:56:33 DEBUG: pid 19185: new_connection: connecting 0 backend
2011-04-28 20:56:33 DEBUG: pid 19185: new_connection: connecting 1 backend
2011-04-28 20:56:33 DEBUG: pid 19185: pool_ssl: SSL requested but SSL 
support is not available
2011-04-28 20:56:33 DEBUG: pid 19185: pool_ssl: SSL requested but SSL 
support is not available
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length: slot: 0 
length: 8
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length: slot: 1 
length: 8
2011-04-28 20:56:33 DEBUG: pid 19185: pool_do_auth: auth kind:3
2011-04-28 20:56:33 DEBUG: pid 19185: trying clear text password 
authentication
2011-04-28 20:56:33 DEBUG: pid 19185: trying clear text password 
authentication
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 25
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 22
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (22) in slot 1 does not match with slot 0(25)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: 
client_encoding value: UTF8
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
application_name value:
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 23
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 25
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (25) in slot 1 does not match with slot 0(23)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: DateStyle 
value: ISO, MDY
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
client_encoding value: UTF8
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 25
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 23
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (23) in slot 1 does not match with slot 0(25)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: 
integer_datetimes value: on
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: DateStyle 
value: ISO, MDY
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 27
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 25
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (25) in slot 1 does not match with slot 0(27)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: IntervalStyle 
value: postgres
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
integer_datetimes value: on
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 21
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 27
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (27) in slot 1 does not match with slot 0(21)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: is_superuser 
value: off
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: IntervalStyle 
value: postgres
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 25
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 21
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (21) in slot 1 does not match with slot 0(25)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: 
server_encoding value: UTF8
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: is_superuser 
value: off
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 25
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 25
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: server_version 
value: 8.4.4
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
server_encoding value: UTF8
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 37
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 25
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (25) in slot 1 does not match with slot 0(37)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: 
session_authorization value: dev1_admin
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: server_version 
value: 9.0.4
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 36
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 37
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (37) in slot 1 does not match with slot 0(36)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: 
standard_conforming_strings value: off
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
session_authorization value: dev1_admin
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 0 length: 17
2011-04-28 20:56:33 DEBUG: pid 19185: pool_read_message_length2: master 
slot: 1 length: 36
2011-04-28 20:56:33 LOG:   pid 19185: pool_read_message_length2: message 
length (36) in slot 1 does not match with slot 0(17)
2011-04-28 20:56:33 DEBUG: pid 19185: 0 th backend: name: TimeZone 
value: UTC
2011-04-28 20:56:33 DEBUG: pid 19185: 1 th backend: name: 
standard_conforming_strings value: off
2011-04-28 20:56:33 ERROR: pid 19185: pool_read_kind: kind does not 
match between master(4b) slot[1] (53)
2011-04-28 20:56:33 ERROR: pid 19185: pool_do_auth: failed to read kind 
before BackendKeyData
2011-04-28 20:57:22 DEBUG: pid 19130: starting health checking
2011-04-28 20:57:22 DEBUG: pid 19130: health_check: 0 th DB node status: 2
2011-04-28 20:57:22 DEBUG: pid 19130: health_check: 1 th DB node status: 2

More information about the Pgpool-general mailing list