Hello,
we have a case where several calls from several applications are receiving the
No call info available for extension xxxxx
a lot of calls where the AESConnector works properly but at some point it start failing, failures are not linked to the hours of high traffic or to other environmental issues, it simply starts failing.
the servers have been restarted and the issue continues to occur, we have isolated some of the information from the logs:
a bad call trace log :
...
12/10/2016 14:55:17:623 DEBUG - 28BD5DACCB1EF23D2476C5A954C0A10E:/UNE_UUI_IVR_INTEGRADO_NOVERDE_V8 : CTICommand.execute: setting session cookie to 28BD5DACCB1EF23D2476C5A954C0A10E:/UNE_UUI_IVR_INTEGRADO_NOVERDE_V8
12/10/2016 14:55:21:631 DEBUG - 28BD5DACCB1EF23D2476C5A954C0A10E:/UNE_UUI_IVR_INTEGRADO_NOVERDE_V8 : CTICommand.execute: callinfo from Manager is error:CallInfo.doGetCallInfoInitialCall: No call info available for extension 17095
in the Trace.log of the aesconnector, the information found at that time :
12/10/2016 14:55:21:631 ERROR - CallInfo.doGetCallInfoInitialCall: No call info available for extension 17095
...
12/10/2016 14:56:28:170 DEBUG - Ending call on extension 17095
12/10/2016 14:56:28:170 DEBUG - CTICallObserver.removeAllCalls: Callid: id passed from app on extension:17095 is null MRCR: MRCC:
12/10/2016 14:56:28:170 DEBUG - CTICallObserver.removeAllCallsFrom:clearing out MRCR
12/10/2016 14:56:28:170 DEBUG - CTICallObserver.removeAllCallsFrom:removed all calls from extension:17095
12/10/2016 14:56:28:170 DEBUG - CTICallObserver.removeAllCallsFromCache:removed all calls from cache at extension:17095
...
12/10/2016 14:57:20:562 ERROR - CallInfo.doGetCallInfoInitialCall: No call info available for extension 17095
note that the time in the app log and in the aesconnector log is an exact match (12/10/2016 14:55:21:631), later on that log, at 14:59:11 (about 3 mins later than the first request) the AESConnector gets this:
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.removeCall:clearing MRCC:8401 from ext:17095
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.removeCall:removing call:8401 from ext:17095
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 175 is 101 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Active Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 176 is 106 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Created Event for id:9262
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: Saving most recent call created:9262
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095: call id is 9262
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095: ucid is 00001092621476302116
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095: setting 9262 to state: initiated
12/10/2016 14:59:11:554 DEBUG - CallInfoData.CallInfoData:17095: callid 9262
12/10/2016 14:59:11:554 DEBUG - CallInfoData.CallInfoData:17095: ani 53190733
12/10/2016 14:59:11:554 DEBUG - CallInfoData.CallInfoData:17095: dnis 196
12/10/2016 14:59:11:554 DEBUG - CallInfoData.CallInfoData:17095: ucid 00001092621476302116
12/10/2016 14:59:11:554 DEBUG - CallInfoData.CallInfoData:17095: uui 10200000453190733000000000000000
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095: added call to list
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095:cache is:false
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 177 is 105 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Connected Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 178 is 206 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent:17095: got Call Control Connection Established Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent:17095: Found no connections object
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 179 is 106 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Created Event for id:9262
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: Saving most recent call created:9262
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.addCall 17095: call id is 9262 is already added, returning call data
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 180 is 104 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Alerting Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 181 is 203 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent:17095: got Call Control alerting Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.updateCallState 17095: setting call:9262 to state:ringing
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 182 is 116 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Terminal Connection Created Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 183 is 119 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Terminal Connection Ringing Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 184 is 218 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Call Control Terminal Ringing Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 185 is 105 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Connected Event
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 186 is 206 for call 9262 Provider:AES3
12/10/2016 14:59:11:554 DEBUG - CTICallObserver.callChangedEvent:17095: got Call Control Connection Established Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: Found no connections object
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 187 is 115 for call 9262 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Terminal Connection Active Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 188 is 219 for call 9262 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: got Terminal Connection Talking Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: Found no connections object
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 189 is 216 for call 9262 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: got Terminal Connection Held Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.updateCallState 17095: setting call:9262 to state:held
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 190 is 101 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Active Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 191 is 106 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Created Event for id:9434
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: Saving most recent call created:9434
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.addCall 17095: call id is 9434
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.addCall 17095: ucid is 00001092621476302116
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.addCall 17095: setting 9434 to state: initiated
12/10/2016 14:59:11:555 DEBUG - CallInfoData.CallInfoData:17095: callid 9434
12/10/2016 14:59:11:555 DEBUG - CallInfoData.CallInfoData:17095: ani 17095
12/10/2016 14:59:11:555 DEBUG - CallInfoData.CallInfoData:17095: dnis 12384
12/10/2016 14:59:11:555 DEBUG - CallInfoData.CallInfoData:17095: ucid 00001092621476302116
12/10/2016 14:59:11:555 DEBUG - CallInfoData.CallInfoData:17095: uui 10200000453190733000000000000000
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.addCall 17095: added call to list
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.addCall 17095:cache is:false
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 192 is 105 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Connection Connected Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 193 is 208 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: got an unknown event 208
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 194 is 116 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Terminal Connection Created Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 195 is 115 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent17095: got Terminal Connection Active Event
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent 17095: Event: 196 is 219 for call 9434 Provider:AES3
12/10/2016 14:59:11:555 DEBUG - CTICallObserver.callChangedEvent:17095: got Terminal Connection Talking Event
12/10/2016 14:59:11:724 DEBUG - No callid found in CTIEnd
because of the ani, extension and information I can tell is the same call, but is getting there 4 minutes late, when asked before the response was 'no call info'
we got reports from AES experts and they say that the information is being sent timely by the AES, all servers are on NTP and have their time/date sync.
Any ideas on how to troubleshoot this issue . thanks in advance