Asterisk 1.8.9 - Re-invites issue

system · February 3, 2012, 11:37pm

Hello,
I hope someone can help shed some light on this problem I’ve been experiencing. The issue is with one our international carriers we terminate traffic to. From their assessment, we are sending a re-invite request after acknowlegding their 200 ok request. We are sending a re-invite message for the same call with a different cseq number on which we are not changing any media or other invitation. When this happens, the call drops immediately when the remote end answers the phone (our carrier sends a 488 to drop the call).

I’ve reverted back to 1.4.43 because 1.6.x & 10.0 also exhibits the same behavior. In 1.4.43, we set canreinvite=no and the calls connect with no issues at all. From what I read in the changelog for 1.8.9, it states:

“…directmedia/canreinvite do not cause Asterisk to ignore reINVITEs. It is only used to stop Asterisk from generating a reINVITE, but does not stop it from accepting them if necessary…”

I’m baffled at what is causing our Asterisk box to send a re-invite to our carrier. I’ve tried different combinations of directmedia=/directrtpsetup/nat=/ but I’m unable to stop or find the reason that’s causing our Asterisk box to send re-invites. My debug log below is done with using G729a as passthrough because our carrier accepts G729a. See the bottom for the SIP history in the debug.

Here’s how our topology flows for those who want to know:
SIP signaling: ATA --> Proxy --> Asterisk --> Gateway --> Carrier

=====================================================================================
SIP.CONF

[general]
useragent = stggw01
udpbindaddr = MYASTERISK
allowguest = yes
ignoresdpversion = yes
match_auth_username = yes
realm = iworldaccounts.com
srvlookup = no
language = en
relaxdtmf = yes
trustrpid = yes
sendrpid = no
prematuremedia = no
progressinband = yes
sdpsession = iWorld
usereqphone = yes
dtmfmode = rfc2833
videosupport = yes
forwardloopdetected = no
session-timers = refuse
session-expires = 600
session-minse = 90
session-refresher = uas
allowsubscribe = no
directmedia = nonat
nat = no ; added
directrtpsetup = no ; added
allowexternaldomains = yes
jbenable = yes
autocreatepeer = yes
allowoverlap = no
allowtransfer = no
pedantic = no
usereqphone = yes
rtupdate = no
tos_sip=cs3 ; Sets TOS for SIP packets.
tos_audio=ef ; Sets TOS for RTP audio packets.
disallow = all
allow = g729
allow = g723.1
allow = ulaw
allow = ilbc
allow = gsm
allow = alaw
rtptimeout=60
rtpholdtimeout=300
autoframing=yes

[GW1G729]
host = MYGATEWAY
type = friend
disallow = all
allow = g729
directmedia=nonat

system · February 3, 2012, 11:38pm

