[jboss-user] [JBoss Web Services Users] - Handlers number depends on number of concurrent threads

sergey.olifirenko do-not-reply at jboss.com
Fri Nov 20 05:16:51 EST 2009 

Hello, I've found possible bug related to WS Handlers creation during concurrent WS access.

Problem is in number of created Handlers for WS and as result their execution order. Their number differs in two cases

1) Single thread calls WS. Then 20 threads concurrently call the same WS. (example below shows 3 created Handlers with order C-B-A-WS-A-B-C )
2) 20 threads call WS concurrently. (example below shows creation 20*3 = 60 handlers, with invalid execution order f.e. C-B-A-B-A-C-...-A-A-WS-A-C-B-A-B-A-C-...-A-A)

As I understand WS Handlers initilization isn't synchronized.
Is it known issue? 

Example:

There is following handler chain:

<handler-chains xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://java.sun.com/xml/ns/javaee javaee_web_services_1_2.xsd">
  <handler-chain>
    
      <handler-class>com.softcomputer.softlab.lab.service.HandlerA</handler-class>
    
    
      <handler-class>com.softcomputer.softlab.lab.service.HandlerB</handler-class>
    
    
      <handler-class>com.softcomputer.softlab.lab.service.HandlerC</handler-class>
    
  </handler-chain>
</handler-chains>

Service:

@WebService(name = "TimeService")
@SOAPBinding(parameterStyle = SOAPBinding.ParameterStyle.BARE)
@Stateless
@HandlerChain(file = "META-INF/custom_handlers.xml")
public class TimeService implements ITimeService
{
   @WebMethod
   public long getServerTime(Void dummy)
   {
      try {
      Thread.sleep(200);
      }
      catch (Exception e) { throw new IllegalStateException(e); }
      return System.currentTimeMillis();
   }
}

Handlers are following:

public class HandlerA implements SOAPHandler
{
   public HandlerA()
   {
      logMsg(this, "Constructor");
   }
   public void close(MessageContext arg0)
   {
      shortLog(this.getClass(), "close");
   }
   public Set getHeaders()
   {
      shortLog(this.getClass(), "get Headers");
      return null;
   }
   public boolean handleFault(SOAPMessageContext arg0)
   {
      fullHandlerLog(this.getClass(), "handleFault", arg0);
      return true;
   }
   public boolean handleMessage(SOAPMessageContext arg0)
   {
      fullHandlerLog(this.getClass(), "handle Message ", arg0);
      return true;
   }
}

public class HandlerB implements SOAPHandler
{
   public HandlerB()
   {
      logMsg(this, "Constructor");
   }
   public void close(MessageContext arg0)
   {
      shortLog(this.getClass(), "close");
   }
   public Set getHeaders()
   {
      shortLog(this.getClass(), "get Headers");
      return null;
   }
   public boolean handleFault(SOAPMessageContext arg0)
   {
      fullHandlerLog(this.getClass(), "handleFault", arg0);
      return true;
   }
   public boolean handleMessage(SOAPMessageContext arg0)
   {
      fullHandlerLog(this.getClass(), "handle Message ", arg0);
      return true;
   }
}

C is the same like  A and B.


Part of 1st case Log:

2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA Constructor
2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA get Headers
2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB Constructor
2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB get Headers
2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC Constructor
2009-11-20 11:28:28,882 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC get Headers
2009-11-20 11:30:30,035 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC handle Message  opName_:urn:getServerTime; way_: IN; user_:scc; ts_:1258709429988
2009-11-20 11:30:30,035 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB handle Message  opName_:urn:getServerTime; way_: IN; user_:scc; ts_:1258709430035
2009-11-20 11:30:30,035 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA handle Message  opName_:urn:getServerTime; way_: IN; user_:scc; ts_:1258709430035
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709430722
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709430722
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709430722
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA close
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB close
2009-11-20 11:30:30,722 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC close
2009-11-20 11:33:01,687 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf3; ts_:1258709581687
2009-11-20 11:33:01,687 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB handle Message  opName_:getServerTime; way_: IN; user_:prf3; ts_:1258709581687
2009-11-20 11:33:01,687 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA handle Message  opName_:getServerTime; way_: IN; user_:prf3; ts_:1258709581687
2009-11-20 11:33:01,718 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf2; ts_:1258709581718
2009-11-20 11:33:01,718 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerB handle Message  opName_:getServerTime; way_: IN; user_:prf2; ts_:1258709581718
2009-11-20 11:33:01,718 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerA handle Message  opName_:getServerTime; way_: IN; user_:prf2; ts_:1258709581718
...
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581922
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581922
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581922
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA close
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerB close
2009-11-20 11:33:01,922 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerC close
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerA handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581937
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerB handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581937
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerC handle Message  opName_:ns1:getServerTimeResponse; way_: OUT; user_:FROM_LAB; ts_:1258709581937
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerA close
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerB close
2009-11-20 11:33:01,937 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerC close


Part of 2nd case Log(execution order detailed for thread 10):

2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-9] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-7] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-4] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-6] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-13] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-14] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-16] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-8] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-20] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-3] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-11] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-15] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-12] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-19] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-5] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-1] HandlerA Constructor
2009-11-20 11:43:44,499 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerA get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerA get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerB Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerB get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerC Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-18] HandlerC get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerB Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerB get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerC Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerC get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerA get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerB Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerB get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerC Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-2] HandlerC get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-16] HandlerA get Headers
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-16] HandlerB Constructor
2009-11-20 11:43:44,515 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-16] HandlerB get Headers
...
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-14] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf4; ts_:125871022454...6
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-7] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf2; ts_:1258710224546
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224546
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-17] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf19; ts_:1258710224546
...
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerB handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224608
...
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerA handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224608
...
2009-11-20 11:43:44,608 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:12587102246080
...
2009-11-20 11:43:44,624 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerB handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224624
...
2009-11-20 11:43:44,624 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerA handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224624
...
2009-11-20 11:43:44,624 DEBUG [com.softcomputer.softlab.lab.service.WebServiceExecutionTimeLogger|http-0.0.0.0-8080-10] HandlerC handle Message  opName_:getServerTime; way_: IN; user_:prf18; ts_:1258710224624

etc. thread 10 calls all 60 handlers randomly.






View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4266712#4266712

Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4266712

More information about the jboss-user mailing list