Author Message
zhibinyang
Joined: Nov 11, 2013
Messages: 3
Offline
I'm a BBE, 2 SME has checked this case and thought the issue is in tsapi client or cticonnector. I will send the whole trace/log to someone who will handle this.
Thank you so much.

CTI connector trace:
06/11/2013 19:15:04:806 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
06/11/2013 19:15:04:946 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 70206 is 16
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 0 is 101 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Active Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 1 is 106 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Created Event for id:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: Saving most recent call created:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: call id is 10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: ucid is 00001094021383736369
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: setting 10680 to state: initiated
06/11/2013 19:15:04:962 DEBUG - CallInfoData.CallInfoData:70206: callid 10680
06/11/2013 19:15:04:962 DEBUG - CallInfoData.CallInfoData:70206: ani T10068#1
06/11/2013 19:15:04:962 DEBUG - CallInfoData.CallInfoData:70206: dnis 21224
06/11/2013 19:15:04:962 DEBUG - CallInfoData.CallInfoData:70206: ucid 00001094021383736369
06/11/2013 19:15:04:962 DEBUG - CallInfoData.CallInfoData:70206: uui 00001010651350273689$0910135281$124001058
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: added call to list
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206:cache is:false
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 2 is 110 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 110
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 3 is 213 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 213
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 4 is 106 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Created Event for id:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: Saving most recent call created:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: call id is 10680 is already added, returning call data
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 5 is 104 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Alerting Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 6 is 203 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got Call Control alerting Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.updateCallState 70206: setting call:10680 to state:ringing
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 7 is 116 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Terminal Connection Created Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 8 is 119 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Terminal Connection Ringing Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 9 is 218 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Call Control Terminal Ringing Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 10 is 106 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Created Event for id:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: Saving most recent call created:10680
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.addCall 70206: call id is 10680 is already added, returning call data
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 11 is 110 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 110
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 12 is 213 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 213
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 13 is 116 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Terminal Connection Created Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 14 is 120 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 120
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 15 is 220 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got an unknown event 220
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 70206 is 4
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 0 is 105 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Connected Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 1 is 206 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got Call Control Connection Established Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: found 3 connections
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 0 is 54
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 1 is 51
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 2 is 54
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: Call is not fully established
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 2 is 115 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent70206: got Terminal Connection Active Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 3 is 219 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: got Terminal Connection Talking Event
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: found 3 connections
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 0 is 54
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 1 is 51
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 2 is 54
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: Call is not fully established
06/11/2013 19:15:05:321 DEBUG - CTICallObserver.addCallToCache:caching call:10680
06/11/2013 19:15:05:321 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:05:321 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:05:836 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:05:836 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:06:350 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:06:350 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:06:865 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:06:865 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:07:380 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:07:380 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:07:895 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:07:895 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:08:410 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:10680
06/11/2013 19:15:08:410 DEBUG - CallInfo:doGetCallInfo:Call exists, but not established. Give CTI Connector time to process
06/11/2013 19:15:08:925 ERROR - CallInfo.doGetCallInfoInitialCall: call on extension:70206 was never established
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 70206 is 1
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 0 is 216 for call 10680 Provider:LK-AES_HA
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent:70206: got Terminal Connection Held Event
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.updateCallState 70206: setting call:10680 to state:held
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.updateCallState 70206: setting cached call:10680 to state:held
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 70206 is 7
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent 70206: Event: 0 is 101 for call 10754 Provider:LK-AES_HA
06/11/2013 19:15:09:112 DEBUG - CTICallObserver.callChangedEvent70206: got Connection Active Event
....


tsapi_trace
.....
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@16d35b4
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@16d35b4
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@16d35b4
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@16d35b4
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@a26068
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@a26068
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@a26068
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@a26068
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@145300b
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@145300b
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - --> getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@145300b
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE LucentV6ConnectionImpl - <-- getState[]: com.avaya.jtapi.tsapi.impl.LucentV6ConnectionImpl@145300b
2013-11-06 19:15:04,962 [pool-9-thread-12] DEBUG TsapiCallMonitor - TP thread returned from callChangedEvent, Unlocked callChangedEvent for CallObserver com.avaya.sce.cticonnector.servlet.server.CTIConnectorManager$CTICallObserver@1ac3b87
2013-11-06 19:15:04,962 [pool-9-thread-12] TRACE TsapiCallMonitor - <-- run[]: com.avaya.jtapi.tsapi.impl.monitor.TsapiCallMonitor@4d5e01

<- 4 second without anything.

2013-11-06 19:15:09,112 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 26 for TSProvider[#2]@118ed3c
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - CSTAHeldEvent ::=
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - {
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 26
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - heldConnection
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - {
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - callID 10680
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - deviceID "70206"
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2013-11-06 19:15:09,112 [GetEventThread] DEBUG TsapiSession - }
.....
NeilGoldsmith
Joined: Nov 6, 2013
Messages: 902
Offline
The problem is here:
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: found 3 connections
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 0 is 54
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 1 is 51
06/11/2013 19:15:04:962 DEBUG - CTICallObserver.callChangedEvent:70206: state of connection 2 is 54

You have 3 connections on this call (not sure what 3rd is, maybe Witness?). In any case, only 1 connection is connected (51) while the other 2 are in an unknown state (54). CTIC will only validate a call when 2 or more connections are connected, otherwise it will wait until a 2nd connection goes to a valid connected state.
Go to:   
Mobile view