2 SEC Delay in Outbound Dial Plan Processing

Support zone
Post Reply
User avatar
Flip
Posts: 95
Joined: Sun Aug 19, 2012 3:53 am

2 SEC Delay in Outbound Dial Plan Processing

Post by Flip » Thu May 26, 2016 12:13 pm

There seems to be such a long delay when dialling numbers.
It appears to be at the "response 100" and "response 401"... Why do I get the 401 unauthorisd from the SIP server? Is this because SIP Sorcery is using cached or expired credentials?
Can I reduce this delay somehow and get the '183' response sooner?

Is there a fix to this? i.e. reduce the 2,645ms delay?

OUTBOUND CALL
See below >>>'s between "DialPlan 09:06:46:229" and "DialPlan 09:06:48:070" / ":085" = 2645ms delay.

Code: Select all

 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
 +     NEW OUTBOUND CALL INITIATED!   OUTBOUND CALL LEG INFORMATION!     +
 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
 o: req.URI: SIPSorcery.SIP.SIPURI // req.URI.Host: sipsorcery.com // req.URI.Host.to_s: sipsorcery.com ...
 o: req.URI.User: 0411223344 // req.URI.User.to_s: 0411223344 ...
 o: req.URI.ToString: sip:0411223344@sipsorcery.com ...
 o: req.Header.From: "61244442222" <sip:medea@sipsorcery.com>;tag=5cb7927717bb07c7o0 ...
 o: req.Header.From.FromURI: SIPSorcery.SIP.SIPURI // req.Header.From.FromURI.User: medea ...
 o: req.Header.From.FromName: 61244442222 ...
 o: req.Header.From.ToString: "61244442222" <sip:medea@sipsorcery.com>;tag=5cb7927717bb07c7o0 ...
 o: req.Header.To: <sip:0411223344@sipsorcery.com> ...
 o: req.Header.To.ToURI: SIPSorcery.SIP.SIPURI // req.Header.To.ToName:  ...
 o: req.Header.Contact[0]: "61244442222" <sip:medea@211.222.233.244:5060;ref=medea> ...
 o: req.Header.Contact[0].ContactURI: SIPSorcery.SIP.SIPURI ...
 o: req.Header.Contact[0].ContactName: 61244442222 ...
 o: req.Header.CSeq: 102 // req.Header.CallId: 1ab4ac37-2c6ab907@192.168.1.190 ...
 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
DialPlan 09:06:46:229 sip1(4816): 
DialPlan 09:06:46:229 sip1(4816): Commencing Dial with: ${EXTEN}@PTL_5.
DialPlan 09:06:46:229 sip1(4816): Attempting to locate a provider for call leg: sip:0411223344@PTL_5.
DialPlan 09:06:46:229 sip1(4816): ForkCall commencing call leg to sip:0411223344@sip.pennytel.com.
DialPlan 09:06:46:229 sip1(4816): SIPClientUserAgent Call using alternate outbound proxy of udp:67.222.131.147:5060.
DialPlan 09:06:46:229 sip1(4816): Switching to sip:0411223344@sip.pennytel.com:5060 via udp:67.222.131.147:5060.
>>> DialPlan 09:06:46:229 sip1(4816): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16392.
>>> DialPlan 09:06:48:070 sip1(4816): Information response 100 Trying for sip:0411223344@sip.pennytel.com.
>>> DialPlan 09:06:48:085 sip1(4816): Response 401 Unauthorized for sip:0411223344@sip.pennytel.com.
DialPlan 09:06:48:304 sip1(4816): Information response 100 Trying for sip:0411223344@sip.pennytel.com.
DialPlan 09:06:51:470 sip1(4816): Information response 183 Session Progress for sip:0411223344@sip.pennytel.com.
DialPlan 09:06:51:470 sip1(4816): UAS call progressing with SessionProgress.
Called: 0411223344
Caller: 61244442222
Account: medea


INBOUND CALL
Inbound doesn't appear to have the same problem, see the >>> below. Only a 180ms delay compared to the 2645ms delay.

