Ahmad Nizami | 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 |