[JBoss JIRA] (MODCLUSTER-433) remove_session_route causes an infinite loop when parsing jsessionid out of URLs
by Aaron Ogburn (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-433?page=com.atlassian.jira.pl... ]
Aaron Ogburn updated MODCLUSTER-433:
------------------------------------
Description:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
{code}
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
{code}
That is looping here:
{code:title=mod_proxy_cluster.c}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
was:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
{code}
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
{code}
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs
> --------------------------------------------------------------------------------
>
> Key: MODCLUSTER-433
> URL: https://issues.jboss.org/browse/MODCLUSTER-433
> Project: mod_cluster
> Issue Type: Bug
> Components: Native (httpd modules)
> Affects Versions: 1.2.9.Final, 1.3.1.Alpha2
> Reporter: Aaron Ogburn
> Assignee: Jean-Frederic Clere
>
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
> {code}
> #0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
> #1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
> #2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
> #3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
> #4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
> #5 0x00007f4cf776df70 in ap_run_handler ()
> #6 0x00007f4cf777180e in ap_invoke_handler ()
> #7 0x00007f4cf777cfd0 in ap_process_request ()
> #8 0x00007f4cf7779d48 in ?? ()
> #9 0x00007f4cf7775a58 in ap_run_process_connection ()
> #10 0x00007f4cf7781fa7 in ?? ()
> #11 0x00007f4cf77822ca in ?? ()
> #12 0x00007f4cf7782f4c in ap_mpm_run ()
> #13 0x00007f4cf7759ab5 in main ()
> {code}
> That is looping here:
> {code:title=mod_proxy_cluster.c}
> while (*path !='&' || *path !='\0')
> path++;
> {code}
> "*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years
[JBoss JIRA] (MODCLUSTER-433) remove_session_route causes an infinite loop when parsing jsessionid out of URLs
by Aaron Ogburn (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-433?page=com.atlassian.jira.pl... ]
Aaron Ogburn updated MODCLUSTER-433:
------------------------------------
Description:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
{code}
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
{code}
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
was:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
{code}
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
{code]
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs
> --------------------------------------------------------------------------------
>
> Key: MODCLUSTER-433
> URL: https://issues.jboss.org/browse/MODCLUSTER-433
> Project: mod_cluster
> Issue Type: Bug
> Components: Native (httpd modules)
> Affects Versions: 1.2.9.Final, 1.3.1.Alpha2
> Reporter: Aaron Ogburn
> Assignee: Jean-Frederic Clere
>
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
> {code}
> #0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
> #1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
> #2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
> #3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
> #4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
> #5 0x00007f4cf776df70 in ap_run_handler ()
> #6 0x00007f4cf777180e in ap_invoke_handler ()
> #7 0x00007f4cf777cfd0 in ap_process_request ()
> #8 0x00007f4cf7779d48 in ?? ()
> #9 0x00007f4cf7775a58 in ap_run_process_connection ()
> #10 0x00007f4cf7781fa7 in ?? ()
> #11 0x00007f4cf77822ca in ?? ()
> #12 0x00007f4cf7782f4c in ap_mpm_run ()
> #13 0x00007f4cf7759ab5 in main ()
> {code}
> That is looping here:
> {code}
> while (*path !='&' || *path !='\0')
> path++;
> {code}
> "*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years
[JBoss JIRA] (MODCLUSTER-433) remove_session_route causes an infinite loop when parsing jsessionid out of URLs
by Aaron Ogburn (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-433?page=com.atlassian.jira.pl... ]
Aaron Ogburn updated MODCLUSTER-433:
------------------------------------
Description:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
{code}
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
{code]
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
was:
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs
> --------------------------------------------------------------------------------
>
> Key: MODCLUSTER-433
> URL: https://issues.jboss.org/browse/MODCLUSTER-433
> Project: mod_cluster
> Issue Type: Bug
> Components: Native (httpd modules)
> Affects Versions: 1.2.9.Final, 1.3.1.Alpha2
> Reporter: Aaron Ogburn
> Assignee: Jean-Frederic Clere
>
> remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
> {code}
> #0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
> #1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
> #2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
> #3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
> #4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
> #5 0x00007f4cf776df70 in ap_run_handler ()
> #6 0x00007f4cf777180e in ap_invoke_handler ()
> #7 0x00007f4cf777cfd0 in ap_process_request ()
> #8 0x00007f4cf7779d48 in ?? ()
> #9 0x00007f4cf7775a58 in ap_run_process_connection ()
> #10 0x00007f4cf7781fa7 in ?? ()
> #11 0x00007f4cf77822ca in ?? ()
> #12 0x00007f4cf7782f4c in ap_mpm_run ()
> #13 0x00007f4cf7759ab5 in main ()
> {code]
> That is looping here:
> {code}
> while (*path !='&' || *path !='\0')
> path++;
> {code}
> "*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years
[JBoss JIRA] (MODCLUSTER-433) remove_session_route causes an infinite loop when parsing jsessionid out of URLs
by Aaron Ogburn (JIRA)
Aaron Ogburn created MODCLUSTER-433:
---------------------------------------
Summary: remove_session_route causes an infinite loop when parsing jsessionid out of URLs
Key: MODCLUSTER-433
URL: https://issues.jboss.org/browse/MODCLUSTER-433
Project: mod_cluster
Issue Type: Bug
Components: Native (httpd modules)
Affects Versions: 1.3.1.Alpha2, 1.2.9.Final
Reporter: Aaron Ogburn
Assignee: Jean-Frederic Clere
remove_session_route causes an infinite loop when parsing jsessionid out of URLs. The stack of the looping thread is:
#0 0x00007f4cf2b66e45 in remove_session_route () from /etc/httpd/modules/mod_proxy_cluster.so
#1 0x00007f4cf2b68ad9 in ?? () from /etc/httpd/modules/mod_proxy_cluster.so
#2 0x00007f4cf2f7d116 in proxy_run_pre_request () from /etc/httpd/modules/mod_proxy.so
#3 0x00007f4cf2f84186 in ap_proxy_pre_request () from /etc/httpd/modules/mod_proxy.so
#4 0x00007f4cf2f813c2 in ?? () from /etc/httpd/modules/mod_proxy.so
#5 0x00007f4cf776df70 in ap_run_handler ()
#6 0x00007f4cf777180e in ap_invoke_handler ()
#7 0x00007f4cf777cfd0 in ap_process_request ()
#8 0x00007f4cf7779d48 in ?? ()
#9 0x00007f4cf7775a58 in ap_run_process_connection ()
#10 0x00007f4cf7781fa7 in ?? ()
#11 0x00007f4cf77822ca in ?? ()
#12 0x00007f4cf7782f4c in ap_mpm_run ()
#13 0x00007f4cf7759ab5 in main ()
That is looping here:
{code}
while (*path !='&' || *path !='\0')
path++;
{code}
"*path !='&' || *path !='\0'" is a tautology so the while never ends. It should be an && instead of ||.
--
This message was sent by Atlassian JIRA
(v6.3.1#6329)
11 years
[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:
----------------------------------------------------
Radoslav Husar <rhusar(a)redhat.com> changed the Status of [bug 1083563|https://bugzilla.redhat.com/show_bug.cgi?id=1083563] from NEW to POST
> 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)
11 years
[JBoss JIRA] (MODCLUSTER-399) Draining pending requests fails with Oracle JDK8
by Michal Babacek (JIRA)
[ https://issues.jboss.org/browse/MODCLUSTER-399?page=com.atlassian.jira.pl... ]
Michal Babacek commented on MODCLUSTER-399:
-------------------------------------------
The patched build Radoslav gave me last night fixes the issue :-) I think it's ready for a pull request and some further regression testing, just in case...
> 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)
11 years