12 Replies Latest reply on Jan 30, 2012 10:32 AM by 850085

    WebLogic Cluster balancer always route to second node

    850085
      I have configured Apache to load balance two WebLogic nodes (using mod_weblogic),
      but all requests are forwarded to second node.

      Here what I have added to httpd.conf:

      LoadModule weblogic_module modules/mod_wl_22.so
      <IfModule mod_weblogic.c>
      MatchExpression /soa-infra WebLogicCluster=node1.domain.com:8001,node2.domain.com:8001
      </IfModule>
      <Location /soa-infra>
      SetHandler weblogic-handler
      WebLogicCluster node1.domain.com:8001,node2.domain.com:8001
      </Location>

      What I have tried with no effect:
      1) swap node1.domain.com and node2.domain.com
      2) change balancing algorithm in WebLogic Administration Console

      Edited by: diesel_den on 24.01.2012 6:25
        • 1. Re: WebLogic Cluster balancer always route to second node
          850085
          Cluster is multicast (not unicast).
          • 2. Re: WebLogic Cluster balancer always route to second node
            Pierluigi Vernetto
            try adding
            Debug ON
            to get more info

            but are you 100% sure that the client is addressing apache and not the individual node?

            can you also netstat on the Apache box and count the number of open connections to either nodes?

            are you also sure that both nodes are reachable (ping) from apache box?
            • 3. Re: WebLogic Cluster balancer always route to second node
              850085
              Thanks for answer!
              1. client is adressing apache - I am testing myself.
              2. I see that apache is creating connection only after request from client/me and it is only connection to second node (on which it is executing).
              3. yes, both nodes are in local network and are reachable.
              I have found interesting thing:
              if I remove all my lines from httpd.conf except line for loading mod_weblogic and restart apache then I have no access via load-balancer - so balancer is really using my config lines,
              but if I remove second node from list then load balancer are still redirecting second node instead of only one listed first node.
              May be issue is that load-balancer is placed on the same machine as second node?

              Edited by: diesel_den on 25.01.2012 4:41
              • 4. Re: WebLogic Cluster balancer always route to second node
                850085
                May be issue is that load-balancer is placed on the same machine as second node?
                But second load-balancer placed on the first node also constantly route requests to second node, so it is not a reason.
                • 5. Re: WebLogic Cluster balancer always route to second node
                  850085
                  [Wed Jan 25 19:07:02 2012] [notice] Parent: Received restart signal -- Restarting the server.
                  [Wed Jan 25 19:07:02 2012] [notice] Child 1708: Exit event signaled. Child process is ending.
                  [Wed Jan 25 19:07:02 2012] [info] Child 1708: Accept thread exiting.
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: init_mod: mpm is threaded.
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: lock file is C:/Apache2.2/wlproxy_lock.2940
                  [Wed Jan 25 19:07:02 2012] [notice] Apache/2.2.21 (Win32) configured -- resuming normal operations
                  [Wed Jan 25 19:07:02 2012] [notice] Server built: Sep 9 2011 10:26:10
                  [Wed Jan 25 19:07:02 2012] [notice] Parent: Created child process 4576
                  [Wed Jan 25 19:07:02 2012] [debug] mpm_winnt.c(477): Parent: Sent the scoreboard to the child
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: init_mod: mpm is threaded.
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: lock file is C:/Apache2.2/wlproxy_lock.4576
                  [Wed Jan 25 19:07:02 2012] [notice] Child 4576: Child process is running
                  [Wed Jan 25 19:07:02 2012] [debug] mpm_winnt.c(398): Child 4576: Retrieved our scoreboard from the parent.
                  [Wed Jan 25 19:07:02 2012] [info] Parent: Duplicating socket 308 and sending it to child process 4576
                  [Wed Jan 25 19:07:02 2012] [debug] mpm_winnt.c(595): Parent: Sent 1 listeners to child 4576
                  [Wed Jan 25 19:07:02 2012] [debug] mpm_winnt.c(554): Child 4576: retrieved 1 listeners from parent
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: init_child: isThreaded = 1
                  [Wed Jan 25 19:07:02 2012] [notice] Oracle WebLogic plugin build date/time: Aug 2 2010 09:40:28. Change Number: 1351550
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: Testing Debug=(null) LogFile=logs/foo_proxy.log TempDir=(null)
                  [Wed Jan 25 19:07:02 2012] [info] mod_weblogic: created global log context in child
                  [Wed Jan 25 19:07:03 2012] [notice] Child 4576: Acquired the start mutex.
                  [Wed Jan 25 19:07:03 2012] [notice] Child 4576: Starting 64 worker threads.
                  [Wed Jan 25 19:07:03 2012] [notice] Child 1708: Released the start mutex
                  [Wed Jan 25 19:07:03 2012] [info] Child 1708: 64 threads blocked on the completion port
                  [Wed Jan 25 19:07:04 2012] [notice] Child 1708: All worker threads have exited.
                  [Wed Jan 25 19:07:04 2012] [notice] Child 1708: Child process is exiting
                  [Wed Jan 25 19:07:04 2012] [notice] Child 4576: Starting thread to listen on port 80.
                  [Wed Jan 25 19:07:12 2012] [info] ap_proxy: Debug is disabled [(null)]
                  [Wed Jan 25 19:07:14 2012] [info] ap_proxy: Debug is disabled [(null)]
                  • 6. Re: WebLogic Cluster balancer always route to second node
                    850085
                    Wed Jan 25 19:51:56 2012 <480013275067001> ap_proxy: isThreaded set to 1
                    Wed Jan 25 19:51:56 2012 <480013275067162>
                    ================New Request: [GET /soa-infra/services/partition/my_composite/my_composite_client_ep?WSDL HTTP/1.1] =================
                    Wed Jan 25 19:51:56 2012 <480013275067162> INFO: SSL is not configured
                    Wed Jan 25 19:51:56 2012 <480013275067162> Using Uri /soa-infra/services/partition/my_composite/my_composite_client_ep
                    Wed Jan 25 19:51:56 2012 <480013275067162> After trimming path: '/soa-infra/services/partition/my_composite/my_composite_client_ep'
                    Wed Jan 25 19:51:56 2012 <480013275067162> The final request string is '/soa-infra/services/partition/my_composite/my_composite_client_ep?WSDL'
                    Wed Jan 25 19:51:56 2012 <480013275067162> Host extracted from serverlist is [node1.domain.com]
                    Wed Jan 25 19:51:56 2012 <480013275067162> Host extracted from serverlist is [node2.domain.com]
                    Wed Jan 25 19:51:56 2012 <480013275067162> Initializing lastIndex=1 for a list of length=2
                    Wed Jan 25 19:51:56 2012 <480013275067162> getListNode: created a new server node: id='node1.domain.com:8001,node2.domain.com:8001' server_name='node2.domain.com', port='80'
                    Wed Jan 25 19:51:56 2012 <480013275067162> getPreferred: availcookie=[JSESSIONID=G2lvPpDQgJcDcBqhwJxY9W3PJYFw3LG3TQvdZSGxJhB861JLd2Sf!-76285319]
                    Wed Jan 25 19:51:56 2012 <480013275067162> Found cookie from cookie header: JSESSIONID=G2lvPpDQgJcDcBqhwJxY9W3PJYFw3LG3TQvdZSGxJhB861JLd2Sf!-76285319
                    Wed Jan 25 19:51:56 2012 <480013275067162> Parsing cookie JSESSIONID=G2lvPpDQgJcDcBqhwJxY9W3PJYFw3LG3TQvdZSGxJhB861JLd2Sf!-76285319
                    Wed Jan 25 19:51:56 2012 <480013275067162> getpreferredServersFromCookie: [-76285319]
                    Wed Jan 25 19:51:56 2012 <480013275067162> primaryJVMID: [-76285319]
                    secondaryJVMID: []
                    Wed Jan 25 19:51:56 2012 <480013275067162> No of JVMIDs found in cookie: 1
                    Wed Jan 25 19:51:56 2012 <480013275067162> getPreferredFromCookie: Start Position is 1, listLen is 2
                    Wed Jan 25 19:51:56 2012 <480013275067162> getPreferredFromCookie: Either JVMIDs not set or they are stale. Will try to get JVMIDs from WLS
                    Wed Jan 25 19:51:56 2012 <480013275067162> initJVMID: Iterating SrvrList from position 1
                    Wed Jan 25 19:51:56 2012 <480013275067162> ======internal request /bea_wls_internal/WLDummyInitJVMIDs======
                    initJVMID: Trying Host[192.168.0.112] Port[8001] SecurePort[8001] useSSL [0] ioTimeout [30] socketTimeout [2]
                    Wed Jan 25 19:51:56 2012 <480013275067162> INFO: New NON-SSL URL
                    Wed Jan 25 19:51:56 2012 <480013275067162> Connect returns -1, and error no set to 10035, msg 'Unknown error'
                    Wed Jan 25 19:51:56 2012 <480013275067162> EINPROGRESS in connect() - selecting
                    Wed Jan 25 19:51:56 2012 <480013275067162> Local Port of the socket is 53607
                    Wed Jan 25 19:51:56 2012 <480013275067162> Remote Host 192.168.0.112 Remote Port 8001
                    Wed Jan 25 19:51:56 2012 <480013275067162> URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 404 Not Found]
                    Wed Jan 25 19:51:56 2012 <480013275067162> URL::parseHeaders: StatusLine set to [404 Not Found]
                    Wed Jan 25 19:51:56 2012 <480013275067162> parsed all headers OK
                    Wed Jan 25 19:51:56 2012 <480013275067162> Parsing cluster list: -76285319!node2.domain.com!8001!-1
                    Wed Jan 25 19:51:56 2012 <480013275067162> parseJVMID: Parsing JVMID '-76285319!node2.domain.com!8001!-1'
                    Wed Jan 25 19:51:56 2012 <480013275067162> parseJVMID: Actually parsing '-76285319!node2.domain.com!8001!-1'
                    Wed Jan 25 19:51:56 2012 <480013275067162> ServerInfo struct for JVMID '-76285319' populated
                    Server Details are:
                    OrigHostInfo [node2.domain.com]
                    isOrigHostInfoDNS [1]
                    Host [192.168.0.112]
                    Port [8001]
                    SecurePort [0]
                    Wed Jan 25 19:51:56 2012 <480013275067162> Initializing lastIndex=0 for a list of length=1
                    Wed Jan 25 19:51:56 2012 <480013275067162> initJVMID: Trying to locate Primary or Secondary using SrvrInfo with JVMID [-76285319]
                    Wed Jan 25 19:51:56 2012 <480013275067162> initJVMID: Found Primary 192.168.0.112:8001:0
                    Wed Jan 25 19:51:56 2012 <480013275067162> .....internal request /bea_wls_internal/WLDummyInitJVMIDs.....processed
                    Wed Jan 25 19:51:56 2012 <480013275067162> getPreferredFromCookie: Found 1 servers
                    Wed Jan 25 19:51:56 2012 <480013275067162> attempt #0 out of a max of 5
                    Wed Jan 25 19:51:56 2012 <480013275067162> trying connect to PRIMARY '192.168.0.112'/8001/0
                    Wed Jan 25 19:51:56 2012 <480013275067162> getPooledConn: No more connections in the pool for Host[192.168.0.112] Port[8001] SecurePort[0]
                    Wed Jan 25 19:51:56 2012 <480013275067162> INFO: New NON-SSL URL
                    Wed Jan 25 19:51:56 2012 <480013275067162> Connect returns -1, and error no set to 10035, msg 'Unknown error'
                    Wed Jan 25 19:51:56 2012 <480013275067162> EINPROGRESS in connect() - selecting
                    Wed Jan 25 19:51:56 2012 <480013275067162> Local Port of the socket is 53608
                    Wed Jan 25 19:51:56 2012 <480013275067162> Remote Host 192.168.0.112 Remote Port 8001
                    Wed Jan 25 19:51:56 2012 <480013275067162> created a new connection to preferred server '192.168.0.112/8001' for '/soa-infra/services/partition/my_composite/my_composite_client_ep?WSDL', Local port:53608
                    Wed Jan 25 19:51:56 2012 <480013275067162> URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 200 OK]
                    Wed Jan 25 19:51:56 2012 <480013275067162> URL::parseHeaders: StatusLine set to [200 OK]
                    Wed Jan 25 19:51:56 2012 <480013275067162> parsed all headers OK
                    Wed Jan 25 19:51:56 2012 <480013275067162> sendResponse() : r->status = '200'
                    Wed Jan 25 19:51:56 2012 <480013275067162> canRecycle: conn=1 status=200 isKA=1 clen=-1 isCTE=1
                    Wed Jan 25 19:51:56 2012 <480013275067162> closeConn: pooling for '192.168.0.112/8001'
                    Wed Jan 25 19:51:56 2012 <480013275067162> request [soa-infra/services/partition/my_composite/my_composite_client_ep?WSDL] processed successfully..................

                    Edited by: diesel_den on 25.01.2012 7:53
                    • 7. Re: WebLogic Cluster balancer always route to second node
                      850085
                      Looks like I have found issue!

                      After several requests I see in log:
                      Wed Jan 25 19:56:49 2012 <480013275070093> Trying a pooled connection for '192.168.0.111/8001/8001'
                      Wed Jan 25 19:56:49 2012 <480013275070093> getPooledConn: No more connections in the pool for Host[192.168.0.111] Port[8001] SecurePort[8001]
                      Wed Jan 25 19:56:49 2012 <480013275070093> general list: trying connect to '192.168.0.111'/8001/8001 at line 2724 for '/soa-infra/services/partition/my_composite/my_composite_client_ep'

                      Wed Jan 25 19:57:05 2012 <480013275070256> Trying to locate Primary or Secondary using SrvrInfo with JVMID: -76285319
                      Wed Jan 25 19:57:05 2012 <480013275070256> getPreferredFromCookie: Found Primary 192.168.0.112:8001:0
                      Wed Jan 25 19:57:05 2012 <480013275070256> getPreferredFromCookie: Found 1 servers

                      192.168.0.111 is a first node, 192.168.0.112 - second.

                      Edited by: diesel_den on 26.01.2012 1:14
                      • 9. Re: WebLogic Cluster balancer always route to second node
                        850085
                        I have not done this:
                        http://www.javaoracleblog.com/java/Installing_an_11g_SOA_Cluster_8211_Part_IV_More_Configuration.jsf
                        Setting SOA/BPM Frontend Host & Cluster Address
                        Can this be a reason?
                        • 10. Re: WebLogic Cluster balancer always route to second node
                          850085
                          Unfortunately removing cookies from my browser haven't helped.
                          Also I have noticed that my test request to get wsdl of composite from soa_server is not creating any cookies in browser and now load balancer is not telling getPreferredFromCookie any more. Just still forwarding to second node.
                          But also now I have noticed next line in log:
                          Fri Jan 27 16:23:20 2012 <455613276670002> Hdrs from WLS:[X-WebLogic-Cluster-List]=[-76285319!node2.domain.com!8001!-1]
                          • 11. Re: WebLogic Cluster balancer always route to second node
                            Pierluigi Vernetto
                            mysterious. Have you tried using for WebLogicCluster a DNS entry for the cluster, rather than a comma-separated list of hostname:portnumber?
                            Otherwise open a support case with Oracle... or call a network expert... I have seen the plugin work perfectly, so I would rule out a bug...
                            • 12. Re: WebLogic Cluster balancer always route to second node
                              850085
                              Have you tried using for WebLogicCluster a DNS entry for the cluster, rather than a comma-separated list of hostname:portnumber?
                              What do you mean? Are you asking me to specify DNS entry of load-balancer in config of load-balancer?