Guide to reading MIVR logs for Telephony Issues - IVR Call Flow

From DocWiki

(Difference between revisions)
Jump to: navigation, search
(Guide to reading MIVR logs for Telephony Issues - IVD Call Flow)
m (1 revision)
 

Latest revision as of 15:20, 9 April 2010

Guide to reading MIVR logs for Telephony Issues - IVR Call Flow

Problem Summary Reading MIVR logs - IVR Call Flow
Error Message NA
Possible Cause NA
Recommended Action

    The ENG debugs and SS_TEL debugs are enabled in the below call flow

    Call Offered at the Route Point. Call ImplID=4371/1, Route Point = 101112. JTAPI Event Received = CallCtlConnOfferedEv
    5620470: Jan 24 22:33:19.888 PST %MIVR-SS_TEL-7-UNK:Route Connection=[101112::1/(P1-jtapiPvdr_65_1) GCID=(1,4373)->ACTIVE]->OFFERED, reason=1, Event= (P1-jtapiPvdr_65_1) 4373/1 CallCtlConnOfferedEv 101112::1 [#417] Cause:100 CallCtlCause:100 CiscoCause:0 FeatReason:12 [#419] Cause:100 CallCtlCause:100 CiscoCause:0 FeatReason:12, cause=100, metacode=129, isMaster=true

    Call is received in CCX. id = internal call ID, implID = used to interact with JTAPI, App name - Application which is being triggered by the route point,cn - Called Number,cgn - Calling Number,atype - Arrival type for the call, it is DIRECT in this scenario,lrd - Last redirect number
    5620474: Jan 24 22:33:19.890 PST %MIVR-SS_TEL-7-UNK:Call.received() JTAPICallContact[id=6,implId=4373/1,state=STATE_RECEIVED_IDX,inbound=true,App name=AA,task=null,session=null,seq num=-1,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230600000000,DestProtocolCallRef=null,TP=null

    CTI port is selected for the call to be redirected to
    5620477: Jan 24 22:33:19.893 PST %MIVR-SS_TEL-7-UNK:Route Connection: [101112::1/(P1-jtapiPvdr_65_1) GCID=(1,4373)->ACTIVE]->OFFERED, CTI Port selected: TP[id=12,implId=6803,state=IN_USE]

    Call is associated with a CTI port. TP and session value is not null as it was in Call.received()
    5620489: Jan 24 22:33:19.911 PST %MIVR-SS_TEL-7-UNK:Call.associated() JTAPICallContact[id=6,implId=4373/1,state=STATE_RECEIVED_IDX,inbound=true,App name=AA,task=null,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]
    5620490: Jan 24 22:33:19.911 PST %MIVR-SS_TEL-7-UNK:Route Connection: [101112::1/(P1-jtapiPvdr_65_1) GCID=(1,4373)->ACTIVE]->OFFERED has 1 current sessions active.

    Call is Offered at the CTI Port, lastRedirectedAdress is the Route Point
    5620491: Jan 24 22:33:19.913 PST %MIVR-SS_TEL-7-UNK:CallID: 6, MediaID: 4373/1 CallCtlConnOfferedEv received for CTI Port: 6803, lastRedirectedAddress: 101112

    Call is disconnected at the route point as it was redirected to the CTI Port
    5620494: Jan 24 22:33:19.920 PST %MIVR-SS_TEL-7-UNK:RP[num=101112], conn=[101112::1/(P1-jtapiPvdr_65_1) GCID=(1,4373)->ACTIVE]->DISCONNECTED, event=(P1-jtapiPvdr_65_1) 4373/1 CallCtlConnDisconnectedEv 101112::1 [#441] Cause:100 CallCtlCause:210 CiscoCause:0 FeatReason:6 [#451] Cause:100 CallCtlCause:210 CiscoCause:0 FeatReason:6 [#453] Cause:100 CallCtlCause:210 CiscoCause:0 FeatReason:6, cause=CAUSE_NORMAL[100], meta=META_CALL_REMOVING_PARTY[131]


    Call is accepted at the CTI Port
    5620496: Jan 24 22:33:19.926 PST %MIVR-SS_TEL-7-UNK:CallID: 6, MediaID: 4373/1 Accepting call for CTI Route Point: 101112 on CTI Port: 6803, ciscoCause=0
    Call state changes to ACCEPTED
    5620497: Jan 24 22:33:19.929 PST %MIVR-SS_TEL-7-UNK:Call.accepted() JTAPICallContact[id=6,implId=4373/1,state=STATE_ACCEPTED_IDX,inbound=true,App name=AA,task=null,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]

    Call is Ringing at the CTI Port
    5620498: Jan 24 22:33:19.929 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1, TerminalConnection to Terminal: ccc_6803 is RINGING, [6803::1/(P1-jtapiPvdr_65_1) GCID=(1,4373)->ACTIVE]->ALERTING
    5620499: Jan 24 22:33:19.930 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 com.cisco.jtapi.CiscoTermInServiceEvImpl received

    Application Task is created
    5620500: Jan 24 22:33:19.930 PST %MIVR-APP_MGR-7-TASK_CREATED:Application task created: Application=App[name=AA,type=Cisco Script Application,id=2,desc=AA,enabled=true,max=10,valid=true,cfg=[ApplicationConfig[schema=ApplicationConfig,time=2010-01-25 06:11:39.0,recordId=7,desc=AA,name=AA,type=Cisco Script Application,id=2,enabled=true,sessions=10,script=SSCRIPT[aa.aef],defaultScript=,vars=[],defaultVars=null]]],Application Trigger=ContactApplicationTrigger[time=1264401199930,locale=en_US,cfg=JTAPITriggerConfig[schema=ApplicationTriggerConfig,time=2010-01-25 06:12:20.0,recordId=2,desc=Cisco JTAPI Trigger,name=101112,type=Cisco JTAPI Trigger,appName=AA,enabled=true,sessions=10,idleTimeout=5000,locale=en_US,parms={},taskGroups=[],controlClass=class com.cisco.call.CallControlChannel,controlGroupId=0,contactGroups=[GroupInfo[class=com.cisco.dialog.DialogChannel,id=0]],dn=101112,redirectCSS=redirecting.party,cmDeviceName=AutoAttendTrig,cmDeviceInvalid=false,cmDescription=AA Trigger,cmDevicePoolUUID={1B1B9EB6-7803-11D3-BDF0-00108302EAD1},cmDevicePoolName=Default,cmCallingSearchSpaceUUID=,cmCallingSearchSpaceName=None,cmLocationUUID={29C5C1C4-8871-4D1E-8394-0B9181E8C54D},cmLocationName=Hub_None,cmPartitionUUID=,cmPartitionName=None,cmVoiceMailProfileUUID=,cmVoiceMailProfileName=None,cmCallPickUpGroupUUID=,cmCallPickUpGroupName=,cmDisplay=,cmExternalPhNumMask=,cmFwdBusyVM=false,cmFwdBusyDest=,cmFwdBusyCSSUUID=,cmFwdBusyCSSName=None,cmAlertingNameAscii=,cmPresenceGroupUUID=ad243d17-98b4-4118-8feb-5ff2e1b781ac,cmPresenceGroupName=Standard Presence group],contact=JTAPICallContact[id=6,implId=4373/1,state=STATE_ACCEPTED_IDX,inbound=true,App name=AA,task=null,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]],Task id=41000000013,Task Class=com.cisco.wfframework.engine.core.WFEngineWorkflowDebugTask,New Task Class=com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
    The task is created for the call and the call is associated with the task ID
    5620521: Jan 24 22:33:19.948 PST %MIVR-SS_TEL-7-UNK:Call.attributed() JTAPICallContact[id=6,implId=4373/1,state=STATE_ATTRIBUTED_IDX,inbound=true,App name=AA,task=41000000013,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]
    5620522: Jan 24 22:33:19.948 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 associated with Task ID: 41000000013

    The application task starts executing
    620528: Jan 24 22:33:19.963 PST %MIVR-ENG-7-UNK:Execute step of Task 41000000013 : Start /* Auto Attendant Template ... */

    The application task executes the Accept Step to answer the call at the CTI Port
    5620530: Jan 24 22:33:19.963 PST %MIVR-ENG-7-UNK:Execute step of Task 41000000013 : Accept (--Triggering Contact--)

    Call on the CTI Port is active
    5620541: Jan 24 22:33:19.981 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013, TerminalConnection to Terminal: ccc_6803 is ACTIVE

    Call is answered at the CTI Port
    5620551: Jan 24 22:33:19.982 PST %MIVR-SS_TEL-7-UNK:Call.answered() JTAPICallContact[id=6,implId=4373/1,state=STATE_ANSWERED_IDX,inbound=true,App name=AA,task=41000000013,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]

    Media Related Events are received
    5620560: Jan 24 22:33:19.988 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 com.cisco.jtapi.CiscoRTPOutputStartedEvImpl received
    5620561: Jan 24 22:33:19.990 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 com.cisco.jtapi.CiscoRTPInputStartedEvImpl received

    Digits received
    5620726: Jan 24 22:33:27.989 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 Digit received: 1
    5620739: Jan 24 22:33:30.682 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 Digit received: 2
    5620740: Jan 24 22:33:31.380 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 Digit received: 0
    5620741: Jan 24 22:33:32.086 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 Digit received: 5
    5620742: Jan 24 22:33:32.761 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 Digit received: 3

    CiscoRTPInputStartedEv Call is getting redirected to another number
    5620778: Jan 24 22:33:39.429 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013, Redirecting to: 2053, Unconditional: false, ResetOrigCalledAddr:false, OrigCalledAddr:2053, CallingSearchSpace:redirecting.party

    Media is being stopped
    5620779: Jan 24 22:33:39.436 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 com.cisco.jtapi.CiscoRTPInputStoppedEvImpl received
    5620780: Jan 24 22:33:39.436 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 com.cisco.jtapi.CiscoRTPOutputStoppedEvImpl received

    Call is being transferred to 2053
    5620781: Jan 24 22:33:39.447 PST %MIVR-SS_TEL-7-UNK:Call.transferring(2053) JTAPICallContact[id=6,implId=4373/1,state=STATE_ANSWERED_IDX,inbound=true,App name=AA,task=41000000013,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]

    Call is dropped from the CTI Port
    5620782: Jan 24 22:33:39.463 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013 gets TermConnDroppedEv, meta code:132, cause code:100
    5620783: Jan 24 22:33:39.463 PST %MIVR-SS_TEL-7-UNK:CallID:6 MediaId:4373/1 Task:41000000013, TerminalConnection to Terminal: ccc_6803 is DROPPED, 4373/1

    5620784: Jan 24 22:33:39.463 PST %MIVR-SS_TEL-7-UNK:Call.abandoned() - transferring JTAPICallContact[id=6,implId=4373/1,state=STATE_ANSWERED_IDX,inbound=true,App name=AA,task=41000000013,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]

    Transfer to 2053 is complete


    5620786: Jan 24 22:33:39.484 PST %MIVR-SS_TEL-7-UNK:Call.transferred(2053) - transferring JTAPICallContact[id=6,implId=4373/1,state=STATE_TRANSFERRED_IDX,inbound=true,App name=AA,task=41000000013,session=21000000007,seq num=0,cn=101112,dn=101112,cgn=2039,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=101112,route=RP[num=101112],OrigProtocolCallRef=0000000000001115014C230700000000,DestProtocolCallRef=null,TP=6803]
Release Release 7.0(1) onwards
Associated CDETS # NA

Rating: 3.3/5 (3 votes cast)

Personal tools