Twilio SIP Trunk

[telecotek1]

Anyone ever setup a SIP Trunk to Twilio using an SBC? I've got it partially working as my inbound calls work perfectly. But my outbound calls fail. I'm seeing the following flows...
invite ->
<-100 giving a try
<-407 Proxy Auth
ACK->
Invite SDP->
<-100 giving a try
Invite->
<-100 giving a try
<-183 Session Progress
<- RTP
Invite SDP->
<-183 Session Progress
<-200 OK
<-200 OK
<-200 OK
Invite SDP ->
<-200 OK
<-200 OK
cancel->
cancel->
cancel->
The outbound call rings the far end. Once the call is answered there's no audio. Then once the far end hangs up Twilio attempts to send the call 2 more time - 2 phantom calls from the PBX. The SBC Incident viewer only shows "BYE Message out of dialog."

 

[janni78]

If you could provide a complete trace that would actually tell me something, now I'm just guessing so it could be configuration or firewall... or both... or routing

"Trying is the first step to failure..." - Homer

 

[telecotek1]

I'll pull a trace in a little while. It's actually my system in my office that I'm trying to get this working on. I'm pretty sure the issue is in the SBC. The SBC is hanging off our firewall in a dmz so shouldn't be a firewall issue. I actually had this working with another sip provider. I like Twilio's "elastic sip" product so I'm hoping that I can get this sorted out.

 

[telecotek1]

UNICODE-UTF8
enu

