Hi Neil,
I'm facing a CTI transfer issue where CTI connector unable to retrieve the hold call after a consultation call transferred failure.
FYI, I have set the max ring to 5 and the browser's fetch time out to 35 seconds but still cannot resolve the problem. Even i changed the max ring to 2 only, the same error still happen.
Below is the trace that i captured:
Application Log:
09/05/2011 14:23:23:697 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : PlatformParams: get parameter|value - __VPLicenseServerURL|https://10.21.150.181:8443/WebLM/LicenseServer
09/05/2011 14:23:23:697 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Using SCESession F55A637A00C2B821D7F066279CE05759:/TferCall servlet : Start
09/05/2011 14:23:23:728 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : ** Pushed Stack Frame [/TferCall]
09/05/2011 14:23:23:744 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPlogpassword]
09/05/2011 14:23:23:744 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPVarAppDate]
09/05/2011 14:23:23:744 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPappname]
09/05/2011 14:23:23:744 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPapplog]
09/05/2011 14:23:23:744 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___sessionid to complex: session:sessionid as [C150CYG183-2011129063658-5]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPbreadcrumb]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPmaxbackuplogfiles]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPvpms]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPloglevel]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPVarAppURL]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPapploggingurl]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPVarGlobalDate]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPlogname]
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Not able to save posted variable information [__VPappvars]
09/05/2011 14:23:23:759 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : runtime_platform : Voice Portal
09/05/2011 14:23:23:759 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : runtime_asr : Desktop Microsoft Speech SAPI
09/05/2011 14:23:23:759 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Acquiring initial License
09/05/2011 14:23:23:759 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Acquiring Avaya Platform runtime license
09/05/2011 14:23:23:822 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Runtime :true
09/05/2011 14:23:23:822 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : IC :true
09/05/2011 14:23:23:822 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : CTI :true
09/05/2011 14:23:23:837 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : Grace Period timer cleared
09/05/2011 14:23:23:853 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : License refresh timer started
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Using SCESession F55A637A00C2B821D7F066279CE05759:/TferCall servlet : Onhold
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videonearfmtp to complex: session:videonearfmtp as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___vprdnis to complex: session:vprdnis as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :redirectinfo___uri to complex: redirectinfo:uri as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :redirectinfo___presentationinfo to complex: redirectinfo:presentationinfo as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___channel to complex: session:channel as [71410]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :shareduui___value to complex: shareduui:value as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___sessionlabel to complex: session:sessionlabel as [undefined]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :shareduui___id to complex: shareduui:id as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :redirectinfo___reason to complex: redirectinfo:reason as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___vpcalledextension to complex: session:vpcalledextension as [71410]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___ani to complex: session:ani as [65001]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videoheight to complex: session:videoheight as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videocodec to complex: session:videocodec as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videofarfmtp to complex: session:videofarfmtp as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___mediatype to complex: session:mediatype as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___protocolname to complex: session:protocolname as [H323]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :redirectinfo___screeninginfo to complex: redirectinfo:screeninginfo as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___ucid to complex: session:ucid as [undefined]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videofps to complex: session:videofps as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___vpcoveragereason to complex: session:vpcoveragereason as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videoformat to complex: session:videoformat as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videoenabled to complex: session:videoenabled as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___sharedmode to complex: session:sharedmode as [serviceprovider]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___calltag to complex: session:calltag as [C150CYG183-71410-2011129063658]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___dnis to complex: session:dnis as [16607]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :_sipcallid to simple: _sipcallid as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___vpcoveragetype to complex: session:vpcoveragetype as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___uui to complex: session:uui as []
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videobitrate to complex: session:videobitrate as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___videowidth to complex: session:videowidth as [unknown]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___protocolversion to complex: session:protocolversion as [1.0]
09/05/2011 14:23:23:884 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Storing :session___aai to complex: session:aai as []
09/05/2011 14:23:23:884 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: encrypted value is nJihhAsdsTNmg8OiFIpFit4TQddYaU0po2HDc9pPQgQ=
09/05/2011 14:23:23:884 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: request to manager is
http://10.21.150.184:8080/cticonnector/CallInfoInitialCall?extension%3D71410&k=nJihhAsdsTNmg8OiFIpFit4TQddYaU0po2HDc9pPQgQ%3D
09/05/2011 14:23:23:884 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: setting session cookie to F55A637A00C2B821D7F066279CE05759:/TferCall
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: callinfo from Manager is callid=12102&ani=65001&dnis=16607&extension=71410&ucID=00001121021304922427&uui= &state=established
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CallInfo.doGetCallInfo: Populating call info variable values...
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: Call ID 12102
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: Calling # (ANI) 65001
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: Called # (DNIS) 16607
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: Ext 71410
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: UCID 00001121021304922427
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: UUI
09/05/2011 14:23:23:900 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.setCallInfoVariableValues: State established
09/05/2011 14:23:29:126 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Using SCESession F55A637A00C2B821D7F066279CE05759:/TferCall servlet : XferCall
09/05/2011 14:23:29:126 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : VariableUtil.getVariableValue: Variable value is 90122900469
09/05/2011 14:23:29:126 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: encrypted value is nJihhAsdsTNmg8OiFIpFipgkli6i2M3nsI1ff+MVLXU=
09/05/2011 14:23:29:126 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : VariableUtil.getVariableValue: Variable value is 12102
09/05/2011 14:23:29:126 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: request to manager is
http://10.21.150.184:8080/cticonnector/ConsultationCall?callee%3D90122900469%26uui%3Dnull%26uuiAsAscii%3Dfalse%26holdAddress%3D12102%26ringMax%3D2%26extension%3D71410%26transferOnRing%3Dfalse&k=nJihhAsdsTNmg8OiFIpFipgkli6i2M3nsI1ff%2BMVLXU%3D
09/05/2011 14:23:29:126 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: setting session cookie to F55A637A00C2B821D7F066279CE05759:/TferCall
09/05/2011 14:23:40:015 DEBUG - F55A637A00C2B821D7F066279CE05759:/TferCall : CTICommand.execute: callinfo from Manager is error:com.avaya.sce.cticonnector.servlet.CTIConnectorException: Wait time exceeded trying to retrieve call on hold
09/05/2011 14:23:40:015 INFO - F55A637A00C2B821D7F066279CE05759:/TferCall : Capturing exception [javax.servlet.ServletException]. Message [ EXCEPTION>
com.avaya.sce.runtimecommon.SCERuntimeException: com.avaya.sce.cticonnector.servlet.CTIConnectorException: Wait time exceeded trying to retrieve call on hold
at com.avaya.sce.runtimecommon.SCESession.throwRTException(SCESession.java:1936)
at com.avaya.sce.runtime.connectivity.cti.ir.CTICommand.execute(CTICommand.java:127)
at com.avaya.sce.runtime.Data.evaluateActions(Data.java:165)
at flow.XferCall.executeDataActions(XferCall.java:67)
at com.avaya.sce.runtime.Data.handleRequest(Data.java:81)
at com.avaya.sce.runtime.AppServlet.processRequest(AppServlet.java:78)
at com.avaya.sce.runtime.SCEServlet.requestHandler(SCEServlet.java:266)
at com.avaya.sce.runtime.SCEServlet.doGet(SCEServlet.java:176)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:857)
at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:565)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1509)
at java.lang.Thread.run(Unknown Source)
]
cti Connector Log:
09/05/2011 14:23:35:459 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 71410 is 0
09/05/2011 14:23:35:553 DEBUG - Retrieve.doRetrieve: retrieving ext:71410
09/05/2011 14:23:35:600 DEBUG - Retrieve.doRetrieve: Terminal connection 0 state is HELD
09/05/2011 14:23:35:600 DEBUG - Retrieve.doRetrieve: Attempting to unhold...
09/05/2011 14:23:36:707 DEBUG - Retrieve.doRetrieve: Attempting to unhold...
09/05/2011 14:23:37:815 DEBUG - Retrieve.doRetrieve: Attempting to unhold...
09/05/2011 14:23:38:907 DEBUG - Retrieve.doRetrieve: Attempting to unhold...
09/05/2011 14:23:40:015 ERROR - Retrieve.doRetrieve: Error: Wait time exceeded trying to retrieve call on hold
09/05/2011 14:23:40:015 ERROR - Retrieve.doRetrieve: error com.avaya.sce.cticonnector.servlet.CTIConnectorException: Wait time exceeded trying to retrieve call on hold
09/05/2011 14:23:41:200 DEBUG - ProviderMonitor: Checking:S21CYG12 for availability
09/05/2011 14:23:49:250 DEBUG - ProviderMonitor: Checking:S21CYG12 for availability
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 71410 is 4
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 0 is 117 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got an unknown event 117
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 1 is 215 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got an unknown event 215
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 2 is 107 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got Connection Disconnected Event 107
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 3 is 205 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got Connection Disconnected Event 205
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 71410 is 5
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 0 is 117 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got an unknown event 117
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 1 is 215 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got an unknown event 215
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 2 is 107 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got Connection Disconnected Event 107
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 3 is 205 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got Connection Disconnected Event 205
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent 71410: Event: 4 is 103 for call 12102
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent:71410: got Call Observation Ended Event
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.removeCall:clearing MRCA:12102 from ext:71410
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.removeCall:removing call:12102 from ext:71410
09/05/2011 14:23:49:905 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 71410 is 0
I will send you the logs to your email account. Hopefully you can help me to sort it out asap.
Thank you very much!
Best Regards,
Seow Leng