DO NOT REPLY [Bug 9334] New: - Intermittent parsing error in Ajp13Request

[bu...@apache.org]

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG 
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://nagoya.apache.org/bugzilla/show_bug.cgi?id=9334>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND 
INSERTED IN THE BUG DATABASE.

http://nagoya.apache.org/bugzilla/show_bug.cgi?id=9334

Intermittent parsing error in Ajp13Request

           Summary: Intermittent parsing error in Ajp13Request
           Product: Tomcat 4
           Version: 4.0.3 Final
          Platform: PC
        OS/Version: Linux
            Status: NEW
          Severity: Normal
          Priority: Other
         Component: Connector:JK/AJP (deprecated)
        AssignedTo: tomcat-dev@jakarta.apache.org
        ReportedBy: lars@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. 

Yours faithfully,

Lars

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