I've been playing around a little bit and It seems that this "psql: expected authentication request from server, but received S" message happens when there is no DBCluster node available (to be correct, I should say, when pglb THINKS there is no DBCluster node available).
These are the steps I follow: 1.- I start everything in the correct order (db nodes, pgreplicate, and then pgl) 2.- I try to connect for some remote host using psql and the connection is successfull (pglb talks with DBCluster_1) 3.- I shut down DBCluster_1 4.- At this moment, if I try another connection from the remote host, I will be able to connect 1 time at most, pglb will forward this connection to DBCluster_2 5.- After this try, pglb thinks there are no more DB nodes available in the cluster and all the following connections fail with a "psql: expected authentication request from server, but received S" message Here are the relevant part of the logs 1.- First connection 2007-12-07 00:18:28 [9345] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv01 port:5433 max:50 use:0 status1 2007-12-07 00:18:28 [9345] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv02 port:5433 max:50 use:0 status1 2007-12-07 00:18:28 [9345] DEBUG:init_pglb():Child_Tbl size is[77400] 2007-12-07 00:18:39 [9345] DEBUG:PGRscan_cluster:2 ClusterDB can be used 2007-12-07 00:18:39 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->1 max->50 use_num->0 2007-12-07 00:18:39 [9345] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv01 port:5433 max:50 use:1 status2 2007-12-07 00:18:39 [9351] DEBUG:PGRdo_child():I am 9351 2007-12-07 00:18:39 [9351] DEBUG:do_accept():I am 9351 accept fd 6 2007-12-07 00:18:39 [9351] DEBUG:read_startup_packet():Protocol Major: 1234 Minor: 5679 database: user: . . . 2007-12-07 00:18:39 [9351] DEBUG:ReadyForQuery(): message length: 5 2007-12-07 00:18:39 [9351] DEBUG:ReadyForQuery(): transaction state: I 2007-12-07 00:18:40 [9351] DEBUG:ProcessFrontendResponse():read kind from frontend X(58) ################################################# 2.- Connection tries after shuting down DB1: 2007-12-07 00:19:53 [9345] DEBUG:PGRscan_cluster:1 ClusterDB can be used 2007-12-07 00:19:53 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->2 max->50 use_num->0 2007-12-07 00:19:53 [9364] DEBUG:PGRdo_child():I am 9364 2007-12-07 00:19:53 [9364] DEBUG:do_accept():I am 9364 accept fd 6 2007-12-07 00:19:53 [9364] DEBUG:read_startup_packet():Protocol Major: 1234 Minor: 5679 database: user: 2007-12-07 00:19:53 [9364] DEBUG:PGRdo_child():SSLRequest: sent N; retry startup 2007-12-07 00:19:53 [9364] DEBUG:read_startup_packet():Protocol Major: 3 Minor: 0 database: asteriskcdr user: ast01 2007-12-07 00:19:53 [9364] ERROR:connect_inet_domain_socket(): connect() failed: Connection refused 2007-12-07 00:19:53 [9364] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv01 port:5433 max:50 use:2 status98 2007-12-07 00:20:01 [9345] DEBUG:PGRscan_cluster:1 ClusterDB can be used 2007-12-07 00:20:01 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->98 max->50 use_num->1 2007-12-07 00:20:01 [9345] DEBUG:PGRscan_cluster:dbsrv02 [5433],useFlag->1 max->50 use_num->0 2007-12-07 00:20:01 [9345] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv02 port:5433 max:50 use:1 status2 2007-12-07 00:20:01 [9366] DEBUG:PGRdo_child():I am 9366 2007-12-07 00:20:01 [9366] DEBUG:do_accept():I am 9366 accept fd 6 2007-12-07 00:20:01 [9366] DEBUG:read_startup_packet():Protocol Major: 1234 Minor: 5679 database: user: 2007-12-07 00:20:01 [9366] DEBUG:PGRdo_child():SSLRequest: sent N; retry startup 2007-12-07 00:20:01 [9366] DEBUG:read_startup_packet():Protocol Major: 3 Minor: 0 database: test user: test 2007-12-07 00:20:01 [9366] DEBUG:create_cp():[dbsrv02] [dbsrv02] is same 2007-12-07 00:20:01 [9366] DEBUG:connect_unix_domain_socket():postmaster Unix domain socket: /var/run/postgresql/.s.PGSQL.5433 2007-12-07 00:20:01 [9366] DEBUG:connect_unix_domain_socket():connected to postmaster Unix domain socket: /var/run/postgresql/.s.PGSQL.5433 fd: 7 2007-12-07 00:20:01 [9366] DEBUG:pool_do_auth():trying md5 authentication 2007-12-07 00:20:01 [9366] DEBUG:ParameterStatus():name: client_encoding value: UTF8 2007-12-07 00:20:01 [9366] DEBUG:pool_param_debug_print(): No.0: name: client_encoding value: UTF8 . . <---Lots of debug information removed . 2007-12-07 00:20:01 [9366] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 266 2007-12-07 00:20:01 [9366] DEBUG:ReadyForQuery(): message length: 5 2007-12-07 00:20:01 [9366] DEBUG:ReadyForQuery(): transaction state: I 2007-12-07 00:20:26 [9348] DEBUG:set_recovery():received no:101 2007-12-07 00:20:26 [9348] DEBUG:PGRset_status_on_cluster_tbl():host:dbsrv01 port:5433 max:50 use:98 status99 ######################################### 3.- Another try, this one is not successfull, pglb thinks there are no more cluster nodes available (dbsrv02 is up and running and accepting connections): 2007-12-07 00:20:33 [9366] DEBUG:ProcessFrontendResponse():read kind from frontend X(58) 2007-12-07 00:20:34 [9348] DEBUG:set_recovery():received no:101 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():no cluster available 2007-12-07 00:20:37 [9345] DEBUG:do_accept():I am 9345 accept fd 6 2007-12-07 00:20:37 [9345] DEBUG:read_startup_packet():Protocol Major: 1234 Minor: 5679 database: user: 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:0 ClusterDB can be used 2007-12-07 00:20:37 [9345] DEBUG:PGRscan_cluster:dbsrv01 [5433],useFlag->99 max->50 use_num->1 2007-12-07 00:20:37 [9345] ERROR:PGRload_balance():no cluster available 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():load balance process failed 2007-12-07 00:20:37 [9345] ERROR:load_balance_main():no cluster available 2007-12-07 00:20:37 [9345] DEBUG:do_accept():I am 9345 accept fd 6 2007-12-07 00:20:37 [9345] DEBUG:read_startup_packet():Protocol Major: 2 Minor: 0 database: test user: test El Monday 03 December 2007 15:49:39 Sanyu escribió: > Hi everybody, > I've been trying to set up a configuration with 2 nodes with Postgresql > 8.2.4 My setting is: > Node 1: > - DBCluster_1 > - Rep_1 > - Lb_1 > > Node 2: > - DBCluster_2 > - Rep_2 > - Lb_2 > > If I stop DBCluster_1 and query Lb_2, queries don't seem to arrive > correctly to DB_Cluster_2 and the only message I get is: > psql: expected authentication request from server, but received S > > This is just an example, any client I use outputs the same message. > With both nodes up and running, replication works perfectly, but the moment > I stop DB1 things stop working > > Anyone out there that has experienced the same problem? > Any clues? > Thanks > > Regards > _______________________________________________ > Pgcluster-general mailing list > [email protected] > http://pgfoundry.org/mailman/listinfo/pgcluster-general _______________________________________________ Pgcluster-general mailing list [email protected] http://pgfoundry.org/mailman/listinfo/pgcluster-general
