[mod_cluster-issues] [JBoss JIRA] (MODCLUSTER-353) SocketTimeoutException in DefaultMCMPHandler when using httpd 2.4.x
Markus Locher (JIRA)
issues at jboss.org
Wed Nov 18 04:36:00 EST 2015
[ https://issues.jboss.org/browse/MODCLUSTER-353?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13130095#comment-13130095 ]
Markus Locher edited comment on MODCLUSTER-353 at 11/18/15 4:35 AM:
--------------------------------------------------------------------
{code:title=Apache-2.4_modcluster_debug ERROR-Log}
[core:notice] [pid 9269] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[suexec:notice] [pid 9268] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost xxx.xxx.xxx:80, skipping SSL setup
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost example.com:80, skipping SSL setup
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost xxx.xxx.xxx:6666, skipping SSL setup
[ssl:info] [pid 9268] AH01887: Init: Initializing (virtual) servers for SSL
[ssl:info] [pid 9268] AH01876: mod_ssl/2.4.6 compiled against Server: Apache/2.4.6, Library: OpenSSL/1.0.1e
[auth_digest:notice] [pid 9268] AH01757: generating secret for digest authentication ...
[auth_digest:debug] [pid 9268] mod_auth_digest.c(250): AH01759: done
[slotmem_shm:debug] [pid 9268] mod_slotmem_shm.c(448): AH02301: attach looking for /run/httpd/slotmem-shm-mod_heartmonitor.shm
[lbmethod_heartbeat:notice] [pid 9268] AH02282: No slotmem from mod_heartmonitor
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(391): AH00821: shmcb_init allocated 512000 bytes of shared memory
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(407): AH00822: for 511912 bytes (512000 including header), recommending 32 subcaches, 88 indexes each
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(440): AH00824: shmcb_init_memory choices follow
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(442): AH00825: subcache_num = 32
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(444): AH00826: subcache_size = 15992
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(446): AH00827: subcache_data_offset = 2128
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(448): AH00828: subcache_data_size = 13864
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(450): AH00829: index_num = 88
[socache_shmcb:info] [pid 9268] AH00830: Shared memory socache initialised
[:notice] [pid 9268] Advertise initialized for process 9268
[mpm_prefork:notice] [pid 9268] AH00163: Apache/2.4.6 (CentOS) mod_cluster/1.3.1.Final OpenSSL/1.0.1e-fips configured -- resuming normal operations
[mpm_prefork:info] [pid 9268] AH00164: Server built: Aug 24 2015 18:11:25
[core:notice] [pid 9268] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[mpm_prefork:debug] [pid 9268] prefork.c(1005): AH00165: Accept mutex: sysvsem (default: sysvsem)
[:debug] [pid 9282] mod_proxy_cluster.c(695): add_balancer_node: Create balancer balancer://jb711-dev-cluster
[:debug] [pid 9282] mod_proxy_cluster.c(293): Created: worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9282] proxy_util.c(1835): AH00924: worker ajp://10.1.1.5:8009 shared already initialized
[proxy:debug] [pid 9282] proxy_util.c(1882): AH00927: initializing worker ajp://10.1.1.5:8009 local
[proxy:debug] [pid 9282] proxy_util.c(1933): AH00931: initialized single connection worker in child 9282 for (10.1.1.5)
[reqtimeout:info] [pid 9274] [client 10.1.1.5:41618] AH01382: Request body read timeout
[:debug] [pid 9280] mod_manager.c(2271): manager_trans CONFIG (/)
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9281] mod_manager.c(2987): manager_handler CONFIG (/) processing: "JVMRoute=jboss711-standalone-node1&Host=10.1.1.5&Maxattempts=1&Port=8009&StickySessionForce=No&Type=ajp&ping=10"
[:debug] [pid 9280] mod_manager.c(3038): manager_handler CONFIG OK
[:debug] [pid 9280] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9280] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9282] mod_manager.c(2271): manager_trans INFO (/)
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9282] mod_manager.c(2987): manager_handler INFO (/) processing: ""
[:debug] [pid 9282] mod_manager.c(3038): manager_handler INFO OK
[:debug] [pid 9274] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9274] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[proxy:debug] [pid 9280] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[proxy:debug] [pid 9271] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[proxy:debug] [pid 9280] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[proxy:debug] [pid 9271] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[proxy:debug] [pid 9280] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[proxy:debug] [pid 9271] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9271] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9280] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9280] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9271] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9271] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[reqtimeout:info] [pid 9282] [client 10.1.1.5:41630] AH01382: Request body read timeout
[:debug] [pid 9270] mod_manager.c(2271): manager_trans CONFIG (/)
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9270] mod_manager.c(2987): manager_handler CONFIG (/) processing: "JVMRoute=jboss711-standalone-node1&Host=10.1.1.5&Maxattempts=1&Port=8009&StickySessionForce=No&Type=ajp&ping=10"
[:debug] [pid 9270] mod_manager.c(3038): manager_handler CONFIG OK
[proxy:debug] [pid 9272] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9280] mod_proxy_cluster.c(1054): update_workers_node starting
[proxy:debug] [pid 9272] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9272] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9270] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9274] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9274] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9271] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9271] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9273] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9272] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9272] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(1066): update_workers_node done
{code}
the access log has theses entries when the jboss error "Read timed out" happens
{code:title=Apache-2.4 ACCESS-Log}
10.1.1.5 - - [18/Nov/2015:10:28:31 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:29:01 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:29:31 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:30:01 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:30:31 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:31:01 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:31:31 +0100] "INFO / HTTP/1.1" 200 230 "-" "ClusterListener/1.0"
10.1.1.5 - - [18/Nov/2015:10:31:51 +0100] "CONFIG / HTTP/1.1" 200 - "-" "ClusterListener/1.0"
...
{code}
and the config
{code:title=Apache-2.4_modcluster_config}
<IfModule manager_module>
Listen 10.1.1.1:6666
Listen 127.0.0.1:6666
ManagerBalancerName jb711-dev-cluster
LogLevel debug
<VirtualHost *:6666>
<Location />
Require local
Require ip 10.1.1
Require ip 10.1.10
Require ip 10.1.0
</Location>
KeepAliveTimeout 300
MaxKeepAliveRequests 0
#ServerAdvertise on http://@IP@:6666
AdvertiseFrequency 5
#AdvertiseSecurityKey secret
#AdvertiseGroup @ADVIP@:23364
AdvertiseGroup 224.0.1.105:23364
EnableMCPMReceive
ServerAdvertise On
<Location /mod_cluster_manager>
SetHandler mod_cluster-manager
Require local
Require ip 10.1.1
Require ip 10.1.10
Require ip 10.1.0
</Location>
</VirtualHost>
</IfModule>
{code}
was (Author: askkeller):
{code:title=Apache-2.4_modcluster_debug Log}
[core:notice] [pid 9269] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[suexec:notice] [pid 9268] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost xxx.xxx.xxx:80, skipping SSL setup
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost example.com:80, skipping SSL setup
[ssl:debug] [pid 9268] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost xxx.xxx.xxx:6666, skipping SSL setup
[ssl:info] [pid 9268] AH01887: Init: Initializing (virtual) servers for SSL
[ssl:info] [pid 9268] AH01876: mod_ssl/2.4.6 compiled against Server: Apache/2.4.6, Library: OpenSSL/1.0.1e
[auth_digest:notice] [pid 9268] AH01757: generating secret for digest authentication ...
[auth_digest:debug] [pid 9268] mod_auth_digest.c(250): AH01759: done
[slotmem_shm:debug] [pid 9268] mod_slotmem_shm.c(448): AH02301: attach looking for /run/httpd/slotmem-shm-mod_heartmonitor.shm
[lbmethod_heartbeat:notice] [pid 9268] AH02282: No slotmem from mod_heartmonitor
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(391): AH00821: shmcb_init allocated 512000 bytes of shared memory
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(407): AH00822: for 511912 bytes (512000 including header), recommending 32 subcaches, 88 indexes each
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(440): AH00824: shmcb_init_memory choices follow
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(442): AH00825: subcache_num = 32
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(444): AH00826: subcache_size = 15992
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(446): AH00827: subcache_data_offset = 2128
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(448): AH00828: subcache_data_size = 13864
[socache_shmcb:debug] [pid 9268] mod_socache_shmcb.c(450): AH00829: index_num = 88
[socache_shmcb:info] [pid 9268] AH00830: Shared memory socache initialised
[:notice] [pid 9268] Advertise initialized for process 9268
[mpm_prefork:notice] [pid 9268] AH00163: Apache/2.4.6 (CentOS) mod_cluster/1.3.1.Final OpenSSL/1.0.1e-fips configured -- resuming normal operations
[mpm_prefork:info] [pid 9268] AH00164: Server built: Aug 24 2015 18:11:25
[core:notice] [pid 9268] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[mpm_prefork:debug] [pid 9268] prefork.c(1005): AH00165: Accept mutex: sysvsem (default: sysvsem)
[:debug] [pid 9282] mod_proxy_cluster.c(695): add_balancer_node: Create balancer balancer://jb711-dev-cluster
[:debug] [pid 9282] mod_proxy_cluster.c(293): Created: worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9282] proxy_util.c(1835): AH00924: worker ajp://10.1.1.5:8009 shared already initialized
[proxy:debug] [pid 9282] proxy_util.c(1882): AH00927: initializing worker ajp://10.1.1.5:8009 local
[proxy:debug] [pid 9282] proxy_util.c(1933): AH00931: initialized single connection worker in child 9282 for (10.1.1.5)
[reqtimeout:info] [pid 9274] [client 10.1.1.5:41618] AH01382: Request body read timeout
[:debug] [pid 9280] mod_manager.c(2271): manager_trans CONFIG (/)
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9280] mod_authz_core.c(809): [client 10.1.1.5:41622] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9281] mod_manager.c(2987): manager_handler CONFIG (/) processing: "JVMRoute=jboss711-standalone-node1&Host=10.1.1.5&Maxattempts=1&Port=8009&StickySessionForce=No&Type=ajp&ping=10"
[:debug] [pid 9280] mod_manager.c(3038): manager_handler CONFIG OK
[:debug] [pid 9280] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9280] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9282] mod_manager.c(2271): manager_trans INFO (/)
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9282] mod_authz_core.c(809): [client 10.1.1.5:41630] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9282] mod_manager.c(2987): manager_handler INFO (/) processing: ""
[:debug] [pid 9282] mod_manager.c(3038): manager_handler INFO OK
[:debug] [pid 9274] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9274] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[proxy:debug] [pid 9280] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[proxy:debug] [pid 9271] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[proxy:debug] [pid 9280] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[proxy:debug] [pid 9271] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[proxy:debug] [pid 9280] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[proxy:debug] [pid 9271] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9271] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9280] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9280] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9271] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9271] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[reqtimeout:info] [pid 9282] [client 10.1.1.5:41630] AH01382: Request body read timeout
[:debug] [pid 9270] mod_manager.c(2271): manager_trans CONFIG (/)
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of <RequireAny>: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require local : denied
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of Require ip 10.1.1: granted
[authz_core:debug] [pid 9270] mod_authz_core.c(809): [client 10.1.1.5:41633] AH01626: authorization result of <RequireAny>: granted
[:debug] [pid 9270] mod_manager.c(2987): manager_handler CONFIG (/) processing: "JVMRoute=jboss711-standalone-node1&Host=10.1.1.5&Maxattempts=1&Port=8009&StickySessionForce=No&Type=ajp&ping=10"
[:debug] [pid 9270] mod_manager.c(3038): manager_handler CONFIG OK
[proxy:debug] [pid 9272] proxy_util.c(2200): AH00942: ajp: has acquired connection for (10.1.1.5)
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9280] mod_proxy_cluster.c(1054): update_workers_node starting
[proxy:debug] [pid 9272] proxy_util.c(2253): [remote (null):0] AH00944: connecting ajp://10.1.1.5:8009/ to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[proxy:debug] [pid 9272] proxy_util.c(2419): [remote (null):0] AH00947: connected / to 10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9280] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1413): proxy_cluster_try_pingpong: connected to backend
[:debug] [pid 9270] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9274] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9270] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9274] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9270] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9271] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9271] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9271] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9273] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9273] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1130): ajp_cping_cpong: Done
[proxy:debug] [pid 9272] proxy_util.c(2215): AH00943: ajp: has released connection for (10.1.1.5)
[:debug] [pid 9272] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(1066): update_workers_node done
[:debug] [pid 9272] mod_proxy_cluster.c(1054): update_workers_node starting
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(317): Created: reusing worker for ajp://10.1.1.5:8009
[:debug] [pid 9272] mod_proxy_cluster.c(1066): update_workers_node done
{code}
and the config
{code:title=Apache-2.4_modcluster_config}
<IfModule manager_module>
Listen 10.1.1.1:6666
Listen 127.0.0.1:6666
ManagerBalancerName jb711-dev-cluster
LogLevel debug
<VirtualHost *:6666>
<Location />
Require local
Require ip 10.1.1
Require ip 10.1.10
Require ip 10.1.0
</Location>
KeepAliveTimeout 300
MaxKeepAliveRequests 0
#ServerAdvertise on http://@IP@:6666
AdvertiseFrequency 5
#AdvertiseSecurityKey secret
#AdvertiseGroup @ADVIP@:23364
AdvertiseGroup 224.0.1.105:23364
EnableMCPMReceive
ServerAdvertise On
<Location /mod_cluster_manager>
SetHandler mod_cluster-manager
Require local
Require ip 10.1.1
Require ip 10.1.10
Require ip 10.1.0
</Location>
</VirtualHost>
</IfModule>
{code}
> SocketTimeoutException in DefaultMCMPHandler when using httpd 2.4.x
> -------------------------------------------------------------------
>
> Key: MODCLUSTER-353
> URL: https://issues.jboss.org/browse/MODCLUSTER-353
> Project: mod_cluster
> Issue Type: Bug
> Affects Versions: 1.2.1.Final
> Environment: httpd-2.4.6 and mod_cluster-1.2.1.Final and above
> Reporter: Marco Danti
> Assignee: Jean-Frederic Clere
> Attachments: screenshot-1.png
>
>
> After upgrading a web server from Apache 2.2.x (with mod_cluster 1.2.0) to Apache 2.4.6 (with mod_cluster 1.2.1.Final), when I bring up JBoss (7.2.0.Final) I start seeing repeated errors like the following:
>
> 14:45:36,777 INFO [org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) IO error sending command CONFIG to proxy stw-1.priv.softeco.it/172.16.0.133:6666: java.net.SocketTimeoutException: Read timed out
> at java.net.SocketInputStream.socketRead0(Native Method) [rt.jar:1.7.0_21]
> at java.net.SocketInputStream.read(SocketInputStream.java:150) [rt.jar:1.7.0_21]
> at java.net.SocketInputStream.read(SocketInputStream.java:121) [rt.jar:1.7.0_21]
> at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) [rt.jar:1.7.0_21]
> at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) [rt.jar:1.7.0_21]
> at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) [rt.jar:1.7.0_21]
> at java.io.InputStreamReader.read(InputStreamReader.java:184) [rt.jar:1.7.0_21]
> at java.io.BufferedReader.fill(BufferedReader.java:154) [rt.jar:1.7.0_21]
> at java.io.BufferedReader.readLine(BufferedReader.java:317) [rt.jar:1.7.0_21]
> at java.io.BufferedReader.readLine(BufferedReader.java:382) [rt.jar:1.7.0_21]
> at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.sendRequest(DefaultMCMPHandler.java:670)
> at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.sendRequests(DefaultMCMPHandler.java:437)
> at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.status(DefaultMCMPHandler.java:385)
> at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.status(DefaultMCMPHandler.java:349)
> at org.jboss.modcluster.ModClusterService.status(ModClusterService.java:468)
> at org.jboss.modcluster.container.catalina.CatalinaEventHandlerAdapter.lifecycleEvent(CatalinaEventHandlerAdapter.java:244)
> at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:115) [jbossweb-7.2.0.Final.jar:7.2.0.Final]
> at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1323) [jbossweb-7.2.0.Final.jar:7.2.0.Final]
> at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1588) [jbossweb-7.2.0.Final.jar:7.2.0.Final]
> at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1574) [jbossweb-7.2.0.Final.jar:7.2.0.Final]
> at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_21]
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
More information about the mod_cluster-issues
mailing list