--- Begin Message ---
Package: libapache2-mod-jk
Version: 1:1.2.23-2
Severity: normal
I have apache2 (version 2.2.3-4) setup in front of a tomcat5.5 (version
5.5.20-2) installation, and use libapache2-mod-jk for the connection
between them.
With the introduction of version 1.2.23-1 into testing, I noticed an
issue after reloading apache's modules. In my investigation, I also
tested version 1.2.23-2 from unstable, with the same results. All the
snippets from logs from my investigation were using 1.2.21-1
and 1.2.23-2.
The webapp makes heavy use of rewrites, and after the upgrade, I
immediately ran into issues...
One of the rewrites in use in the system is:
RewriteRule ^/item/([0-9]+)\.html$ /servlet/Main/ItemPage?item_id=$1
[QSA,PT,L]
If I browsed to
http://loris.website.com/servlet/Main/ItemPage?item_id=38244 there were
no problems, but if I used the rewritten url,
http://loris.website.com/item/38244.html I noticed a 400 response code
in the apache access.log.
First I checked the rewrite logs, and from the logging it appears to
be working as expected:
10.0.0.18 - - [19/Jun/2007:15:29:37 --0500]
[loris.website.com/sid#8265b28][rid#834a290/initial] (3) applying
pattern
'^/item/([0-9]+)\.html$' to uri '/item/38244.html'
10.0.0.18 - - [19/Jun/2007:15:29:37 --0500]
[loris.website.com/sid#8265b28][rid#834a290/initial] (2) rewrite
'/item/38244.html' -> '/servlet/Main/ItemPage?item_id=38244'
10.0.0.18 - - [19/Jun/2007:15:29:37 --0500]
[loris.website.com/sid#8265b28][rid#834a290/initial] (3) split
uri=/servlet/Main/ItemPage?item_id=38244 ->
uri=/servlet/Main/ItemPage, args=item_id=38244
10.0.0.18 - - [19/Jun/2007:15:29:37 --0500]
[loris.website.com/sid#8265b28][rid#834a290/initial] (2) forcing
'/servlet/Main/ItemPage' to get passed through to next API
URI-to-filename handler
After bumping up the logging in the mod_jk.log, I see the following
error:
[Tue Jun 19 15:29:37 2007] [14509:2960] [debug] jk_handler::mod_jk.c
(2238): Service finished with status=400 for worker=ajp13_worker
A bit earlier in the log I can make out the following error message
coming back from AJP:
No Host matches server name loris.website.com
I turned on the RequestDumperValve and I used ngrep for a little further
investigation...
For version 1.2.21-1 and 1.2.23-2, I first loaded the full url, and then
the rewritten url, and used the following ngrep command to capture the
conversation:
ngrep -qW byline port 8009 -d lo
version 1.2.21-1, full request:
T 127.0.0.1:46581 -> 127.0.0.1:8009 [AP]
.4.F....HTTP/1.1.../servlet/Main/ItemPage...10.0.0.18.....loris.website.com..P.......loris.website.com....eMozilla/5.0
(X11; U; Linux i686; en-US; rv:1.8.0.11) Gecko/20070324
(Debian-1.8.0.11-4)
Epiphany/2.14....ctext/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5.....gzip,deflate.....ISO-8859-1,utf-8;q=0.7,*;q=0.7..
Keep-Alive...300....
keep-alive.....JSESSIONID=958FA4582A9B2D4770614436CA528B20;
browser=H9FRGJ7YM5; cookiesEnabled=true;
loyaltyDiscount=a3c3ede6-7a4b-4bef-8d7f-80242e348273;
browser=YQB8JUJCQ8.....0....item_id=38244..
T 127.0.0.1:8009 -> 127.0.0.1:46581 [AP]
AB.......OK....
Set-Cookie..3JSESSIONID=958FA4582A9B2D4770614436CA528B20; Path=/..
Set-Cookie..9tuylu=show; Expires=Thu, 01-Jan-1970 00:00:10 GMT;
Path=/...Content-Type...text/html.
T 127.0.0.1:8009 -> 127.0.0.1:46581 [AP]
AB.....<!-- ItemPage.html -->
<html>
... snip ...
</html>
.AB....
---
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: REQUEST URI =/servlet/Main/ItemPage
... snip ...
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: contextPath=/servlet
... snip ...
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: method=GET
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: parameter=item_id=38244
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: pathInfo=/ItemPage
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: protocol=HTTP/1.1
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: queryString=item_id=38244
... snip ...
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverName=loris.website.com
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverPort=80
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: servletPath=/Main
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: isSecure=false
Jun 19, 2007 3:24:33 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:24:38 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:24:38 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: authType=null
... snip ...
Jun 19, 2007 3:24:38 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: status=200
Jun 19, 2007 3:24:38 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ===============================================================
-----
version 1.2.21-1, rewritten request:
T 127.0.0.1:46581 -> 127.0.0.1:8009 [AP]
.4.F....HTTP/1.1.../servlet/Main/ItemPage...10.0.0.18.....loris.website.com..P.......loris.website.com....eMozilla/5.0
(X11; U; Linux i686; en-US; rv:1.8.0.11) Gecko/20070324
(Debian-1.8.0.11-4)
Epiphany/2.14....ctext/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5.....gzip,deflate.....ISO-8859-1,utf-8;q=0.7,*;q=0.7..
Keep-Alive...300....
keep-alive.....JSESSIONID=958FA4582A9B2D4770614436CA528B20;
browser=H9FRGJ7YM5; cookiesEnabled=true;
loyaltyDiscount=a3c3ede6-7a4b-4bef-8d7f-80242e348273;
browser=YQB8JUJCQ8.....0....item_id=38244..
T 127.0.0.1:8009 -> 127.0.0.1:46581 [AP]
AB.n.....OK....
Set-Cookie..9tuylu=show; Expires=Thu, 01-Jan-1970 00:00:10 GMT;
Path=/...Content-Type...text/html.
T 127.0.0.1:8009 -> 127.0.0.1:46581 [AP]
AB.....<!-- ItemPage.html -->
<html>
... snip ...
</html>
.
T 127.0.0.1:8009 -> 127.0.0.1:46581 [AP]
AB....
---
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: REQUEST URI =/servlet/Main/ItemPage
... snip ...
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: contextPath=/servlet
... snip ...
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: method=GET
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: parameter=item_id=38244
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: pathInfo=/ItemPage
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: protocol=HTTP/1.1
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: queryString=item_id=38244
... snip ...
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverName=loris.website.com
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverPort=80
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: servletPath=/Main
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: isSecure=false
Jun 19, 2007 3:24:45 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:24:46 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:24:46 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: authType=null
... snip ...
Jun 19, 2007 3:24:46 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: status=200
Jun 19, 2007 3:24:46 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ===============================================================
-----
version 1.23-2, full request:
T 127.0.0.1:49847 -> 127.0.0.1:8009 [AP]
.4.F....HTTP/1.1.../servlet/Main/ItemPage...10.0.0.18.....loris.website.com..P.......loris.website.com....eMozilla/5.0
(X11; U; Linux i686; en-US; rv:1.8.0.11) Gecko/20070324
(Debian-1.8.0.11-4)
Epiphany/2.14....ctext/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5.....gzip,deflate.....ISO-8859-1,utf-8;q=0.7,*;q=0.7..
Keep-Alive...300....
keep-alive.....JSESSIONID=958FA4582A9B2D4770614436CA528B20;
browser=H9FRGJ7YM5; cookiesEnabled=true;
loyaltyDiscount=a3c3ede6-7a4b-4bef-8d7f-80242e348273;
browser=YQB8JUJCQ8.....0....item_id=38244..
T 127.0.0.1:8009 -> 127.0.0.1:49847 [AP]
AB.n.....OK....
Set-Cookie..9tuylu=show; Expires=Thu, 01-Jan-1970 00:00:10 GMT;
Path=/...Content-Type...text/html.
T 127.0.0.1:8009 -> 127.0.0.1:49847 [AP]
AB.....<!-- ItemPage.html -->
<html>
... snip ...
</html>
.
---
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: REQUEST URI =/servlet/Main/ItemPage
... snip ...
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: contextPath=/servlet
... snip ...
INFO: method=GET
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: parameter=item_id=38244
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: pathInfo=/ItemPage
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: protocol=HTTP/1.1
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: queryString=item_id=38244
... snip ...
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverName=loris.website.com
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverPort=80
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: servletPath=/Main
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: isSecure=false
Jun 19, 2007 3:29:31 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:29:32 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:29:32 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: authType=null
... snip ...
Jun 19, 2007 3:29:32 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: status=200
Jun 19, 2007 3:29:32 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ===============================================================
-----
version 1.2.23-2, rewritten request:
T 127.0.0.1:49847 -> 127.0.0.1:8009 [AP]
.4.?....HTTP/1.1.../item/38244.html...10.0.0.18.....loris.website.com..P.......loris.website.com....eMozilla/5.0
(X11; U; Linux i686; en-US; rv:1.8.0.11) Gecko/20070324
(Debian-1.8.0.11-4)
Epiphany/2.14....ctext/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5.....gzip,deflate.....ISO-8859-1,utf-8;q=0.7,*;q=0.7..
Keep-Alive...300....
keep-alive.....JSESSIONID=958FA4582A9B2D4770614436CA528B20;
browser=H9FRGJ7YM5; cookiesEnabled=true;
loyaltyDiscount=a3c3ede6-7a4b-4bef-8d7f-80242e348273;
browser=YQB8JUJCQ8.....0....item_id=38244..
T 127.0.0.1:8009 -> 127.0.0.1:49847 [AP]
AB.3....+No Host matches server name loris.website.com...
T 127.0.0.1:8009 -> 127.0.0.1:49847 [AP]
AB....
---
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: REQUEST URI =/item/38244.html
... snip ...
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: contextPath=null
... snip ...
INFO: method=GET
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: parameter=item_id=38244
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: pathInfo=null
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: protocol=HTTP/1.1
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: queryString=item_id=38244
... snip ...
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverName=loris.website.com
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: serverPort=80
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: servletPath=null
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: isSecure=false
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ---------------------------------------------------------------
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: authType=null
... snip ...
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: status=400
Jun 19, 2007 3:29:37 PM org.apache.catalina.valves.RequestDumperValve
invoke
INFO: ===============================================================
-----
Here are the mount points defined in /etc/apache2/conf.d/mod_jk.conf:
JkMount /*.jsp ajp13_worker
JkMount /servlet/* ajp13_worker
JkMount /manager* ajp13_worker
JkMount /admin* ajp13_worker
As you can see, in version 1.2.23-2, the rewritten request appears to be
comming in as /item/38244.html, even though the rewrite logs imply the
rewrite to /servlet/Main/ItemPage?item_id=38244 is happening. Since
there's nothing in the mod_jk.conf to match /item urls, mod_jk
wouldn't be sending the request on to tomcat if it really thought it was
an /item url. But somehow the /item/38244.html is actually
getting through to tomcat, which has nothing defined for that context
path, so tomcat is erroring out with the 400 status code.
I'd be happy to provide any more information that might be helpful.
Thanks for your hard work, and thanks for helping me out.
-- System Information:
Debian Release: lenny/sid
APT prefers unstable
APT policy: (500, 'unstable')
Architecture: i386 (i686)
Kernel: Linux 2.6.18-4-686 (SMP w/2 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/bash
Versions of packages libapache2-mod-jk depends on:
ii apache2 2.2.3-4 Next generation, scalable, extenda
ii apache2-mpm-worker [apache2] 2.2.3-4 High speed threaded model for Apac
ii apache2.2-common 2.2.3-4 Next generation, scalable, extenda
ii libc6 2.5-9+b1 GNU C Library: Shared libraries
libapache2-mod-jk recommends no packages.
-- no debconf information
--- End Message ---
