users@glassfish.java.net

Re: loadbalancer with apache

From: <glassfish_at_javadesktop.org>
Date: Thu, 25 Sep 2008 02:00:01 PDT

> You can turn on debug logs, by setting log-level to debug, to provide more details.
Do you referer to apache error-log?
However I collect more data about error:

The cluster with 2 node agent and instances are started.

I attach my loadbalancer.xml

When I start Apache its log entries are:

[notice] Initializing lbplugin BuildId: A701212-164111
[notice] Initializing lbplugin BuildId: A701212-164111
[notice] Apache/2.0.63 (Win32) mod_ssl/2.0.63 OpenSSL/0.9.7m configured -- resuming normal operations
[notice] Server built: Jan 17 2008 22:58:29
[notice] Parent: Created child process 5028
[notice] Initializing lbplugin BuildId: A701212-164111
[notice] Initializing lbplugin BuildId: A701212-164111
[notice] Child 5028: Child process is running
[notice] Child 5028: Acquired the start mutex.
[notice] Child 5028: Starting 250 worker threads.

It's seems ok.
First call on loadbalancer (to apache hostname)

[alert] --------------------Name Trans---------
[alert] apache process id = 5028 ; URI = /clusterjsp
[alert] Within apachelbplugin_name_trans()
[warn] lb.runtime: RNTM2019: Daemon http://mobipc:38080 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon https://mobipc:38181 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon http://MOBISERVER:38081 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon https://MOBISERVER:38182 has been intialized.
[crit] lb.runtime: RNTM2003:After LBDaemonManager::init()
[alert] This request is INSECURE...
[crit] lb.runtime: RNTM2005: after LBApacheProxyRequest::LBApacheProxyRequest()
[alert] This request is for APACHE LB Plugin...
[alert] -----------------Request/Response handler---------
[alert] apache process id = 5028 ; URI = /clusterjsp
[crit] lb.runtime: LBRT1002: Executing Runtime method mod_apachelbplugin.cpp:apachelbplugin_handle_req
[crit] lb.runtime: RNTM2017:Header Name = Accept ====> Value = image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, */*
[crit] lb.runtime: RNTM2017:Header Name = Accept-Language ====> Value = en,it;q=0.5
[crit] lb.runtime: RNTM2017:Header Name = Accept-Encoding ====> Value = gzip, deflate
[crit] lb.runtime: RNTM2017:Header Name = User-Agent ====> Value = Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)
[crit] lb.runtime: RNTM2017:Header Name = Host ====> Value = localhost:85
[crit] lb.runtime: RNTM2017:Header Name = Connection ====> Value = Keep-Alive
[crit] lb.runtime: RNTM2017:Header Name = Cookie ====> Value = JSESSIONID=897d02d1291d49ba3929d787305e; JSESSIONIDVERSION=/clusterjsp:0
[alert] response code ....= 302
[alert] request headers ....= accept="image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, */*" accept-Language="en,it;q=0.5" accept-Encoding="gzip, deflate" user-Agent="Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)" host="localhost:85" cookie="JSESSIONID=897d02d1291d49ba3929d787305e; JSESSIONIDVERSION=/clusterjsp:0"
[alert] response headers ....= x-powered-by="Servlet/2.5" location="http://localhost:85/clusterjsp/" content-type="text/html; charset=iso-8859-1" date="Thu, 25 Sep 2008 08:26:57 GMT"
[alert] Sending Response Headers to Client ....\n\n
[crit] lb.runtime: RNTM2017:Header Name = X-powered-by ====> Value = Servlet/2.5
[crit] lb.runtime: RNTM2017:Header Name = Location ====> Value = http://localhost:85/clusterjsp/
[crit] lb.runtime: RNTM2017:Header Name = Content-type ====> Value = text/html; charset=iso-8859-1
[crit] lb.runtime: RNTM2017:Header Name = Date ====> Value = Thu, 25 Sep 2008 08:26:57 GMT
[crit] lb.runtime: RNTM2003:After LBDaemonManager::serviceRequest()
[crit] lb.runtime: RNTM2007:Request Succeeded
[alert] --------------------Name Trans---------
[alert] apache process id = 5028 ; URI = /clusterjsp/
[alert] Within apachelbplugin_name_trans()
[warn] lb.runtime: RNTM2019: Daemon http://mobipc:38080 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon https://mobipc:38181 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon http://MOBISERVER:38081 has been intialized.
[warn] lb.runtime: RNTM2019: Daemon https://MOBISERVER:38182 has been intialized.
[crit] lb.runtime: RNTM2003:After LBDaemonManager::init()
[alert] This request is INSECURE...
[crit] lb.runtime: RNTM2005: after LBApacheProxyRequest::LBApacheProxyRequest()
[alert] This request is for APACHE LB Plugin...
[alert] -----------------Request/Response handler---------
[alert] apache process id = 5028 ; URI = /clusterjsp/
[crit] lb.runtime: LBRT1002: Executing Runtime method mod_apachelbplugin.cpp:apachelbplugin_handle_req
[crit] lb.runtime: RNTM2017:Header Name = Accept ====> Value = image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, */*
[crit] lb.runtime: RNTM2017:Header Name = Accept-Language ====> Value = en,it;q=0.5
[crit] lb.runtime: RNTM2017:Header Name = Accept-Encoding ====> Value = gzip, deflate
[crit] lb.runtime: RNTM2017:Header Name = User-Agent ====> Value = Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)
[crit] lb.runtime: RNTM2017:Header Name = Host ====> Value = localhost:85
[crit] lb.runtime: RNTM2017:Header Name = Connection ====> Value = Keep-Alive
[crit] lb.runtime: RNTM2017:Header Name = Cookie ====> Value = JSESSIONID=897d02d1291d49ba3929d787305e; JSESSIONIDVERSION=/clusterjsp:0
[alert] response code ....= 200
[alert] Sending Response Headers to Client ....\n\n
[crit] lb.runtime: RNTM2017:Header Name = X-powered-by ====> Value = JSP/2.1
[crit] lb.runtime: RNTM2017:Header Name = Content-type ====> Value = text/html;charset=ISO-8859-1
[crit] lb.runtime: RNTM2017:Header Name = Content-length ====> Value = 1584
[crit] lb.runtime: RNTM2017:Header Name = Date ====> Value = Thu, 25 Sep 2008 08:26:57 GMT
[crit] lb.runtime: RNTM2017:Header Name = Set-cookie ====> Value = JSESSIONIDVERSION=/clusterjsp:1; Path=/clusterjsp
[crit] lb.runtime: RNTM2003:After LBDaemonManager::serviceRequest()
[crit] lb.runtime: RNTM2007:Request Succeeded

It's seems ok.
Then I Strees(only few thread) apache with jmeter and many request make the error.

Now In the apache error.log continuously appear this entries:
(p.s. MOBISERVER and mobipc are the nodes hostname)

[warn] lb.runtime: RNTM2024: Daemon http://MOBISERVER:38081 is unhealthy.
[warn] lb.runtime: RNTM2030: Daemon Monitor : http://MOBISERVER:38081 : could be because daemon is down
[warn] lb.runtime: RNTM2025: Daemon http://mobipc:38080 is healthy.
[warn] lb.runtime: RNTM2025: Daemon http://mobipc:38080 is healthy.
[warn] lb.runtime: RNTM2025: Daemon http://mobipc:38080 is healthy.
[warn] lb.healthchecker: HLCK3003: Listener: http://MOBISERVER:38081 is detected to be still unHealthy in cluster: cluster
[warn] lb.healthchecker: HLCK3003: Listener: http://MOBISERVER:38081 is detected to be still unHealthy in cluster: cluster
[warn] lb.healthchecker: HLCK3003: Listener: http://MOBISERVER:38081 is detected to be still unHealthy in cluster: cluster
[warn] lb.healthchecker: HLCK3003: Listener: http://mobipc:38080 is detected to be still unHealthy in cluster: cluster
[warn] lb.healthchecker: HLCK3003: Listener: http://mobipc:38080 is detected to be still unHealthy in cluster: cluster
..
[warn] lb.runtime: RNTM2024: Daemon http://mobipc:38080 is unhealthy.
[warn] lb.runtime: RNTM2030: Daemon Monitor : http://mobipc:38080 : could be because daemon is down
[warn] lb.runtime: RNTM2024: Daemon http://mobipc:38080 is unhealthy.
[warn] lb.runtime: RNTM2030: Daemon Monitor : http://mobipc:38080 : could be because daemon is down
[warn] lb.runtime: RNTM2024: Daemon http://MOBISERVER:38081 is unhealthy.
[warn] lb.runtime: RNTM2030: Daemon Monitor : http://MOBISERVER:38081 : could be because daemon is down
[warn] lb.runtime: RNTM2025: Daemon http://mobipc:38080 is healthy.
[warn] lb.healthchecker: HLCK3003: Listener: http://MOBISERVER:38081 is detected to be still unHealthy in cluster: cluster
..

When I call the page by loadbalancer, both when error appear and not appear in glassfish instance server.log I read this entry:

- Log Level:INFO
- Logger: javax.enterprise.system.stream.out
- Name-Value Pairs: _ThreadID=22;_ThreadName=httpSSLWorkerThread-38080-4;
- Record Number: 3750
- Message ID
- Complete Message: No parameter entered for this request

I think that the mod_balancer detect the server sometime healty and some time unhealty, so when it detect unHealthy the error appear.
But I can't understand this because the instance are always running.

Moreover with jmeter test I notice performance downgrade by using loadbalancer, the single cluster instance is better .
[Message sent by forum member 'peppeme' (peppeme)]

http://forums.java.net/jive/thread.jspa?messageID=301497