« Back to CVP - All Versions

CVP send to VRU failing

Combination View Flat View Tree View
Threads [ Previous | Next ]
I have following situation and will appreciate any helpful clues and advises please;

Call Flow

- Dialing an RP from CUCM (53051)
- Hitting ICM script
- Script has Send to VRU node so ICM issues a VRU label back to CUCM (599991)
- CUCM is passing the Label back to CUSP
- CUSP is routing the label to CVP
- CVP passes it back to ICM and ICM then issues VRU label for CVP back (666601)
- CVP consults CUSP and passes it to VXML GW
- VXML GW dial peer is matched and triggers boot strap.tcl
- However after this I see dialogue failure on Router and CVP PG.
 
DNIS lenght configured on CVP Call Servers = 6
 
Some quick logs;

Call Router:

16:42:45 Trace: (65543 x 0 : 0 0) NewCall: CID=(150180,58218815), DN=53051, ANI=3295, CED=, RCID=5000, MRDID=1, CallAtVRU=0, OpCode=0
16:42:45 Trace: (65543 x 10026 : 0 0) TransferToVRU: Label=599991, CorID=10026, VRUID=5000, RCID=5000 [This is sent back to CUCM]
16:42:45 Trace: (65543 25 10026 : 0 0) RequestInstr: CID=(150180,58218815), CallState=1
16:42:45 Trace: (25 25 10027 : 0 0) TransferToVRU: Label=666601, CorID=10027, VRUID=5000, RCID=5001 [This is sent to CVP and then VXML GW trigerring bootstrap.tcl]
16:42:45 Trace: (25 25 10027 : 0 0) CallEventReport: CID=(150180,58218815),Event=DISCONNECT, DlgEnds=1, FromVRU=0, CallState=1, Cause=NORMAL
16:42:45 Trace: (25 25 10027 : 0 0) Deleting Dialog.

VRU PG OPC

