Apparent race condition in Cactus?

Mon, 21 Oct 2002 11:49:12 -0700

I'm using Cactus and I'm running into a strange problem. About half the time, my tests fail, and it appears to be caused by GET_RESULT being invoked before the results are saved to the context.

From the server log:

...
02:39:27,096 [HttpProcessor[8080][3]] DEBUG
ache.cactus.ServiceEnumeration - <equals([GET_RESULTS])
02:39:27,096 [HttpProcessor[8080][3]] DEBUG
ache.cactus.ServiceEnumeration - >equals = [true]02:39:27,096
[HttpProcessor[8080][3]] DEBUG s.server.AbstractWebTestCaller -
Test Result = [null]
02:39:27,130 [HttpProcessor[8080][4]] DEBUG
s.server.AbstractWebTestCaller - Test result : [Test ok]
02:39:27,131 [HttpProcessor[8080][4]] DEBUG
s.server.AbstractWebTestCaller - Result saved in context scope
...


From the client log:

...
02:39:27,091 [main] DEBUG httpclient.HttpConnection -
HttpConnection.write(byte[])
02:39:27,091 [main] INFO httpclient.wire - >> "GET
/test/ServletRedirector?Cactus_Service=GET_RESULTS HTTP/1.1
"
02:39:27,091 [main] DEBUG httpclient.HttpMethod -
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
02:39:27,091 [main] DEBUG httpclient.HttpConnection -
HttpConnection.write(byte[])
02:39:27,091 [main] INFO httpclient.wire - >>
"Host: localhost
"
02:39:27,092 [main] DEBUG httpclient.HttpConnection -
HttpConnection.write(byte[])
02:39:27,092 [main] INFO httpclient.wire - >>
"User-Agent: Jakarta HTTP Client/2.0.0a1
"
02:39:27,092 [main] DEBUG httpclient.HttpConnection -
HttpConnection.write(byte[])
02:39:27,092 [main] INFO httpclient.wire - >>
"Content-type: application/x-www-form-urlencoded
"
02:39:27,092 [main] DEBUG httpclient.HttpConnection -
HttpConnection.writeLine()
02:39:27,092 [main] INFO httpclient.wire - >> \r\n
02:39:27,108 [main] DEBUG httpclient.HttpMethod -
HttpMethodBase.readResponse(HttpState,HttpConnection)
02:39:27,108 [main] DEBUG httpclient.HttpMethod -
HttpMethodBase.readStatusLine(HttpState,HttpConnection)
02:39:27,108 [main] DEBUG httpclient.HttpConnection -
HttpConnection.readLine()
02:39:27,109 [main] INFO httpclient.wire - <<
"HTTP/1.1 500 Internal Server Error" [\r\n]

...

02:39:27,115 [main] INFO httpclient.wire - <<
"<html><head><title>Apache Tomcat/4.1.12 - Error
report</title><STYLE><!--H1{font-family :
sans-serif,Arial,Tahoma;color : white;background-color : #0086b2;}
H3{font-family : sans-serif,Arial,Tahoma;color :
white;background-color : #0086b2;} BODY{font-family :
sans-serif,Arial,Tahoma;color : black;background-color : white;}
B{color : white;background-color : #0086b2;} HR{color : #0086b2;}
--></STYLE> </head><body><h1>HTTP Status 500 - Internal Server
Error</h1><HR size="1" noshade><p><b>type</b> Exception
report</p><p><b>message</b> <u>Internal Server
Error</u></p><p><b>description</b> <u>The server encountered an
internal error (Internal Server Error) that prevented it from
fulfilling this request.</u></p><p><b>exception</b>
<pre>java.lang.NullPointerException
at
org.apache.cactus.server.AbstractWebTestCaller.doGetResults(AbstractWebTestCaller.java:196)
at
org.apache.cactus.server.AbstractWebTestController.dispatch87_handleRequest(AbstractWebTestController.java;org/apache/cactus/util/log/LogAspect.aj(1k):131)

...

It appears that one server thread is trying to get the results (thread 3) before the other (thread 4) has posted them. The times that the tests work, I notice from the logs that the client sent the GET_RESULTS request a few ms after the results were already posted:

From the server.log:

03:08:13,388 [HttpProcessor[8080][4]] DEBUG
s.server.AbstractWebTestCaller - Test result : [Test ok]
03:08:13,388 [HttpProcessor[8080][4]] DEBUG
s.server.AbstractWebTestCaller - Result saved in context scope

From the client.log:

03:08:13,424 [main] INFO httpclient.wire - >> "GET
/test/ServletRedirector?Cactus_Service=GET_RESULTS HTTP/1.1
"
03:08:13,425 [main] DEBUG httpclient.HttpMethod -
HttpMethodBase.writeRequestHeaders


I'm not doing anything too different than the examples. The only real difference is that my Servlet inherits from a class in the Barracuda framework, so I pass the request/response into a different method:

public void testDailySchedule()
{
try
{
OCSGateway servlet = new OCSGateway();

servlet.init(config);
servlet.handleDefault(request, response);

theLog.debug("CHECKING SESSION!!!!");
assertNotNull(session);
theLog.debug("Mode: " + session.getAttribute(OCS.MODE));
theLog.debug("Date: " + session.getAttribute(OCS.DATE));
theLog.debug("Schd: " + session.getAttribute(OCS.SCHEDULE));

theLog.debug("DONE WITH TEST!!!!");
}
catch (Exception e)
{
theLog.error("Unable to complete request:", e);
fail(e.getMessage());
}
}

I also tried "servlet.service(request, response)", but the results were the same.

BTW, when I turn on full debug, it works more often. It took a looping script 49 tries to finally get it to fail so I could include the full debug at the top of the message.

I'm running the tests from Ant using Tomcat 4.1.12 with Cactus 1.3-1.4.1. Any ideas would be greatly appreciated!

Thank you,

Frank

Reply via email to