[JBoss JIRA] (MODCLUSTER-399) Draining pending requests fails with Oracle JDK8
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-399?page=com.atlassian.jira.pl... ]
RH Bugzilla Integration commented on MODCLUSTER-399:
----------------------------------------------------
Michal Babacek <mbabacek(a)redhat.com> changed the Status of [bug 1083563|https://bugzilla.redhat.com/show_bug.cgi?id=1083563] from ON_QA to VERIFIED
> Draining pending requests fails with Oracle JDK8
> ------------------------------------------------
>
> Key: MODCLUSTER-399
> URL: https://issues.jboss.org/browse/MODCLUSTER-399
> Project: mod_cluster
> Issue Type: Bug
> Affects Versions: 1.2.8.Final
> Environment: RHEL7 x86_64, Apache/2.2.26 (Red Hat Enterprise Web Server), Oracle JDK 8
> Reporter: Michal Babacek
> Assignee: Radoslav Husar
> Attachments: 1-access_log.zip, 1-error_log.zip, 1-server.log, 2-access_log.zip, 2-error_log.zip, 2-server.log, 3-access_log.zip, 3-error_log.zip, 3-server.log, 4-access_log.zip, 4-error_log.zip, 4-server.log, 5-access_log.zip, 5-error_log.zip, 5-server.log, clusterbench.war, Flood.py, JDK7-JDK8.log, mod_cluster.conf, simplecontext-666.war, standalone-ha.xml, trace-logs-jdk17AndJdk18.zip
>
>
> I've noticed several tests that run O.K. with Oracle JDK7 and fail with Oracle JDK8. One can reproduce these failures anytime, they are not just random glitches.
> Notes on the setup:
> * {{simplecontext-666}} is a simple JSP web app, non-distributable
> * {{clusterbench}} is a distributable webapp
> * all the tests use 1 worker node and 1 balancer
> * many clients throwing many requests at the {{simplecontext-666}} context
> h3. Stop Context Timeout test
> First, there is the setup with {{stop-context-timeout="20"}}:
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" stop-context-timeout="20" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior. On a clean shutdown, message {{Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds}} is displayed. See the whole log here: [^1-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 22) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-8) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 284ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000022: Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-11) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 20035ms
> {noformat}
> On the other hand, with *JDK8*, this utterly fails. No waiting for pending requests, no message. See the whole log here: [^2-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 18) JBAS018224: Unregister web context: /simplecontext-666
> [org.apache.tomcat.util] (http-/10.16.88.17:8080-Acceptor) JBWEB003022: Channel processing failed
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.server.deployment] (MSC service thread 1-10) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 310ms
> [org.jboss.as] (MSC service thread 1-2) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 348ms
> {noformat}
> These are the Apache HTTP Server logs, showing exactly what was the test doing:
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> *JDK7*, access_log, (See the complete log here [^1-access_log.zip])
> {noformat}
> [06:47:04] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:12] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "STATUS / HTTP/1.1" 200 60 "-" "ClusterListener/1.0"
> [06:47:13] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:20] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:47:40] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^2-access_log.zip])
> {noformat}
> [06:43:10] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:17] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [06:43:19] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:25] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> In the aforementioned snippets, it is noteworthy that the *JDK8* run sent only one {{STOP-APP}} message. This is confirmed in error logs:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^1-error_log.zip])
> {noformat}
> [06:47:20] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:20] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:47:20] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:47:20] mod_manager.c(2666): manager_handler STOP-APP OK
> [06:47:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [06:47:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 294
> [06:47:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^2-error_log.zip])
> {noformat}
> [06:43:25] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:43:25] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:43:25] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:43:25] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> One could argue that there was a test error and the *JDK8* test run actually didn't access {{simplecontext-666}} application. Let me dissolve this argument right away:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27250
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK7/httpd/logs/access_log
> 27927
> {noformat}
> h3. Default settings, the same problem...
> Trial with the default settings reveals the same problem with some additional findings in the Apache's error log.
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior, this time with the default 10 seconds timeout. See the whole log here: [^3-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 263ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000022: Failed to drain 340 remaining pending requests from default-host:/simplecontext-666 within 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-9) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 10082ms
> {noformat}
> *JDK8* fails. No waiting for pending requests, no message. This time even with ISE :(. See the whole log here: [^4-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.modcluster] (ServerService Thread Pool -- 19) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.0 seconds
> [org.jboss.as.txn] (ajp-/10.16.88.17:8009-21) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException
> at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.checkTransactionStatus(TransactionRollbackSetupAction.java:112)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:66)
> at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:61) [jboss-as-web-7.4.0.Final-redhat-6.jar:7.4.0.Final-redhat-6]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:490) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at java.lang.Thread.run(Thread.java:744) [rt.jar:1.8.0]
> +++
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 301ms
> [org.jboss.as] (MSC service thread 1-15) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 313ms
> {noformat}
> In the access logs, it is noteworthy that both {{clusterbench}} and {{simplecontext-666}} sent {{ENABLE-APP}}, but there was only one {{STOP-APP}} message. Furthermore, who and why used {{OPTIONS}} method?
> *JDK7*, access_log, (See the complete log here [^3-access_log.zip])
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> {noformat}
> [07:31:49] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:31:57] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:31:58] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:32:05] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:14] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:32:15] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^4-access_log.zip])
> {noformat}
> [07:29:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:32] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:29:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> Error log shows what context was the {{STOP-APP}} message linked to:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^3-error_log.zip])
> {noformat}
> [07:32:15] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:32:15] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [07:32:15] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 340
> [07:32:15] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^4-error_log.zip])
> {noformat}
> [07:29:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:29:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:29:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:29:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> h3. Default settings, again
> I had considered the {{JBAS010151: Unable to get transaction state: java.lang.IllegalStateException}} being probably an unrelated glitch, so I tried the default test run with *JDK8* again. Test failed, yet this time without any exception. Nothing has changed since the last run as far as environment and configuration are concerned.
> *JDK8* fails. No waiting for pending requests on {{/simplecontext-666}}. See the whole log here: [^5-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /clusterbench
> [org.apache.catalina.core] (MSC service thread 1-6) JBWEB001079: Container org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/] has not been started
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003075: Coyote HTTP/1.1 pausing on: http-/10.16.88.17:8080
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003077: Coyote HTTP/1.1 stopping on : http-/10.16.88.17:8080
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-15) JBAS010409: Unbound data source [java:jboss/datasources/ExampleDS]
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 9) JBAS010282: Stopped repl cache from web container
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 16) JBAS010282: Stopped default-host/clusterbench cache from web container
> [org.jboss.as.server.deployment] (MSC service thread 1-13) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 306ms
> [org.jboss.as.server.deployment] (MSC service thread 1-5) JBAS015877: Stopped deployment clusterbench.war (runtime-name: clusterbench.war) in 310ms
> [org.jboss.as] (MSC service thread 1-16) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 333ms
> {noformat}
> *JDK8*, access_log, (See the complete log here [^5-access_log.zip])
> {noformat}
> [07:45:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:33] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [07:45:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:39] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:41] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> This time, there were two {{STOP-APP}} messages all right, but instead one of them being for {{clusterbench}} and the other one for {{simplecontext-666}}, they were both for {{clusterbench}}. I find this behavior being a rather disturbing one.
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^5-error_log.zip])
> {noformat}
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> Again, there were plenty of requests sent to {{simplecontext-666/}}:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27587
> {noformat}
> WDYT?
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-432) on MacOSX Mavericks java stops behaving linuxlike...
by Jean-Frederic Clere (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-432?page=com.atlassian.jira.pl... ]
Jean-Frederic Clere updated MODCLUSTER-432:
-------------------------------------------
Summary: on MacOSX Mavericks java stops behaving linuxlike... (was: mod_cluster binds to multicast socket instead uncast one)
> on MacOSX Mavericks java stops behaving linuxlike...
> ----------------------------------------------------
>
> Key: MODCLUSTER-432
> URL: https://issues.jboss.org/browse/MODCLUSTER-432
> Project: mod_cluster
> Issue Type: Feature Request
> Components: Core & Container Integration (Java)
> Affects Versions: 1.3.1.Alpha2
> Reporter: Jean-Frederic Clere
> Assignee: Jean-Frederic Clere
> Fix For: 1.3.1.Alpha3
>
>
> Basically that causes 2 tests to fail on macsox (Darwin Kernel Version 13.4.0)
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-399) Draining pending requests fails with Oracle JDK8
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-399?page=com.atlassian.jira.pl... ]
RH Bugzilla Integration commented on MODCLUSTER-399:
----------------------------------------------------
Michal Babacek <mbabacek(a)redhat.com> changed the Status of [bug 1083563|https://bugzilla.redhat.com/show_bug.cgi?id=1083563] from MODIFIED to ON_QA
> Draining pending requests fails with Oracle JDK8
> ------------------------------------------------
>
> Key: MODCLUSTER-399
> URL: https://issues.jboss.org/browse/MODCLUSTER-399
> Project: mod_cluster
> Issue Type: Bug
> Affects Versions: 1.2.8.Final
> Environment: RHEL7 x86_64, Apache/2.2.26 (Red Hat Enterprise Web Server), Oracle JDK 8
> Reporter: Michal Babacek
> Assignee: Radoslav Husar
> Attachments: 1-access_log.zip, 1-error_log.zip, 1-server.log, 2-access_log.zip, 2-error_log.zip, 2-server.log, 3-access_log.zip, 3-error_log.zip, 3-server.log, 4-access_log.zip, 4-error_log.zip, 4-server.log, 5-access_log.zip, 5-error_log.zip, 5-server.log, clusterbench.war, Flood.py, JDK7-JDK8.log, mod_cluster.conf, simplecontext-666.war, standalone-ha.xml, trace-logs-jdk17AndJdk18.zip
>
>
> I've noticed several tests that run O.K. with Oracle JDK7 and fail with Oracle JDK8. One can reproduce these failures anytime, they are not just random glitches.
> Notes on the setup:
> * {{simplecontext-666}} is a simple JSP web app, non-distributable
> * {{clusterbench}} is a distributable webapp
> * all the tests use 1 worker node and 1 balancer
> * many clients throwing many requests at the {{simplecontext-666}} context
> h3. Stop Context Timeout test
> First, there is the setup with {{stop-context-timeout="20"}}:
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" stop-context-timeout="20" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior. On a clean shutdown, message {{Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds}} is displayed. See the whole log here: [^1-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 22) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-8) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 284ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000022: Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-11) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 20035ms
> {noformat}
> On the other hand, with *JDK8*, this utterly fails. No waiting for pending requests, no message. See the whole log here: [^2-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 18) JBAS018224: Unregister web context: /simplecontext-666
> [org.apache.tomcat.util] (http-/10.16.88.17:8080-Acceptor) JBWEB003022: Channel processing failed
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.server.deployment] (MSC service thread 1-10) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 310ms
> [org.jboss.as] (MSC service thread 1-2) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 348ms
> {noformat}
> These are the Apache HTTP Server logs, showing exactly what was the test doing:
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> *JDK7*, access_log, (See the complete log here [^1-access_log.zip])
> {noformat}
> [06:47:04] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:12] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "STATUS / HTTP/1.1" 200 60 "-" "ClusterListener/1.0"
> [06:47:13] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:20] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:47:40] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^2-access_log.zip])
> {noformat}
> [06:43:10] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:17] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [06:43:19] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:25] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> In the aforementioned snippets, it is noteworthy that the *JDK8* run sent only one {{STOP-APP}} message. This is confirmed in error logs:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^1-error_log.zip])
> {noformat}
> [06:47:20] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:20] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:47:20] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:47:20] mod_manager.c(2666): manager_handler STOP-APP OK
> [06:47:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [06:47:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 294
> [06:47:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^2-error_log.zip])
> {noformat}
> [06:43:25] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:43:25] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:43:25] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:43:25] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> One could argue that there was a test error and the *JDK8* test run actually didn't access {{simplecontext-666}} application. Let me dissolve this argument right away:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27250
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK7/httpd/logs/access_log
> 27927
> {noformat}
> h3. Default settings, the same problem...
> Trial with the default settings reveals the same problem with some additional findings in the Apache's error log.
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior, this time with the default 10 seconds timeout. See the whole log here: [^3-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 263ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000022: Failed to drain 340 remaining pending requests from default-host:/simplecontext-666 within 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-9) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 10082ms
> {noformat}
> *JDK8* fails. No waiting for pending requests, no message. This time even with ISE :(. See the whole log here: [^4-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.modcluster] (ServerService Thread Pool -- 19) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.0 seconds
> [org.jboss.as.txn] (ajp-/10.16.88.17:8009-21) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException
> at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.checkTransactionStatus(TransactionRollbackSetupAction.java:112)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:66)
> at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:61) [jboss-as-web-7.4.0.Final-redhat-6.jar:7.4.0.Final-redhat-6]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:490) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at java.lang.Thread.run(Thread.java:744) [rt.jar:1.8.0]
> +++
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 301ms
> [org.jboss.as] (MSC service thread 1-15) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 313ms
> {noformat}
> In the access logs, it is noteworthy that both {{clusterbench}} and {{simplecontext-666}} sent {{ENABLE-APP}}, but there was only one {{STOP-APP}} message. Furthermore, who and why used {{OPTIONS}} method?
> *JDK7*, access_log, (See the complete log here [^3-access_log.zip])
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> {noformat}
> [07:31:49] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:31:57] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:31:58] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:32:05] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:14] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:32:15] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^4-access_log.zip])
> {noformat}
> [07:29:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:32] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:29:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> Error log shows what context was the {{STOP-APP}} message linked to:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^3-error_log.zip])
> {noformat}
> [07:32:15] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:32:15] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [07:32:15] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 340
> [07:32:15] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^4-error_log.zip])
> {noformat}
> [07:29:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:29:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:29:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:29:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> h3. Default settings, again
> I had considered the {{JBAS010151: Unable to get transaction state: java.lang.IllegalStateException}} being probably an unrelated glitch, so I tried the default test run with *JDK8* again. Test failed, yet this time without any exception. Nothing has changed since the last run as far as environment and configuration are concerned.
> *JDK8* fails. No waiting for pending requests on {{/simplecontext-666}}. See the whole log here: [^5-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /clusterbench
> [org.apache.catalina.core] (MSC service thread 1-6) JBWEB001079: Container org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/] has not been started
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003075: Coyote HTTP/1.1 pausing on: http-/10.16.88.17:8080
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003077: Coyote HTTP/1.1 stopping on : http-/10.16.88.17:8080
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-15) JBAS010409: Unbound data source [java:jboss/datasources/ExampleDS]
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 9) JBAS010282: Stopped repl cache from web container
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 16) JBAS010282: Stopped default-host/clusterbench cache from web container
> [org.jboss.as.server.deployment] (MSC service thread 1-13) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 306ms
> [org.jboss.as.server.deployment] (MSC service thread 1-5) JBAS015877: Stopped deployment clusterbench.war (runtime-name: clusterbench.war) in 310ms
> [org.jboss.as] (MSC service thread 1-16) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 333ms
> {noformat}
> *JDK8*, access_log, (See the complete log here [^5-access_log.zip])
> {noformat}
> [07:45:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:33] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [07:45:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:39] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:41] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> This time, there were two {{STOP-APP}} messages all right, but instead one of them being for {{clusterbench}} and the other one for {{simplecontext-666}}, they were both for {{clusterbench}}. I find this behavior being a rather disturbing one.
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^5-error_log.zip])
> {noformat}
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> Again, there were plenty of requests sent to {{simplecontext-666/}}:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27587
> {noformat}
> WDYT?
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-432) mod_cluster binds to multicast socket instead uncast one
by Jean-Frederic Clere (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-432?page=com.atlassian.jira.pl... ]
Jean-Frederic Clere updated MODCLUSTER-432:
-------------------------------------------
Git Pull Request: https://github.com/modcluster/mod_cluster/pull/120 (was: https://github.com/modcluster/mod_cluster/pull/118)
> mod_cluster binds to multicast socket instead uncast one
> --------------------------------------------------------
>
> Key: MODCLUSTER-432
> URL: https://issues.jboss.org/browse/MODCLUSTER-432
> Project: mod_cluster
> Issue Type: Feature Request
> Components: Core & Container Integration (Java)
> Affects Versions: 1.3.1.Alpha2
> Reporter: Jean-Frederic Clere
> Assignee: Jean-Frederic Clere
> Fix For: 1.3.1.Alpha3
>
>
> Basically that causes 2 tests to fail on macsox (Darwin Kernel Version 13.4.0)
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-399) Draining pending requests fails with Oracle JDK8
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-399?page=com.atlassian.jira.pl... ]
RH Bugzilla Integration commented on MODCLUSTER-399:
----------------------------------------------------
Kabir Khan <kkhan(a)redhat.com> changed the Status of [bug 1083563|https://bugzilla.redhat.com/show_bug.cgi?id=1083563] from POST to MODIFIED
> Draining pending requests fails with Oracle JDK8
> ------------------------------------------------
>
> Key: MODCLUSTER-399
> URL: https://issues.jboss.org/browse/MODCLUSTER-399
> Project: mod_cluster
> Issue Type: Bug
> Affects Versions: 1.2.8.Final
> Environment: RHEL7 x86_64, Apache/2.2.26 (Red Hat Enterprise Web Server), Oracle JDK 8
> Reporter: Michal Babacek
> Assignee: Radoslav Husar
> Attachments: 1-access_log.zip, 1-error_log.zip, 1-server.log, 2-access_log.zip, 2-error_log.zip, 2-server.log, 3-access_log.zip, 3-error_log.zip, 3-server.log, 4-access_log.zip, 4-error_log.zip, 4-server.log, 5-access_log.zip, 5-error_log.zip, 5-server.log, clusterbench.war, Flood.py, JDK7-JDK8.log, mod_cluster.conf, simplecontext-666.war, standalone-ha.xml, trace-logs-jdk17AndJdk18.zip
>
>
> I've noticed several tests that run O.K. with Oracle JDK7 and fail with Oracle JDK8. One can reproduce these failures anytime, they are not just random glitches.
> Notes on the setup:
> * {{simplecontext-666}} is a simple JSP web app, non-distributable
> * {{clusterbench}} is a distributable webapp
> * all the tests use 1 worker node and 1 balancer
> * many clients throwing many requests at the {{simplecontext-666}} context
> h3. Stop Context Timeout test
> First, there is the setup with {{stop-context-timeout="20"}}:
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" stop-context-timeout="20" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior. On a clean shutdown, message {{Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds}} is displayed. See the whole log here: [^1-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 22) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-8) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 284ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000022: Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-11) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 20035ms
> {noformat}
> On the other hand, with *JDK8*, this utterly fails. No waiting for pending requests, no message. See the whole log here: [^2-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 18) JBAS018224: Unregister web context: /simplecontext-666
> [org.apache.tomcat.util] (http-/10.16.88.17:8080-Acceptor) JBWEB003022: Channel processing failed
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.server.deployment] (MSC service thread 1-10) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 310ms
> [org.jboss.as] (MSC service thread 1-2) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 348ms
> {noformat}
> These are the Apache HTTP Server logs, showing exactly what was the test doing:
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> *JDK7*, access_log, (See the complete log here [^1-access_log.zip])
> {noformat}
> [06:47:04] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:12] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "STATUS / HTTP/1.1" 200 60 "-" "ClusterListener/1.0"
> [06:47:13] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:20] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:47:40] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^2-access_log.zip])
> {noformat}
> [06:43:10] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:17] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [06:43:19] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:25] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> In the aforementioned snippets, it is noteworthy that the *JDK8* run sent only one {{STOP-APP}} message. This is confirmed in error logs:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^1-error_log.zip])
> {noformat}
> [06:47:20] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:20] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:47:20] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:47:20] mod_manager.c(2666): manager_handler STOP-APP OK
> [06:47:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [06:47:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 294
> [06:47:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^2-error_log.zip])
> {noformat}
> [06:43:25] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:43:25] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:43:25] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:43:25] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> One could argue that there was a test error and the *JDK8* test run actually didn't access {{simplecontext-666}} application. Let me dissolve this argument right away:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27250
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK7/httpd/logs/access_log
> 27927
> {noformat}
> h3. Default settings, the same problem...
> Trial with the default settings reveals the same problem with some additional findings in the Apache's error log.
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior, this time with the default 10 seconds timeout. See the whole log here: [^3-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 263ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000022: Failed to drain 340 remaining pending requests from default-host:/simplecontext-666 within 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-9) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 10082ms
> {noformat}
> *JDK8* fails. No waiting for pending requests, no message. This time even with ISE :(. See the whole log here: [^4-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.modcluster] (ServerService Thread Pool -- 19) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.0 seconds
> [org.jboss.as.txn] (ajp-/10.16.88.17:8009-21) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException
> at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.checkTransactionStatus(TransactionRollbackSetupAction.java:112)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:66)
> at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:61) [jboss-as-web-7.4.0.Final-redhat-6.jar:7.4.0.Final-redhat-6]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:490) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at java.lang.Thread.run(Thread.java:744) [rt.jar:1.8.0]
> +++
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 301ms
> [org.jboss.as] (MSC service thread 1-15) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 313ms
> {noformat}
> In the access logs, it is noteworthy that both {{clusterbench}} and {{simplecontext-666}} sent {{ENABLE-APP}}, but there was only one {{STOP-APP}} message. Furthermore, who and why used {{OPTIONS}} method?
> *JDK7*, access_log, (See the complete log here [^3-access_log.zip])
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> {noformat}
> [07:31:49] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:31:57] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:31:58] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:32:05] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:14] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:32:15] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^4-access_log.zip])
> {noformat}
> [07:29:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:32] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:29:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> Error log shows what context was the {{STOP-APP}} message linked to:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^3-error_log.zip])
> {noformat}
> [07:32:15] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:32:15] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [07:32:15] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 340
> [07:32:15] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^4-error_log.zip])
> {noformat}
> [07:29:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:29:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:29:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:29:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> h3. Default settings, again
> I had considered the {{JBAS010151: Unable to get transaction state: java.lang.IllegalStateException}} being probably an unrelated glitch, so I tried the default test run with *JDK8* again. Test failed, yet this time without any exception. Nothing has changed since the last run as far as environment and configuration are concerned.
> *JDK8* fails. No waiting for pending requests on {{/simplecontext-666}}. See the whole log here: [^5-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /clusterbench
> [org.apache.catalina.core] (MSC service thread 1-6) JBWEB001079: Container org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/] has not been started
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003075: Coyote HTTP/1.1 pausing on: http-/10.16.88.17:8080
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003077: Coyote HTTP/1.1 stopping on : http-/10.16.88.17:8080
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-15) JBAS010409: Unbound data source [java:jboss/datasources/ExampleDS]
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 9) JBAS010282: Stopped repl cache from web container
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 16) JBAS010282: Stopped default-host/clusterbench cache from web container
> [org.jboss.as.server.deployment] (MSC service thread 1-13) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 306ms
> [org.jboss.as.server.deployment] (MSC service thread 1-5) JBAS015877: Stopped deployment clusterbench.war (runtime-name: clusterbench.war) in 310ms
> [org.jboss.as] (MSC service thread 1-16) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 333ms
> {noformat}
> *JDK8*, access_log, (See the complete log here [^5-access_log.zip])
> {noformat}
> [07:45:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:33] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [07:45:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:39] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:41] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> This time, there were two {{STOP-APP}} messages all right, but instead one of them being for {{clusterbench}} and the other one for {{simplecontext-666}}, they were both for {{clusterbench}}. I find this behavior being a rather disturbing one.
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^5-error_log.zip])
> {noformat}
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> Again, there were plenty of requests sent to {{simplecontext-666/}}:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27587
> {noformat}
> WDYT?
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-432) mod_cluster binds to multicast socket instead uncast one
by Paul Ferraro (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-432?page=com.atlassian.jira.pl... ]
Paul Ferraro commented on MODCLUSTER-432:
-----------------------------------------
Can you post a stacktrace of the failures?
> mod_cluster binds to multicast socket instead uncast one
> --------------------------------------------------------
>
> Key: MODCLUSTER-432
> URL: https://issues.jboss.org/browse/MODCLUSTER-432
> Project: mod_cluster
> Issue Type: Feature Request
> Components: Core & Container Integration (Java)
> Affects Versions: 1.3.1.Alpha2
> Reporter: Jean-Frederic Clere
> Assignee: Jean-Frederic Clere
> Fix For: 1.3.1.Alpha3
>
>
> Basically that causes 2 tests to fail on macsox (Darwin Kernel Version 13.4.0)
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-432) mod_cluster binds to multicast socket instead uncast one
by Radoslav Husar (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-432?page=com.atlassian.jira.pl... ]
Radoslav Husar updated MODCLUSTER-432:
--------------------------------------
Summary: mod_cluster binds to multicast socket instead uncast one (was: mod_cluster bind to multicast socket instead uncast one.)
Fix Version/s: 1.3.1.Alpha3
Affects Version/s: 1.3.1.Alpha2
Component/s: Core & Container Integration (Java)
> mod_cluster binds to multicast socket instead uncast one
> --------------------------------------------------------
>
> Key: MODCLUSTER-432
> URL: https://issues.jboss.org/browse/MODCLUSTER-432
> Project: mod_cluster
> Issue Type: Feature Request
> Components: Core & Container Integration (Java)
> Affects Versions: 1.3.1.Alpha2
> Reporter: Jean-Frederic Clere
> Assignee: Jean-Frederic Clere
> Fix For: 1.3.1.Alpha3
>
>
> Basically that causes 2 tests to fail on macsox (Darwin Kernel Version 13.4.0)
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-399) Draining pending requests fails with Oracle JDK8
by Radoslav Husar (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-399?page=com.atlassian.jira.pl... ]
Radoslav Husar resolved MODCLUSTER-399.
---------------------------------------
Resolution: Rejected
This turned out to be an integration issue, nothing had to be changed in mod_cluster project itself. Please see linked bugzilla and Jira for the respective fixes.
> Draining pending requests fails with Oracle JDK8
> ------------------------------------------------
>
> Key: MODCLUSTER-399
> URL: https://issues.jboss.org/browse/MODCLUSTER-399
> Project: mod_cluster
> Issue Type: Bug
> Affects Versions: 1.2.8.Final
> Environment: RHEL7 x86_64, Apache/2.2.26 (Red Hat Enterprise Web Server), Oracle JDK 8
> Reporter: Michal Babacek
> Assignee: Radoslav Husar
> Attachments: 1-access_log.zip, 1-error_log.zip, 1-server.log, 2-access_log.zip, 2-error_log.zip, 2-server.log, 3-access_log.zip, 3-error_log.zip, 3-server.log, 4-access_log.zip, 4-error_log.zip, 4-server.log, 5-access_log.zip, 5-error_log.zip, 5-server.log, clusterbench.war, Flood.py, JDK7-JDK8.log, mod_cluster.conf, simplecontext-666.war, standalone-ha.xml, trace-logs-jdk17AndJdk18.zip
>
>
> I've noticed several tests that run O.K. with Oracle JDK7 and fail with Oracle JDK8. One can reproduce these failures anytime, they are not just random glitches.
> Notes on the setup:
> * {{simplecontext-666}} is a simple JSP web app, non-distributable
> * {{clusterbench}} is a distributable webapp
> * all the tests use 1 worker node and 1 balancer
> * many clients throwing many requests at the {{simplecontext-666}} context
> h3. Stop Context Timeout test
> First, there is the setup with {{stop-context-timeout="20"}}:
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" stop-context-timeout="20" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior. On a clean shutdown, message {{Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds}} is displayed. See the whole log here: [^1-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 22) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-8) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 284ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000022: Failed to drain 294 remaining pending requests from default-host:/simplecontext-666 within 20.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 9) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-8) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-11) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 20035ms
> {noformat}
> On the other hand, with *JDK8*, this utterly fails. No waiting for pending requests, no message. See the whole log here: [^2-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 18) JBAS018224: Unregister web context: /simplecontext-666
> [org.apache.tomcat.util] (http-/10.16.88.17:8080-Acceptor) JBWEB003022: Channel processing failed
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.server.deployment] (MSC service thread 1-10) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 310ms
> [org.jboss.as] (MSC service thread 1-2) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 348ms
> {noformat}
> These are the Apache HTTP Server logs, showing exactly what was the test doing:
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> *JDK7*, access_log, (See the complete log here [^1-access_log.zip])
> {noformat}
> [06:47:04] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:12] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:12] "STATUS / HTTP/1.1" 200 60 "-" "ClusterListener/1.0"
> [06:47:13] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:19] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:20] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:47:40] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:47:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^2-access_log.zip])
> {noformat}
> [06:43:10] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:17] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:17] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [06:43:19] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [06:43:25] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [06:43:25] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> In the aforementioned snippets, it is noteworthy that the *JDK8* run sent only one {{STOP-APP}} message. This is confirmed in error logs:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^1-error_log.zip])
> {noformat}
> [06:47:20] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:20] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:47:20] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:47:20] mod_manager.c(2666): manager_handler STOP-APP OK
> [06:47:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:47:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [06:47:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 294
> [06:47:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^2-error_log.zip])
> {noformat}
> [06:43:25] mod_manager.c(1901): manager_trans STOP-APP (/)
> [06:43:25] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [06:43:25] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [06:43:25] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> One could argue that there was a test error and the *JDK8* test run actually didn't access {{simplecontext-666}} application. Let me dissolve this argument right away:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27250
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK7/httpd/logs/access_log
> 27927
> {noformat}
> h3. Default settings, the same problem...
> Trial with the default settings reveals the same problem with some additional findings in the Apache's error log.
> {code}
> <subsystem xmlns="urn:jboss:domain:modcluster:1.2">
> <mod-cluster-config advertise-socket="modcluster" connector="ajp">
> <dynamic-load-provider>
> <load-metric type="busyness"/>
> </dynamic-load-provider>
> </mod-cluster-config>
> </subsystem>
> {code}
> On *JDK7*, one may observe exactly the desired behavior, this time with the default 10 seconds timeout. See the whole log here: [^3-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 263ms
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000024: All active sessions drained from default-host:/simplecontext-666 in 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000022: Failed to drain 340 remaining pending requests from default-host:/simplecontext-666 within 10.0 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 7) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-13) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as] (MSC service thread 1-9) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 10082ms
> {noformat}
> *JDK8* fails. No waiting for pending requests, no message. This time even with ISE :(. See the whole log here: [^4-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.modcluster] (ServerService Thread Pool -- 19) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.0 seconds
> [org.jboss.as.txn] (ajp-/10.16.88.17:8009-21) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException
> at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.checkTransactionStatus(TransactionRollbackSetupAction.java:112)
> at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:66)
> at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:61) [jboss-as-web-7.4.0.Final-redhat-6.jar:7.4.0.Final-redhat-6]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:490) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.4.0.Final.jar:7.4.0.Final]
> at java.lang.Thread.run(Thread.java:744) [rt.jar:1.8.0]
> +++
> [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 301ms
> [org.jboss.as] (MSC service thread 1-15) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 313ms
> {noformat}
> In the access logs, it is noteworthy that both {{clusterbench}} and {{simplecontext-666}} sent {{ENABLE-APP}}, but there was only one {{STOP-APP}} message. Furthermore, who and why used {{OPTIONS}} method?
> *JDK7*, access_log, (See the complete log here [^3-access_log.zip])
> Note that thousands of {{"GET /simplecontext-666/ HTTP/1.1"}} messages were omitted from these snippets.
> {noformat}
> [07:31:49] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:31:57] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:31:57] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:31:58] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:32:05] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:14] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:32:15] "STOP-APP / HTTP/1.1" 200 86 "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:32:15] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> {noformat}
> *JDK8*, access_log, (See the complete log here [^4-access_log.zip])
> {noformat}
> [07:29:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:32] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:32] "STATUS / HTTP/1.1" 200 63 "-" "ClusterListener/1.0"
> [07:29:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:29:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:29:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> Error log shows what context was the {{STOP-APP}} message linked to:
> *JDK7*, error_log, {{grep STOP-APP}} (See the complete log here [^3-error_log.zip])
> {noformat}
> [07:32:15] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:32:15] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fsimplecontext-666"
> [07:32:15] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 340
> [07:32:15] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^4-error_log.zip])
> {noformat}
> [07:29:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:29:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:29:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:29:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> h3. Default settings, again
> I had considered the {{JBAS010151: Unable to get transaction state: java.lang.IllegalStateException}} being probably an unrelated glitch, so I tried the default test run with *JDK8* again. Test failed, yet this time without any exception. Nothing has changed since the last run as far as environment and configuration are concerned.
> *JDK8* fails. No waiting for pending requests on {{/simplecontext-666}}. See the whole log here: [^5-server.log].
> {noformat}
> [org.jboss.web] (ServerService Thread Pool -- 16) JBAS018224: Unregister web context: /clusterbench
> [org.apache.catalina.core] (MSC service thread 1-6) JBWEB001079: Container org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/] has not been started
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003075: Coyote HTTP/1.1 pausing on: http-/10.16.88.17:8080
> [org.apache.coyote.http11.Http11NioProtocol] (MSC service thread 1-14) JBWEB003077: Coyote HTTP/1.1 stopping on : http-/10.16.88.17:8080
> [org.jboss.web] (ServerService Thread Pool -- 3) JBAS018224: Unregister web context: /simplecontext-666
> [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-15) JBAS010409: Unbound data source [java:jboss/datasources/ExampleDS]
> [org.jboss.modcluster] (ServerService Thread Pool -- 16) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000021: All pending requests drained from default-host:/clusterbench in 0.1 seconds
> [org.jboss.modcluster] (ServerService Thread Pool -- 14) MODCLUSTER000002: Initiating mod_cluster shutdown
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003048: Pausing Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.apache.coyote.ajp] (MSC service thread 1-1) JBWEB003051: Stopping Coyote AJP/1.3 on ajp-/10.16.88.17:8009
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 9) JBAS010282: Stopped repl cache from web container
> [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 16) JBAS010282: Stopped default-host/clusterbench cache from web container
> [org.jboss.as.server.deployment] (MSC service thread 1-13) JBAS015877: Stopped deployment simplecontext-666.war (runtime-name: simplecontext-666.war) in 306ms
> [org.jboss.as.server.deployment] (MSC service thread 1-5) JBAS015877: Stopped deployment clusterbench.war (runtime-name: clusterbench.war) in 310ms
> [org.jboss.as] (MSC service thread 1-16) JBAS015950: JBoss EAP 6.3.0.Alpha2 (AS 7.4.0.Final-redhat-6) stopped in 333ms
> {noformat}
> *JDK8*, access_log, (See the complete log here [^5-access_log.zip])
> {noformat}
> [07:45:25] "GET /mcm HTTP/1.1" 200 446 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:33] "INFO / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "ENABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:33] "STATUS / HTTP/1.1" 200 62 "-" "ClusterListener/1.0"
> [07:45:34] "GET /mcm HTTP/1.1" 200 1916 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
> [07:45:39] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "DISABLE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "STOP-APP / HTTP/1.1" 200 84 "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "REMOVE-APP /* HTTP/1.1" 200 - "-" "ClusterListener/1.0"
> [07:45:40] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> [07:45:41] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.26 (Red Hat Enterprise Web Server) (internal dummy connection)"
> {noformat}
> This time, there were two {{STOP-APP}} messages all right, but instead one of them being for {{clusterbench}} and the other one for {{simplecontext-666}}, they were both for {{clusterbench}}. I find this behavior being a rather disturbing one.
> *JDK8*, error_log, {{grep STOP-APP}} (See the complete log here [^5-error_log.zip])
> {noformat}
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> [07:45:40] mod_manager.c(1901): manager_trans STOP-APP (/)
> [07:45:40] mod_manager.c(2617): manager_handler STOP-APP (/) processing: "JVMRoute=jboss-eap-6.3&Alias=default-host%2Clocalhost%2Cexample.com&Context=%2Fclusterbench"
> [07:45:40] mod_manager.c(1429): process_appl_cmd: STOP-APP nbrequests 0
> [07:45:40] mod_manager.c(2666): manager_handler STOP-APP OK
> {noformat}
> Again, there were plenty of requests sent to {{simplecontext-666/}}:
> {noformat}
> grep -c "GET /simplecontext-666/ HTTP/1.1\" 200" ./targetJDK8/httpd/logs/access_log
> 27587
> {noformat}
> WDYT?
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-390) add failonstatus to mod_cluster
by Jean-Frederic Clere (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-390?page=com.atlassian.jira.pl... ]
Jean-Frederic Clere commented on MODCLUSTER-390:
------------------------------------------------
Actually the bahaviour of mod_cluster makes sense but it different to mod_proxy_balancer I am not sure which on is the best.
mod_proxy_balancer wats for the retry time mod_cluster doesn't.
> add failonstatus to mod_cluster
> -------------------------------
>
> Key: MODCLUSTER-390
> URL: https://issues.jboss.org/browse/MODCLUSTER-390
> Project: mod_cluster
> Issue Type: Enhancement
> Affects Versions: 1.2.6.Final, 1.3.0.Final
> Reporter: Jean-Frederic Clere
> Assignee: Jean-Frederic Clere
> Priority: Critical
> Fix For: 1.2.8.Final, 1.3.1.Alpha3
>
> Attachments: error_log.zip
>
>
> The feature was added in httpd-2.2.17 in the mod_proxy_balancer we just need to copy that code and find a way to configure it,
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0
[JBoss JIRA] (MODCLUSTER-430) CreateBalancers behave the same with option 0 or 2
by Michal Babacek (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-430?page=com.atlassian.jira.pl... ]
Michal Babacek updated MODCLUSTER-430:
--------------------------------------
Fix Version/s: 1.2.10.Final
1.3.1.Alpha3
> CreateBalancers behave the same with option 0 or 2
> --------------------------------------------------
>
> Key: MODCLUSTER-430
> URL: https://issues.jboss.org/browse/MODCLUSTER-430
> Project: mod_cluster
> Issue Type: Bug
> Components: Native (httpd modules)
> Affects Versions: 1.3.0.Final, 1.2.9.Final
> Environment: RHEL 6.4.0
> Apache HTTPD 2.4.10
> JBoss 6.1.1
> Mod_cluster 1.3.0 Final
> Reporter: John Jerome
> Assignee: Michal Babacek
> Fix For: 1.2.10.Final, 1.3.1.Alpha3
>
>
> The directive CreateBalancers with directive 0 or 2 creates the balancers on all httpd vhosts.
> With option 2, the balancers should be created on the main server only, not in the vhosts.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
9 years, 6 months
- 1
- 0