Code: Select all

 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
 +      NEW INBOUND CALL INITIATED!   INBOUND CALL LEG INFORMATION!      +
 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
 i: req.URI: SIPSorcery.SIP.SIPURI // req.URI.Host: 67.222.131.147:5060 // req.URI.Host.to_s: 67.222.131.147:5060 ...
 i: req.URI.User: medea // req.URI.User.to_s: medea // req.Header: SIPSorcery.SIP.SIPHeader ...
 i: req.URI.ToString: sip:medea@67.222.131.147:5060;user=phone ...
 i: req.Header.From: "0416344669" <sip:0416344669@125.213.160.81>;tag=7e4958d-co118-INS001 ...
 i: req.Header.From.FromURI: SIPSorcery.SIP.SIPURI // 
 i: req.Header.From.FromURI.User: 0416344669 // req.Header.From.FromName: 0416344669 ...
 i: req.Header.From.ToString: "0416344669" <sip:0416344669@125.213.160.81>;tag=7e4958d-co118-INS001 ...
 i: req.Header.To: <sip:medea@67.222.131.147> ...
 i: req.Header.To.ToURI: SIPSorcery.SIP.SIPURI // req.Header.To.ToName:  ...
 i: req.Header.Contact[0]: <sip:0416344669@125.213.160.81:5060> ...
 i: req.Header.Contact[0].ContactURI: SIPSorcery.SIP.SIPURI ...
 i: req.Header.Contact[0].ContactName:  ...
 i: req.Header.CSeq: 11801 // req.Header.CallId: ac593a-513-4262016103222-img-ws8-6-125.213.168.31 ...
 + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +
DialPlan 09:36:56:000 sip1(2192): 
DialPlan 09:36:56:000 sip1(2192): Commencing Dial with: medea@sipsorcery.com
DialPlan 09:36:56:016 sip1(2192): Call leg is for local domain looking up bindings for medea@sipsorcery.com for call leg medea@sipsorcery.com.
DialPlan 09:36:56:031 sip1(2192): 1 found for medea@sipsorcery.com.
DialPlan 09:36:56:031 sip1(2192): Attempting to locate a provider for call leg: sip:17778000000@in.callcentric.com.
DialPlan 09:36:56:031 sip1(2192): ForkCall commencing call leg to sip:medea@211.222.233.244:5060.
DialPlan 09:36:56:031 sip1(2192): SIPClientUserAgent Call using alternate outbound proxy of udp:67.222.131.147:5060.
DialPlan 09:36:56:031 sip1(2192): Switching to sip:medea@211.222.233.244:5060 via udp:67.222.131.147:5060.
DialPlan 09:36:56:031 sip1(2192): SDP on UAC call had public IP not mangled, RTP socket 125.213.160.79:25704.
>>> DialPlan 09:36:56:281 sip1(2192): Information response 100 Trying for sip:medea@211.222.233.244:5060.
>>> DialPlan 09:36:56:468 sip1(2192): Information response 180 Ringing for sip:medea@211.222.233.244:5060.
DialPlan 09:36:56:468 sip1(2192): UAS call progressing with Ringing.
Called: 61244442222
Caller: 0411223344
Account: medea


OUTBOUND DIAL PLAN:
I was hoping to share my inbound and outbound plans, however want to be sure there is no faulty OR if something could be done better.
Thank you for your help. :)

Code: Select all

