We have a customer who is sometimes getting unexpected UUI "E" in OD application from aesconnector;

06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CallInfo.doGetCallInfo: Populating call info variable values...
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: Call ID 5984
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: Calling # (ANI) 2833
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: Called # (DNIS) 910450
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: Ext 950009
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: UCID 00001059431583471550
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: UUI E
06/03/2020 14:52:00:361 DEBUG - _UaiTbGD6NOaNueqLCeCh-T:/ANA_ATM : CTICommand.setCallInfoVariableValues: State established

It seems aesconnector is getting uui “E” from jtapi client like below;
[Bad case(aesconnector log)]
06/03/2020 14:51:59:700 DEBUG - CallInfoData.CallInfoData:950009: callid 5984
06/03/2020 14:51:59:700 DEBUG - CallInfoData.CallInfoData:950009: ani 2833
06/03/2020 14:51:59:700 DEBUG - CallInfoData.CallInfoData:950009: dnis 910450
06/03/2020 14:51:59:700 DEBUG - CallInfoData.CallInfoData:950009: ucid 00001059431583471550
06/03/2020 14:51:59:700 DEBUG - CallInfoData.CallInfoData:950009: uui E
06/03/2020 14:51:59:700 DEBUG - CTICallObserver.addCall 950009: added call to list
--
06/03/2020 14:51:59:741 DEBUG - CallInfoData.CallInfoData:950009: callid 5984
06/03/2020 14:51:59:741 DEBUG - CallInfoData.CallInfoData:950009: ani 2833
06/03/2020 14:51:59:742 DEBUG - CallInfoData.CallInfoData:950009: dnis 910450
06/03/2020 14:51:59:742 DEBUG - CallInfoData.CallInfoData:950009: ucid 00001059431583471550
06/03/2020 14:51:59:742 DEBUG - CallInfoData.CallInfoData:950009: uui E
06/03/2020 14:51:59:742 DEBUG - CTICallObserver.addCall 950009: added call to list

This issue rarely happens, and normally we get correct uui like below;

[Good case(aesconnector log)]
06/03/2020 14:45:42:829 DEBUG - CallInfoData.CallInfoData:950004: callid 5979
06/03/2020 14:45:42:829 DEBUG - CallInfoData.CallInfoData:950004: ani 2833
06/03/2020 14:45:42:829 DEBUG - CallInfoData.CallInfoData:950004: dnis 910450
06/03/2020 14:45:42:829 DEBUG - CallInfoData.CallInfoData:950004: ucid 00001059791583473538
06/03/2020 14:45:42:829 DEBUG - CallInfoData.CallInfoData:950004: uui ###########UCID=00001059431583471550
06/03/2020 14:45:42:829 DEBUG - CTICallObserver.addCall 950004: added call to list
--
06/03/2020 14:45:42:843 DEBUG - CallInfoData.CallInfoData:950004: callid 5979
06/03/2020 14:45:42:843 DEBUG - CallInfoData.CallInfoData:950004: ani 2833
06/03/2020 14:45:42:843 DEBUG - CallInfoData.CallInfoData:950004: dnis 910450
06/03/2020 14:45:42:843 DEBUG - CallInfoData.CallInfoData:950004: ucid 00001059791583473538
06/03/2020 14:45:42:843 DEBUG - CallInfoData.CallInfoData:950004: uui ###########UCID=00001059431583471550
06/03/2020 14:45:42:844 DEBUG - CTICallObserver.addCall 950004: added call to list


Regarding this, we got comment from AES team as below; Is this aesconnector issue?

///
> The following are the 2 DeliveredEvent for the good call and the bad call. The uui data in both of them are ‘2323232323232323232323554349443D3030303031303539343331353833343731 ...’, the same. But the AESConnector seems parse them different results. I would recommend you to reach out to the EP team for more help.

<good call>
<135>Mar 6 14:45:42 ccpaestk01 TSAPI[20464]: +09:00 2020 723 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 type uuiIa5Ascii,
<135>Mar 6 14:45:42 ccpaestk01 TSAPI[20464]: +09:00 2020 723 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 data '2323232323232323232323554349443D3030303031303539343331353833343731 ...'H
<135>Mar 6 14:45:42 ccpaestk01 TSAPI[20464]: +09:00 2020 723 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 },

<bad call>
<135>Mar 6 14:51:59 ccpaestk01 TSAPI[20464]: +09:00 2020 637 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 type uuiIa5Ascii,
<135>Mar 6 14:51:59 ccpaestk01 TSAPI[20464]: +09:00 2020 637 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 data '2323232323232323232323554349443D3030303031303539343331353833343731 ...'H
<135>Mar 6 14:51:59 ccpaestk01 TSAPI[20464]: +09:00 2020 637 1 com.avaya.aes | csta_trace:Thread 0xd5b58b40 },
///