16:42:45 Trace: CSTA_DELIVERED(PID=5001):  Conn=(CID=25,Dev=,Type=Static)AlertingDev=ID_NOT_KNOWN CallingDev=(TRUNK)6553600 CalledDev=(DEV)599991 LastRedirDev=ID_NOT_KNOWN  localConnInfo(1)=CS_INITIAT
E cause=-1
16:42:45 Trace: Trunk::SetCall - trunk assigned to call (CallID=25(0xbf70f0) TG=200 trunkNum=6553600 trunkObject=0x2077300).
16:42:45 Trace: Call::SetTrunk assigning  TG=200 TrunkNum=6553600 TrunkObj=0x2077300 to call 25(0xbf70f0)
16:42:45 Trace: VRUPrivateCallDeliveredData_t: Svc=2 uui="" ani="3295" DID=25 ptid=""
16:42:45 Trace: AssignTarget(PID=5001): Trying to assign to non-configured service 2 to call 25.
16:42:45 Trace: Call:SetCallState (PID=5001) - CallID=25(0xbf70f0)[SrcDev() DestDev()] NewState=NULL OldState=NONE.
16:42:45 Trace: SendINRCMessage: REQUEST_INSTRUCTION  RCID=5001 PID=5001 DID=25 DIDRelSeq#=1 CorrID=10026 CalledParty#= CallingParty#=3295 CallGUID=8F6C3600000100000000010746A0650A PstnTrkGrp(ID=10.101.160.70 ,Chann#=2147483647)
16:42:45 Trace: ProcessINRCMsgs - BEGIN Msg=24 src=48 dest=1 flag=3 size=52
16:42:45 Trace: SendPIMINRCMessage: VRU_QUEUE_SERVICE  RCID=5001 PID=5001 DID=25 DIDRelSeq#=0 RtrDate=150180 RtrCID=58218815 RCKSeq#=2 STID=-1 RouteID=0
16:42:45 Trace: ProcessINRCMsgs - END Msg=24 src=48 dest=1 flag=3
16:42:45 Trace: ProcessINRCMsgs - BEGIN Msg=8 src=48 dest=1 flag=3 size=384
16:42:45 Trace: SendPIMINRCMessage: CONNECT  RCID=5001 PID=5001 DID=25 DIDRelSeq#=1 CRS(RtrDate=150180,RtrCID=58218815) RCKSeq#=1 ErrorCode=0 TRTargetID=-1 CorrID=10027 EventSel=119 SvcType=4 NICCallID={PCID=5001,RCID=5001,Remote=0,0,DID=0x19,RemDID=0x0,Grp=0,Data=0,RtrData=0,CCID=x00000001/x00000000} PGCallID={N/A} OperationCode=CLASSIC OperationFlags=COOP_NONE NetworkTransferEnabled=F Label(Type=8)=666601 NICCalledParty#=53051 SGSTID=-1 SvcSTID=-1 AGSTID=-1 AGInfo= CallGUID=8F6C3600000100000000010746A0650A
16:42:45 Trace: ProcessINRCMsgs - END Msg=8 src=48 dest=1 flag=3
16:42:45 Trace: ProcessINRCPIMMessage - CALL_EVENT_REPORT received cause code 1
16:42:45 Trace: SendINRCMessage: CALL_EVENT_REPORT  RCID=5001 PID=5001 DID=25 DIDRelSeq#=2 LabelIndex=0 Event=6 DialogEnds=1 Cause=1
16:42:45 Trace: CSTA_CALL_CLEARED(PID=5001):  clearedCall=(CID=25,Dev=,Type=Static) localConnInfo(-1)=CS_NONE cause=1013
16:42:45 Trace: VRUPrivateCallClearedData_t: CRSCallID_Date=150180 CRSCallID_ID=58218815 CRSCallID_Seq#:2 CallTypeID=5002 NICCalledParty#=53051 ECCSize=53
16:42:45 Trace: Call:SetCallState (PID=5001) - CallID=25(0xbf70f0)[SrcDev() DestDev()] NewState=NONE OldState=NULL.
16:42:45 Trace: Cleared(PID=5001): CallObj=(0xbf70f0)  SrcConn(CID=25,Dev=,DevType=Static) DestConn(CID=-1,Dev=,DevType=Unknown)
16:42:45 Trace: Call:Cleared - No src or dest agent associated with this CallID=25(0xbf70f0).
16:42:45 Trace: ClearTrunk: CID=25 CallObj=0xbf70f0 Removing Trunk Assignment (TG=200 TrunkNum=6553600 m_Trunk=0x2077300)
16:42:45 Trace: Trunk::ClearCall - trunk removed from call (CallID=25(0xbf70f0) TG=200 trunkNum=6553600 TrunkObj=0x2077300).
16:42:45 Trace: BuildClosedCallRecord: CallObj=0xbf70f0 DateTime=03/07 16:42:45 IntervalDatetime=03/07/2012 16:30:00
16:42:45 Trace:  BuildClosedCallRecord(PID=5001): MRDomainID=1 CID=25 RCK(RtrDate=150180,RtrCID=58218815) RCKSeq#=2 CD=13(DBCD_DROP_HANDLED_PRIMARY_ROUTE) CDF=1(DBCDF_HANDLED) PeriphCallType=1,DBCD_ACD_IN AppTaskCD=0 ICRCK=268435461, ICRCKParent=-1 ICRCKChild=-1 NetworkTime=0 Duration=1 RingTime=0 DelayTime=1 TimeToAband=1 HoldTime=0 TlkTime=0 WorkTime=0 LocalQTime=0 NetworkQTime=0 BillRate=-1 SegmentTime=-1 NewTransaction=78 RouteID=-1 AGSTID=-1() SGSTID=-1(0xffffffff) SvcSTID=-1(-1) RoutedAGSGID=0 RoutedSGSTID=0 RoutedSvcSTID=0 SRCAGSTID=-1() DigDialed=53051 NetworkTID=-1 TrkGID=5001(200) InstPort#=-1 DNIS=599991 UUIDatar=(null) AnsWithinSvcLevel=N ConfTime=0 Priority=-1 Trk=-1 BadCallTag=N CallTypeID=5002 CED=(null) ANI=3295 WrapupData=(null) ECCSize=53 NetworkConsult=FALSE CallGUID=8F6C3600000100000000010746A0650A LocationParamPKID= LocationParamName= PstnTrkGrpID=10.101.160.70  PstnTrkGrpChann#=1234616 CallOrginiated=0 CallReferenceID=(null) ProtocolID=2 ApplicationData='\0'
16:42:45 Trace: BuildClosedCallRecord(PID=5001): CID=25 RCK(RtrDate=150180,RtrCID=58218815) PV1=(null) PV2=(null) PV3=(null) PV4=(null) PV5=(null) PV6=(null) PV7=(null) PV8=(null) PV9=(null) PV10=(nul
l)16:42:45 Trace: BuildClosedCallRecord:
Name                           Type        Index    Value
user.microapp.app_media_lib    Scalar               ..
user.microapp.input_type       Scalar               D
user.microapp.locale           Scalar               en-us
user.microapp.media_server     Scalar               http://mediaserver
user.microapp.sys_media_lib    Scalar               ..
16:42:45 Trace: ProcessINRCMsgs - BEGIN Msg=17 src=48 dest=1 flag=3 size=30
16:42:45 Trace: SendPIMINRCMessage: DIALOG_FAIL  RCID=5001 PID=5001 FailureType=2 NumOfEvents=1 DID=25 DIDRelSeqNo=2 ReasonCode=18
16:42:45 Trace: ProcessINRCMsgs - END Msg=17 src=48 dest=1 flag=3
16:42:48 Trace: CSTA_DELIVERED(PID=5002):  Conn=(CID=7,Dev=,Type=Static)AlertingDev=ID_NOT_KNOWN CallingDev=(TRUNK)6553600 CalledDev=(DEV)599991 LastRedirDev=ID_NOT_KNOWN  localConnInfo(1)=CS_INITIATE cause=-1
16:42:48 Trace: Trunk::SetCall - trunk assigned to call (CallID=7(0x217cc30) TG=200 trunkNum=6553600 trunkObject=0x20de608).
16:42:48 Trace: Call::SetTrunk assigning  TG=200 TrunkNum=6553600 TrunkObj=0x20de608 to call 7(0x217cc30)
16:42:48 Trace: VRUPrivateCallDeliveredData_t: Svc=2 uui="" ani="3295" DID=7 ptid=""
16:42:48 Trace: AssignTarget(PID=5002): Trying to assign to non-configured service 2 to call 7.
16:42:48 Trace: Call:SetCallState (PID=5002) - CallID=7(0x217cc30)[SrcDev() DestDev()] NewState=NULL OldState=NONE.
16:42:48 Trace: SendINRCMessage: REQUEST_INSTRUCTION  RCID=5002 PID=5001 DID=7 DIDRelSeq#=1 CorrID=10028 CalledParty#= CallingParty#=3295 CallGUID=9135F980000100000000010846A0650A PstnTrkGrp(ID=10.101.160.70 ,Chann#=2147483647)
16:42:48 Trace: ProcessINRCMsgs - BEGIN Msg=24 src=48 dest=1 flag=3 size=52
16:42:48 Trace: SendPIMINRCMessage: VRU_QUEUE_SERVICE  RCID=5002 PID=5001 DID=7 DIDRelSeq#=0 RtrDate=150180 RtrCID=58218816 RCKSeq#=2 STID=-1 RouteID=0
16:42:48 Trace: ProcessINRCMsgs - END Msg=24 src=48 dest=1 flag=3
16:42:48 Trace: ProcessINRCMsgs - BEGIN Msg=8 src=48 dest=1 flag=3 size=384
16:42:48 Trace: SendPIMINRCMessage: CONNECT  RCID=5002 PID=5001 DID=7 DIDRelSeq#=1 CRS(RtrDate=150180,RtrCID=58218816) RCKSeq#=1 ErrorCode=0 TRTargetID=-1 CorrID=10029 EventSel=119 SvcType=4 NICCallID={PCID=5001,RCID=5002,Remote=0,0,DID=0x7,RemDID=0x0,Grp=0,Data=0,RtrData=0,CCID=x00000001/x00000000} PGCallID={N/A} OperationCode=CLASSIC OperationFlags=COOP_NONE NetworkTransferEnabled=F Label(Type=8
)=666601 NICCalledParty#=53051 SGSTID=-1 SvcSTID=-1 AGSTID=-1 AGInfo= CallGUID=9135F980000100000000010846A0650A
16:42:48 Trace: ProcessINRCMsgs - END Msg=8 src=48 des