********** Rolled Over Log - filename = C:\Users\Administrator.RSCNJ\Documents\SysMonLogs\rscnj 20160403 140332 (0).txt **********
14:03:30 144107543mS H323Evt: Recv: RegistrationRequest 10.10.101.35; Extn(4014), time since last RRQ-KA 55010, Endpoints registered: 14; Endpoints in registration: 0
14:03:32 144109180mS H323Evt: Recv: RegistrationRequest 10.10.101.34; Extn(4006), time since last RRQ-KA 55010, Endpoints registered: 14; Endpoints in registration: 0
14:03:34 144111547mS H323Evt: Recv: RegistrationRequest 10.10.101.28; Extn(4007), time since last RRQ-KA 55010, Endpoints registered: 14; Endpoints in registration: 0
14:03:36 144113710mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 9
14:03:36 144113711mS CMCallEvt: 0000000000000000 0.1274.0 -1 BaseEP: NEW CMEndpoint f193f960 TOTAL NOW=1 CALL_LIST=0
14:03:36 144113711mS CMCallEvt: 0000000000000000 0.1274.0 -1 Ext4013.-1: NEW CMExtnEndpoint f193f960, Name=Ext4013, Extn=4013, Phys Extn=4013
14:03:36 144113712mS CMCallEvt: CREATE CALL:75 (f196f44c)
14:03:36 144113712mS CMCallEvt: 0000000000000000 0.1275.0 -1 BaseEP: NEW CMEndpoint f196db40 TOTAL NOW=2 CALL_LIST=0
14:03:36 144113714mS CMExtnEvt: Ext4013: CMExtnHandler::SetCurrent( id: 0->1274 )
14:03:36 144113715mS CMExtnRx: v=4013, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[4013] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 12 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Ext4013
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=User4013
14:03:36 144113715mS CMCallEvt: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
14:03:36 144113715mS CMExtnEvt: v=17 State, new=Dialling old=Idle,0,0,Ext4013
14:03:36 144113715mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=4013 calling_sub= dir=out complete=0 ses=0
14:03:36 144113715mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
14:03:36 144113716mS CMCallEvt: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
14:03:36 144113719mS CMExtnTx: v=4013, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
CMSecurityElement RX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
CMSecurityElement TX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
Timed: 03/04/16 14:03
14:03:36 144113719mS H323Evt: PortmAvayaH323Phone:ortmAvayaH323PhoneDelay: 4013 - delay disabled
14:03:36 144113719mS CMExtnTx: v=4013, p1=8015
CMFacility
Line: type=IPLine 250 Call: lid=266 id=17 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
14:03:36 144113719mS CMExtnTx: v=4013, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Timed: 03/04/16 14:03
14:03:36 144113720mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[9] Type=Default (100) Reason=CMDRdirect Keypad[9]
14:03:36 144113720mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: Setting Hard Timer 4000
14:03:36 144113720mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=9 sub= calling=4013 calling_sub= dir=out complete=0 ses=0
14:03:36 144113720mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: ADD TARGET (N): number=9 type=100 depth=1 nobar=1 setorig=1 ses=0
14:03:36 144113721mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: SYS SC: 9 2 sc=type=Dial code=9N, num=N callinfop->sending_complete=0 secondary_dialtone=
14:03:36 144113721mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
14:03:36 144113721mS CMARS: MakeCallTarget - Called Number:
14:03:36 144113721mS CMCallEvt: 0000000000000000 0.1276.0 -1 BaseEP: NEW CMEndpoint f1963be4 TOTAL NOW=3 CALL_LIST=1
14:03:36 144113722mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: CancelTimer CMTCDelayedProcessing
14:03:36 144113722mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: INITIAL TARGETING SUCCEEDED
14:03:36 144113722mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: GetNoAnswerTimer:15
14:03:36 144113723mS CMCallEvt: 0000000000000000 0.1275.0 75 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
14:03:36 144113724mS CMCallEvt: 0000000000000000 0.1276.0 75 ARS for Main: StateChange: END=T CMCSIdle->CMCSOffering
14:03:36 144113724mS CMCallEvt: 0000000000000000 0.1275.0 75 TargetingEP: RequestEnd 0000000000000000 0.1276.0 75 ARS for Main
14:03:36 144113725mS CMTARGET: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: CancelTimer CMTCNoAnswerTimeout
14:03:36 144113725mS CMCallEvt: 0000000000000000 0.1276.0 75 ARS for Main: StateChange: END=B CMCSOffering->CMCSOverlapRecv
14:03:36 144113726mS CMExtnTx: v=4013, p1=0
CMProgress
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLUser (0), pd=CMPDInbandPattern (8)
Display [TRANSFERABLE_SEC_DIAL_TONE]
Timed: 03/04/16 14:03
14:03:36 144113726mS CMARS: FORM: Main - Received Number:
14:03:36 144113726mS CMARS: CMARSTargetingPending
14:03:36 144113727mS CMCallEvt: 0000000000000000 0.1275.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
14:03:36 144113727mS CMCallEvt: 0000000000000000 0.1275.0 -1 BaseEP: DELETE CMEndpoint f196db40 TOTAL NOW=2 CALL_LIST=1
14:03:36 144113729mS CD: CALL: 266.1274.0 BState=Idle Cut=2 Music=3.0 Aend="Ext4013(4013)" (0.0) Bend="" [] (0.0) CalledNum=9 () CallingNum=4013 (Ext4013) Internal=1 Time=17 AState=Dialling
14:03:36 144113730mS H323Evt: SESS 40 SetOperational local 10.10.101.254:0 remote 0.0.0.0:0 to 0
14:03:36 144113730mS H323Evt: SESS 40 SetRemUDP 0 -> 49120, remote IP 0.0.0.0 -> 10.10.101.21
14:03:36 144113730mS CMMap: PCG::AddToneGenerator g D1[1] for cp[253]b0r1 append pcp[254]b0r1 (total 1)
14:03:36 144113730mS CMMap: PlatformConnectionAudioSAP::Bind pcp[254]b0r1 to 0.0
14:03:36 144113730mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[254]b0r1 Configure 0.0
14:03:36 144113731mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[254]b0r1 ConnectIndication 0.0
14:03:36 144113731mS CMMap: a=0.0 b=0.0 pcp[253]b0r1 RTPD1
14:03:36 144113731mS H323Evt: SESS 40 SetOperational local 10.10.101.254:46750 remote 10.10.101.21:49120 to 1
14:03:37 144114033mS RES: Sun 3/4/2016 14:03:38 FreeMem=56308524 Heap=55966884(4) Cache=341640 MemObjs=9699(10632) CMMsg=11(11) ASN=0 Buff=5200 1372 980 7460 5 Links=52711(52962) BTree=418(781) CPU=06.05% CPUStats=07.78%/20/27/2488/33368/37454/00.09%/0/
01.98% MCR=0 MCW=0
14:03:37 144114033mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=97 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=0 TCP=47(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
14:03:37 144114033mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
14:03:37 144114033mS RES5: CLog MemObjs=89 FreePoolMem(Objs)=5772(111) TotalMem=144450
14:03:37 144114566mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 1
14:03:37 144114566mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[1] Type=Default (100) Reason=CMDRdirect Keypad[1]
14:03:37 144114567mS CMARS: FORM: Main - Received Number: 1
14:03:37 144114567mS CMARS: CMARSTargetingPending
14:03:37 144114568mS CMMap: a=0.0 b=0.0 pcp[253]b0r1 RTPD0
14:03:37 144114568mS H323Evt: SESS 40 SetOperational local 10.10.101.254:46750 remote 10.10.101.21:49120 to 0
14:03:37 144114783mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 2
14:03:37 144114783mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
14:03:37 144114784mS CMARS: FORM: Main - Received Number: 12
14:03:37 144114784mS CMARS: CMARSTargetingPending
14:03:38 144115011mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 0
14:03:38 144115011mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
14:03:38 144115012mS CMARS: FORM: Main - Received Number: 120
14:03:38 144115012mS CMARS: CMARSTargetingPending
14:03:39 144115331mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 1
14:03:39 144115332mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[1] Type=Default (100) Reason=CMDRdirect Keypad[1]
14:03:39 144115332mS CMARS: FORM: Main - Received Number: 1201
14:03:39 144115332mS CMARS: CMARSTargetingPending
14:03:39 144115898mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 6
14:03:39 144115899mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[6] Type=Default (100) Reason=CMDRdirect Keypad[6]
14:03:39 144115899mS CMARS: FORM: Main - Received Number: 12015
14:03:39 144115899mS CMARS: CMARSTargetingPending
14:03:40 144116068mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 6
14:03:40 144116068mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[6] Type=Default (100) Reason=CMDRdirect Keypad[6]
14:03:40 144116069mS CMARS: FORM: Main - Received Number: 120155
14:03:40 144116069mS CMARS: CMARSTargetingPending
14:03:40 144116312mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 0
14:03:40 144116312mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
14:03:40 144116313mS CMARS: FORM: Main - Received Number: 1201555
14:03:40 144116313mS CMARS: CMARSTargetingPending
14:03:40 144116527mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 3
14:03:40 144116527mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[3] Type=Default (100) Reason=CMDRdirect Keypad[3]
14:03:40 144116528mS CMARS: FORM: Main - Received Number: 12015551
14:03:40 144116528mS CMARS: CMARSTargetingPending
14:03:40 144116742mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 8
14:03:40 144116743mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[8] Type=Default (100) Reason=CMDRdirect Keypad[8]
14:03:40 144116743mS CMARS: FORM: Main - Received Number: 12015512
14:03:40 144116743mS CMARS: CMARSTargetingPending
14:03:40 144116961mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 2
14:03:40 144116961mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
14:03:40 144116962mS CMARS: FORM: Main - Received Number: 1201555121
14:03:40 144116962mS CMARS: CMARSTargetingPending
14:03:41 144117186mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,4013: Digit Key Pressed 8
14:03:41 144117186mS CMExtnRx: v=4013, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
Called[8] Type=Default (100) Reason=CMDRdirect Keypad[8]
14:03:41 144117186mS CMARS: FORM: Main - Received Number: 12015551212
14:03:41 144117187mS CMARS: CMARSTargetingPending
14:03:41 144117850mS SIP Rx: UDP 10.10.101.240:5060 -> 10.10.101.254:5060

14:03:43 144119409mS SIP Rx: UDP 10.10.101.36:5060 -> 10.10.101.254:5060

14:03:44 144121722mS CMARS: Case 1 - dial_delay_time: 4000 has expired - Resolve what we might have - Called Number: 12015551212 Addr: f1963be4
14:03:44 144121722mS CMARS: FORM: Main - Received Number: 12015551212
14:03:44 144121722mS CMARS: FOUND A SHORT CODE - short_code: 1XXXXXXXXXX; - Tel: +1N - Called_Party: +12015551212 - Line Group Id: 17
14:03:44 144121722mS CMARS: SetCurrentTarget: Short_Code: 1XXXXXXXXXX; - Line_Group_ID: 17
14:03:44 144121722mS CMARS: FindActiveARSByGroupID GroupID=17 - Not Found
14:03:44 144121722mS CMLRQ: FindActiveLRQByGroupID GroupID=17 - Not Found
14:03:44 144121723mS Sip: SIP Line (17): License, Valid 1, Available 20, Consumed 0
14:03:44 144121723mS CMCallEvt: 0000000000000000 0.1277.0 -1 BaseEP: NEW CMEndpoint f1925bfc TOTAL NOW=3 CALL_LIST=1
14:03:44 144121723mS Sip: SIP Line (17): sip_trunk_config_items 001a0001, voip.flags 00040949
14:03:44 144121723mS Sip: SIPDialog f19117bc created, dialogs 1 txn_keys 13
14:03:44 144121725mS CMARS: ModifyCMARSTarget: Short_Code: 1XXXXXXXXXX; - Line_Group_ID: 17 set line status to CMARS_TRYING
14:03:44 144121725mS CMARS: FOUND LINE - Line Id: 17 - using line group id: 17 (code 1XXXXXXXXXX;, line 17) - Called Number: +12015551212 - Calling Number: 4013
14:03:44 144121725mS CMARS: SEND Setup TO LINE
14:03:44 144121725mS CMCallEvt: 0a0a65fe000004fd 17.1277.0 75 SIPTrunk Endpoint: StateChange: END=child CMCSIdle->CMCSOffering
14:03:44 144121727mS CMLineTx: v=0
CMSetup
Line: type=SIPLine 17 Call: lid=17 id=1277 in=0
Called[+12015551212] Type=Default (100) Reason=CMDRdirect SndComp Calling[4013] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 14680
user 'Ext4013' presentation Allowed
IE CMIEFastStartInfoData (6) 6 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Ext4013
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=User4013
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Ext4013
IE CMIERespondingPartyKName (229)(Type=CMNameDefault) name=User4013
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=4013
IE CMIEDeviceDetail (231) 0a0a65fe000004fa LOCALE=enu HW=15 VER=9 class=CMDeviceH323Phone type=110 number=8015 channel=0 features=0x10000420 rx_gain=32 tx_gain=32 ep_callid=1274 ipaddr=10.10.101.254 apps=0 loc=0 em_loc=0 features2=0x0 is_spcal
l=0
IE CMIEMohSourceId (247) MOH Source = 255
IE CMIESecurityData (253) 2 item(s)
CMSecurityElement RX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 3)
}
CMSecurityElement TX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 3)
}
Locale: enu
14:03:44 144121727mS Sip: 0a0a65fe000004fd 17.1277.0 75 SIPTrunk Endpoint(f1925bfc) received CMSetup
14:03:44 144121728mS Sip: 0a0a65fe000004fd 17.1277.0 75 SIPTrunk Endpoint(f19117bc) SetLocalRTPAddress to 10.10.101.254:46752
14:03:44 144121730mS SIP Call Tx: 17
INVITE sip:+12015551212@10.10.101.251 SIP/2.0
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
CSeq: 1910927512 INVITE
Contact: "Ext4013" <sip:+19735551212@10.10.101.254:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer,100rel
User-Agent: IP Office 9.1.6.0 build 153
Content-Type: application/sdp
Content-Length: 253

