Unexpected Behaviour. Unable to go live.
joaocunhalopes Apr 12, 2011 12:58 PMFirst, this is what I belive that should not happen:
Looking at the Apache logs, for two subsequent requests at the same context (one request is OK the other is showing a 404 Page Not Found error)
This is the Apache access log: Green is expected. Red is unexpected:
192.168.120.115 - - [07/Apr/2011:10:29:02 +0100] "POST /scpcqaw/SurveyServiceWS HTTP/1.1" 200 2326
192.168.120.115 - - [07/Apr/2011:10:29:03 +0100] "POST /scpcqaw/SurveyServiceWS HTTP/1.1" 404 -
This is the Apache error log (in debug mode) for both requests. Again, I have marked green what it's expected and red what I consider to be unexpected:
[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS
[Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2011): proxy: AJP: has acquired connection for (192.168.150.43)
[Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS to 192.168.150.43:8309
[Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2193): proxy: connected /scpcqaw/SurveyServiceWS to 192.168.150.43:8309
[Thu Apr 07 10:29:02 2011] [debug] ajp_utils.c(31): Into ajp_handle_cping_cpong
[Thu Apr 07 10:29:02 2011] [debug] ajp_utils.c(102): ajp_handle_cping_cpong: Done
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [SOAPAction] = [""]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Accept] = [text/xml, multipart/related, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [Content-Type] = [text/xml;charset="utf-8"]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [JAX-WS RI 2.1.3-b02-]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Host] = [192.168.150.6]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [Connection] = [keep-alive]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[6] [Content-Length] = [529]
[Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(450): ajp_marshal_into_msgb: Done
[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(265): proxy: APR_BUCKET_IS_EOS
[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(270): proxy: data to read (max 8186 at 4)
[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(285): proxy: got 529 bytes of data
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 200
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 2
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [X-Powered-By] = [Servlet 2.5; JBoss-5.0/JBossWeb-2.1]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[1] [Content-Type] = [text/xml;charset=utf-8]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(609): ajp_unmarshal_response: ap_set_content_type done
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 05
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 05
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(568): proxy: got response from 192.168.150.43:8309 (192.168.150.43)
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (192.168.150.43)
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_cluster.c(1423): proxy: byrequests balancer DONE (ajp://192.168.150.43:8109)
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy.c(1015): Running scheme balancer handler (attempt 0)
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2011): proxy: AJP: has acquired connection for (192.168.150.43)
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS to 192.168.150.43:8109
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2193): proxy: connected /scpcqaw/SurveyServiceWS to 192.168.150.43:8109
[Thu Apr 07 10:29:03 2011] [debug] ajp_utils.c(31): Into ajp_handle_cping_cpong
[Thu Apr 07 10:29:03 2011] [debug] ajp_utils.c(102): ajp_handle_cping_cpong: Done
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [SOAPAction] = [""]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Accept] = [text/xml, multipart/related, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [Content-Type] = [text/xml;charset="utf-8"]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [JAX-WS RI 2.1.3-b02-]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Host] = [192.168.150.6]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [Connection] = [keep-alive]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[6] [Content-Length] = [386]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(450): ajp_marshal_into_msgb: Done
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(265): proxy: APR_BUCKET_IS_EOS
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(270): proxy: data to read (max 8186 at 4)
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(285): proxy: got 386 bytes of data
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 404
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 1
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [Content-Length] = [0]
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 05
[Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 05
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(568): proxy: got response from 192.168.150.43:8109 (192.168.150.43)
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (192.168.150.43)
It's unexpected that the request (I mean, the one with 404 Page Not Found) is routed to
192.168.150.43:8109
The reason why this is unexpected is based on the fact that there is no /scpcqaw context on this IP/port.
Take a look at the mod_cluster manager information:
Node: [1],Name: si_part2_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8209,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 2,Read: 22009,Transfered: 410,Connected: 0,Load: 96
Node: [2],Name: si_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8109,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 97
Node: [3],Name: ph_part1_node2,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.44,Port: 8009,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 96
Node: [4],Name: ph_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8009,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 47,Read: 0,Transfered: 0,Connected: 0,Load: 97
Node: [5],Name: ne_part1_node2,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.44,Port: 8409,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 1,Read: 0,Transfered: 0,Connected: 0,Load: 96
Node: [6],Name: ne_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8409,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 1,Read: 0,Transfered: 0,Connected: 0,Load: 98
Node: [7],Name: pc_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8309,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 84,Read: 1027146,Transfered: 77,Connected: 0,Load: 94
Vhost: [1:1:1], Alias: localhost
Vhost: [2:1:2], Alias: localhost
Vhost: [3:1:3], Alias: localhost
Vhost: [4:1:4], Alias: localhost
Vhost: [5:1:5], Alias: localhost
Vhost: [6:1:6], Alias: localhost
Vhost: [7:1:7], Alias: localhost
Context: [1:1:1], Context: /femss, Status: ENABLED
Context: [3:1:3], Context: /fephn, Status: ENABLED
Context: [4:1:4], Context: /fephn, Status: ENABLED
Context: [5:1:5], Context: /load-demo, Status: ENABLED
Context: [6:1:6], Context: /load-demo, Status: ENABLED
Context: [7:1:7], Context: /bopcapl, Status: ENABLED
Context: [7:1:8], Context: /scpcreports, Status: ENABLED
Context: [2:1:9], Context: /fectt, Status: ENABLED
Context: [7:1:10], Context: /fepcapl, Status: ENABLED
Context: [7:1:11], Context: /scpcpsm, Status: ENABLED
Context: [7:1:12], Context: /scpcqaw, Status: ENABLED
Context: [7:1:13], Context: /scpcmgu, Status: ENABLED
So the question is:
if there is no /scpcqaw context on
Node: [2],Name: si_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8109,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 97
why are there these lines
[Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS
[Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS to 192.168.150.43:8109
on the Apache logs?
Any help is welcome!