CVP Call Server

620: 10.101.160.79: Mar 07 2012 16:42:45.399 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DATAI.3} Found an incoming CISCO-GUID hdr : 2406233600-0000065536-0000000263-1184916746, Generated a new CVP-ID hdr : 8F6C3600000100000000010746A0650A 
621: 10.101.160.79: Mar 07 2012 16:42:45.399 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DATAI.3} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : Display Name ["Kcom-3295"] Is Using Survivability CallServer build CVP_8_5_1_0_0_0_312 
622: 10.101.160.79: Mar 07 2012 16:42:45.399 +0000: %CVP_8_5_SIP-7-PARAM:  {Thrd=DATAI.3} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : ReqURI (DN) sip:59999110026@CVP.MARSHALLS.CO.UK FromURI sip:3295@10.101.160.70 Video:false m_needs_postcallsurvey:false 
623: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DATAI.3} NEW CALL with guid=8F6C3600000100000000010746A0650A legid=8f6c3600-f5719005-107-46a0650a dn=59999110026 ani=3295 uui=null calldate=Wed Mar 07 16:42:45 GMT 2012 video=false cachecallcontext = false is_postcallsurvey = false RouterCallKey = null RouterCallKeyDay = null RouterCallKeySequenceNumber = null 
624: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DATAI.3} Sending msg:>>HEADERS: (JMSType)=MsgBus:NEW_CALL (JMSDestination)=Topic(CVP.SIP.CC.REQ) (JMSTimestamp)=1331138565415 >>BODY: replyto=true callguid=8F6C3600000100000000010746A0650A ani=3295 dnis=59999110026 timezone=Europe/London version=CVP_8_5 pstntrkgrpsrcip=10.101.160.70 calldate=Wed Mar 07 16:42:45 GMT 2012 calltypeid=4 localOffset=0 calllegid=8f6c3600-f5719005-107-46a0650a  >>STATE: isTabular=false isWriteable=true cursor=-1 
682: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-15-ICM-95} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = -1 - Processing ,, [MsgBus:NEW_CALL],   ssId=SYS_SIP2,   mediaType=,   location=,   locationpkid=,   locationsiteid=,   srcaddr=10.101.160.70,   pstntrunkgroupid=10.101.160.70 ,   pstntrunkgroupchannelnum=2147483647,   sipheader=,   rckey=,   rcday=,   rcseq=,   uui=,   calltypeid=4,   CallContext:,     user.media.id: 8F6C3600000100000000010746A0650A,, LEGID = null, DNIS = -1, ANI = -1 
683: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-15-ICM-95} CALLGUID = 8F6C3600000100000000010746A0650A - Correlation ID routed call 
684: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-15-ICM-95} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Publishing ,, [ICM_REQUEST_INSTRUCTION],   dialogueId=25,   sendSeqNo=1,   trunkGroupId=200,   trunkNumber=0,   serviceId=2,   uui=,   correlationId=10026,   location=,   locationpkid=,   pstntrunkgroupid=10.101.160.70 ,   pstntrunkgroupchannelnum=2147483647,   sipheader=,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
685: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-16-ICM-96} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Processing ,, [ICM_TEMPORARY_CONNECT],   dialogueId=25,   sendSeqNo=1,   label=666601,   correlationId=10027,   callguid=8F6C3600000100000000010746A0650A,   rckey=58218815,   rcday=150180,   rcseq=2,   CallContext:,     user.microapp.input_type: D,     user.microapp.locale: en-us,     user.microapp.app_media_lib: ..,     user.microapp.sys_media_lib: ..,     user.microapp.media_server: http://mediaserver,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
686: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-16-ICM-96} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Publishing ,, [MsgBus:CONNECT],   ssId=SYS_SIP2,   labelType=,   label=666601,   correlationId=10027,   command=null,   rckey=58218815,   rcday=150180,   rcseq=2,   CallContext:,     user.microapp.input_type: D,     user.microapp.locale: en-us,     user.microapp.app_media_lib: ..,     user.microapp.sys_media_lib: ..,     user.microapp.media_server: http://mediaserver,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
625: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-17-SIP-418} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - Handling CONNECT :>>HEADERS: (JMSType)=MsgBus:CONNECT (JMSDestination)=Topic(CVP.ICM.CC.RESP.SYS_SIP2) (JMSTimestamp)=1331138565415 (ServerID)=mar-hal-cvp01.SYS_ICM2:ICM:ICM2:mar-hal-cvp01.MsgBus002 >>BODY: callguid=8F6C3600000100000000010746A0650A RouterCallKey=58218815 floatingvars=>>HEADERS: (JMSType)=MsgBus:FLOATINGVARS >>BODY: callvars=[, , , , , , , , , ] user.microapp.app_media_lib=.. user.microapp.media_server=http://mediaserver user.microapp.FromExtVXML=[null, null, null, null] user.microapp.sys_media_lib=.. user.microapp.ToExtVXML=[null, null, null, null, null] user.microapp.locale=en-us user.microapp.input_type=D  >>STATE: isTabular=false isWriteable=true cursor=-1 dnis=59999110026 correlationid=10027 timezone=Europe/London RouterCallKeySequenceNumber=2 version=CVP_8_5 RouterCallKeyDay=150180 labeltype=-1 label=66660110027 localOffset=0 calllegid=8f6c3600-f5719005-107-46a0650a  >>STATE: isTabular=false isWriteable=false cursor=-1 
626: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-17-SIP-418} Using Outbound Proxy for sip:66660110027@10.101.160.235:5060 
627: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-17-SIP-418} Found an incoming CISCO-GUID hdr : 2406233600-0000065536-0000000263-1184916746, Found an existing CVP-ID hdr: 8F6C3600000100000000010746A0650A 
628: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-17-SIP-418} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : INVITE TO <sip:66660110027@10.101.160.235:5060;transport=udp> FROM "Kcom-3295" <sip:3295@10.101.160.79:5060> EXPIRES[60] 100REL 
629: 10.101.160.79: Mar 07 2012 16:42:45.415 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Invitation proceeding 100 
630: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Invitation accepted - ack'ing 
631: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-18-SIP-419} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : Updated by : CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : with event type INV_ACCEPTED 
632: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-18-SIP-419} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : Send the 200 OK back to caller with SDP of this dialog. 
633: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-18-SIP-419} Sending BUS MSG:>>HEADERS: (JMSType)=MsgBus:CALL_STATE_EVENT (JMSDestination)=Topic(CVP.SIP.CC.EVENT) (JMSTimestamp)=1331138565431 >>BODY: callguid=8F6C3600000100000000010746A0650A RouterCallKey=58218815 RouterCallKeySent=false causecode=0 timezone=Europe/London RouterCallKeySequenceNumber=2 version=CVP_8_5 labeltype=-1 RouterCallKeyDay=150180 calldate=Wed Mar 07 16:42:45 GMT 2012 label=66660110027 localOffset=0 eventid=4 calllegid=8F6C3600000100000000010746A0650A-133113856541523  >>STATE: isTabular=false isWriteable=true cursor=-1 
687: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-19-ICM-97} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = -1 - Processing ,, [MsgBus:CALL_STATE_EVENT],   ssId=SYS_SIP2,   eventId=ANSWER,   causeCode=NONE,, LEGID = null, DNIS = 59999110026, ANI = 3295 
688: 10.101.160.79: Mar 07 2012 16:42:45.431 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-19-ICM-97} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Publishing ,, [ICM_EVENT_REPORT],   dialogueId=25,   sendSeqNo=2,   eventId=ANSWER,   causeCode=NONE,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
634: 10.101.160.79: Mar 07 2012 16:42:45.446 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : DsSipInviteDialog ack'ed 
635: 10.101.160.79: Mar 07 2012 16:42:45.446 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-20-SIP-420} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Updated by : CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : with event type INV_ACKED 
636: 10.101.160.79: Mar 07 2012 16:42:45.446 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-20-SIP-420} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Acked the invite. 
637: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - DURATION (msecs) = 63 - DIALOG TERMINATED. Reason: Q.850;cause=47
 