# DIAGNOSTICS
sys.Log("+ - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +")
sys.Log("+     NEW OUTBOUND CALL INITIATED!   OUTBOUND CALL LEG INFORMATION!     +")
sys.Log("+ - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +")
sys.Log("o: req.URI: #{req.URI} // req.URI.Host: #{req.URI.Host} // req.URI.Host.to_s: #{req.URI.Host.to_s} ...")
sys.Log("o: req.URI.User: #{req.URI.User} // req.URI.User.to_s: #{req.URI.User.to_s{}} // req.Header: #{req.Header} ...")
sys.Log("o: req.URI.ToString: #{req.URI.ToString{}} ...")
sys.Log("o: req.Header.From: #{req.Header.From} ...")
sys.Log("o: req.Header.From.FromURI: #{req.Header.From.FromURI} ...")
sys.Log("o: req.Header.From.FromURI.User: #{req.Header.From.FromURI.User} // req.Header.From.FromName: #{req.Header.From.FromName} ...")
sys.Log("o: req.Header.From.ToString: #{req.Header.From.ToString()} ...")
sys.Log("o: req.Header.To: #{req.Header.To} ...")
sys.Log("o: req.Header.To.ToURI: #{req.Header.To.ToURI} // req.Header.To.ToName: #{req.Header.To.ToName} ...")
sys.Log("o: req.Header.Contact[0]: #{req.Header.Contact[0]} ...")
sys.Log("o: req.Header.Contact[0].ContactURI: #{req.Header.Contact[0].ContactURI} ...")
sys.Log("o: req.Header.Contact[0].ContactName: #{req.Header.Contact[0].ContactName} ...")
sys.Log("o: req.Header.CSeq: #{req.Header.CSeq} // req.Header.CallId: #{req.Header.CallId} ...")
sys.log("+ - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - + - - - +")
sys.Log("")