---------- SIP HISTORY for ‘6091d6c860dcc10f14c86f165af0 [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: * [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 001. NewChan [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 002. TxReqRel [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 003. ReTx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 004. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 005. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 006. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 007. TxReq [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 008. ReInv [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 009. TxReqRel [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 010. ReTx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 011. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 012. TxReq [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 013. ReInv [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 014. TxReqRel [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 015. ReTx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 016. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 017. TxReq [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 018. ReInv [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 019. TxReqRel [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 020. Hangup [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 021. SchedDestroy [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 022. [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 023. ReTx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 024. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 025. TxReq [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 026. TxReqRel [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 027. SchedDestroy [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 028. Rx [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c: 029. NeedDestroy [2012-02-03 13:53:38] DEBUG[2917] chan_sip.c:
---------- END SIP HISTORY for ‘6091d6c860dcc10f14c86f16 [2012-02-03 13:53:38] DEBUG[2917] rtp_engine.c: Destroyed [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: Auto [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: Destroying [2012-02-03 13:54:09] VERBOSE[2917] chan_sip.c: Really [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: Destroying [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: -REALTIME- [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c:
---------- SIP HISTORY for 'b8152216-4de43ed1@192.168.8 [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: * [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 001. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 002. NewChan [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 003. TxResp [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 004. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 005. TxResp [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 006. TxResp [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 007. TxRespRel [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 008. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 009. ReInv [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 010. TxReqRel [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 011. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 012. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 013. TxReq [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 014. Rx [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 015. RTCPaudio [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 016. [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 017. RTCPaudioLoss [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 018. RTCPaudioRTT [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 019. SchedDestroy [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 020. TxResp [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 021. Hangup [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c: 022. AutoDestroy [2012-02-03 13:54:09] DEBUG[2917] chan_sip.c:
---------- END SIP HISTORY for 'b8152216-4de43ed1@192.1 [2012-02-03 13:54:09] DEBUG[2917] rtp_engine.c: Destroyed ab2d@MYASTERISK:5060’
SIP Call
Channel SIP/GW1G729-00000027 - from 6091d6c860dcc10f14c86f165af
INVITE / 102 INVITE - INVITE
1000 INVITE sip:CARRIER011919838878657@MYGATEWAY SIP/2.0
SIP/2.0 / 102 INVITE / 183 Session Progress
SIP/2.0 / 102 INVITE / 180 Ringing
SIP/2.0 / 102 INVITE / 200 OK
ACK / 102 ACK - ACK
Re-invite sent
INVITE / 103 INVITE - INVITE
1000 INVITE sip:011919838878657@CARRIER:5060 SIP/2.0
SIP/2.0 / 103 INVITE / 200 OK
ACK / 103 ACK - ACK
Re-invite sent
INVITE / 104 INVITE - INVITE
1000 INVITE sip:011919838878657@CARRIER:5060 SIP/2.0
SIP/2.0 / 104 INVITE / 200 OK
ACK / 104 ACK - ACK
Re-invite sent
INVITE / 105 INVITE - INVITE
Cause Normal Clearing
32000 ms
CancelDestroy
1000 INVITE sip:011919838878657@CARRIER:5060 SIP/2.0
SIP/2.0 / 105 INVITE / 200 OK
ACK / 105 ACK - ACK
BYE / 106 BYE - BYE
32000 ms
SIP/2.0 / 106 BYE / 200 OK
Setting needdestroy because received 200 response
5af0ab2d@MYASTERISK:5060’
RTP instance ‘0x7f718c005f28’
destroying SIP dialog 'b8152216-4de43ed1@192.168.8.x’
SIP dialog b8152216-4de43ed1@192.168.8.x
destroying SIP dialog 'b8152216-4de43ed1@192.168.8.x’ Method: BYE
SIP peer SIPACCOUNT
peer Destroyed. Name: SIPACCOUNT. Realtime Peer objects: 0
.x’
SIP Call
INVITE / 102 INVITE / sip:919838878657@MYPROXY
Channel SIP/SIPACCOUNT-00000026 - from b8152216-4de43ed1@192.
SIP/2.0 / 102 INVITE - 100 Trying
INVITE / 102 INVITE / sip:919838878657@MYPROXY
SIP/2.0 / 102 INVITE - 100 Trying
SIP/2.0 / 102 INVITE - 183 Session Progress
SIP/2.0 / 102 INVITE - 200 OK
ACK / 102 ACK / sip:919838878657@MYASTERISK:5060
Re-invite sent
INVITE / 102 INVITE - INVITE
SIP/2.0 / 102 INVITE / 100 Giving a try
SIP/2.0 / 102 INVITE / 200 OK
ACK / 102 ACK - ACK
BYE / 103 BYE / sip:919838878657@MYASTERISK:5060
Quality:ssrc=688776254;themssrc=4029104110;lp=0;rxjitter=0.0056
RTCPaudioJitter Quality:minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0
Quality:minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.00000
Quality:minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrt
32000 ms
SIP/2.0 / 103 BYE - 200 OK
Cause Normal Clearing
b8152216-4de43ed1@192.168.8.x
68.8.x’
RTP instance ‘0x7f71d80060e8’

system · February 3, 2012, 11:40pm

.

david55 · February 4, 2012, 1:05am

If you had said this only affected 1.8 and 1.10, I would have said it was updating the connected line information. I believe this can be frustrated by disabling the use of RPID, although the service provide is broken if they drop the call on a reinvite. If they don’t like it they should reject it and continue the call.

system · February 8, 2012, 8:24pm

Hello David,
I’m still having the same issue, the call will drop on a re-invite. Do you have any further suggestions? I’ve tried your suggestion with different combinations of the following settings:

trustrpid = yes/no
sendrpid = yes/rpid/pai/no
rpid_update = no/yes

How do I configure the inbound and outbound leg to be bridged within my asterisk and not an attempt to divert/update the original call mid-transaction/process on our carriers’ servers?

I’ve included the debug messages for the Re-invite and the SIP history at the end of the call.

[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729)
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c: Initializing already initialized SIP dialog 4a6673cf1c6f4af117a4f8e6586456cf@MYASTERISK:5060 (presumably reinvite)
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  0 [ 55]: INVITE sip:94771542226@CARRIER:5060 SIP/2.0
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  1 [ 57]: Via: SIP/2.0/UDP MYASTERISK:5060;branch=z9hG4bK436eb151
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  2 [ 83]: Route: <sip:94771542226@MYGATEWAY;lr=on;ftag=as25fa33e2;did=56d.4bb499c1>
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  3 [ 16]: Max-Forwards: 70
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  4 [ 65]: From: "SIPACCOUNT" <sip:SIPACCOUNT@MYASTERISK>;tag=as25fa33e2
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  5 [ 74]: To: <sip:94771542226@MYGATEWAY;user=phone>;tag=3537720169-765117
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  6 [ 44]: Contact: <sip:SIPACCOUNT@MYASTERISK:5060>
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  7 [ 59]: Call-ID: 4a6673cf1c6f4af117a4f8e6586456cf@MYASTERISK:5060
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  8 [ 16]: CSeq: 103 INVITE
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header  9 [ 19]: User-Agent: MYASTERISK
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header 10 [ 37]: Access-URL: <94771542226>;mode=active
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header 11 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header 12 [ 19]: Supported: replaces
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header 13 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge)
[2012-02-08 12:02:51] DEBUG[4855] chan_sip.c:  Header 14 [ 29]: Content-Type: application/sdp



---------- SIP HISTORY for '4a6673cf1c6f4af117a4f8e6586456cf@MYASTERISK:5060'
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   * SIP Call
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   001. NewChan         Channel SIP/DIAL-00000049 - from 4a6673cf1c6f4af117a4f8e6586
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   002. TxReqRel        INVITE / 102 INVITE - INVITE
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   003. ReTx            1000 INVITE sip:94771542226@MYGATEWAY;user=phone SIP/
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   004. ReTx            2000 INVITE sip:94771542226@MYGATEWAY;user=phone SIP/
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   005. ReTx            4000 INVITE sip:94771542226@MYGATEWAY;user=phone SIP/
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   006. ReTx            8000 INVITE sip:94771542226@MYGATEWAY;user=phone SIP/
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   007. Rx              SIP/2.0 / 102 INVITE / 183 Session Progress
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   008. Rx              SIP/2.0 / 102 INVITE / 200 OK
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   009. TxReq           ACK / 102 ACK - ACK
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   010. ReInv           Re-invite sent
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   011. TxReqRel        INVITE / 103 INVITE - INVITE
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   012. Rx              SIP/2.0 / 103 INVITE / 488 Not Acceptable Here
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   013. TxReq           ACK / 103 ACK - ACK
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   014. NeedDestroy     Setting needdestroy because received 488 response
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   015. Hangup          Cause Bearer capability not available
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   016. SchedDestroy    32000 ms
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   017. RTCPaudio       Quality:ssrc=1033111065;themssrc=818934718;lp=0;rxjitter=0.0037
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   018. TxReqRel        BYE / 104 BYE - BYE
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   019. Rx              SIP/2.0 / 104 BYE / 200 OK
[2012-02-08 12:02:52] DEBUG[4584] chan_sip.c:   020. NeedDestroy     Setting needdestroy because received 200 response

system · February 8, 2012, 11:14pm

[2012-02-08 12:43:56] VERBOSE[4584] chan_sip.c: --- (16 headers 13 lines) ---
[2012-02-08 12:43:56] DEBUG[4584] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2012-02-08 12:43:56] DEBUG[4584] chan_sip.c: Ignoring SIP message because of retransmit (INVITE Seqno 102, ours 102)
[2012-02-08 12:43:56] VERBOSE[4584] chan_sip.c: Ignoring this INVITE request
[2012-02-08 12:43:56] DEBUG[4584] chan_sip.c: Got a SIP re-transmit of INVITE for call 3cebae56-610b9cbb@192.168.4.123
[2012-02-08 12:43:56] VERBOSE[4584] chan_sip.c:

david55 · February 8, 2012, 11:53pm

directmedia should be no, not nonat. nonat only applies when Asterisk is on a public network and the peer is not. You almost certainly have the reverse case.

system · February 9, 2012, 5:34pm

Hello David,
I tried with directmedia=no/nonat/yes and the results are the same. Again, when we downgrade back to 1.4.43 using canreinvite=no, the problem doesn’t exist. But since directmedia= was introduced, we started seeing this problem. Any other suggestions.?

david55 · February 9, 2012, 5:50pm

directmedia is just a renaming of canreinvite, as there are other reasons for reinvites, so the original name was misleading.

I note that it says “X-asterisk-Info: SIP re-invite (External RTP bridge)” which means it is due to the use of directmedia.

The channel name doesn’t look right. I would expect SIP/GW1G729-…, although maybe this is a 1.8 thing. Previous versions would have used the target address when not using sip.conf, and the sip.conf section name, when using it. Are you doing that? (putting the target address in sip.conf, rather than referencing the sip.conf section name? That would cause you to get the default directmedia setting.

Generally including the dialplan CLI output from, at least, verbose level 3, makes it much easier to see what is going on.