638: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} Sending BUS MSG:>>HEADERS: (JMSType)=MsgBus:CALL_STATE_EVENT (JMSDestination)=Topic(CVP.SIP.CC.EVENT) (JMSTimestamp)=1331138565462 >>BODY: callguid=8F6C3600000100000000010746A0650A RouterCallKey=58218815 RouterCallKeySent=true causecode=1 timezone=Europe/London RouterCallKeySequenceNumber=2 version=CVP_8_5 labeltype=-1 RouterCallKeyDay=150180 calldate=Wed Mar 07 16:42:45 GMT 2012 label=66660110027 localOffset=0 eventid=6 calllegid=8f6c3600-f5719005-107-46a0650a  >>STATE: isTabular=false isWriteable=true cursor=-1 
639: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-21-SIP-421} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Updated by : CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8f6c3600-f5719005-107-46a0650a - : with event type TERMINATED 
640: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-21-SIP-422} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - DURATION (msecs) = 47 - HANGUP with Call History 
641: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=pool-1-thread-21-SIP-422} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - : Terminated with Q.850;cause=16 
689: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-23-ICM-98} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Processing ,, [MsgBus:CALL_STATE_EVENT],   ssId=SYS_SIP2,   eventId=DISCONNECT,   causeCode=NORMAL_COMPLETION,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
690: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-23-ICM-98} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Publishing ,, [ICM_EVENT_REPORT],   dialogueId=25,   sendSeqNo=3,   eventId=DISCONNECT,   causeCode=NORMAL_COMPLETION,, LEGID = 8f6c3600-f5719005-107-46a0650a, DNIS = 59999110026, ANI = 3295 
691: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-23-ICM-98} CALLGUID = 8F6C3600000100000000010746A0650A, DLGID = 25 [SIP_LEG_PRERTE_CORRID] - Deleted dialogue. Duration: 0 hrs, 0 mins, 0 secs, 47 msecs 
692: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_ICM-7-CALL:  {Thrd=pool-1-thread-23-ICM-98} CALLGUID = 8F6C3600000100000000010746A0650A - Deleted call.  Duration: 0 hrs, 0 mins, 0 secs, 47 msecs 
642: 10.101.160.79: Mar 07 2012 16:42:45.462 +0000: %CVP_8_5_SIP-7-CALL:  {Thrd=DIALOG_CALLBACK.2} CALLGUID = 8F6C3600000100000000010746A0650A LEGID = 8F6C3600000100000000010746A0650A-133113856541523 - DURATION (msecs) = 47 - DIALOG TERMINATED. Reason: Q.850;cause=86
 
