[asterisk-dev] Maximum retries exceeded on transmission issue.

Mon Jun 23 04:49:14 CDT 2008

Hi guys,

I have a system which is disconnecting between 3 and 6 calls per day with a
maximum retries exceeded on transmission error.

I have turned on SIP debug and found that it retries 6 times to send a 200
OK to the remote host and then terminates the call with a BYE. (See below
for log excerpts.) The person ringing in just keeps on ringing until a
timeout at the host is reached and the maximum retries are exceeded once the
phone call has been answered.

Seeing as it is intermittent and fairly similar to this post
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg178034.html I
was wondering if I have the same issue and wanted to chang the setting in
chan_sip.c. Would someone be able to confirm that the line I should adjust
(so the call is no longer terminated if the other side of the conversation
doesn't respect the 200 OK) is

res = transmit_response_with_sdp(p, "200 OK", &p->initreq, XMIT_CRITICAL);

and what values in the line I should change.

Whilst I believe all the NAT settings are correct, I am also going to change
the network layout so the server has a direct pulic IP address on one
interface and an internal IP address on the second interface so we can avoid
any issues related to NAT.

Thanks for your assistance.

The log (trimmed but I think there might be a second call in here as well):

[Jun 23 15:45:22] VERBOSE[2687] logger.c:
<--- SIP read from xxx.x.xx.xxx:5060 --->
INVITE sip:0xxxxxxxxx at xxx.x.xx.xxx:5060 SIP/2.0
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4
Max-Forwards: 69
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
Supported: em,timer,replaces,path
Allow:
REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
User-Agent: VIC-VOGW-01/v.4.80A.012.010
Content-Type: application/sdp
Content-Length: 304
Date: Mon, 23 Jun 2008 05:45:22 GMT
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx:5060;transport=udp>

v=0
o=AudiocodesGW 1359890123 1359889824 IN IP4 xxx.x.xx.xxx
s=Phone-Call
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 14988 RTP/AVP 18 8 101
c=IN IP4 xxx.x.xx.xxx
a=rtpmap:18 g729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 pcma/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

<------------->
[Jun 23 15:45:22] VERBOSE[2687] logger.c: --- (14 headers 14 lines) ---
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Sending to xxx.x.xx.xxx : 5060
(NAT)
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Using INVITE request as basis
request - 1359909400236200854521
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found peer 'XxxXxxxx-2'
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found RTP audio format 18
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found RTP audio format 8
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found RTP audio format 101
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Peer audio RTP is at port
xxx.x.xx.xxx:14988
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found audio description format
g729 for ID 18
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found audio description format
pcma for ID 8
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Found audio description format
telephone-event for ID 101
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Capabilities: us - 0x10c
(ulaw|alaw|g729), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing),
combined - 0x108 (alaw|g729)
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Non-codec capabilities (dtmf): us
- 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1
(telephone-event)
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Peer audio RTP is at port
xxx.x.xx.xxx:14988
[Jun 23 15:45:22] VERBOSE[2687] logger.c: Looking for 0xxxxxxxxx in
custom-get-did-from-sip (domain xxx.x.xx.xxx)
[Jun 23 15:45:22] VERBOSE[2687] logger.c: list_route: hop:
<sip:0xxxxxxxxx at xxx.x.xx.xxx:5060;transport=udp>
[Jun 23 15:45:22] VERBOSE[2687] logger.c:
<--- Transmitting (NAT) to xxx.x.xx.xxx:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Length: 0

[Jun 23 15:45:22] DEBUG[4737] chan_sip.c: Call to peer '201' is 2 out of 50
[Jun 23 15:45:22] VERBOSE[4737] logger.c: Audio is at 10.0.0.120 port 14000
[Jun 23 15:45:22] VERBOSE[4737] logger.c: Adding codec 0x8 (alaw) to SDP
[Jun 23 15:45:22] VERBOSE[4737] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jun 23 15:45:22] VERBOSE[4737] logger.c: Adding non-codec 0x1
(telephone-event) to SDP
[Jun 23 15:45:22] VERBOSE[4737] logger.c: Reliably Transmitting (no NAT) to
10.0.0.220:5060:
INVITE sip:201 at 10.0.0.220:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.120:5060;branch=z9hG4bK7bf65928;rport
From: "0xxxxxxxxx" <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>
>;tag=as6886acbe
To: <sip:201 at 10.0.0.220:5060>
Contact: <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>>
Call-ID: 37a77d2663c1934c3a04957a59b4878e at 10.0.0.120
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Mon, 23 Jun 2008 05:45:22 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 258

v=0
o=root 2596 2596 IN IP4 10.0.0.120
s=session
c=IN IP4 10.0.0.120
t=0 0
m=audio 14000 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

