Bug 52056

Summary: Wrong HTTP status 200 in log instead of 500/503
Product: Tomcat Connectors Reporter: Dmitry Zamaruev <avenger>
Component: mod_jkAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: minor    
Priority: P2    
Version: 1.2.32   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Attachments: default value for request_rec.status
mod_jk configuration
mod_jk workers properties

Description Dmitry Zamaruev 2011-10-19 10:04:19 UTC
Created attachment 27818 [details]
default value for request_rec.status

In case JkLogFormat contains "%s" (Request HTTP status) placeholder - it is not always shows correct codes.
If there are no workers available - mod_jk records 200 (HTTP_OK) in logs, while httpd records and shows 503 error:

<<access.log:
172.16.16.1 - - [19/Oct/2011:10:35:01 +0300] "GET / HTTP/1.1" 503 323

<<mod_jk.log:
[Wed Oct 19 10:35:01.906 2011] [2053:3086162528] [error] ajp_send_request::jk_ajp_common.c (1630): (devel) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=111)                        
[Wed Oct 19 10:35:01.906 2011] [2053:3086162528] [error] ajp_send_request::jk_ajp_common.c (1630): (devel) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=111)                        
[Wed Oct 19 10:35:01.906 2011] [2053:3086162528] [error] ajp_service::jk_ajp_common.c (2626): (devel) connecting to tomcat failed.

[Wed Oct 19 10:35:01.906 2011] 0.100435 - vm201.int GET / HTTP/1.1 200

[Wed Oct 19 10:35:01.906 2011] [2053:3086162528] [info] jk_handler::mod_jk.c (2678): Service error=-3 for worker=devel

It seems that request.status (the one that got recorded in logs) have default value of 200 and is updated only in jk_ajp_common.c::ajp_get_reply(). But this function never hit if jk_ajp_common.c::ajp_send_request() returns anything besides JK_TRUE. 
Maybe request.status variable should be initialized the same way as is_error variable in jk_handler() - default value HTTP_INTERNAL_SERVER_ERROR, and all subsequent  functions will alter its value to one they needed. With such modification mod_jk will put 500 error in case request failed before it have a chance to connect to backend (see attachment).
Comment 1 Dmitry Zamaruev 2011-10-19 10:07:32 UTC
With patch applied I have more correct values in logs:
<<access.log:
[19/Oct/2011:12:32:45 +0300] "GET / HTTP/1.1" 503 323 "-"
[19/Oct/2011:12:33:45 +0300] "GET /jk-status HTTP/1.1" 200 5459 "-"

<<mod_jk.log:
[19/Oct/2011:12:32:45 +0300] 0.101018 - vm201.int "GET / HTTP/1.1" 500
19/Oct/2011:12:33:45 +0300] 0.002270 - vm201.int "GET /jk-status HTTP/1.1" 200
Comment 2 Konstantin Kolinko 2011-10-19 10:15:39 UTC
1. Versions of everything = ?
There are various fixes in various Tomcat versions and the behaviour may be different.

2. What exactly are those files, "access.log" and "mod_jk.log"?
Or better provide exact steps & configuration to reproduce this.
Comment 3 Dmitry Zamaruev 2011-10-19 10:38:00 UTC
Created attachment 27819 [details]
mod_jk configuration
Comment 4 Dmitry Zamaruev 2011-10-19 10:38:33 UTC
Created attachment 27820 [details]
mod_jk workers properties

Sorry, forget about versions:
mod_jk - 1.2.32 (latest) 
httpd - 2.2.21

access.log - default apache access log, configured with:
CustomLog /var/log/httpd/access.log combined

mod_jk.log - default mod_jk log file:
JkLogFile /var/log/httpd/mod_jk.log
JkRequestLogFormat     "%T %R %V \"%r\" %s"

Configuration is simple - any unreachable worker will work. See attachments for example configuration.
Comment 5 Rainer Jung 2011-10-23 15:31:17 UTC
Fixed in r1187906. Will be part of mod_jk 1.2.33.

To fix the problem, the JK request log was refactored to use the standard request log hook. You can apply the changes in r1187906 on top of 1.2.32 to test it.

regards,

Rainer