v=0
o=UserA 1856583709 3981644339 IN IP4 10.10.101.254
s=Session SDP
c=IN IP4 10.10.101.254
t=0 0
m=audio 46752 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
14:03:44 144121730mS SIP Tx: UDP 10.10.101.254:5060 -> 10.10.101.251:5060
INVITE sip:+12015551212@10.10.101.251 SIP/2.0
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
CSeq: 1910927512 INVITE
Contact: "Ext4013" <sip:+19735551212@10.10.101.254:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer,100rel
User-Agent: IP Office 9.1.6.0 build 153
Content-Type: application/sdp
Content-Length: 253

v=0
o=UserA 1856583709 3981644339 IN IP4 10.10.101.254
s=Session SDP
c=IN IP4 10.10.101.254
t=0 0
m=audio 46752 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
14:03:44 144121731mS CD: CALL: 266.1274.0 BState=Idle Cut=2 Music=0.0 Aend="Ext4013(4013)" (0.0) Bend="" [Line 17] (0.0) CalledNum=912015551212 () CallingNum=4013 (Ext4013) Internal=1 Time=8019 AState=Dialling
14:03:44 144121736mS SIP Rx: UDP 10.10.101.251:5060 -> 10.10.101.254:5060
SIP/2.0 100 Trying
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
CSeq: 1910927512 INVITE
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
Via: SIP/2.0/UDP 10.10.101.254:5060;rport=5060;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
Content-Length: 0

