0 Replies Latest reply on Nov 20, 2009 5:16 AM by Sergey Olifirenko

    Handlers number depends on number of concurrent threads

    Sergey Olifirenko Newbie

      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.