VXML GW (Debug voice ccapi all)

ar  7 15:54:19.125: len=2, reqHeader[0].attr.datap=To
Mar  7 15:54:19.125: len=50, reqHeader[0].value.datap=<sip:6666011010@10.101.160.235:5060;transport=udp>
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccGetCallActiveByCallID:
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccGetAvlistProtoHeader:
   tag=41, reqHeader=2AC03DF8, reqCount=1, sess_protocol=SIP
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccDumpAttrValuePair:
  
Mar  7 15:54:19.125: len=10, reqHeader[0].attr.datap=X-CallInfo
Mar  7 15:54:19.125: len=0, reqHeader[0].value.datap=
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccGetSetupIndProtoHeader:
   tag=41, instance=0, sess_protocol=SIP
Mar  7 15:54:19.125: //-1/xxxxxxxxxxxx/CCAPI/ccCopyValuesToReqHeaders:
   reqHeader[0]=X-CallInfo, len=10, reqValue[0]=, len=0
Mar  7 15:54:19.125: Parse Error: url_generic_get_headers: headerp=0, num_headers=0 found, url(sip:6666011010@VXMLHAL.MARSHALLS.CO.UK)
Mar  7 15:54:19.125: Parse Error: url_generic_get_headers: reqHeader[0]=X-CallInfo, len=10
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccGetAvlistProtoHeader:
   No header match found.
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccDumpAttrValuePair:
  