14:03:44 144121737mS SIP Call Rx: 17
SIP/2.0 100 Trying
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
CSeq: 1910927512 INVITE
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
Via: SIP/2.0/UDP 10.10.101.254:5060;rport=5060;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
Content-Length: 0

14:03:44 144121738mS CMLineRx: v=0
CMProceeding
Line: type=SIPLine 17 Call: lid=17 id=1277 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[4013] Type=Internal Plan=Default
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=912015551212
IE CMIEDeviceDetail (231) 0a0a65fe000004fd LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x1 rx_gain=32 tx_gain=32 ep_callid=1277 ipaddr=10.10.101.254 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
14:03:44 144121738mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
14:03:45 144122033mS RES: Sun 3/4/2016 14:03:45 FreeMem=56247112 Heap=55934096(4) Cache=313016 MemObjs=10008(10632) CMMsg=11(11) ASN=0 Buff=5200 1372 980 7460 5 Links=52752(52962) BTree=419(781) CPU=05.82% CPUStats=06.27%/9/11/2488/33505/37454/00.19%/0/
02.05% MCR=0 MCW=0
14:03:45 144122033mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=97 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=0 TCP=47(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
14:03:45 144122033mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
14:03:45 144122033mS RES5: CLog MemObjs=89 FreePoolMem(Objs)=5772(111) TotalMem=144450

********** SysMonitor v9.1.6.0 build 153 [connected to 10.10.101.254 (00E0070CBF30)] **********
14:03:45 144122181mS PRN: Monitor Status IP 500 V2 9.1.6.0 build 153
14:03:45 144122181mS PRN: LAW=U PRI=0, BRI=0, ALOG=0, VCOMP=32, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=75)
14:03:55 144132393mS CMExtnTx: v=4013, p1=8015
CMFacility
Line: type=IPLine 250 Call: lid=266 id=17 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
14:03:55 144132393mS CMExtnRx: v=4013, p1=0
CMReleaseComp
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
14:03:55 144132393mS CMCallEvt: 0a0a65fe000004fa 266.1274.0 75 Ext4013.0: StateChange: END=A CMCSDialling->CMCSCompleted
14:03:55 144132394mS CMExtnEvt: v=17 State, new=PortRecoverDelay old=Dialling,0,0,Ext4013
14:03:55 144132396mS CMExtnTx: v=4013, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=266 id=1274 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 03/04/16 14:03
14:03:55 144132396mS CMLOGGING: CALL:2016/04/0314:03,00:00:00,000,4013,O,912015551212,912015551212,JLieberman,,,1,,"",0,n/a
14:03:55 144132396mS CD: CALL: 266.1274.0 BState=Idle Cut=2 Music=0.0 Aend="Ext4013(4013)" (0.0) Bend="" [Line 17] (0.0) CalledNum=912015551212 () CallingNum=4013 (Ext4013) Internal=1 Time=18684 AState=Idle
14:03:55 144132396mS CD: CALL: 266.1274.0 Deleted
14:03:55 144132397mS CMExtnEvt: Ext4013: CALL LOST (CMCauseNormal)
14:03:55 144132397mS CMExtnEvt: Ext4013: Extn(4013) Calling Party Number(4013) Type(CMNTypeInternal)
14:03:55 144132397mS CMExtnEvt: Ext4013: CMExtnHandler::SetCurrent( id: 1274->0 )
14:03:55 144132398mS CMCallEvt: 0a0a65fe000004fa 266.1274.0 -1 Ext4013.-1: StateChange: END=X CMCSCompleted->CMCSDelete
14:03:55 144132398mS CMARS: CMARSEndpoint::CallLost(cause=16) - Address: 0a0a65fe000004fa 0.1276.0 75 ARS for Main - Call State: CMCSOverlapRecv
14:03:55 144132398mS CMLineTx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=1277 in=0
Cause=16, Normal call clearing
14:03:55 144132399mS Sip: 0a0a65fe000004fd 17.1277.0 -1 SIPTrunk Endpoint(f1925bfc) received CMReleaseComp
14:03:55 144132400mS SIP Call Tx: 17
CANCEL sip:+12015551212@10.10.101.251 SIP/2.0
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
CSeq: 1910927512 CANCEL
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer,100rel
Reason: Q.850;cause=16;text="Normal call clearing"
User-Agent: IP Office 9.1.6.0 build 153
Content-Length: 0