[Jun 23 15:45:42] VERBOSE[2687] logger.c:
<--- SIP read from 10.0.0.220:5060 --->
SIP/2.0 200 OK
To: <sip:201 at 10.0.0.220:5060>;tag=605a42dafdadd833i0
From: "0xxxxxxxxx" <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>
>;tag=as6886acbe
Call-ID: 37a77d2663c1934c3a04957a59b4878e at 10.0.0.120
CSeq: 103 BYE
Via: SIP/2.0/UDP 10.0.0.120:5060;branch=z9hG4bK57799f65
Server: Linksys/SPA942-5.2.8
Content-Length: 0

<------------->
[Jun 23 15:45:42] VERBOSE[2687] logger.c: --- (8 headers 0 lines) ---
[Jun 23 15:45:42] VERBOSE[2687] logger.c: Really destroying SIP dialog '
37a77d2663c1934c3a04957a59b4878e at 10.0.0.120' Method: INVITE
[Jun 23 15:45:42] VERBOSE[2687] logger.c: Retransmitting #1 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 23 15:45:42] VERBOSE[2687] logger.c: Retransmitting #2 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 23 15:45:42] VERBOSE[2687] logger.c: Retransmitting #3 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 23 15:45:43] VERBOSE[2687] logger.c: Retransmitting #4 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 23 15:45:45] VERBOSE[2687] logger.c: Retransmitting #5 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 23 15:45:45] VERBOSE[2687] logger.c:
<--- SIP read from 10.0.0.220:5060 --->
BYE sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120> SIP/2.0
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bK-6da3d2e2
From: <sip:201 at 10.0.0.220 <sip%3A201 at 10.0.0.220>>;tag=7ae697d099518d81i0
To: "0xxxxxxxxx" <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>
>;tag=as2b6c1d69
Call-ID: 2975319b72894a2c4151361567c5b360 at 10.0.0.120
CSeq: 105 BYE
Max-Forwards: 70
User-Agent: Linksys/SPA942-5.2.8
Content-Length: 0

<------------->
[Jun 23 15:45:45] VERBOSE[2687] logger.c: --- (9 headers 0 lines) ---
[Jun 23 15:45:45] VERBOSE[2687] logger.c: Sending to 10.0.0.220 : 5060 (no
NAT)
[Jun 23 15:45:45] VERBOSE[2687] logger.c: Scheduling destruction of SIP
dialog '2975319b72894a2c4151361567c5b360 at 10.0.0.120' in 6400 ms (Method:
BYE)
[Jun 23 15:45:45] VERBOSE[2687] logger.c:
<--- Transmitting (no NAT) to 10.0.0.220:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bK-6da3d2e2;received=10.0.0.220
From: <sip:201 at 10.0.0.220 <sip%3A201 at 10.0.0.220>>;tag=7ae697d099518d81i0
To: "0xxxxxxxxx" <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>
>;tag=as2b6c1d69
Call-ID: 2975319b72894a2c4151361567c5b360 at 10.0.0.120
CSeq: 105 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at 10.0.0.120 <sip%3A0xxxxxxxxx at 10.0.0.120>>
Content-Length: 0

<------------>
[Jun 23 15:45:48] VERBOSE[2687] logger.c: Retransmitting #6 (NAT) to
xxx.x.xx.xxx:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
xxx.x.xx.xxx:5060;branch=z9hG4bK788e32928c747f8eac98e4e3d60214a4;received=xxx.x.xx.xxx
From: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx>;tag=1c1359910123
To: <sip:0xxxxxxxxx at xxx.xxxxxxxx.xxx.xx;user=phone>;tag=as3c4944c2
Call-ID: 1359909400236200854521
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0xxxxxxxxx at xxx.x.xx.xxx>
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 2596 2596 IN IP4 xxx.x.xx.xxx
s=session
c=IN IP4 xxx.x.xx.xxx
t=0 0
m=audio 12734 RTP/AVP 8 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

[Jun 23 15:45:51] VERBOSE[2687] logger.c: SIP Response message for INCOMING
dialog BYE arrived
[Jun 23 15:45:51] VERBOSE[2687] logger.c: Really destroying SIP dialog '
2975319b72894a2c4151361567c5b360 at 10.0.0.120' Method: BYE
[Jun 23 15:45:52] WARNING[2687] chan_sip.c: Maximum retries exceeded on
transmission 1359909400236200854521 for seqno 1 (Critical Response)
[Jun 23 15:45:52] VERBOSE[2687] logger.c: Really destroying SIP dialog
'1359909400236200854521' Method: BYE
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-dev/attachments/20080623/e5babd6e/attachment-0001.htm 