Outbound calls on a UC 520 take 20 seconds to dial

[dhankins1]

This wasn't a problem at this site when we set it up but now

every call has a 20 second delay before it begins to ring. Looked at a debug and saw

out of sequence packets and packet queue overflow but I am not sure if this is the issue. What

can I test to narrow down the culprit?

I added the log we generated although I don't know if that will help.

Our SIP provider is feigning innocence.

[Steven DiStefano · Accepted solution]

Looking in the log, I see the place where the time delay is most evident for a 9+1<10dig> Call:

Looks like its expecting more digits and then times out and routes.

If you used CCA for this, what does your DIALPLAN Outgoing patters look like for 1+10  ????

-----

Here is where you finished dialing 7 digits:

082532: May 24 16:20:37.145: //-1/A3FAB07EA1EF/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=918044939, Peer Info Type=DIALPEER_INFO_SPEECH

Here is where you dialed the last of 10 digits:

082596: May 24 16:20:37.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersCore:
    Calling Number=, Called Number=918044939396, Peer Info  Type=DIALPEER_INFO_SPEECH

Then

082603: May 24 16:20:37.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersMoreArg:
  Result=MORE_DIGITS_NEEDED(1)
082604: May 24 16:20:38.141: TCP0: ACK timeout timer expired
082605: May 24 16:20:42.185: TCB87956670 setting property TCP_TOS (11) 88833FF8
082606: May 24 16:20:42.389: TCP0: ACK timeout timer expired
082607: May 24 20:20:49.169: %FW-4-TCP_OoO_SEG: Dropping TCP Segment: seq:2889902131 1500 bytes is out-of-order; expected seq:2889877311. Reason: TCP reassembly queue overflow - session 192.168.10.15:49903 to 204.0.59.120:80
082608: May 24 20:20:49.169: %FW-6-DROP_PKT: Dropping http session 204.0.59.120:80 192.168.10.15:49903  due to  Out-Of-Order Segment with ip ident 38341 tcpflags 0x5010 seq.no 2889902131 ack 3171389951
082609: May 24 16:20:52.945: //5050/A3FAB07EA1EF/CCAPI/cc_handle_inter_digit_timer:
   Generate inter-digit timeout CC_EV_CALL_DIGIT_END event

then he matches dial peer...

082610: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=918044939396T, Peer Info Type=DIALPEER_INFO_SPEECH
082611: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=918044939396T
082612: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchCore:
   Dial String=918044939396T, Expanded String=918044939396T, Calling Number=
   Timeout=FALSE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
082613: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/MatchNextPeer:
   Result=Success(0); Outgoing Dial-peer=63 Is Matched
082614: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/MatchNextPeer:
   Result=Success(0); Outgoing Dial-peer=1029 Is Matched
082615: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
082616: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchSafModulePlugin:
   dialstring=918044939396T, saf_enabled=1, saf_dndb_lookup=0, dp_result=0
082617: May 24 16:20:52.945: //-1/A3FAB07EA1EF/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=1029
     2: Dial-peer Tag=63