# CALL LOGIC
case req.URI.User
 # SPEED DIAL # [INTERNAL].
  # >> Providers: SIPSorery.com & Local accounts.
    when /^200/ then sys.Dial("medea@sipsorcery.com")
     when "medea" then sys.Dial("medea@sipsorcery.com")
    when /^201/ then sys.Dial("hecate@sipsorcery.com")
     when "hecate" then sys.Dial("hecate@sipsorcery.com")
    when /^202/ then sys.Dial("xxxx@sipsorcery.com")
     when "xxxx" then sys.Dial("xxxx@sipsorcery.com")
    when /^211/ then sys.Dial("zzzz@sipsorcery.com")
     when "zzzz" then sys.Dial("zzzz@sipsorcery.com")
    # etc. .. ...
    when /^222/ then sys.Dial("17778000000@in.callcentric.com")
     when "ccvm" then sys.Dial("17778000000@in.callcentric.com")
    # when "____" then sys.Dial("____@sipsorcery.com") # sipsorcery.com or @local

 # SPEED DIAL # [EXTERNAL].
  # >> Providers: PTL_x MNF_x TELECUBE_x Entrust_CloudPBX etc.
  # [FAMILY & FRIENDS].
    # when /^___/ then sys.Dial("___@____")
    # when "___" then sys.Dial("___@____")
  # [WORK & CLIENTS]
    # when /^___/ then sys.Dial("___@____")
    # when "___" then sys.Dial("___@____")
  # [OTHER RULES].
    # when /^___/ then sys.Dial("___@____")
    # when "___" then sys.Dial("___@____")

 # VSP ACCOUNT PREFIX.
 # >> Providers: PTL_x MNF_x TELECUBE_x Entrust_CloudPBX etc. Prefer /^1\*/ as supports more speed dial's over /^\*1/
  # NUMBER + ASTERISK. [Preferred to avoid confusion]
    when /^1\*/ then sys.Dial("${EXTEN:2}@PTL_1") # $28.76
    when /^2\*/ then sys.Dial("${EXTEN:2}@PTL_2") # $4.31
    when /^3\*/ then sys.Dial("${EXTEN:2}@PTL_3") # $8.62
    when /^4\*/ then sys.Dial("${EXTEN:2}@MNF_1") # $17.76
    when /^5\*/ then sys.Dial("${EXTEN:2}@MNF_2") # $.....
    when /^6\*/ then sys.Dial("${EXTEN:2}@MNF_3") # $10.00
    when /^7\*/ then sys.Dial("${EXTEN:2}@TELECUBE_1") # $7.00
    when /^8\*/ then sys.Dial("${EXTEN:2}@TELECUBE_2") # $6.00
    when /^9\*/ then sys.Dial("${EXTEN:1}@sipbroker.com[rm=a]") # 9*234.. to *234..@sipbroker.com
    when /^0\*/ then sys.Dial("${EXTEN:2}@local") # 0*987654321 to 987654321@sipsorcery.com
    when /^10\*/ then sys.Dial("${EXTEN:3}@Entrust_CloudPBX1")
    when /^11\*/ then sys.Dial("${EXTEN:3}@Entrust_CloudPBX2")
    # ASTERISK NUMBERS
    when "*123" then sys.Dial("${EXTEN}@Entrust_CloudPBX1") # User Voicemail
    when "*124" then sys.Dial("${EXTEN}@Entrust_CloudPBX1") # Group Voicemail
    # when /^__\*/ then sys.Dial("${EXTEN:2}@____")

 # VSP & PUBLIC DIAGNOSTIC NUMBERS [MUSIC, ECHO TEST, CLID, DTMF, AUDIO CHANNEL & CONNECTIVITY].
    when /^300/ then sys.Dial("music@iptel.org")        # Normal
    when /^301/ then sys.Dial("early_music@iptel.org")  # Early Media
    when /^303/ then sys.Dial("wbdemo@conf.zipdx.com")  # Wide Band
    # when /^304/ then sys.Dial("6414539840@podlinez.net") # Parliment Question Time **BROKEN!**
    when /^305/ then sys.Dial("775@PTL_1")              # Test Audio

    when /^311/ then sys.Dial("0871271201@PTL_3") # Two-way Audio Echo Test.
    when /^312/ then sys.Dial("0871271202@PTL_3") # Plays Music from Radio Paradise.
    when /^313/ then sys.Dial("0871271203@PTL_3") # Announce CLI / CLID / CID.
    when /^314/ then sys.Dial("0871271204@PTL_3") # Speaking Day/Date/Time.
    when /^315/ then sys.Dial("0871271205@PTL_3") # Test DTMF Key Tones.
    # when /^3__/ then sys.Dial("____@xxxx")

 # REGULAR DIALING RULES | ${EXTEN:2} = RHS of 2nd Character. ??? \d{9}/ or \d{9}$/ ???
    when /^000/ then sys.Dial("${EXTEN}@PTL_1", 20)           # 000S0|
    when /^0011/ then sys.Dial("${EXTEN}@PTL_1", 20)          # 0011xxxxxxxx.S3|
    when /^0[2378][2-9]\d{7}/ then sys.Dial("${EXTEN}@PTL_1", 20)  # 0[2378][2-9]xxxxxxxS0|
    when /^04\d{8}/ then sys.Dial("${EXTEN}@PTL_1", 20)       # 0[4]xx xxx xxxS0|  [0-9][0-9]
    when /^0[1569]\d{8}/ then sys.Dial("${EXTEN}@PTL_1", 20)       # 0[1569]xxxxxxxxS0|

    when /^106/ then sys.Dial("${EXTEN}@PTL_1", 20)           # 106S0| hearing impaired
    when /^112/ then sys.Dial("${EXTEN}@PTL_1", 20)           # 112S0|
    #??? when /^___/ then sys.Dial("${EXTEN}@PTL_1")    # >>> Patterns: 110, 114, 124/5, 127, 127... 14.., 17.. <<<
    when /^1[258]1/ then sys.Dial("${EXTEN}@MNF_1", 20)       # 1[258]1S0|
    when /^12[34]/ then sys.Respond(403, "NO PREMIUM 12[34]!!!", 20) # 12[34]!|
        #? then rejectCall(603," ... NO PREMIUM  12[34] ...")
    when /^122/ then sys.Dial("${EXTEN}@PTL_1", 20)           # 12x.S0|
    when /^1[38]00\d{6}/ then sys.Dial("${EXTEN}@PTL_1", 20)  # 1[38]00xxxxxxS0|
    when /^1[38][1-9]\d{3}/ then sys.Dial("${EXTEN}@PTL_1", 20) # 1[38][1-9]xxxS0| or z
    when /^1[9]0[02]/ then sys.Respond(403, "NO PREMIUM 190[02]!!!", 20) # 1[9]0[02]xxxxxx!|
        #? then rejectCall(603," ... NO PREMIUM  1900/1902! ...")

    when /^[46-9]\d{7}/ then sys.Dial("${EXTEN}@PTL_1", 20) # ??? ,true,15 -or- ,15,true ??? # [3-9] or [46789]xxxxxxxS0|
    when /^77[178]/ then sys.Dial("${EXTEN}@PTL_1", 20)       # 77[1578]S0| Stripped '5'.
    when /^888\d{7}/ then sys.Dial("${EXTEN}@PTL_1", 20)      # 888xxxxxxxS0|
    # when /^___/ then sys.Dial("${EXTEN}@PTL___") # 

  else
    sys.log("# - - - # - - - # - - - # - - - # - - - # - - - # - - - # - - - # - - - #")
    sys.log("... No Rule Match! ...") # " '#{req.URI.User.to_s}' "
    num = req.URI.User.to_s          # Return Dialled Number >> +61 (0)2 9988-1122 <<
    num = num.gsub(/[^0-9*#]/,'')    # Strip ALL Text/Symbols (Except: "0-9", "#", "*")
    sys.log("# - - - # - - - # - - - # - - - # - - - # - - - # - - - # - - - #")
    sys.Log("PRIMARY $ ROUTE [STD: 8c/call, MOB: 7.8c/min] & DID: $15/3yr")
    sys.Dial("#{num}@PTL_5", 20) # ", true" = Send Trace. # ", 15" = Contiue after 15 Secs.
    sys.Log("SECONDARY $$$ ROUTE [STD: 10c/call, MOB: 15c/min] & DID: $15/3yr")
    sys.Dial("#{num}@MNF_3", 20)
    sys.Log("TERTIARY A $$ ROUTE [STD: 1.5c/min, MOB: 5c/min] & DID: $18/3yr")
    sys.Dial("#{num}@TELECUBE_1", 20)
    sys.Log("TERTIARY B $$ ROUTE [STD: 10c/call, MOB: 5c/min] & DID: $18/3yr")
    sys.Dial("#{num}@TELECUBE_2", 20)
    sys.log("# - - - # - - - # - - - # - - - # - - - # - - - # - - - # - - - # - - - #")

    sys.Respond(404, "#--- Oops! Sorry, no destination was found, a destination time-out occurred, or no dial plan matched URI/EXTEN: #{req.Header.To}! ---#")
end
ISP: Southern Phone ADSL2+ $55 Bundle. 22.4/1.2Mbps, GB Bundle [Telstra].
VSP: SIPTalk¹, Symbio² & MyNetFone³ via SIPSorcery Cloud PBX. [Warning! Avoid DIDLogic!!! Beware!!]
H/W: Asus RT-AC86U; Cisco SPA232D, 2 x SPA901's, SPA3102; Yealink SIP-T46G.

Aaron
Site Admin
Posts: 4652
Joined: Thu Jul 12, 2007 12:13 am

Re: 2 SEC Delay in Outbound Dial Plan Processing

Post by Aaron » Fri May 27, 2016 8:50 am

Are you talking about the delay between these two log messages?

Code: Select all

DialPlan 09:06:48:304 sip1(4816): Information response 100 Trying for sip:0411223344@sip.pennytel.com.
DialPlan 09:06:51:470 sip1(4816): Information response 183 Session Progress for sip:0411223344@sip.pennytel.com.
You'd need to ask Pennytel (or mynetfone since they now own Pennytel) about that.

User avatar
Flip
Posts: 95
Joined: Sun Aug 19, 2012 3:53 am

Re: 2 SEC Delay in Outbound Dial Plan Processing

Post by Flip » Fri May 27, 2016 8:26 pm

Thanks. Yes and also the authorisation error - "401 Unauthorised".

To me this appeared to be what is possibly causing the delay... i.e. "09:06:46:229" to "09:06:48:070"...

Hmmm after more testing, it seems to be mobile calls. Obviously haven't to broadcast the network and wait for the phone in sleep mode wake up and respond.

Flip wrote:There seems to be such a long delay when dialling numbers.
It appears to be at the "response 100" and "response 401"... Why do I get the 401 unauthorisd from the SIP server? Is this because SIP Sorcery is using cached or expired credentials?
Can I reduce this delay somehow and get the '183' response sooner?

Is there a fix to this? i.e. reduce the 2sec delay?
INBOUND

Code: Select all

DialPlan 10:11:04:355 sip1(2036): SIPClientUserAgent Call using alternate outbound proxy of udp:67.222.131.147:5060.
DialPlan 10:11:04:355 sip1(2036): Switching to sip:medea@211.222.233.244:5060 via udp:67.222.131.147:5060.
DialPlan 10:11:04:355 sip1(2036): SDP on UAC call had public IP not mangled, RTP socket 125.213.160.79:15494.
DialPlan 10:11:04:604 sip1(2036): Information response 100 Trying for sip:medea@211.222.233.244:5060.
DialPlan 10:11:04:729 sip1(2036): Information response 180 Ringing for sip:medea@211.222.233.244:5060.

DialPlan 10:53:03:389 sip1(2984): SIPClientUserAgent Call using alternate outbound proxy of udp:67.222.131.147:5060.
DialPlan 10:53:03:389 sip1(2984): Switching to sip:medea@211.222.233.244:5060 via udp:67.222.131.147:5060.
DialPlan 10:53:03:389 sip1(2984): SDP on UAC call had public IP not mangled, RTP socket 125.213.160.71:16036.
DialPlan 10:53:03:701 sip1(2984): Information response 100 Trying for sip:medea@211.222.233.244:5060.
DialPlan 10:53:03:872 sip1(2984): Information response 180 Ringing for sip:medea@211.222.233.244:5060.

DialPlan 10:58:57:063 sip1(2640): SIPClientUserAgent Call using alternate outbound proxy of udp:67.222.131.147:5060.
DialPlan 10:58:57:063 sip1(2640): Switching to sip:medea@211.222.233.244:5060 via udp:67.222.131.147:5060.
DialPlan 10:58:57:079 sip1(2640): SDP on UAC call had public IP not mangled, RTP socket 125.213.160.149:24236.
DialPlan 10:58:57:406 sip1(2640): Information response 100 Trying for sip:medea@211.222.233.244:5060.
DialPlan 10:58:57:547 sip1(2640): Information response 180 Ringing for sip:medea@211.222.233.244:5060.
No issues with inbound... 125ms, 171ms, 141ms accordingly.


OUTBOUND

Code: Select all

MOBILE CALLS
DialPlan 10:13:15:615 sip1(2036): Switching to sip:0411223344@202.85.243.105:5060 via udp:67.222.131.147:5060.
DialPlan 10:13:15:615 sip1(2036): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16418.
DialPlan 10:13:17:533 sip1(2036): Information response 100 Trying for sip:0411223344@202.85.243.105.
DialPlan 10:13:17:565 sip1(2036): Response 401 Unauthorized for sip:0411223344@202.85.243.105.
DialPlan 10:13:17:783 sip1(2036): Information response 100 Trying for sip:0411223344@202.85.243.105.
DialPlan 10:13:20:997 sip1(2036): Information response 183 Session Progress for sip:0411223344@202.85.243.105.
= 3.432sec delay (PTL)

DialPlan 10:46:16:564 sip1(2984): Switching to sip:0411223344@125.213.160.82:5060 via udp:67.222.131.147:5060.
DialPlan 10:46:16:564 sip1(2984): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16426.
DialPlan 10:46:16:814 sip1(2984): Information response 100 Trying for sip:0411223344@125.213.160.82.
DialPlan 10:46:16:845 sip1(2984): Response 401 Unauthorized for sip:0411223344@125.213.160.82.
DialPlan 10:46:17:079 sip1(2984): Information response 100 Trying for sip:0411223344@125.213.160.82.
DialPlan 10:46:20:574 sip1(2984): Information response 183 Session Progress for sip:0411223344@125.213.160.82.
= 3.76sec delay (MNF 2)

DialPlan 10:50:51:816 sip1(2984): Switching to sip:0411223344@125.213.160.81:5060 via udp:67.222.131.147:5060.
DialPlan 10:50:51:816 sip1(2984): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16428.
DialPlan 10:50:52:034 sip1(2984): Information response 100 Trying for sip:0411223344@125.213.160.81.
DialPlan 10:50:52:066 sip1(2984): Response 401 Unauthorized for sip:0411223344@125.213.160.81.
DialPlan 10:50:52:268 sip1(2984): Information response 100 Trying for sip:0411223344@125.213.160.81.
DialPlan 10:50:55:778 sip1(2984): Information response 183 Session Progress for sip:0411223344@125.213.160.81.
= 3.74sec delay (MNF 1)

DialPlan 11:15:54:653 sip1(2640): Switching to sip:0490113355@202.85.243.105:5060 via udp:67.222.131.147:5060.
DialPlan 11:15:54:653 sip1(2640): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16442.
DialPlan 11:15:54:887 sip1(2640): Information response 100 Trying for sip:0490113355@202.85.243.105.
DialPlan 11:15:54:903 sip1(2640): Response 401 Unauthorized for sip:0490113355@202.85.243.105.
DialPlan 11:15:55:121 sip1(2640): Information response 100 Trying for sip:0490113355@202.85.243.105.
DialPlan 11:15:59:942 sip1(2640): Information response 183 Session Progress for sip:0490113355@202.85.243.105.
= 5.06sec delay (PTL)

DialPlan 11:54:01:027 sip1(2576): Switching to sip:0490113355@125.213.160.81:5060 via udp:67.222.131.147:5060.
DialPlan 11:54:01:027 sip1(2576): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16448.
DialPlan 11:54:01:230 sip1(2576): Information response 100 Trying for sip:0490113355@125.213.160.81.
DialPlan 11:54:01:230 sip1(2576): Response 401 Unauthorized for sip:0490113355@125.213.160.81.
DialPlan 11:54:01:449 sip1(2576): Information response 100 Trying for sip:0490113355@125.213.160.81.
DialPlan 11:54:05:848 sip1(2576): Information response 183 Session Progress for sip:0490113355@125.213.160.81.
= 4.62sec delay (MNF 1)

LANDLINE CALLS
DialPlan 11:02:46:544 sip1(2640): Switching to sip:0871271202@202.85.243.105:5060 via udp:67.222.131.147:5060.
DialPlan 11:02:46:544 sip1(2640): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16434.
DialPlan 11:02:46:778 sip1(2640): Information response 100 Trying for sip:0871271202@202.85.243.105.
DialPlan 11:02:46:778 sip1(2640): Response 401 Unauthorized for sip:0871271202@202.85.243.105.
DialPlan 11:02:46:996 sip1(2640): Information response 100 Trying for sip:0871271202@202.85.243.105.
DialPlan 11:02:47:370 sip1(2640): Information response 180 Ringing for sip:0871271202@202.85.243.105.
DialPlan 11:02:48:385 sip1(2640): Response 200 OK for sip:0871271202@202.85.243.105.
DialPlan 11:02:48:385 sip1(2640): SDP on UAC response had public IP not mangled, RTP socket 125.213.162.242:36786.
DialPlan 11:02:48:385 sip1(2640): Cancelling all call legs for ForkCall app.
DialPlan 11:02:48:385 sip1(2640): Answering client call with a response status of 200.
DialPlan 11:02:48:447 sip1(2640): Dial command was successfully answered in 1.90s.
= 1.61sec delay (PTL Slower)

DialPlan 11:28:02:827 sip1(4764): Switching to sip:0871271202@125.213.160.81:5060 via udp:67.222.131.147:5060.
DialPlan 11:28:02:827 sip1(4764): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16444.
DialPlan 11:28:03:029 sip1(4764): Information response 100 Trying for sip:0871271202@125.213.160.81.
DialPlan 11:28:03:045 sip1(4764): Response 401 Unauthorized for sip:0871271202@125.213.160.81.
DialPlan 11:28:03:248 sip1(4764): Information response 100 Trying for sip:0871271202@125.213.160.81.
DialPlan 11:28:03:731 sip1(4764): Information response 180 Ringing for sip:0871271202@125.213.160.81.
DialPlan 11:28:03:731 sip1(4764): UAS call progressing with Ringing.
DialPlan 11:28:04:730 sip1(4764): Response 200 OK for sip:0871271202@125.213.160.81.
DialPlan 11:28:04:730 sip1(4764): SDP on UAC response had public IP not mangled, RTP socket 125.213.160.71:12130.
DialPlan 11:28:04:730 sip1(4764): Cancelling all call legs for ForkCall app.
DialPlan 11:28:04:730 sip1(4764): Answering client call with a response status of 200.
DialPlan 11:28:04:792 sip1(4764): Dial command was successfully answered in 1.97s.
= 702msec delay (MNF Faster)

INTERNET CALLS
DialPlan 11:08:56:318 sip1(2640): Switching to sip:music@iptel.org:5060 via udp:67.222.131.147:5060.
DialPlan 11:08:56:318 sip1(2640): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16436.
DialPlan 11:08:58:112 sip1(2640): Information response 100 Trying for sip:music@iptel.org.
DialPlan 11:08:58:112 sip1(2640): Response 200 OK for sip:music@iptel.org.
DialPlan 11:08:58:112 sip1(2640): SDP on UAC response had public IP not mangled, RTP socket 212.79.111.157:11568.
DialPlan 11:08:58:112 sip1(2640): Cancelling all call legs for ForkCall app.
DialPlan 11:08:58:112 sip1(2640): Answering client call with a response status of 200.
DialPlan 11:08:58:158 sip1(2640): Dial command was successfully answered in 1.84s.
= 0msec delay

DialPlan 11:10:30:138 sip1(2640): Switching to sip:wbdemo@conf.zipdx.com:5060 via udp:67.222.131.147:5060.
DialPlan 11:10:30:138 sip1(2640): SDP on UAC call had public IP not mangled, RTP socket 211.222.233.244:16438.
DialPlan 11:10:31:791 sip1(2640): Information response 100 Trying for sip:wbdemo@conf.zipdx.com.
DialPlan 11:10:31:807 sip1(2640): Response 200 Ok for sip:wbdemo@conf.zipdx.com.
DialPlan 11:10:31:807 sip1(2640): SDP on UAC response had public IP not mangled, RTP socket 166.88.23.109:13188.
DialPlan 11:10:31:807 sip1(2640): Cancelling all call legs for ForkCall app.
DialPlan 11:10:31:807 sip1(2640): Answering client call with a response status of 200.
DialPlan 11:10:31:885 sip1(2640): Dial command was successfully answered in 1.75s.
= 16msec delay
Delay issue appears to be related to Mobile network calls and not PSTN! Internet calls (to SIP URI) have only a 40ms to 70ms delay.
ISP: Southern Phone ADSL2+ $55 Bundle. 22.4/1.2Mbps, GB Bundle [Telstra].
VSP: SIPTalk¹, Symbio² & MyNetFone³ via SIPSorcery Cloud PBX. [Warning! Avoid DIDLogic!!! Beware!!]
H/W: Asus RT-AC86U; Cisco SPA232D, 2 x SPA901's, SPA3102; Yealink SIP-T46G.

Aaron
Site Admin
Posts: 4652
Joined: Thu Jul 12, 2007 12:13 am

Re: 2 SEC Delay in Outbound Dial Plan Processing

Post by Aaron » Sat May 28, 2016 12:46 am

The 401 responses are part of the SIP challenge response authentication sequence. They are essential (unless you wanted to turn off SIP security) and it's highly unlikely they are adding more than a a few hundred milliseconds at the absolute maximum to your call processing.

In my experience a 2 or 3 second delay for a call to mobile network is pretty good. I find even calls directly from my mobile, so on the same network, can take up to 5s to set up. If the delay was in the 8 to 10s range then it can become a problem as that's around the point people will start to think something has gone wrong and give up.

Post Reply