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 _______________________________________________ jboss-user mailing list [email protected] https://lists.jboss.org/mailman/listinfo/jboss-user
