Hi

I am getting the following error when trying to retrieve CTI info from the AES from a DD developed application:

04/08/2008 08:23:06 DEBUG - DAAD738FFEE5B2301D1E74B522FB95DA:/Module1Test : CTICommand.execute: encrypted value is PfdYRShyADCHj1jmBDSx4gxNmlNRpbv6d5wmsPwB0Qk=
04/08/2008 08:23:06 DEBUG - DAAD738FFEE5B2301D1E74B522FB95DA:/Module1Test : CTICommand.execute: request to manager is http://172.16.25.24:8080/cticonnector/CallInfoInitialCall?extension%3D3302&k=PfdYRShyADCHj1jmBDSx4gxNmlNRpbv6d5wmsPwB0Qk%3D
04/08/2008 08:23:10 DEBUG - DAAD738FFEE5B2301D1E74B522FB95DA:/Module1Test : CTICommand.execute: callinfo from Manager is error:CallInfo.doGetCallInfoInitialCall: call on extension:3302 was never established
04/08/2008 08:23:11 ERROR - DAAD738FFEE5B2301D1E74B522FB95DA:/Module1Test : session id:DDLABAVP-2008217061136-14 | CallInfo.doGetCallInfoInitialCall: call on extension:3302 was never established

04/08/2008 08:23:11 ERROR - DAAD738FFEE5B2301D1E74B522FB95DA:/Module1Test : session id:DDLABAVP-2008217061136-14 |
EXCEPTION>
com.avaya.sce.runtimecommon.SCERuntimeException: CallInfo.doGetCallInfoInitialCall: call on extension:3302 was never established
   at com.avaya.sce.runtimecommon.SCESession.throwRTException(SCESession.java:1532)
   at com.avaya.sce.runtime.connectivity.cti.ir.CTICommand.execute(CTICommand.java:106)
   at com.avaya.sce.runtime.SCEServlet.ProcessCTIGetCallInfo(SCEServlet.java:469)
   at com.avaya.sce.runtime.SCEServlet.processRequest(SCEServlet.java:292)
   at com.avaya.sce.runtime.AppDocument.processRequest(AppDocument.java:136)
   at com.avaya.sce.runtime.SCEServlet.requestHandler(SCEServlet.java:197)
   at com.avaya.sce.runtime.SCEServlet.doPost(SCEServlet.java:163)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
   at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
   at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
   at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
   at java.lang.Thread.run(Thread.java:619)

Can you tell me why we are getting this error?

Kind Regards
Manie

Looks like the call is not able to get the CTI CallInfo and hence not able to process the call any further. Have you checked if the AES was up when the issue occured. If this issue is happening frequently, please collect the detailed logs/traces.

What version of DD are you using?

Share the detailed TSAPI traces. If you have not cptured them , then here are the steps that you will need to follow to collect detailed logs:

Increase the log level for CTI Connector to Highest (verbosity level 3)
Navigate to "<Tomcat>\webapps\cticonnector\WEB-INF" and edit the web.xml. Look for:

<param-name>trace.verbosity</param-name>
<param-value>3</param-value>



Set this value to 3 and Restart Tomcat.

After restarting Tomcat the CTI connector logs will be written in file - "<Tomcat>\webapps\cticonnector\data\log\trace.log"

You also need to set debuglevel = 7 in <Tomcat>\common\classes\tsapi.pro for capturing the tsapi logs. Note that this log file grows very rapidly so reset to original debug level once the logs are captured.
Restart tomcat, make a call for the failure. When you start seeing the problem wait for couple minutes and
then share the logs snippets of the following files for the failed call -
a) *tsapi_trace.txt* file from the Tomcat home directory

b) *trace.log* file from the *cticonnector/data/log* directory

c) Tomcat logs

Hi, Sorry for taking so long, but I had to make sure I have all the data... Here is the Callflow Log

15/09/2008 11:51:07 DEBUG - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : CTICommand.execute: encrypted value is NDkCuvfvcqcO2+twfHphKIJFxV72i9w1nGLKIPsZWqU=
15/09/2008 11:51:07 DEBUG - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : CTICommand.execute: request to manager is http://10.14.177.30:8080/cticonnector/CallInfoInitialCall?extension%3D2000&k=NDkCuvfvcqcO2%2BtwfHphKIJFxV72i9w1nGLKIPsZWqU%3D
15/09/2008 11:51:11 DEBUG - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : CTICommand.execute: callinfo from Manager is error:CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established
15/09/2008 11:51:11 ERROR - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : session id:ABSADEVMPP1-2008259094844-1 | CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established

15/09/2008 11:51:11 ERROR - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : session id:ABSADEVMPP1-2008259094844-1 |
EXCEPTION>
com.avaya.sce.runtimecommon.SCERuntimeException: CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established
   at com.avaya.sce.runtimecommon.SCESession.throwRTException(SCESession.java:1532)
   at com.avaya.sce.runtime.connectivity.cti.ir.CTICommand.execute(CTICommand.java:106)
   at com.avaya.sce.runtime.Data.evaluateActions(Data.java:104)
   at flow.TraceSessionData.executeDataActions(TraceSessionData.java:89)
   at com.avaya.sce.runtime.Data.handleRequest(Data.java:73)
   at com.avaya.sce.runtime.AppServlet.processRequest(AppServlet.java:63)
   at com.avaya.sce.runtime.SCEServlet.requestHandler(SCEServlet.java:197)
   at com.avaya.sce.runtime.SCEServlet.doGet(SCEServlet.java:156)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
   at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
   at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
   at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
   at java.lang.Thread.run(Thread.java:619)

15/09/2008 11:51:11 ERROR - 2871A950ABA9AFB8E79CA0EBAFA9AB26:/Module1Test : session id:ABSADEVMPP1-2008259094844-1 | Error processing request
EXCEPTION>
java.lang.Exception: javax.servlet.ServletException: CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established
   at com.avaya.sce.runtime.AppServlet.processRequest(AppServlet.java:69)
   at com.avaya.sce.runtime.SCEServlet.requestHandler(SCEServlet.java:197)
   at com.avaya.sce.runtime.SCEServlet.doGet(SCEServlet.java:156)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
   at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
   at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
   at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
   at java.lang.Thread.run(Thread.java:619)
Caused by: javax.servlet.ServletException: CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established
   at com.avaya.sce.runtime.Data.handleRequest(Data.java:81)
   at com.avaya.sce.runtime.AppServlet.processRequest(AppServlet.java:63)
   ... 18 more