Mar  7 15:54:19.125: len=10, reqHeader[0].attr.datap=X-CallInfo
Mar  7 15:54:19.125: len=0, reqHeader[0].value.datap=
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccCallConnect:
   Progress Indication=NULL(0), Data Bitmask=0x0
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccCallConnect:
   Call Entry(Connected=TRUE, Responsed=TRUE)
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccAssociateStream:
   Coder=5, DTMF Relay=1, Vad=0,
   Record Function=0x0, Event Queue=0x2A7828D4, Stream Context=C090F544,
   Record Context=0x0, Stream Call Id=15324, Call Id=15323
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccAssociateStream:
   Call Entry(Stream Status=2, Digit Enable=FALSE)
Mar  7 15:54:19.125: //15323/CB4FCD000000/CCAPI/ccAssociateStream:exit@3035
Mar  7 15:54:19.129: //15323/CB4FCD000000/CCAPI/cc_set_post_tagdata:
Mar  7 15:54:19.129: //15323/CB4FCD000000/CCAPI/cc_api_call_active_notify:
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/cc_api_call_disconnected:
   Cause Value=96, Interface=0x405CB0BC, Call Id=15323
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=96, Retry Count=0)
Mar  7 15:54:19.145: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Mar  7 15:54:19.145: //-1/xxxxxxxxxxxx/CCAPI/ccGenerateToneInfo:
   CALL_ERROR_INFORMATIONAL; Call Entry Is Not Found
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccDisassociateStream:
   Record Context=0x0, Stream Call Id=15324, Call Id=15323
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccDisassociateStream:
   Call Entry(Stream Status=1, Digit Enable=FALSE)
