Hi devconnect
I'm working on an application running on AEP 8.1.2, and compiled with AOD 8.1.2. the application uses aesconnector to get call information.
I've exported the runtime environment to the application server. I've got 90 H323 ports, I've made sure 90 extension are licensed, and all are configured in a hunt group.
The issue is that, for some calls the aesconnector is taking upto 6 seconds to return callinfo. This scenario was reviewed with AES and AEP BBE, but no errors were found.
Please look at the next example:
From application log we see a request at 12:10:49:151 for extension info (3204):
20/02/2023 12:10:49:151 DEBUG - 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend : CTICommand.execute: request to manager is
http://172.16.34.115:9080/aesconnector/CallInfoInitialCall?extension%3D3204&k=BfXTOrU3QhMSK5uKwPnJzmTzEGAAUaR85KdBV4bak%2Fk%3D
20/02/2023 12:10:49:151 DEBUG - 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend : CTICommand.execute: setting session cookie to 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend
From aesconnector trace we see the next message:
20/02/2023 12:10:49:162 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
20/02/2023 12:10:49:215 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
20/02/2023 12:10:54:163 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
20/02/2023 12:10:54:281 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
...
...
From aesconnector trace we see the information is available after 5 seconds :
20/02/2023 12:10:54:350 DEBUG - CTICallObserver.callChangedEvent: Number of events on extension 3204 is 17
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 0 is 101 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Active Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 1 is 106 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Created Event for id:6941
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: Saving most recent call created:6941
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204: call id is 6941
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204: ucid is 00001069411676938254
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204: setting 6941 to state: initiated
20/02/2023 12:10:54:351 DEBUG - CallInfoData.CallInfoData:3204: callid 6941
20/02/2023 12:10:54:351 DEBUG - CallInfoData.CallInfoData:3204: ani 4210
20/02/2023 12:10:54:351 DEBUG - CallInfoData.CallInfoData:3204: dnis 2900
20/02/2023 12:10:54:351 DEBUG - CallInfoData.CallInfoData:3204: ucid 00001069411676938254
20/02/2023 12:10:54:351 DEBUG - CallInfoData.CallInfoData:3204: uui
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204: added call to list
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204:cache is:false
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 2 is 105 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Connected Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 3 is 206 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: got Call Control Connection Established Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: found 2 connections
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 0 is 51
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 1 is 51
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: established both connections of call
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.updateCallState 3204: setting call:6941 to state:established
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 4 is 116 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Terminal Connection Created Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 5 is 115 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Terminal Connection Active Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 6 is 219 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: got Terminal Connection Talking Event
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: found 2 connections
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 0 is 51
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 1 is 51
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: established both connections of call
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.updateCallState 3204: setting call:6941 to state:established
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 7 is 106 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Created Event for id:6941
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent3204: Saving most recent call created:6941
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.addCall 3204: call id is 6941 is already added, returning call data
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 8 is 203 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:351 DEBUG - CTICallObserver.callChangedEvent:3204: got Call Control alerting Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.updateCallState 3204: setting call:6941 to state:ringing
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 9 is 104 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Alerting Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 10 is 105 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Connection Connected Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 11 is 206 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: got Call Control Connection Established Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: found 2 connections
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 0 is 51
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 1 is 51
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: established both connections of call
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.updateCallState 3204: setting call:6941 to state:established
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 12 is 116 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Terminal Connection Created Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 13 is 218 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Call Control Terminal Ringing Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 14 is 119 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Terminal Connection Ringing Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 15 is 115 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent3204: got Terminal Connection Active Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent 3204: Event: 16 is 219 for call 6941 Provider:AES2BT
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: got Terminal Connection Talking Event
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: found 2 connections
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 0 is 51
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: state of connection 1 is 51
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.callChangedEvent:3204: established both connections of call
20/02/2023 12:10:54:352 DEBUG - CTICallObserver.updateCallState 3204: setting call:6941 to state:established
20/02/2023 12:10:54:485 DEBUG - CallInfo:doGetCallInfo:Didn't find a matching call. Give CTI Connector time to process
20/02/2023 12:10:54:664 DEBUG - CTICallObserver.addCallToCache:caching call:6941
20/02/2023 12:10:54:664 DEBUG - CTICallObserver.getCallInfo: app is interested in call, setting MRCR:6941
After the aesconnector throws the above information, the application can populate callinfo values:
20/02/2023 12:10:54:664 DEBUG - 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend : CTICommand.execute: callinfo from Manager is callid=6941&ani=4210&dnis=2900&extension=3204&ucID=00001069411676938254&uui= &state=established
20/02/2023 12:10:54:664 DEBUG - 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend : CTICommand.processCallInfoResults: rawResponse: callid=6941&ani=4210&dnis=2900&extension=3204&ucID=00001069411676938254&uui=+&state=established
20/02/2023 12:10:54:664 DEBUG - 50D71724B5F943F18CA4757EBB61098F:/ivr-volaris-backend : CallInfo.doGetCallInfo: Populating call info variable values...
The AES analisis shows that the transaction for this call takes place in the same second.
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 TSERVER Src: DRVR
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 Login: "AEPuser" App Name: "Jtapi Client" SessionID: 122 Transport ID: 172.16.34.115
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 MonitorCrossRefID: 65
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 Driver: AVAYA#CMDUPLEX#CSTA-S#AES2BT
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 Message:
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 value EstablishedEvent ::=
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 establishedConnection
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 callID 6941,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceID "3204",
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 devIDType staticId
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 },
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 answeringDevice
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceID "3204",
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDType explicitPrivateLocalNumber,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDStatus idProvided
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 },
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 215 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 callingDevice
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceID "4210",
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDType explicitPrivateLocalNumber,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDStatus idProvided
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 },
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 calledDevice
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceID "2900",
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDType explicitPrivateLocalNumber,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDStatus idProvided
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 },
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 lastRedirectionDevice
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 {
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceID "2900",
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDType explicitPrivateLocalNumber,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 deviceIDStatus idProvided
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 },
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 localConnectionInfo csConnect,
<135>Feb 20 12:10:57 aes2bt TSAPI[23570]: -06:00 2023 216 1 com.avaya.aes | csta_trace:Thread 0x71ffb700 cause ecNewCall
Does anyone had has this issue before? could any one help me with this issue?
Regards!
