Handlers number depends on number of concurrent threads
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.