This is the CTIConnector Log for this period:

15/09/2008 11:50:56 DEBUG - ProviderMonitor: Checking:ABSACTILink for availability
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2000 is 13
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 0 is 101 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Active Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 1 is 106 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Created Event for id:40
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: call id is 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: ucid is 00001000401221471199
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: setting 40 to state: initiated
15/09/2008 11:51:03 DEBUG - CallInfoData.CallInfoData:2000: callid 40
15/09/2008 11:51:03 DEBUG - CallInfoData.CallInfoData:2000: ani 2020
15/09/2008 11:51:03 DEBUG - CallInfoData.CallInfoData:2000: dnis 95078
15/09/2008 11:51:03 DEBUG - CallInfoData.CallInfoData:2000: ucid 00001000401221471199
15/09/2008 11:51:03 DEBUG - CallInfoData.CallInfoData:2000: uui
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: added call to list
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000:cache is:false
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 2 is 105 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Connected Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 3 is 206 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: got Call Control Connection Established Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: found 2 connections
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 0 is 51
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 1 is 50
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: Call is not fully established
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 4 is 116 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Created Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 5 is 115 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Active Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 6 is 219 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: got Terminal Connection Talking Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: found 2 connections
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 0 is 51
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 1 is 50
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: Call is not fully established
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 7 is 106 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Created Event for id:40
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: call id is 40 is already added, returning call data
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 8 is 104 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Alerting Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 9 is 203 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: got Call Control alerting Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.updateCallState 2000: setting call:40 to state:ringing
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 10 is 116 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Created Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 11 is 119 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Ringing Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 12 is 218 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Call Control Terminal Ringing Event
15/09/2008 11:51:04 DEBUG - ProviderMonitor: Checking:ABSACTILink for availability
15/09/2008 11:51:07 DEBUG - CTICallObserver.addCallToCache:caching call:40
15/09/2008 11:51:07 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:07 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:07 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:07 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:08 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:08 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:08 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:08 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:09 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:09 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:09 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:09 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:10 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:10 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:10 DEBUG - CTICallObserver.getCallInfo: turning on cache
15/09/2008 11:51:10 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
15/09/2008 11:51:11 ERROR - CallInfo.doGetCallInfoInitialCall: call on extension:2000 was never established
15/09/2008 11:51:11 DEBUG - Ending call on extension 2000
15/09/2008 11:51:11 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2000 from all calls if necessary.
15/09/2008 11:51:11 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension from call:40
15/09/2008 11:51:11 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2000
15/09/2008 11:51:11 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2000
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2000 is 4
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 0 is 117 for call 40
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got an unknown event 117
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 1 is 215 for call 40
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got an unknown event 215
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 2 is 107 for call 40
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got Connection Disconnected Event 107
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got disconnect, but no cticall found.
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 3 is 205 for call 40
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got Connection Disconnected Event 205
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got disconnect, but no cticall found.
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2000 is 1
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 0 is 103 for call 40
15/09/2008 11:51:11 DEBUG - CTICallObserver.callChangedEvent:2000: got Call Observation Ended Event
15/09/2008 11:51:12 DEBUG - ProviderMonitor: Checking:ABSACTILink for availability
15/09/2008 11:51:20 DEBUG - ProviderMonitor: Checking:ABSACTILink for availability
15/09/2008 11:51:24 DEBUG - CTIConnectorManager.ProviderMonitor: Exiting
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2000 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2000
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2000 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2000: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2000
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2001 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2001
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2001 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2001
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2001: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2001: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2002 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2002
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2002 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2002
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2002: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2002: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2004 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2004
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2004 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2004
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2004: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2004: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2003 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2003
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2003 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2003: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2003: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2003
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2005 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2005
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2005 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2005
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2005: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2005: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - CTICallObserver.disconnectFromCalls:disconnect extension:2006 from all calls if necessary.
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from extension:2006
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 2006 is 1
15/09/2008 11:51:24 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:2006
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent 2006: Event: 0 is 103 for call
15/09/2008 11:51:24 DEBUG - CTICallObserver.callChangedEvent:2006: got Call Observation Ended Event
15/09/2008 11:51:24 DEBUG - shutting down CTI-JTAPI Providers
15/09/2008 11:51:24 DEBUG - ProviderObserver.providerChangedEvent: got providerobservation event, got provider to shutdown
15/09/2008 11:51:24 DEBUG - CTI-JTAPI Providers are shut down, CTI Connector is terminating
15/09/2008 11:51:24 DEBUG - ProviderObserver.providerChangedEvent:ABSACTILink is added to list of downed providers
15/09/2008 11:51:24 DEBUG - ProviderObserver.providerChangedEvent: JTAPI Provider is down


Ok, and the TSAPI log is big, but I will try to share the snipet here:

09/15/08 11:51:02.928 <DistributeCSTAEvent> CSTA Unsolicited Event: CSTAEvent[CSTADeliveredEvent]@45e228
09/15/08 11:51:02.928 <DistributeCSTAEvent> Free memory: 5391688
09/15/08 11:51:02.928 <DistributeCSTAEvent> Total memory: 15667200
09/15/08 11:51:02.928 <DistributeCSTAEvent> Handling CSTA_DELIVERED for TSProvider@fced4
09/15/08 11:51:02.943 <DistributeCSTAEvent> Constructing call TSCall[40]@78dc4c with ID 40 for TSProvider@fced4
09/15/08 11:51:02.943 <DistributeCSTAEvent> Constructing device TSDevice[95078]@c70b0d with name 95078 for TSProvider@fced4
09/15/08 11:51:02.943 <DistributeCSTAEvent> Sent InvokeID 74 for TSProvider@fced4
09/15/08 11:51:02.943 <DistributeCSTAEvent> CSTAQueryDeviceInfo ::=
09/15/08 11:51:02.943 <DistributeCSTAEvent> {
09/15/08 11:51:02.943 <DistributeCSTAEvent> device "95078"
09/15/08 11:51:02.943 <DistributeCSTAEvent> }
09/15/08 11:51:03.006 <GetEventThread> Received invokeID 74 for TSProvider@fced4
09/15/08 11:51:03.006 <GetEventThread> CSTAQueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.006 <GetEventThread> {
09/15/08 11:51:03.006 <GetEventThread> device "95078"
09/15/08 11:51:03.006 <GetEventThread> deviceType 19 < DT_ACD_GROUP >
09/15/08 11:51:03.006 <GetEventThread> deviceClass 0x80000000 < DC_VOICE >
09/15/08 11:51:03.006 <GetEventThread> }
09/15/08 11:51:03.006 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:03.006 <GetEventThread> {
09/15/08 11:51:03.006 <GetEventThread> vendor "ECS"
09/15/08 11:51:03.006 <GetEventThread> data 2 0 62 0 30 8 a 1 0 a 1 a 16 0
09/15/08 11:51:03.006 <GetEventThread> tsType 38
09/15/08 11:51:03.006 <GetEventThread> }
09/15/08 11:51:03.006 <GetEventThread> Handling INVOKE ID 74 for TSProvider@fced4
09/15/08 11:51:03.006 <GetEventThread> DONE handling INVOKE ID 74 for TSProvider@fced4
09/15/08 11:51:03.006 <DistributeCSTAEvent> LucentV5QueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.006 <DistributeCSTAEvent> {
09/15/08 11:51:03.006 <DistributeCSTAEvent> extensionClass 0 < EC_VDN >
09/15/08 11:51:03.006 <DistributeCSTAEvent> associatedClass 10 < EC_OTHER >
09/15/08 11:51:03.006 <DistributeCSTAEvent> associatedDevice <null>
09/15/08 11:51:03.006 <DistributeCSTAEvent> }
09/15/08 11:51:03.006 <DistributeCSTAEvent> Sent InvokeID 75 for TSProvider@fced4
09/15/08 11:51:03.006 <DistributeCSTAEvent> CSTASnapshotCall ::=
09/15/08 11:51:03.006 <DistributeCSTAEvent> {
09/15/08 11:51:03.006 <DistributeCSTAEvent> snapshotObject
09/15/08 11:51:03.006 <DistributeCSTAEvent> {
09/15/08 11:51:03.006 <DistributeCSTAEvent> callID 40
09/15/08 11:51:03.006 <DistributeCSTAEvent> deviceID "2000"
09/15/08 11:51:03.006 <DistributeCSTAEvent> devIDType 0 < STATIC_ID >
09/15/08 11:51:03.006 <DistributeCSTAEvent> }
09/15/08 11:51:03.006 <DistributeCSTAEvent> }
09/15/08 11:51:03.006 <DistributeCSTAEvent> DONE handling CSTA_DELIVERED for TSProvider@fced4
09/15/08 11:51:03.053 <GetEventThread> Received invokeID 75 for TSProvider@fced4
09/15/08 11:51:03.053 <GetEventThread> CSTASnapshotCallConfEvent ::=
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> snapshotData
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> deviceOnCall
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> deviceID "2020"
09/15/08 11:51:03.053 <GetEventThread> deviceIDType 55 < EXPLICIT_PRIVATE_LOCAL_NUMBER >
09/15/08 11:51:03.053 <GetEventThread> deviceIDStatus 0 < ID_PROVIDED >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> callIdentifier
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> callID 40
09/15/08 11:51:03.053 <GetEventThread> deviceID "2020"
09/15/08 11:51:03.053 <GetEventThread> devIDType 0 < STATIC_ID >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> localConnectionState 3 < CS_CONNECT >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> deviceOnCall
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> deviceID "2000"
09/15/08 11:51:03.053 <GetEventThread> deviceIDType 55 < EXPLICIT_PRIVATE_LOCAL_NUMBER >
09/15/08 11:51:03.053 <GetEventThread> deviceIDStatus 0 < ID_PROVIDED >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> callIdentifier
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> callID 40
09/15/08 11:51:03.053 <GetEventThread> deviceID "2000"
09/15/08 11:51:03.053 <GetEventThread> devIDType 0 < STATIC_ID >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> localConnectionState 2 < CS_ALERTING >
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:03.053 <GetEventThread> {
09/15/08 11:51:03.053 <GetEventThread> vendor "ECS"
09/15/08 11:51:03.053 <GetEventThread> data 2 0 8a 0 30 2 30 0
09/15/08 11:51:03.053 <GetEventThread> tsType 121
09/15/08 11:51:03.053 <GetEventThread> }
09/15/08 11:51:03.053 <GetEventThread> Putting event CSTAEvent[CSTASnapshotCallConfEvent]@1d840cd. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:03.053 <DistributeCSTAEvent> Getting event CSTAEvent[CSTASnapshotCallConfEvent]@1d840cd for TSProvider@fced4
09/15/08 11:51:03.053 <DistributeCSTAEvent> LucentSnapshotCallInfoConfEvent ::=
09/15/08 11:51:03.053 <DistributeCSTAEvent> {
09/15/08 11:51:03.053 <DistributeCSTAEvent> deviceHistory
09/15/08 11:51:03.053 <DistributeCSTAEvent> {
09/15/08 11:51:03.053 <DistributeCSTAEvent> }
09/15/08 11:51:03.053 <DistributeCSTAEvent> }
09/15/08 11:51:03.053 <DistributeCSTAEvent> Handling INVOKE ID 75 for TSProvider@fced4
09/15/08 11:51:03.053 <DistributeCSTAEvent> Constructing device TSDevice[2020]@867fc9 with name 2020 for TSProvider@fced4
09/15/08 11:51:03.053 <DistributeCSTAEvent> Sent InvokeID 76 for TSProvider@fced4
09/15/08 11:51:03.053 <DistributeCSTAEvent> CSTAQueryDeviceInfo ::=
09/15/08 11:51:03.053 <DistributeCSTAEvent> {
09/15/08 11:51:03.053 <DistributeCSTAEvent> device "2020"
09/15/08 11:51:03.053 <DistributeCSTAEvent> }
09/15/08 11:51:03.100 <GetEventThread> Received invokeID 76 for TSProvider@fced4
09/15/08 11:51:03.100 <GetEventThread> CSTAQueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.100 <GetEventThread> {
09/15/08 11:51:03.100 <GetEventThread> device "2020"
09/15/08 11:51:03.100 <GetEventThread> deviceType 0 < DT_STATION >
09/15/08 11:51:03.100 <GetEventThread> deviceClass 0x80000000 < DC_VOICE >
09/15/08 11:51:03.100 <GetEventThread> }
09/15/08 11:51:03.100 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:03.100 <GetEventThread> {
09/15/08 11:51:03.100 <GetEventThread> vendor "ECS"
09/15/08 11:51:03.100 <GetEventThread> data 2 0 62 0 30 8 a 1 6 a 1 a 16 0
09/15/08 11:51:03.100 <GetEventThread> tsType 38
09/15/08 11:51:03.100 <GetEventThread> }
09/15/08 11:51:03.100 <GetEventThread> Handling INVOKE ID 76 for TSProvider@fced4
09/15/08 11:51:03.100 <GetEventThread> DONE handling INVOKE ID 76 for TSProvider@fced4
09/15/08 11:51:03.100 <DistributeCSTAEvent> LucentV5QueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.100 <DistributeCSTAEvent> {
09/15/08 11:51:03.100 <DistributeCSTAEvent> extensionClass 6 < EC_PROPRIETARY >
09/15/08 11:51:03.100 <DistributeCSTAEvent> associatedClass 10 < EC_OTHER >
09/15/08 11:51:03.100 <DistributeCSTAEvent> associatedDevice <null>
09/15/08 11:51:03.100 <DistributeCSTAEvent> }
09/15/08 11:51:03.100 <DistributeCSTAEvent> Constructing Lucent termConn TSConnection[termConn:(40,2020)]@c3e82b for TSProvider@fced4
09/15/08 11:51:03.100 <DistributeCSTAEvent> Constructing Lucent conn TSConnection[conn:(-,2020)]@2d7440 for TSProvider@fced4
09/15/08 11:51:03.100 <DistributeCSTAEvent> Constructing Lucent termConn TSConnection[termConn:(40,2000)]@2b349d for TSProvider@fced4
09/15/08 11:51:03.100 <DistributeCSTAEvent> Constructing Lucent conn TSConnection[conn:(-,2000)]@8b567c for TSProvider@fced4
09/15/08 11:51:03.115 <DistributeCSTAEvent> Constructing device TSDevice[99049]@ea5461 with name 99049 for TSProvider@fced4
09/15/08 11:51:03.115 <DistributeCSTAEvent> Sent InvokeID 77 for TSProvider@fced4
09/15/08 11:51:03.115 <DistributeCSTAEvent> CSTAQueryDeviceInfo ::=
09/15/08 11:51:03.115 <DistributeCSTAEvent> {
09/15/08 11:51:03.115 <DistributeCSTAEvent> device "99049"
09/15/08 11:51:03.115 <DistributeCSTAEvent> }
09/15/08 11:51:03.147 <GetEventThread> Received invokeID 77 for TSProvider@fced4
09/15/08 11:51:03.147 <GetEventThread> CSTAQueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.147 <GetEventThread> {
09/15/08 11:51:03.147 <GetEventThread> device "99049"
09/15/08 11:51:03.147 <GetEventThread> deviceType 19 < DT_ACD_GROUP >
09/15/08 11:51:03.147 <GetEventThread> deviceClass 0x80000000 < DC_VOICE >
09/15/08 11:51:03.147 <GetEventThread> }
09/15/08 11:51:03.147 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:03.147 <GetEventThread> {
09/15/08 11:51:03.147 <GetEventThread> vendor "ECS"
09/15/08 11:51:03.147 <GetEventThread> data 2 0 62 0 30 8 a 1 1 a 1 a 16 0
09/15/08 11:51:03.147 <GetEventThread> tsType 38
09/15/08 11:51:03.147 <GetEventThread> }
09/15/08 11:51:03.147 <GetEventThread> Handling INVOKE ID 77 for TSProvider@fced4
09/15/08 11:51:03.147 <GetEventThread> DONE handling INVOKE ID 77 for TSProvider@fced4
09/15/08 11:51:03.147 <DistributeCSTAEvent> LucentV5QueryDeviceInfoConfEvent ::=
09/15/08 11:51:03.147 <DistributeCSTAEvent> {
09/15/08 11:51:03.147 <DistributeCSTAEvent> extensionClass 1 < EC_ACD_SPLIT >
09/15/08 11:51:03.147 <DistributeCSTAEvent> associatedClass 10 < EC_OTHER >
09/15/08 11:51:03.147 <DistributeCSTAEvent> associatedDevice <null>
09/15/08 11:51:03.147 <DistributeCSTAEvent> }
09/15/08 11:51:03.162 <DistributeCSTAEvent> Getting TsapiCallObserver lock to deliver events for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.162 <DistributeCSTAEvent> meta event BEGIN: cause (110) metaCode (128) for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.162 {Finalizer} Device 99049 (object= TSDevice[99049]@ea5461) being deleted for TSProvider@fced4
09/15/08 11:51:03.162 {Finalizer} %- Device 99049 (object= TSDevice[99049]@ea5461) about to consider DevMon stop (xref=0, for TSProvider@fced4
09/15/08 11:51:03.162 {Finalizer} TSDevice state transition: Active -> BeingDeleted, device TSDevice[99049]@ea5461
09/15/08 11:51:03.162 {Finalizer} NOTICE: devHash.remove() removed TSDevice[99049]@ea5461 for device name(0) 99049
09/15/08 11:51:03.162 {Finalizer} TSDevice state transition: BeingDeleted -> Deleted, device TSDevice[99049]@ea5461
09/15/08 11:51:03.162 <DistributeCSTAEvent> CALLACTIVEEVENT for TSCall[40]@78dc4c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.178 <DistributeCSTAEvent> CONNECTIONCREATEDEVENT for TSConnection[conn:(40,2020)]@2d7440 for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.178 <DistributeCSTAEvent> CONNECTIONCONNECTEDEVENT for TSConnection[conn:(40,2020)]@2d7440 for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.193 <DistributeCSTAEvent> CONNECTIONESTABLISHEDEVENT for TSConnection[conn:(40,2020)]@2d7440 for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.209 <DistributeCSTAEvent> TERMINALCONNECTIONCREATEDEVENT for TSConnection[termConn:(40,2020)]@c3e82b for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.209 <DistributeCSTAEvent> TERMINALCONNECTIONACTIVEEVENT for TSConnection[termConn:(40,2020)]@c3e82b for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.209 <DistributeCSTAEvent> TERMINALCONNECTIONTALKINGEVENT for TSConnection[termConn:(40,2020)]@c3e82b for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.209 <DistributeCSTAEvent> CONNECTIONCREATEDEVENT for TSConnection[conn:(40,2000)]@8b567c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.209 <DistributeCSTAEvent> CONNECTIONALERTINGEVENT for TSConnection[conn:(40,2000)]@8b567c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> CONNECTIONALERTINGEVENT_CC for TSConnection[conn:(40,2000)]@8b567c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> TERMINALCONNECTIONCREATEDEVENT for TSConnection[termConn:(40,2000)]@2b349d for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> TERMINALCONNECTIONRINGINGEVENT for TSConnection[termConn:(40,2000)]@2b349d for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> TERMINALCONNECTIONRINGINGEVENT_CC for TSConnection[termConn:(40,2000)]@2b349d for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> meta event END for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75 eventList size=13
09/15/08 11:51:03.225 <ThreadPool#1> TP thread woke up: Locked callChangedEvent, attempting to Lock TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> Storing new events, assigning TP thread Thread[ThreadPool#1,5,main] in TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <ThreadPool#1> TP thread Locked TsapiCallObserver: removing events, itself for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <DistributeCSTAEvent> DONE handling INVOKE ID 75 for TSProvider@fced4
09/15/08 11:51:03.225 <ThreadPool#1> TP thread Unlocked TsapiCallObserver: calling callChangedEvent, delivering events for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <ThreadPool#1> TP thread returned from callChangedEvent, Unlocked callChangedEvent for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:03.225 <ThreadPool#1> Observer ThreadPool size: 1 for TSProvider@fced4
09/15/08 11:51:04.100 {Thread-1} LucentQueryTod ::=
09/15/08 11:51:04.100 {Thread-1} {
09/15/08 11:51:04.100 {Thread-1} NULL
09/15/08 11:51:04.100 {Thread-1} }
09/15/08 11:51:04.100 {Thread-1} Sent InvokeID 78 for TSProvider@fced4
09/15/08 11:51:04.100 {Thread-1} CSTAEscapeSvc ::=
09/15/08 11:51:04.100 {Thread-1} {
09/15/08 11:51:04.100 {Thread-1} NULL
09/15/08 11:51:04.100 {Thread-1} }
09/15/08 11:51:04.100 {Thread-1} TsapiPrivate ::=
09/15/08 11:51:04.100 {Thread-1} {
09/15/08 11:51:04.100 {Thread-1} vendor "ECS"
09/15/08 11:51:04.100 {Thread-1} data 2 0 18 0 30 2 5 0
09/15/08 11:51:04.100 {Thread-1} tsType 89
09/15/08 11:51:04.100 {Thread-1} }
09/15/08 11:51:04.147 <GetEventThread> Received invokeID 78 for TSProvider@fced4
09/15/08 11:51:04.147 <GetEventThread> CSTAEscapeSvcConfEvent ::=
09/15/08 11:51:04.147 <GetEventThread> {
09/15/08 11:51:04.147 <GetEventThread> NULL
09/15/08 11:51:04.147 <GetEventThread> }
09/15/08 11:51:04.147 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:04.147 <GetEventThread> {
09/15/08 11:51:04.147 <GetEventThread> vendor "ECS"
09/15/08 11:51:04.147 <GetEventThread> data 2 0 19 0 30 12 2 1 8 2 1 9 2 1 f 2 1 b 2 1 21 2 1 16
09/15/08 11:51:04.147 <GetEventThread> tsType 90
09/15/08 11:51:04.147 <GetEventThread> }
09/15/08 11:51:04.147 <GetEventThread> Putting event CSTAEvent[CSTAEscapeSvcConfEvent]@5e8d7d. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:04.147 <DistributeCSTAEvent> Getting event CSTAEvent[CSTAEscapeSvcConfEvent]@5e8d7d for TSProvider@fced4
09/15/08 11:51:04.147 <DistributeCSTAEvent> LucentQueryTodConfEvent ::=
09/15/08 11:51:04.147 <DistributeCSTAEvent> {
09/15/08 11:51:04.147 <DistributeCSTAEvent> year 8
09/15/08 11:51:04.147 <DistributeCSTAEvent> month 9
09/15/08 11:51:04.147 <DistributeCSTAEvent> day 15
09/15/08 11:51:04.147 <DistributeCSTAEvent> hour 11
09/15/08 11:51:04.147 <DistributeCSTAEvent> minute 33
09/15/08 11:51:04.147 <DistributeCSTAEvent> second 22
09/15/08 11:51:04.147 <DistributeCSTAEvent> }
09/15/08 11:51:04.147 <DistributeCSTAEvent> Handling INVOKE ID 78 for TSProvider@fced4
09/15/08 11:51:04.147 <DistributeCSTAEvent> DONE handling INVOKE ID 78 for TSProvider@fced4
09/15/08 11:51:11.319 {http-8080-Processor24} Sent InvokeID 79 for TSProvider@fced4
09/15/08 11:51:11.319 {http-8080-Processor24} CSTAClearConnection ::=
09/15/08 11:51:11.319 {http-8080-Processor24} {
09/15/08 11:51:11.319 {http-8080-Processor24} call
09/15/08 11:51:11.319 {http-8080-Processor24} {
09/15/08 11:51:11.319 {http-8080-Processor24} callID 40
09/15/08 11:51:11.319 {http-8080-Processor24} deviceID "2000"
09/15/08 11:51:11.319 {http-8080-Processor24} devIDType 0 < STATIC_ID >
09/15/08 11:51:11.319 {http-8080-Processor24} }
09/15/08 11:51:11.319 {http-8080-Processor24} }
09/15/08 11:51:11.412 <GetEventThread> Received invokeID 79 for TSProvider@fced4
09/15/08 11:51:11.412 <GetEventThread> CSTAClearConnectionConfEvent ::=
09/15/08 11:51:11.412 <GetEventThread> {
09/15/08 11:51:11.412 <GetEventThread> NULL
09/15/08 11:51:11.412 <GetEventThread> }
09/15/08 11:51:11.412 <GetEventThread> Putting event CSTAEvent[CSTAClearConnectionConfEvent]@309f9f. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> Getting event CSTAEvent[CSTAClearConnectionConfEvent]@309f9f for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> Handling INVOKE ID 79 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> Getting TsapiCallObserver lock to deliver events for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> meta event BEGIN: cause (100) metaCode (131) for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <GetEventThread>
Received monitorCrossRefID 1 for TSProvider@fced4
09/15/08 11:51:11.412 <GetEventThread> CSTAConnectionClearedEvent ::=
09/15/08 11:51:11.412 <GetEventThread> {
09/15/08 11:51:11.412 <GetEventThread> droppedConnection
09/15/08 11:51:11.412 <GetEventThread> {
09/15/08 11:51:11.412 <GetEventThread> callID 40
09/15/08 11:51:11.412 <GetEventThread> deviceID "2000"
09/15/08 11:51:11.412 <GetEventThread> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.412 <GetEventThread> }
09/15/08 11:51:11.412 <GetEventThread> releasingDevice
09/15/08 11:51:11.412 <GetEventThread> {
09/15/08 11:51:11.412 <GetEventThread> deviceID "2000"
09/15/08 11:51:11.412 <GetEventThread> deviceIDType 55 < EXPLICIT_PRIVATE_LOCAL_NUMBER >
09/15/08 11:51:11.412 <GetEventThread> deviceIDStatus 0 < ID_PROVIDED >
09/15/08 11:51:11.412 <GetEventThread> }
09/15/08 11:51:11.412 <GetEventThread> localConnectionInfo 0 < CS_NULL >
09/15/08 11:51:11.412 <GetEventThread> cause -1 < EC_NONE >
09/15/08 11:51:11.412 <GetEventThread> }
09/15/08 11:51:11.412 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:11.412 <GetEventThread> {
09/15/08 11:51:11.412 <GetEventThread> vendor "ECS"
09/15/08 11:51:11.412 <GetEventThread> data 2 0 86 0 30 22 30 5 a 1 ff 4 0 30 19 30 17 16 4 32 30 30 30 a 1 ff 30 c 2 1 28 16 4 32 30 30 30 a 1 0
09/15/08 11:51:11.412 <GetEventThread> tsType 56
09/15/08 11:51:11.412 <GetEventThread> }
09/15/08 11:51:11.412 <GetEventThread> Putting event CSTAEvent[CSTAConnectionClearedEvent]@dfe303. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> TERMINALCONNECTIONDROPPEDEVENT for TSConnection[termConn:(40,2000)]@2b349d for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> TERMINALCONNECTIONDROPPEDEVENT_CC for TSConnection[termConn:(40,2000)]@2b349d for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> CONNECTIONDISCONNECTEDEVENT for TSConnection[conn:(40,2000)]@8b567c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> CONNECTIONDISCONNECTEDEVENT_CC for TSConnection[conn:(40,2000)]@8b567c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> meta event END for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75 eventList size=4
09/15/08 11:51:11.412 <DistributeCSTAEvent> Storing new events, assigning TP thread Thread[ThreadPool#1,5,main] in TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> TP thread woke up: Locked callChangedEvent, attempting to Lock TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> DONE handling INVOKE ID 79 for TSProvider@fced4
09/15/08 11:51:11.412 <ThreadPool#1> TP thread Locked TsapiCallObserver: removing events, itself for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> Getting event CSTAEvent[CSTAConnectionClearedEvent]@dfe303 for TSProvider@fced4
09/15/08 11:51:11.412 <ThreadPool#1> TP thread Unlocked TsapiCallObserver: calling callChangedEvent, delivering events for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> TP thread returned from callChangedEvent, Unlocked callChangedEvent for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> Observer ThreadPool size: 1 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> LucentV7ConnectionClearedEvent ::=
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> userInfo <null>
09/15/08 11:51:11.412 <DistributeCSTAEvent> deviceHistory
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> oldDeviceID "2000"
09/15/08 11:51:11.412 <DistributeCSTAEvent> eventCause -1 < EC_NONE >
09/15/08 11:51:11.412 <DistributeCSTAEvent> oldConnectionID
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> callID 40
09/15/08 11:51:11.412 <DistributeCSTAEvent> deviceID "2000"
09/15/08 11:51:11.412 <DistributeCSTAEvent> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> CSTA Unsolicited Event: CSTAEvent[CSTAConnectionClearedEvent]@dfe303
09/15/08 11:51:11.412 <DistributeCSTAEvent> Free memory: 4159680
09/15/08 11:51:11.412 <DistributeCSTAEvent> Total memory: 15667200
09/15/08 11:51:11.412 <DistributeCSTAEvent> Handling CSTA_CONNECTION_CLEARED for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> set redo snapshot call to true
09/15/08 11:51:11.412 <DistributeCSTAEvent> Sent InvokeID 80 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> CSTASnapshotCall ::=
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> snapshotObject
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> callID 40
09/15/08 11:51:11.412 <DistributeCSTAEvent> deviceID "2000"
09/15/08 11:51:11.412 <DistributeCSTAEvent> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> Getting TsapiCallObserver lock to deliver deleteReference events for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> meta event BEGIN: cause (100) metaCode (136) for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> OBSERVATIONENDEDEVENT for observed: TSCall[40]@78dc4c for observer com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> meta event END for com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75 eventList size=1
09/15/08 11:51:11.412 <ThreadPool#1> TP thread woke up: Locked callChangedEvent, attempting to Lock TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <DistributeCSTAEvent> Storing new events (deleteReference), assigning TP thread Thread[ThreadPool#1,5,main] in TsapiCallObserver for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> TP thread Locked TsapiCallObserver: removing events, itself for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> TP thread Unlocked TsapiCallObserver: calling callChangedEvent, delivering events for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> TP thread returned from callChangedEvent, Unlocked callChangedEvent for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1843a75
09/15/08 11:51:11.412 <ThreadPool#1> Observer ThreadPool size: 1 for TSProvider@fced4
09/15/08 11:51:11.412 <DistributeCSTAEvent> DONE handling CSTA_CONNECTION_CLEARED for TSProvider@fced4
09/15/08 11:51:11.459 <GetEventThread> Received invokeID 80 for TSProvider@fced4
09/15/08 11:51:11.459 <GetEventThread> CSTASnapshotCallConfEvent ::=
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> snapshotData
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> deviceOnCall
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> deviceID "2020"
09/15/08 11:51:11.459 <GetEventThread> deviceIDType 55 < EXPLICIT_PRIVATE_LOCAL_NUMBER >
09/15/08 11:51:11.459 <GetEventThread> deviceIDStatus 0 < ID_PROVIDED >
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> callIdentifier
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> callID 40
09/15/08 11:51:11.459 <GetEventThread> deviceID "2020"
09/15/08 11:51:11.459 <GetEventThread> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> localConnectionState 3 < CS_CONNECT >
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:11.459 <GetEventThread> {
09/15/08 11:51:11.459 <GetEventThread> vendor "ECS"
09/15/08 11:51:11.459 <GetEventThread> data 2 0 8a 0 30 1b 30 19 30 17 16 4 32 30 30 30 a 1 ff 30 c 2 1 28 16 4 32 30 30 30 a 1 0
09/15/08 11:51:11.459 <GetEventThread> tsType 121
09/15/08 11:51:11.459 <GetEventThread> }
09/15/08 11:51:11.459 <GetEventThread> Putting event CSTAEvent[CSTASnapshotCallConfEvent]@1041876. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:11.459 <DistributeCSTAEvent> Getting event CSTAEvent[CSTASnapshotCallConfEvent]@1041876 for TSProvider@fced4
09/15/08 11:51:11.459 <DistributeCSTAEvent> LucentSnapshotCallInfoConfEvent ::=
09/15/08 11:51:11.459 <DistributeCSTAEvent> {
09/15/08 11:51:11.459 <DistributeCSTAEvent> deviceHistory
09/15/08 11:51:11.459 <DistributeCSTAEvent> {
09/15/08 11:51:11.459 <DistributeCSTAEvent> {
09/15/08 11:51:11.459 <DistributeCSTAEvent> oldDeviceID "2000"
09/15/08 11:51:11.459 <DistributeCSTAEvent> eventCause -1 < EC_NONE >
09/15/08 11:51:11.459 <DistributeCSTAEvent> oldConnectionID
09/15/08 11:51:11.459 <DistributeCSTAEvent> {
09/15/08 11:51:11.459 <DistributeCSTAEvent> callID 40
09/15/08 11:51:11.459 <DistributeCSTAEvent> deviceID "2000"
09/15/08 11:51:11.459 <DistributeCSTAEvent> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.459 <DistributeCSTAEvent> }
09/15/08 11:51:11.459 <DistributeCSTAEvent> }
09/15/08 11:51:11.459 <DistributeCSTAEvent> }
09/15/08 11:51:11.459 <DistributeCSTAEvent> }
09/15/08 11:51:11.459 <DistributeCSTAEvent> Handling INVOKE ID 80 for TSProvider@fced4
09/15/08 11:51:11.459 <DistributeCSTAEvent> DONE handling INVOKE ID 80 for TSProvider@fced4
09/15/08 11:51:12.147 {Thread-1} LucentQueryTod ::=
09/15/08 11:51:12.147 {Thread-1} {
09/15/08 11:51:12.147 {Thread-1} NULL
09/15/08 11:51:12.147 {Thread-1} }
09/15/08 11:51:12.147 {Thread-1} Sent InvokeID 81 for TSProvider@fced4
09/15/08 11:51:12.147 {Thread-1} CSTAEscapeSvc ::=
09/15/08 11:51:12.147 {Thread-1} {
09/15/08 11:51:12.147 {Thread-1} NULL
09/15/08 11:51:12.147 {Thread-1} }
09/15/08 11:51:12.147 {Thread-1} TsapiPrivate ::=
09/15/08 11:51:12.147 {Thread-1} {
09/15/08 11:51:12.147 {Thread-1} vendor "ECS"
09/15/08 11:51:12.147 {Thread-1} data 2 0 18 0 30 2 5 0
09/15/08 11:51:12.147 {Thread-1} tsType 89
09/15/08 11:51:12.147 {Thread-1} }
09/15/08 11:51:12.162 <GetEventThread> Received invokeID 81 for TSProvider@fced4
09/15/08 11:51:12.162 <GetEventThread> CSTAEscapeSvcConfEvent ::=
09/15/08 11:51:12.162 <GetEventThread> {
09/15/08 11:51:12.162 <GetEventThread> NULL
09/15/08 11:51:12.162 <GetEventThread> }
09/15/08 11:51:12.162 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:12.162 <GetEventThread> {
09/15/08 11:51:12.162 <GetEventThread> vendor "ECS"
09/15/08 11:51:12.162 <GetEventThread> data 2 0 19 0 30 12 2 1 8 2 1 9 2 1 f 2 1 b 2 1 21 2 1 1e
09/15/08 11:51:12.162 <GetEventThread> tsType 90
09/15/08 11:51:12.162 <GetEventThread> }
09/15/08 11:51:12.162 <GetEventThread> Putting event CSTAEvent[CSTAEscapeSvcConfEvent]@1896a4c. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:12.162 <DistributeCSTAEvent> Getting event CSTAEvent[CSTAEscapeSvcConfEvent]@1896a4c for TSProvider@fced4
09/15/08 11:51:12.162 <DistributeCSTAEvent> LucentQueryTodConfEvent ::=
09/15/08 11:51:12.162 <DistributeCSTAEvent> {
09/15/08 11:51:12.162 <DistributeCSTAEvent> year 8
09/15/08 11:51:12.162 <DistributeCSTAEvent> month 9
09/15/08 11:51:12.162 <DistributeCSTAEvent> day 15
09/15/08 11:51:12.162 <DistributeCSTAEvent> hour 11
09/15/08 11:51:12.162 <DistributeCSTAEvent> minute 33
09/15/08 11:51:12.162 <DistributeCSTAEvent> second 30
09/15/08 11:51:12.162 <DistributeCSTAEvent> }
09/15/08 11:51:12.162 <DistributeCSTAEvent> Handling INVOKE ID 81 for TSProvider@fced4
09/15/08 11:51:12.162 <DistributeCSTAEvent> DONE handling INVOKE ID 81 for TSProvider@fced4
09/15/08 11:51:20.163 {Thread-1} LucentQueryTod ::=
09/15/08 11:51:20.163 {Thread-1} {
09/15/08 11:51:20.163 {Thread-1} NULL
09/15/08 11:51:20.163 {Thread-1} }
09/15/08 11:51:20.163 {Thread-1} Sent InvokeID 82 for TSProvider@fced4
09/15/08 11:51:20.163 {Thread-1} CSTAEscapeSvc ::=
09/15/08 11:51:20.163 {Thread-1} {
09/15/08 11:51:20.163 {Thread-1} NULL
09/15/08 11:51:20.163 {Thread-1} }
09/15/08 11:51:20.163 {Thread-1} TsapiPrivate ::=
09/15/08 11:51:20.163 {Thread-1} {
09/15/08 11:51:20.163 {Thread-1} vendor "ECS"
09/15/08 11:51:20.163 {Thread-1} data 2 0 18 0 30 2 5 0
09/15/08 11:51:20.163 {Thread-1} tsType 89
09/15/08 11:51:20.163 {Thread-1} }
09/15/08 11:51:20.209 <GetEventThread> Received invokeID 82 for TSProvider@fced4
09/15/08 11:51:20.209 <GetEventThread> CSTAEscapeSvcConfEvent ::=
09/15/08 11:51:20.209 <GetEventThread> {
09/15/08 11:51:20.209 <GetEventThread> NULL
09/15/08 11:51:20.209 <GetEventThread> }
09/15/08 11:51:20.209 <GetEventThread> TsapiPrivate ::=
09/15/08 11:51:20.209 <GetEventThread> {
09/15/08 11:51:20.209 <GetEventThread> vendor "ECS"
09/15/08 11:51:20.209 <GetEventThread> data 2 0 19 0 30 12 2 1 8 2 1 9 2 1 f 2 1 b 2 1 21 2 1 26
09/15/08 11:51:20.209 <GetEventThread> tsType 90
09/15/08 11:51:20.209 <GetEventThread> }
09/15/08 11:51:20.209 <GetEventThread> Putting event CSTAEvent[CSTAEscapeSvcConfEvent]@1786a3c. EVENT Q SIZE = 1 MAX Q SIZE = 5 for TSProvider@fced4
09/15/08 11:51:20.209 <DistributeCSTAEvent> Getting event CSTAEvent[CSTAEscapeSvcConfEvent]@1786a3c for TSProvider@fced4


I hope you will be able to see this...

Kind Regards
manie

Here is what my initial look into the logs showing:

There is some issue while ESTABLISHING the connection.

15/09/2008 11:51:09 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process

There are no traces in TSAPI Traces in the interval of 5 secoonds:

09/15/08 11:51:04.147 <DistributeCSTAEvent> DONE handling INVOKE ID 78 for TSProvider@fced4
09/15/08 11:51:11.319 {http-8080-Processor24} Sent InvokeID 79 for TSProvider@fced4

Again in TSAPI traces I could see:
09/15/08 11:51:11.412 <DistributeCSTAEvent> LucentV7ConnectionClearedEvent ::=
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> userInfo <null>
09/15/08 11:51:11.412 <DistributeCSTAEvent> deviceHistory
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> oldDeviceID "2000"
09/15/08 11:51:11.412 <DistributeCSTAEvent> eventCause -1 < EC_NONE >
09/15/08 11:51:11.412 <DistributeCSTAEvent> oldConnectionID
09/15/08 11:51:11.412 <DistributeCSTAEvent> {
09/15/08 11:51:11.412 <DistributeCSTAEvent> callID 40
09/15/08 11:51:11.412 <DistributeCSTAEvent> deviceID "2000"
09/15/08 11:51:11.412 <DistributeCSTAEvent> devIDType 0 < STATIC_ID >
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> }
09/15/08 11:51:11.412 <DistributeCSTAEvent> CSTA Unsolicited Event:

Looks like none of the calls is getting connected. Which version of DD are you using?
Are you running the latest release? If not please upgrade first and re-run the testing.

What is happening on the AES end during the time issue is seen on IR/VP?

We will try to share nore insight into the issue after going in details of the traces.

Thanks,

Hi

We are using DD 4.1.0107. This issue started happening just after one of our developers tried to upgrade to the .09 update. Since then we have experienced this error. We have also removed the updates and re-installed the tomcat server ect. to ensure that we are NOT using the Update 09 anymore...

Kind Regards
Manie

Hi

Any update on this call yet??

Kind Regards
Manie

how frequently is the issue happening? If all the calls are failing?
You are using blind transfer or consultative transfer?
Were you able to see AES behavior during the failure?
Is your application transferring to a VDN?
can you upgrade your DD to the latest version available and test placing calls?

Hi

Some Answers...
It Happens on ALL calls. We are NOT usign a Transfer. The Application just picks up the call and then plays a prompt and put the call down again.. It is not transferring at all. What do you mean activity on the AES. Where can I look for the activity on the AES? Any specific logs ?

If you look in this part of the log below, the call comes in and goes to an alerting state, but it never progresses further then that from the AES perspective. The JTAPI log is quiet for about 5 seconds, so no events come in from the AES. This is more of an AES issue (or possibly switch) then a DD issue. The CTIC is just waiting for events that never come in. You would be better served bringing this to Avaya customer support and have the case go to the AES/JTAPI team. They can then analyze AES logs to determine the cause.


15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: found 2 connections
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 0 is 51
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: state of connection 1 is 50
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: Call is not fully established
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 7 is 106 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Created Event for id:40
15/09/2008 11:51:03 DEBUG - CTICallObserver.addCall 2000: call id is 40 is already added, returning call data
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 8 is 104 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Connection Alerting Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 9 is 203 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent:2000: got Call Control alerting Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.updateCallState 2000: setting call:40 to state:ringing
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 10 is 116 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Created Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 11 is 119 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Terminal Connection Ringing Event
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent 2000: Event: 12 is 218 for call 40
15/09/2008 11:51:03 DEBUG - CTICallObserver.callChangedEvent2000: got Call Control Terminal Ringing Event
15/09/2008 11:51:04 DEBUG - ProviderMonitor: Checking:ABSACTILink for availability
15/09/2008 11:51:07 DEBUG - CTICallObserver.addCallToCache:caching call:40

Thanks I have logged a formal support call ticket number 05454 and will also post these comments there... Thanks a lot for you assistance..

Just as a matter of interest... I have confirmed that this error also persists with the new .09 SP of DD.

Kind Regards
manie

I think I am facing the same error, A call comes to the IR, DD asks for cti call info, but no info is returned, so the calls disconnect, did you reach any results with the case you have opened?

No, I am not getting much of a support from the AVAYA team, what I can tell you is that we are suspecting the network at this stage. It seems as if the network gets congested and that even though the VOIP traffic is prioritized on the network, the data is then delayed a bit (this call is off course a data request and not VOIP), so I think we will also have to get the traffic between the AES and the AVP also prioritized for data, to ensure that all is working fine.

What you can also try is to run a cross over cable between the AES and the AVP App server (or where the CTI request will get generated from) and see if this helps, to rule out network congestion at least.

Hope this helps...

Kind Regards
Manie

I don't think it is a network congestion matter, as currenlty the IR is not fully loaded and the problem is happening.

Also putting a crossed cable is somewhat difficult, you have to put one between the AES and the CLAN on the PBX, and put another one between the AES and hte application server
you must have two clans one for the AES connection and the other for the Voip traffic !!
I will try to monitor the traffic on hte switch maybe it can show something, but I think this is very unlikly.

What we found was that the call is active for a very short while, and then the call drops, but due to the fact that the AES receives the call dropped event before our GetCTIInfo event, this caused the time out.

Do you use the Autoinvoke GetCTI parametsr, or are you using a separate GetCTI request from within the call flow? We found by not ding the Autoinvoke parameter also sometimes helped not getting the error, as our error was intermittently at first.

We also tried to put this GetCTIInfo request inside a Try Catch block, to prevent the call from putting down, but it totally ignored the Try Catch block and still put down the call..

Not sure if this helps...

Kind Regards
Manie