14:03:55 144132400mS SIP Tx: UDP 10.10.101.254:5060 -> 10.10.101.251:5060
CANCEL sip:+12015551212@10.10.101.251 SIP/2.0
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
CSeq: 1910927512 CANCEL
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer,100rel
Reason: Q.850;cause=16;text="Normal call clearing"
User-Agent: IP Office 9.1.6.0 build 153
Content-Length: 0

14:03:55 144132401mS CMCallEvt: 0a0a65fe000004fd 17.1277.0 -1 SIPTrunk Endpoint: StateChange: END=X CMCSOffering->CMCSCompleted
14:03:55 144132401mS CMCallEvt: 0a0a65fe000004fa 0.1276.0 -1 ARS for Main: StateChange: END=X CMCSOverlapRecv->CMCSDelete
14:03:55 144132401mS CMCallEvt: 0a0a65fe000004fa 0.1276.0 -1 BaseEP: DELETE CMEndpoint f1963be4 TOTAL NOW=2 CALL_LIST=0
14:03:55 144132401mS CMCallEvt: END CALL:75 (f196f44c)
14:03:55 144132402mS CMTARGET: 0a0a65fe000004fa 266.1274.0 -1 BaseEP: ~CMTargetHandler f1967ae4 ep f193f960
14:03:55 144132402mS CMCallEvt: 0a0a65fe000004fa 266.1274.0 -1 BaseEP: DELETE CMEndpoint f193f960 TOTAL NOW=1 CALL_LIST=0
14:03:55 144132404mS H323Evt: SESS 40: RTP(END): 10.10.101.254/46750 10.10.101.21/49120 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=18674 SENT=42 RECV=34 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
14:03:55 144132405mS SIP Rx: UDP 10.10.101.251:5060 -> 10.10.101.254:5060
SIP/2.0 200 OK
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>;tag=ba99e017029d
CSeq: 1910927512 CANCEL
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
Content-Length: 0

