[asterisk-users] Asterisk uses 3 seconds to send ACK after OK

Fri Mar 15 09:21:01 CDT 2013

Hello!

We recently upgraded one of our customers from 1.4.44 to 1.8.15-cert1. We have several other customers running both versions.
The customer in question does not use us as their provider as they’re located in a different country.

When they make outgoing calls, there is a 3 second delay between answering the call and the call being established. When debugging this, I found that Asterisk waits 3 seconds after receiving 200 OK before returning the ACK. See attached image. There’s no verbose output in the CLI during this time. I turned on full debugging. This seems to produce around a hundred lines of debug per second until suddenly I see a full 3 seconds stop just before sending the ACK.

[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 Ok
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  1 [ 57]: Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:xxxx;branch=z9hG4bK135effb0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  2 [ 66]: From: "a" <sip:a at xxx.xxx.xxx.xxx:xxxx>;tag=as6b9fcf86
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  3 [ 61]: To: <sip:b at FQDNy:5060>;tag=1014243474
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  4 [ 59]: Call-ID: 03dffd7b5ecd7eb47c2bae6b101ba1aa at 62.109.37.34:5088
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  6 [ 51]: Contact: <sip:b at FQDNz:5060>
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  7 [117]: Record-Route: <sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  8 [ 69]: Allow: INVITE,ACK,PRACK,SUBSCRIBE,BYE,CANCEL,NOTIFY,INFO,REFER,UPDATE
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  9 [ 24]: Supported: timer, 100rel
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 10 [ 29]: Content-Type: application/sdp
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 11 [ 19]: Content-Length: 352
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 12 [  0]:
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  0 [  3]: v=0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  1 [ 35]: o=- 25469059 0 IN IP4 ccc.ccc.ccc.ccc
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  2 [ 13]: s=Cisco SDP 0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  3 [ 22]: c=IN IP4 ccc.ccc.ccc.ccc
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  4 [  5]: t=0 0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  5 [ 31]: m=audio 21252 RTP/AVP 8 101 100
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  6 [ 33]: a=rtpmap:101 telephone-event/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  7 [ 15]: a=fmtp:101 0-15
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  8 [ 23]: a=rtpmap:100 X-NSE/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  9 [ 18]: a=fmtp:100 200-202
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 10 [  9]: a=X-sqn:0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 11 [ 28]: a=X-cap: 1 audio RTP/AVP 100
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 12 [ 33]: a=X-cpar: a=rtpmap:100 X-NSE/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 13 [ 28]: a=X-cpar: a=fmtp:100 200-202
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 14 [ 26]: a=X-cap: 2 image udptl t38
[Mar 15 13:16:05] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:05] --- (12 headers 15 lines) ---
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: = Looking for  Call ID: 03dffd7b5ecd7eb47c2bae6b101ba1aa at xxx.xxx.xxx.xxx:xxxx (Checking To) --From tag as6b9fcf86 --To-tag 1014243474
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Acked pending invite 102
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Stopping retransmission on '03dffd7b5ecd7eb47c2bae6b101ba1aa at xxx.xxx.xxx.xxx:xxxx' of Request 102: Match Found
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: SIP response 200 to standard invite
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: SIP response 200 to standard invite
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Call 03dffd7b5ecd7eb47c2bae6b101ba1aa at xxx.xxx.xxx.xxx:xxxx responded to our reinvite without changing SDP version; ignoring SDP.
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Updating call counter for outgoing call
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: build_route: Record-Route hop: <sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:05] list_route: hop: <sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] DEBUG[27947] netsock2.c: Splitting 'FQDNz:5060' into...
[Mar 15 13:16:05] DEBUG[27947] netsock2.c: ...host 'FQDNz' and port '5060'.
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: No provider found, checking channel drivers for SIP – FQDNy
[Mar 15 13:16:05] DEBUG[27931] chan_sip.c: Checking device state for peer FQDNy
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: Changing state for SIP/FQDNy - state 2 (In use)
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: device 'SIP/FQDNy' state '2'
[Mar 15 13:16:05] DEBUG[27967] app_queue.c: Device 'SIP/FQDNy' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: Splitting 'yyy.yyy.yyy.yyy' into...
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: ...host 'yyy.yyy.yyy.yyy' and port ''.
[Mar 15 13:16:08] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:08] Transmitting (no NAT) to yyy.yyy.yyy.yyy:5060:
ACK sip:004741888800 at FQDNz:5060 SIP/2.0

Could it be a parsing issue because the Record-Route header doesn’t include a port?

With kind regards,
Pan
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20130315/b66f71f3/attachment.htm>