Solved: UCCX Callback feature fails

RamKumar40563 · ‎04-29-2021

Hello All,

I have been trying to get the callback feature working for one of our customers in their UCCX setup. Unfortunately, it fails. I have tried lot of iteration to keep the script simple and have also done lot of trail and error but nothing seems to be working at the moment.

When I checked the logs, the script is able to receive the callback number, check the length and prompt the user to record a callback message if needed, right after this a second call should be placed from this script to the ghost script to check agent availability and connect with customer accordingly, but this is where the issue seems to be.

The user disconnects the call after providing the callback number and the system just terminates the call and releases the session. which is normal, but I'm trying to figure out why it is not initiating the callback using place call step.

FYI: I'm using different CCG for both the Triggers.

This is impacting out customer since I have been trying to get this working for over a month. Any help is much appreciated!!!!

MIVR Logs where the call is getting disconnected and the session gets terminated:

24922948: Apr 28 15:50:16.119 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: #
24922949: Apr 28 15:50:16.335 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 5
24922952: Apr 28 15:50:16.643 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 7
24922956: Apr 28 15:50:16.854 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 7
24922957: Apr 28 15:50:17.158 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: #
24922960: Apr 28 15:50:17.552 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 8
24922961: Apr 28 15:50:17.823 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 9
24922962: Apr 28 15:50:18.011 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 9
24922966: Apr 28 15:50:18.381 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: #
24922967: Apr 28 15:50:18.381 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Set Enterprise Call Info (--Triggering Contact--) Variables Used:CB_Successful
24922969: Apr 28 15:50:18.382 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : pCallBackNumber = Create Generated Prompt telephone.number (CallBackNumber)
24922970: Apr 28 15:50:18.382 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Explicit Confirmation (--Triggering Contact--, pConfirmation_Start + pCallBackNumber + pConfirmation_End)
24923839: Apr 28 15:50:30.880 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 Digit received: 1
24923840: Apr 28 15:50:31.087 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Set ExplicitConf = "True"
24923841: Apr 28 15:50:31.087 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Set Enterprise Call Info (--Triggering Contact--) Variables Used:ExplicitConf
24923843: Apr 28 15:50:31.087 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : If (CallBackNumber.length() == 7) Then
24923845: Apr 28 15:50:31.087 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Set out_callbackno = 81 + CallBackNumber
24923846: Apr 28 15:50:31.087 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : Set Enterprise Call Info (--Triggering Contact--) Variables Used:out_callbackno
24923850: Apr 28 15:50:31.088 EDT %MIVR-ENG-7-UNK: [MIVR_ENG_TASKS-31-39-TASK:0xab5d0e884_MS_Script_LSI_04272021.aef] com.cisco.wfapi.impl.WFTracingLogImpl Execute step of Task 46000040068 : RecordMessage = Recording (--Triggering Contact--, pRecordCBMessage, 30)
24924032: Apr 28 15:50:42.227 EDT %MIVR-SS_TEL-7-UNK: [(P1-192.168.101.10) EventThread] com.cisco.wf.subsystems.jtapi.TAPIPortGroup.Port.InCallObserverImpl CallID:35787 MediaId:135293/1 Task:46000040068 com.cisco.jtapi.CiscoRTPInputStoppedEvImpl received
24924034: Apr 28 15:50:42.227 EDT %MIVR-SS_TEL-7-UNK: [(P1-192.168.101.10) EventThread] com.cisco.wf.subsystems.jtapi.TAPIPortGroup.Port.InCallObserverImpl CallID:35787 MediaId:135293/1 Task:46000040068 com.cisco.jtapi.CiscoRTPOutputStoppedEvImpl received
24924058: Apr 28 15:50:43.336 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068 gets TermConnDroppedEv, meta code:132, cause code:100
24924059: Apr 28 15:50:43.336 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.executor.impl.ExecutorStubImpl.RequestImpl CallID:35787 MediaId:135293/1 Task:46000040068, TerminalConnection to Terminal: UCCX_7722 is DROPPED, 135293/1
24924061: Apr 28 15:50:43.340 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.wf.subsystems.jtapi.CallImpl Call.abandoned() JTAPICallContact[id=35787,implId=135293/1,state=STATE_ABANDONED_IDX,inbound=true,App name=0155_Corp_Test,task=46000040068,session=144000028410,seq num=0,cn=0156,dn=0156,cgn=8993,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=0156,route=RP[num=0156],OrigProtocolCallRef=000000000002107D01E906E800000000,DestProtocolCallRef=000000000002107D01E906E600000000,TP=7722]
24924062: Apr 28 15:50:43.340 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.wf.subsystems.jtapi.TAPIPortGroup.Port.InCallObserverImpl CallID:35787 MediaId:135293/1 Task:46000040068, released TP[type=Cisco CTI Port,id=52,implId=7722,active=false,state=IDLE] from 0156, and releasing udpPort 26766
24924063: Apr 28 15:50:43.340 EDT %MIVR-SS_TEL-7-UNK: [MIVR_SS_TEL_PORT_QEXE_7722-139-222-TERM_CONN_EV:7722] com.cisco.wf.subsystems.jtapi.TAPIPortGroup.Port.InCallObserverImpl CallID:35787 MediaId:135293/1 Task:46000040068 com.cisco.jtapi.TermObservationEndedEvImpl received
24924077: Apr 28 15:50:45.338 EDT %MIVR-LIB_EVENT-5-TOO_LONG_IN_QUEUE: [MIVR_CONTACT_MGR_CLOCK-9-0-FINAL_EVENT_35787] com.cisco.manager.impl.ManagerManagerImpl.EventLoggerImpl Event queue time exceeded: Event=com.cisco.call.CallEvent[CALL_DISCONNECTED,state=CALL_DISCONNECTED,isRemote=true,task=AppTask[id=0xab5d0e884,time=1619639396457,state=ABORTED,exception=com.cisco.contact.ContactInactiveException: Contact id: 35787, Channel id: 53, Contact is in Terminated/Connected state,active=false,aborting=com.cisco.contact.ContactInactiveException: Contact id: 35787, Channel id: 53, Contact is in Terminated/Connected state,app=App[name=0155_Corp_Test,type=Cisco Script Application,id=98,desc=0155_Corp,enabled=true,max=50,valid=true,cfg=[ApplicationConfig[schema=ApplicationConfig,time=2021-04-27 07:28:04.0,recordId=1565,desc=0155_Corp,name=0155_Corp_Test,type=Cisco Script Application,id=98,enabled=true,sessions=50,surveyName=,dispatchId=,script=SCRIPT[MS_Script_LSI_04272021.aef],defaultScript=,surveyS...
24924077: Apr 28 15:50:45.338 EDT %MIVR-LIB_EVENT-5-TOO_LONG_IN_QUEUE: [MIVR_CONTACT_MGR_CLOCK-9-0-FINAL_EVENT_35787] com.cisco.manager.impl.ManagerManagerImpl.EventLoggerImpl Event queue time exceeded: Event=com.cisco.call.CallEvent[CALL_DISCONNECTED,state=CALL_DISCONNECTED,isRemote=true,task=AppTask[id=0xab5d0e884,time=1619639396457,state=ABORTED,exception=com.cisco.contact.ContactInactiveException: Contact id: 35787, Channel id: 53, Contact is in Terminated/Connected state,active=false,aborting=com.cisco.contact.ContactInactiveException: Contact id: 35787, Channel id: 53, Contact is in Terminated/Connected state,app=App[name=0155_Corp_Test,type=Cisco Script Application,id=98,desc=0155_Corp,enabled=true,max=50,valid=true,cfg=[ApplicationConfig[schema=ApplicationConfig,time=2021-04-27 07:28:04.0,recordId=1565,desc=0155_Corp,name=0155_Corp_Test,type=Cisco Script Application,id=98,enabled=true,sessions=50,surveyName=,dispatchId=,script=SCRIPT[MS_Script_LSI_04272021.aef],defaultScript=,surveyS...

RamKumar40563 · ‎04-29-2021

Hello All,

Thank You for your response, I was able to figure out the issue after hours of reactive debugging. The callback fails only when callers disconnect the call after recording their message. UCCX considers this as a abandoned/terminated call by caller.

In this scenario, callback won't be initiated by the script. I had to make couple of changes to the script like disconnecting the call from script using terminate step, right after acquiring the callback number. In this scenario, the system won't consider the call as abandoned call and it would initiate a callback. I tested the script couple of times and I did receive callbacks post changes.

Thank You all for your inputs. Appreciate it.

Regards

Ram Kumar

View solution in original post

Sean Lynch · ‎04-29-2021

Ram,

I just took a quick look at the log and stepped through the script items. Does the application crash at the same point while doing an interactive debug? It stops at the record prompt step. Your call control group for the CTI ports may not have the proper media configured to handle this step.

Please check.

Hope this helps.

-Sean

Elliot Dierksen · ‎04-29-2021

Are you sure that the CSS that is assigned to the CTI ports has the ability to dial the number you are calling? https://CUCM/dna is your friend to check that out.

RamKumar40563 · ‎04-29-2021

Hello All,

Thank You for your response, I was able to figure out the issue after hours of reactive debugging. The callback fails only when callers disconnect the call after recording their message. UCCX considers this as a abandoned/terminated call by caller.

In this scenario, callback won't be initiated by the script. I had to make couple of changes to the script like disconnecting the call from script using terminate step, right after acquiring the callback number. In this scenario, the system won't consider the call as abandoned call and it would initiate a callback. I tested the script couple of times and I did receive callbacks post changes.

Thank You all for your inputs. Appreciate it.

Regards

Ram Kumar