Intermittent bug in Tomcat 4.0.3

[Lars George <la...@worldlingo.com>]

Hi,

We use Tomcat 4.0.3, with Apache 1.3.24 and mod_jk, all in a loadbalanced
setup. We experience an intermittent bug in Tomcat that I fixed by changing
the server code. I would like to describe the problem in the following by
hoping someone can tell me what this is about.

The problem is in the Ajp13Processor class. Once a processor is taken from
the pool the AJP details are read with 

                status = ajp13.receiveNextRequest(ajpRequest);

Then later it is assigned to the supposedly recycled Ajp13Request from the
previous use

                // set up request
                request.setAjpRequest(ajpRequest);

So far so good. What happens for us is that at least 5 times every minute
(up to 20-30 times) the flag "parsed" in Ajp13Request (the "request"
instance variable of the Ajp13Processor class) is suddenly set to "true"!

This causes the following problem. The incoming query string is not parsed
anymore because the request thinks it had done this already. Therefore in
our code when we use getParamXXXX() methods they all return "null" or an
empty map. This of course means ours servlets assume that no parameters have
been provided and they do whatever they should do in this case - which of
course fails what the customer expects.

What I did to quickly fix this problem is to add the following lines into
Ajp13Request.java

    void setAjpRequest(BaseRequest ajp) throws UnsupportedEncodingException
{
        // XXX make this guy wrap AjpRequest so
        // we're more efficient (that's the whole point of
        // all of the MessageBytes in AjpRequest)

        /** @todo DEBUG */
        if (parsed == true) {
          parsed = false;
          System.err.println("!!! parsed was true in recycled request !!!");
        }
        /** @todo DEBUG */

        setMethod(ajp.method().toString());
        setProtocol(ajp.protocol().toString());
        ....

Note the DEBUG lines above, when I detect that, although the request should
have been recycled, that the "parsed" flag is already set before even
anything is assigned to it I reset the flag to "false" and everything is
working fine. The error message I print out above is the one that shows up
in our catalina.out the specified number of times (see above).

I then went on and added this to the HttpRequestBase.java

    public void setQueryString(String query) {

        /** @todo DEBUG */
        if (parsed) {
          System.err.println("### reassigned query string ###\nqueryString:
" +
          queryString + "\nnew value: " + query);
        }
        /** @todo DEBUG */

        this.queryString = query;

    }

Although this should never happen - or am I wrong here - this is what I see
in the catalina.out

### reassigned query string ###
queryString: null
new value:
wl_srclang=ES&wl_trglang=FR&wl_gloss=7&wl_text=Provinc%EDa+de+la+direcci%F3n
+destino+de+la+mercanc%EDa
!!! parsed was true in recycled request !!!


Clearly, the request gets some values assigned twice somehow. But what
puzzles me is that "parsed" is only set to "true" when someone calls any of
the getParameterXXXX() methods. But because userland code hasn't been
executed so far this is impossible. This all happens within a single thread
and within two classes of Tomcat source code. What is going on?

I also had some debug code in the "recycle" method to check - assuming that
recycle is called fine - if everything gets cleared, including the "parsed"
flag. This shows the correct behaviour during all my testing, ie. everything
is cleared fine. Also I wrapped the call to "recycle" in Ajp13Request with a
try/catch to see if maybe an error is thrown that would prevent a "recycle"
being called - again, I never had any errors showing up at this point. Also
when dumping the values from the request instance it looks like it is always
cleared correctly; I have never seen some sort of "left overs" from a
previous request, so recycling the request does not seem to be the issue.

The only explanation I have so far is that somehow
HttpRequestBase.parseParameters is called before the BaseRequest values
(from the Ajp13 connection) are assigned to it. But having one single thread
running through the Ajp13Processor and no trace of someone calling
getParamXXXX(), how whould that happen?

Just to explain, we use three servers that all show the same problem. Two
are running Sun JDK 1.3.0_02 and one the newest Sun JDK 1.3.1_03, again to
note, all show this behaviour. Tomcat was built with the Sun JDK 1.3.1_03
version for all of them.

I recompiled Tomcat heaps of times with different debug output to find the
problem and this has not changed anything, so it does not look like the
infamous Heisenberg uncertainty, ie. recompiling or monitoring the code does
not make the problem go away. Always the same problem, same spot. 

It does not seem to be load related as the number of errors just increases
proportionally with the load; and even minor load causes the problem to show
up.

I am at the end of my wisdom here as to what this is related to or caused
by. I appreciate any comments, ideas, suggestions etc. to clarify this
issue. 

Kind regards,

Lars

--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>