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:[email protected]:xxxx>;tag=as6b9fcf86 [Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Header 3 [ 61]: To: <sip:b@FQDNy:5060>;tag=1014243474 [Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Header 4 [ 59]: Call-ID: [email protected]: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@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: [email protected]: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 '[email protected]: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 [email protected]: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@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
-- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- New to Asterisk? Join us for a live introductory webinar every Thurs: http://www.asterisk.org/hello asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users
