We enabled full log, with milliseconds timestamp, sip debug and verbose and debug to level 5.
The call starts from a softphone (linphone) on 10.245.8.16, through asterisk (10.245.8.12) reaches the cisco call manager (10.120.4.10) that answers and pauses the call.
When the phone registered on the cisco call manager (10.120.2.31) takes the call, the cisco call manager resumes the call and asterisk receives a SIP ACK with an SDP including the new media address (c=IN IP4 10.120.2.31, timestamp 15:13:11.282).
Only 1 second and half later, the SDP with the new media address is sent to the linphone (c=IN IP4 10.120.2.31, timestamp 15:13:12.883).
It happens that sometimes this delay is up to 5 seconds.
Here’s the relevant part of the log:
[code][2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282]
<— SIP read from UDP:10.120.4.10:5060 —>
ACK sip:11130154031031@10.245.8.12:5060 SIP/2.0
Via: SIP/2.0/UDP 10.120.4.10:5060;branch=z9hG4bK10191bd0bb
From: sip:110010301@10.120.4.10;tag=8764~8fa62566-e1be-407f-a988-17cf779f66b8-29553229
To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=as174fdd0b
Date: Mon, 04 Mar 2013 14:13:09 GMT
Call-ID: 44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060
Max-Forwards: 70
CSeq: 103 ACK
Allow-Events: presence
Content-Type: application/sdp
Content-Length: 154
v=0
o=CiscoSystemsCCM-SIP 8764 5 IN IP4 10.120.4.10
s=SIP Call
c=IN IP4 10.120.2.31
t=0 0
m=audio 21382 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=ptime:20
<------------->
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 0 [ 47]: ACK sip:11130154031031@10.245.8.12:5060 SIP/2.0
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.120.4.10:5060;branch=z9hG4bK10191bd0bb
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 2 [ 88]: From: sip:110010301@10.120.4.10;tag=8764~8fa62566-e1be-407f-a988-17cf779f66b8-29553229
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 3 [ 67]: To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=as174fdd0b
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 4 [ 35]: Date: Mon, 04 Mar 2013 14:13:09 GMT
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 5 [ 58]: Call-ID: 44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 7 [ 13]: CSeq: 103 ACK
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 8 [ 22]: Allow-Events: presence
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 10 [ 19]: Content-Length: 154
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Header 11 [ 0]:
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 0 [ 3]: v=0
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 1 [ 47]: o=CiscoSystemsCCM-SIP 8764 5 IN IP4 10.120.4.10
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 2 [ 10]: s=SIP Call
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.120.2.31
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 4 [ 5]: t=0 0
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 5 [ 23]: m=audio 21382 RTP/AVP 0
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Body 7 [ 10]: a=ptime:20
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] — (11 headers 8 lines) —
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: = Looking for Call ID: 44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060 (Checking From) --From tag 8764~8fa62566-e1be-407f-a988-17cf779f66b8-29553229 --To-tag as174fdd0b
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #161
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Stopping retransmission on ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ of Response 103: Match Found
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED.
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing session-level SDP o=CiscoSystemsCCM-SIP 8764 5 IN IP4 10.120.4.10… UNSUPPORTED.
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing session-level SDP s=SIP Call… UNSUPPORTED.
[2013-03-04 15:13:11.282] DEBUG[19988] netsock2.c: Splitting ‘10.120.2.31’ into…
[2013-03-04 15:13:11.282] DEBUG[19988] netsock2.c: …host ‘10.120.2.31’ and port ‘’.
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing session-level SDP c=IN IP4 10.120.2.31… OK.
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED.
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] Found RTP audio format 0
[2013-03-04 15:13:11.282] DEBUG[19988] rtp_engine.c: Setting payload 0 based on m type on 0x7f259e541db0
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] Found audio description format PCMU for ID 0
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000… OK.
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Processing media-level (audio) SDP a=ptime:20… OK.
[2013-03-04 15:13:11.282] DEBUG[19988] rtp_engine.c: Incorporating payload 0 on 0x7f259e541db0
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing)
[2013-03-04 15:13:11.282] DEBUG[19988] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7f2568003688’
[2013-03-04 15:13:11.282] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.282] Peer audio RTP is at port 10.120.2.31:21382
[2013-03-04 15:13:11.282] DEBUG[19988] rtp_engine.c: Copying payload 0 from 0x7f259e541db0 to 0x7f2568003850
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: We’re settling with these formats: 0x4 (ulaw)
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: We have an owner, now see if we need to change this call
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘378622661’ Method: ACK
[2013-03-04 15:13:11.282] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ Method: ACK
[2013-03-04 15:13:11.668] DEBUG[19988] chan_sip.c: SIP TIMER: Not rescheduling id #156:OPTIONS (Method 3) (No timer T1)
[2013-03-04 15:13:11.668] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.668] Retransmitting #4 (no NAT) to 10.245.8.49:5060:
OPTIONS sip:7701@10.245.8.49:5060 SIP/2.0
Via: SIP/2.0/UDP 10.245.8.12:5060;branch=z9hG4bK40dc677a
Max-Forwards: 70
From: “asterisk” sip:asterisk@10.245.8.12;tag=as609de6cf
To: sip:7701@10.245.8.49:5060
Contact: sip:asterisk@10.245.8.12:5060
Call-ID: 41c8f99655b923d934dac057418c17a5@10.245.8.12:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.8.7.1
Date: Mon, 04 Mar 2013 14:13:07 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0
[2013-03-04 15:13:11.668] DEBUG[19988] chan_sip.c: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 10.245.8.49:5060
[2013-03-04 15:13:11.668] DEBUG[19988] chan_sip.c: Destroying SIP dialog 41c8f99655b923d934dac057418c17a5@10.245.8.12:5060
[2013-03-04 15:13:11.668] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:11.668] Really destroying SIP dialog ‘41c8f99655b923d934dac057418c17a5@10.245.8.12:5060’ Method: OPTIONS
[2013-03-04 15:13:11.668] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘378622661’ Method: ACK
[2013-03-04 15:13:11.668] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ Method: ACK
[2013-03-04 15:13:12.669] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘378622661’ Method: ACK
[2013-03-04 15:13:12.669] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ Method: ACK
[2013-03-04 15:13:12.882] DEBUG[30772] res_rtp_asterisk.c: Got RTCP report of 112 bytes
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ changed end address to 10.120.2.31:21382 (format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ changed end vaddress to (null) (format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ changed end taddress to (null) (format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ was (null)/(format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ was (null)/(format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] rtp_engine.c: Oooh, ‘SIP/CiscoCallManager-00000001’ was (null)/(format ulaw)
[2013-03-04 15:13:12.882] DEBUG[30772] chan_sip.c: Sending reinvite on SIP ‘378622661’ - It’s audio soon redirected to IP 10.120.2.31:21382
[2013-03-04 15:13:12.882] DEBUG[30772] chan_sip.c: Strict routing enforced for session 378622661
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] set_destination: Parsing sip:toto@10.245.8.16 for address/port to send to
[2013-03-04 15:13:12.883] DEBUG[30772] netsock2.c: Splitting ‘10.245.8.16’ into…
[2013-03-04 15:13:12.883] DEBUG[30772] netsock2.c: …host ‘10.245.8.16’ and port ‘’.
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] set_destination: set destination to 10.245.8.16:5060
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: ** Our native-bridge filtered capablity: 0x4 (ulaw)
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] Audio is at 5060
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] Adding codec 0x4 (ulaw) to SDP
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] Adding non-codec 0x1 (telephone-event) to SDP
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: – Done with adding codecs to SDP
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Initializing already initialized SIP dialog 378622661 (presumably reinvite)
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 0 [ 35]: INVITE sip:toto@10.245.8.16 SIP/2.0
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.245.8.12:5060;branch=z9hG4bK0e61eb2f;rport
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 3 [ 54]: From: “POU” sip:110010301@10.245.8.12;tag=as27a0f010
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 4 [ 66]: To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=423554740
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 5 [ 41]: Contact: sip:110010301@10.245.8.12:5060
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 6 [ 18]: Call-ID: 378622661
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 7 [ 16]: CSeq: 103 INVITE
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 1.8.7.1
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 10 [ 26]: Supported: replaces, timer
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge)
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp
[2013-03-04 15:13:12.883] VERBOSE[30772] chan_sip.c: [2013-03-04 15:13:12.883] Reliably Transmitting (no NAT) to 10.245.8.16:5060:
INVITE sip:toto@10.245.8.16 SIP/2.0
Via: SIP/2.0/UDP 10.245.8.12:5060;branch=z9hG4bK0e61eb2f;rport
Max-Forwards: 70
From: “POU” sip:110010301@10.245.8.12;tag=as27a0f010
To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=423554740
Contact: sip:110010301@10.245.8.12:5060
Call-ID: 378622661
CSeq: 103 INVITE
User-Agent: Asterisk PBX 1.8.7.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 261
v=0
o=root 1332572859 1332572861 IN IP4 10.120.2.31
s=Asterisk PBX 1.8.7.1
c=IN IP4 10.120.2.31
t=0 0
m=audio 21382 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #163
[2013-03-04 15:13:12.883] DEBUG[30772] chan_sip.c: Trying to put ‘INVITE sip:’ onto UDP socket destined for 10.245.8.16:5060
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘378622661’ Method: ACK
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ Method: ACK
[2013-03-04 15:13:12.883] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:12.883]
<— SIP read from UDP:10.245.8.16:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.245.8.12:5060;branch=z9hG4bK0e61eb2f;rport=5060
From: “POU” sip:110010301@10.245.8.12;tag=as27a0f010
To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=423554740
Call-ID: 378622661
CSeq: 103 INVITE
User-Agent: Linphone/3.5.2 (eXosip2/3.6.0)
Content-Length: 0
<------------->
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 1 [ 67]: Via: SIP/2.0/UDP 10.245.8.12:5060;branch=z9hG4bK0e61eb2f;rport=5060
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 2 [ 54]: From: “POU” sip:110010301@10.245.8.12;tag=as27a0f010
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 3 [ 66]: To: “Emerg.Interf.” sip:11130154031031@10.245.8.12;tag=423554740
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 4 [ 18]: Call-ID: 378622661
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 5 [ 16]: CSeq: 103 INVITE
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 6 [ 42]: User-Agent: Linphone/3.5.2 (eXosip2/3.6.0)
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Header 7 [ 17]: Content-Length: 0
[2013-03-04 15:13:12.883] VERBOSE[19988] chan_sip.c: [2013-03-04 15:13:12.883] — (8 headers 0 lines) —
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: = Looking for Call ID: 378622661 (Checking To) --From tag as27a0f010 --To-tag 423554740
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: *** SIP TIMER: Cancelling retransmission #163 - INVITE (got response)
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘378622661’ Request 103: Found
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: SIP response 100 to RE-invite on outgoing call 378622661
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘378622661’ Method: ACK
[2013-03-04 15:13:12.883] DEBUG[19988] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog ‘44f9c052047f3ec9357eea83392b0987@10.245.8.12:5060’ Method: ACK[/code]
I’ll post the sip.conf later since it exceeds the maximum number of characters.