[Asterisk-Users] SIP rapid INVITE re-transmission: bug, or config problem?

[John Todd]

I'm having a problem with Asterisk sending too many INVITEs to a peer for a single call.  I can't quite figure out why there are these rapid INVITEs sent to the call proxy.  The call completes correctly (to, in this example, an echo test found via ENUM) but the number of INVITEs is really out of control and is a Bad Thing overall.

My notes:

1) This isn't a firewall problem - there aren't any.  Additionally, you'll note that the INVITEs are all being replied to eventually.

2) The intervals between the INIVTEs after the 407 sequence are: 34ms, 30ms, 49ms, 91ms.  This is _way_ too fast for response timers to be expiring for reliable re-transmissions of INVITEs... isn't it?  According to DEFAULT_RETRANS in chan_sip.c, the proper delay should be 1000ms between retransmissions.

3) Here is the peer definition for this system:

[testbed]
type=peer
username=9
secret=dio0sywa82a
host=10.0.3.173
insecure=very
context=default
qualify=4000 

4) The 10.0.3.173 host is running a variant of SER, but that shouldn't matter since the problem is pretty clearly Asterisk's pushy INVITE problems.

5) I'm running CVS-HEAD 2005-11-18 22:14:30 UTC.  

6) The INVITEs create a huge logjam of "100 Trying" and "200 OK with SDP" messages.  This is Bad.

7) I have verified that only one INVITE is coming from the UA to Asterisk and the dialplan is only being executed once, so this is an Asterisk->testbed problem.

8) Here's the console output:

cookies*CLI> testbed
    -- Executing Dial("SIP/2598-dbb4", "SIP/437800047111 at testbed") in new stack
    -- Called 437800047111 at testbed
    -- SIP/testbed-6b7c answered SIP/2598-dbb4
    -- Attempting native bridge of SIP/2598-dbb4 and SIP/testbed-6b7c
    -- Executing Hangup("SIP/2598-dbb4", "") in new stack
cookies*CLI> 

9) Here's the tethereal output showing the conversation between Asterisk (10.0.3.170) and SER (10.0.3.173):

poptart# tethereal -n port 5060
  0.000000 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.037369 10.0.3.173 -> 10.0.3.170 SIP Status: 407 Proxy Authentication Required
  0.037941 10.0.3.170 -> 10.0.3.173 SIP Request: ACK sip:437800047111 at 10.0.3.173
  0.038190 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.072043 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.102148 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.151999 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.242048 10.0.3.170 -> 10.0.3.173 SIP/SDP Request: INVITE sip:437800047111 at 10.0.3.173, with session description
  0.317500 10.0.3.173 -> 10.0.3.170 SIP Status: 100 trying -- your call is important to us
  0.354345 10.0.3.173 -> 10.0.3.170 SIP Status: 100 trying -- your call is important to us
  0.395474 10.0.3.173 -> 10.0.3.170 SIP Status: 100 trying -- your call is important to us  
[etc]

10) The (post-407) INVITEs are identical to each other - there are no differences in Call-ID, branch, tag, nonces, or SDP.  I then compared the INVITES between a working peer and the broken peer to each other - they're almost identical except for IP addresses, so nothing obvious there, either.

11) Each INVITE in a "sip debug" output is tagged with something like "Retransmitting #4 (no NAT) to 10.0.3.173:5060:" but there are no timer statements that I could see in the debug.

12) Interestingly, when I dial one of my UAs which is listed as a peer in sip.conf, there is (in my first test) a 420ms delay between the INVITE and the "100 Trying" from the UA.  Asterisk does not re-transmit the INVITE in that interval.  Something is different about my [testbed] peer.

13) More interestingly, a peer configured _almost_ identically (different IP address and secret, but otherwise EXACTLY the same) doesn't have the problem.  Asterisk respectfully waits for the reply from the proxy and does not blast several INVITEs at it.  The delay between the first (post-407) INVITE and the reply from the functional peer is ~50ms, much longer than Asterisk waits before re-transmitting on the [testbed] peer.

I am _totally_ stumped here.  I have changed the names of the peers, changed the qualify= statement, moved the peers around in sip.conf, stood on my head, etc.  Your insights on this would be appreciated, since I'm not quite sure what Asterisk is up to with these rapid INVITE sequences.  I'm thinking "bug" but maybe there is some subtle config option that I'm overlooking, so I'll ask the list before I file the bug.  Maybe it's just that I've had too much caffeine today and the obvious solution is the one that's the most difficult to see.

JT