Mar  7 15:54:19.145: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Mar  7 15:54:19.145: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Mar  7 15:54:19.145: //-1/xxxxxxxxxxxx/CCAPI/cc_api_request_rt_packet_stats:
   CALL_ERROR_INFORMATIONAL; Call Entry Is Not Found
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccCallDisconnect:
   Cause Value=96, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=96)
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=TRUE)
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccCallDisconnect:
   Cause Value=96, Call Entry(Disconnect Cause=96)
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccCallDisconnect:
   Call Entry(Disconnect Cause=96)
Mar  7 15:54:19.145: //15323/CB4FCD000000/CCAPI/ccCallDisconnect:
   Cause Value=96, Call Entry(Responsed=TRUE, Cause Value=96)
Mar  7 15:54:19.149: //-1/xxxxxxxxxxxx/CCAPI/cc_api_icpif:
   ExpectFactor=0xA
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_api_insert_call_history:
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/ccGetCallActiveByCallID:
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_decr_if_call_volume:
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_decr_if_call_volume:
   Remote IP Address
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_decr_if_call_volume:
   Total Call Count=0, Voip Call Count=0, MMoip Call Count=0
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x405CB0BC, Tag=0x0, Call Id=15323,
   Call Entry(Disconnect Cause=96, Voice Class Cause Code=0, Retry Count=0)
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_disconnect_notify:
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/callStackPop:exit@4971
Mar  7 15:54:19.149: //15323/CB4FCD000000/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent