jakarta-cactus-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Frank Baxter <fr...@baxres.org>
Subject Apparent race condition in Cactus?
Date Mon, 21 Oct 2002 19:16:03 GMT
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


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message