Above logs are from a test and scenario is as below;
1) Agent receives call from external and the connection established.
2) Agent make a call to EP with TSAPI Client application to create conference for IVR authentication.
-> At this time Agent’s TSAPI application sets UUI and send it to aesconnector however it sometimes fails like above.
3) Disconnect from EP.
4) We keep the connection of step 1), and repeated 2) and 3) to reproduce the issue. (So ucid is all the same (00001059791583473538) for other calls during the test.)

And we have following logs;
- jtapi client trace
- aesconnector trace
- OD application trace

Thanks,

The "E" seems to come from the other end. The log in jtapi shows that:

2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - userInfo
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - {
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - type 4 < UUI_IA5_ASCII >
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - data "E"
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - }
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - deviceHistory

Hi Wilson,

We got below comment from AES team;

//
I further checked the data “E” in the JTAPI Client trace, almost all of them are from the ConnectionClearedEvent, but the the data ‘E’ in the AESConnector trace seems from the other events, not related to the ConnectionClearedEvent.
So I would still recommend you to reach out to the EP engineer to check from which AES event the AESConnector parses the ‘data “E” ’.
//

I also see that uui data "E" are appeared in ConnectionClearedEvent for all calls. (Not sure if this is right or wrong, but it is seen for all calls.)

2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - LucentV7ConnectionClearedEvent ::=
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - {
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - userInfo
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - {
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - type 4 < UUI_IA5_ASCII >
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - data "E"
2020-03-06 14:23:28,014 [DistributeCSTAEvent] DEBUG LucentPrivateData - }

Now for the bad call, Jtapi is receiving correct uui as below, so we see at least right uui comes at jtapi;

2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 9
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - connection
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - callID 5984
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - deviceID "950009"
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - }
...
2020-03-06 14:51:59,611 [DistributeCSTAEvent] DEBUG LucentPrivateData - userInfo
2020-03-06 14:51:59,611 [DistributeCSTAEvent] DEBUG LucentPrivateData - {
2020-03-06 14:51:59,611 [DistributeCSTAEvent] DEBUG LucentPrivateData - type 4 < UUI_IA5_ASCII >
2020-03-06 14:51:59,611 [DistributeCSTAEvent] DEBUG LucentPrivateData - data "###########UCID=00001059431583471550"
2020-03-06 14:51:59,611 [DistributeCSTAEvent] DEBUG LucentPrivateData - }

Now we found one thing. For the bad call, it seems that CSTAConferencedEvent comes before CSTAEstablishedEvent, whereas all good calls have CSTAEstablishedEvent before CSTAConferencedEvent. Is something to do for aesconnector to get wrong uui, e.g.,possibly getting uui “E” from ConnectionClearedEvent in previous callID if CSTAConferencedEvent comes before CSTAEstablishedEvent?

Below show the order of Established/Conferenced Event comes;
<Good>
2020-03-06 14:45:42,709 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 4 for TSProvider[#2]@c9bbdb57
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - CSTADeliveredEvent ::=
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 4
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - connection
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - callID 5979
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - deviceID "950004"
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:45:42,709 [GetEventThread] DEBUG TsapiSession - }
...
2020-03-06 14:45:42,903 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 4 for TSProvider[#2]@c9bbdb57
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - CSTAEstablishedEvent ::=
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 4
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - establishedConnection
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - callID 5979
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - deviceID "950004"
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:45:42,903 [GetEventThread] DEBUG TsapiSession - }
...
2020-03-06 14:45:43,535 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 4 for TSProvider[#2]@c9bbdb57
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - CSTAConferencedEvent ::=
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 4
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - primaryOldCall
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - callID 5978
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - deviceID "2833"
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - }
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - secondaryOldCall
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - callID 5979
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - deviceID "2833"
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:45:43,535 [GetEventThread] DEBUG TsapiSession - }

<Bad>
2020-03-06 14:51:59,609 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 9 for TSProvider[#2]@c9bbdb57
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - CSTADeliveredEvent ::=
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 9
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - connection
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - callID 5984
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - deviceID "950009"
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:51:59,609 [GetEventThread] DEBUG TsapiSession - }
...
2020-03-06 14:51:59,681 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 9 for TSProvider[#2]@c9bbdb57
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - CSTAConferencedEvent ::=
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 9
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - primaryOldCall
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - callID 5983
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - deviceID "2833"
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - }
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - secondaryOldCall
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - callID 5984
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - deviceID "2833"
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:51:59,681 [GetEventThread] DEBUG TsapiSession - }
...
2020-03-06 14:51:59,827 [GetEventThread] INFO TsapiSession - Received monitorCrossRefID 9 for TSProvider[#1]@d23f0e73
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - CSTAEstablishedEvent ::=
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - monitorCrossRefID 9
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - establishedConnection
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - {
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - callID 5984
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - deviceID "950009"
2020-03-06 14:51:59,827 [GetEventThread] DEBUG TsapiSession - devIDType 0 < STATIC_ID >
2020-03-06 14:51:59,828 [GetEventThread] DEBUG TsapiSession - }

Thanks,

I can assure you that EP has nothing to do with this. The calls show in JTAPI first before they get to AES Connector.