14:03:55 144132407mS SIP Call Rx: 17
SIP/2.0 200 OK
From: "Ext4013" <sip:+19735551212@10.10.101.251>;tag=fa879d43dea3756d
To: <sip:+12015551212@10.10.101.251>;tag=ba99e017029d
CSeq: 1910927512 CANCEL
Call-ID: cee89a8ede5b167d4b0ee09bef445bfe
Via: SIP/2.0/UDP 10.10.101.254:5060;rport;branch=z9hG4bKb36d4ffa60234a526e729ace62b19be3
Content-Length: 0

14:03:55 144132533mS RES: Sun 3/4/2016 14:03:57 FreeMem=56252092 Heap=55901308(4) Cache=350784 MemObjs=9948(10632) CMMsg=11(11) ASN=0 Buff=5200 1372 980 7460 5 Links=52693(52962) BTree=417(781) CPU=06.41% CPUStats=07.11%/1/2/2488/33749/37454/00.19%/1/02
.04% MCR=0 MCW=0
14:03:55 144132533mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=99 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=0 TCP=47(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
14:03:55 144132533mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
14:03:55 144132533mS RES5: CLog MemObjs=89 FreePoolMem(Objs)=5772(111) TotalMem=144450
14:03:55 144132853mS SIP Rx: UDP 10.10.101.240:5060 -> 10.10.101.254:5060

14:03:57 144134398mS CMExtnEvt: Ext4013: Recover Timer reason=CMTRWrapUp
14:03:57 144134398mS CMExtnEvt: v=17 State, new=Idle old=PortRecoverDelay,0,0,Ext4013
14:03:57 144134398mS CMExtnTx: v=4013, p1=0
CMVoiceMailStatus
Line: type=IPLine 250 Call: lid=0 id=-1 in=0
Called[Ext4013 Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [Ext4013 Msgs=0]
Timed: 03/04/16 14:03
14:03:57 144134421mS SIP Rx: UDP 10.10.101.36:5060 -> 10.10.101.254:5060

14:04:00 144137407mS Sip: Dialog f19117bc Pending 487, do not release EP
14:04:00 144137533mS RES: Sun 3/4/2016 14:04:02 FreeMem=56289232 Heap=55934096(4) Cache=355136 MemObjs=9855(10632) CMMsg=11(11) ASN=0 Buff=5200 1372 980 7460 5 Links=52691(52962) BTree=417(781) CPU=06.80% CPUStats=07.22%/1/2/2488/33862/37454/00.01%/1/01

 

[janni78]

Looks like you dial the number wait for 11 seconds and then hangup the call.
You get a Trying from the SBC but no Ringing. You'll need to trace on the SBC side to see what it does.

When you trace SIP on IPO just have SIP Tx/Rx enabled if you're just interested in the SIP part.

"Trying is the first step to failure..." - Homer

 

[telecotek1]

Wasn't sure what filters to enable on the sip tab. Figured more was better than less...

My first post shows what the flows look like. I'm not sure how to modify the sbc to change the way it sets up. Clearly the provider wants to see something different but I'm not sure what to change.

 

[janni78]

If you have a SBC you'll need a log from that.

IPO trace only shows what's sent between the IPO and SBC, not what's going to the provider.

"Trying is the first step to failure..." - Homer

 

[telecotek1]

I have an sbc. The logs are not showing anything relevant - not even any entries in the log since last week. the only thing that seems somewhat helpful is the Incident viewer. But it's not giving me very much detail. I think as far as the sbc is concerned it's completing the call.

This shows in the incident viewer after every failed outbound call.

Incident Type BYE Message Out of Dialog Category Protocol Discrepancy
Timestamp April 3, 2016 10:04:53 PM EDT Device sbc01
Cause General Method not allowed Out-Of-Dialog

Shouldn't I be looking at the wireshark traces?

BTW - appreciate the help!