ASTERISK-12009: Asterisk replies with VNAK (and wrong destination call) to AUTHREQ to its NEW (sometimes) when call bounced back.

[Home]

Summary: ASTERISK-12009: Asterisk replies with VNAK (and wrong destination call) to AUTHREQ to its NEW (sometimes) when call bounced back.

Reporter: Lionel Elie Mamane (lmamane) Labels:

Date Opened: 2008-05-12 17:19:44 Date Closed: 2008-05-29 13:51:04

Priority: Major Regression? No

Status: Closed/Complete Components: Channels/chan_iax2

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) A-console-with-IAX-debug
( 1) foo
( 2) T-console-with-IAX-debug

Description: Two asterisk boxes, A and T. T is 82.95.233.223 and A is 193.202.115.224. Both machines run Asterisk 1.4.19.1.
T makes an IAX2 call to A (through a peer/user association and RSA authentication or through DUNDi, the problem happens in both cases), which ends up executing this in the dialplan of A:

Dial(Local/1010@lemfat-lookup&Local/1012@lemfat-lookup&SIP/lionel&IAX2/lionel)

Local/1010@lemfat-lookup itself through a DUNDi lookup is an IAX2 call back to T, of the form:
dundi:SECRET@82.95.233.223/1010@incoming-lemfat
thus _not_ using the same peer/user association, but the DUNDi user with its rotating secret system.

Sometimes, that call works fine, and sometimes it doesn't. When it doesn't work, A's console says:

-- Executing [1001@incoming-lemfat:1] Dial("IAX2/dundi-11958", "Local/1010@lemfat-lookup&Local/1012@lemfat-lookup&SIP/lionel&IAX2/lionel") in new stack
-- Called 1010@lemfat-lookup
-- Called 1012@lemfat-lookup
-- Called dundi:SECRET@88.207.241.223/1012@incoming-lemfat
-- Called dundi:SECRET@82.95.233.223/1010@incoming-lemfat
-- Hungup 'IAX2/82.95.233.223:4569-6823'
== Everyone is busy/congested at this time (1:0/0/1)

and T's console does not register the call at all.

Running a wireshark on T shows the following sequence of IAX2 packets:

Internet Protocol, Src: 82.95.233.223 (82.95.233.223), Dst: 193.202.115.224 (193.202.115.224)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.011 0011 0001 0101 = Source call: 13077
.000 0000 0000 0000 = Destination call: 0
0... .... .... .... = Retransmission: False
[Call identifier: 39]
Timestamp: 10
[Absolute Time: May 12, 2008 22:53:20.159322000]
[Lateness: -0.009000000 seconds]
Outbound seq.no.: 0
Inbound seq.no.: 0
Type: IAX (6)
IAX subclass: NEW (1)
Internet Protocol, Src: 193.202.115.224 (193.202.115.224), Dst: 82.95.233.223 (82.95.233.223)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.010 1110 1011 0110 = Source call: 11958
.011 0011 0001 0101 = Destination call: 13077
0... .... .... .... = Retransmission: False
[Call identifier: 39]
Timestamp: 11
[Absolute Time: May 12, 2008 22:53:20.160322000]
[Lateness: 0.004056000 seconds]
Outbound seq.no.: 0
Inbound seq.no.: 1
Type: IAX (6)
IAX subclass: AUTHREQ (8)
Internet Protocol, Src: 82.95.233.223 (82.95.233.223), Dst: 193.202.115.224 (193.202.115.224)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.011 0011 0001 0101 = Source call: 13077
.010 1110 1011 0110 = Destination call: 11958
0... .... .... .... = Retransmission: False
[Call identifier: 39]
Timestamp: 26
[Absolute Time: May 12, 2008 22:53:20.175322000]
[Lateness: -0.008908000 seconds]
Outbound seq.no.: 1
Inbound seq.no.: 1
Type: IAX (6)
IAX subclass: AUTHREP (9)
Internet Protocol, Src: 193.202.115.224 (193.202.115.224), Dst: 82.95.233.223 (82.95.233.223)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.010 1110 1011 0110 = Source call: 11958
.011 0011 0001 0101 = Destination call: 13077
0... .... .... .... = Retransmission: False
[Call identifier: 39]
Timestamp: 26
[Absolute Time: May 12, 2008 22:53:20.175322000]
[Lateness: 0.004305000 seconds]
Outbound seq.no.: 1
Inbound seq.no.: 2
Type: IAX (6)
IAX subclass: ACCEPT (7)
Internet Protocol, Src: 82.95.233.223 (82.95.233.223), Dst: 193.202.115.224 (193.202.115.224)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.011 0011 0001 0101 = Source call: 13077
.010 1110 1011 0110 = Destination call: 11958
0... .... .... .... = Retransmission: False
[Call identifier: 39]
Timestamp: 26
[Absolute Time: May 12, 2008 22:53:20.175322000]
[Lateness: 0.006499000 seconds]
Outbound seq.no.: 2
Inbound seq.no.: 2
Type: IAX (6)
IAX subclass: ACK (4)

That is, the call from T to A goes correctly. Now, the call from A to T:

Internet Protocol, Src: 193.202.115.224 (193.202.115.224), Dst: 82.95.233.223 (82.95.233.223)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.001 1010 1010 0111 = Source call: 6823
.000 0000 0000 0000 = Destination call: 0
0... .... .... .... = Retransmission: False
[Call identifier: 41]
Timestamp: 7
[Absolute Time: May 12, 2008 22:53:20.265737000]
[Lateness: -0.006000000 seconds]
Outbound seq.no.: 0
Inbound seq.no.: 0
Type: IAX (6)
IAX subclass: NEW (1)
Internet Protocol, Src: 82.95.233.223 (82.95.233.223), Dst: 193.202.115.224 (193.202.115.224)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.011 0010 1101 0000 = Source call: 13008
.001 1010 1010 0111 = Destination call: 6823
0... .... .... .... = Retransmission: False
[Call identifier: 41]
Timestamp: 1
[Absolute Time: May 12, 2008 22:53:20.259737000]
[Lateness: 0.002017000 seconds]
Outbound seq.no.: 0
Inbound seq.no.: 1
Type: IAX (6)
IAX subclass: AUTHREQ (8)
Internet Protocol, Src: 193.202.115.224 (193.202.115.224), Dst: 82.95.233.223 (82.95.233.223)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.001 1010 1010 0111 = Source call: 6823
.011 0011 0001 0101 = Destination call: 13077
0... .... .... .... = Retransmission: False
Timestamp: 10
Outbound seq.no.: 0
Inbound seq.no.: 0
Type: IAX (6)
IAX subclass: VNAK (18)

Note that the VNAK comes with the wrong destination call number! It is the destination call of the T->A call, but it is sent in answer to the AUTHREQ of the A->T call! T used to be Asterisk 1.4.18.1 and replied by resending the AUTHREQ, which triggered an INVAL and VNAK from A (Asterisk 1.4.19.1) and again an INVAL from T and thus ended the call, but I upgraded T to Asterisk 1.4.19.1 and now it replies with an INVAL directly:

Internet Protocol, Src: 82.95.233.223 (82.95.233.223), Dst: 193.202.115.224 (193.202.115.224)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.011 0011 0001 0101 = Source call: 13077
.001 1010 1010 0111 = Destination call: 6823
0... .... .... .... = Retransmission: False
Timestamp: 0
Outbound seq.no.: 0
Inbound seq.no.: 0
Type: IAX (6)
IAX subclass: INVAL (10)
Internet Protocol, Src: 193.202.115.224 (193.202.115.224), Dst: 82.95.233.223 (82.95.233.223)
User Datagram Protocol, Src Port: iax (4569), Dst Port: iax (4569)
Inter-Asterisk eXchange v2
Packet type: Full packet (1)
.001 1010 1010 0111 = Source call: 6823
.011 0010 1101 0000 = Destination call: 13008
0... .... .... .... = Retransmission: False
[Call identifier: 41]
Timestamp: 0
[Absolute Time: May 12, 2008 22:53:20.258737000]
[Lateness: 0.016007000 seconds]
Outbound seq.no.: 0
Inbound seq.no.: 0
Type: IAX (6)
IAX subclass: INVAL (10)

Here is the chan_iax debug output on A (from another instance of the problem, so the call numbers will not match with the wireshark-captured packets, sorry):

[May 12 23:52:45] DEBUG[4429] chan_iax2.c: New max nontrunk callno is 13704
[May 12 23:52:45] DEBUG[4429] chan_iax2.c: Creating new call structure 13703
[May 12 23:52:45] DEBUG[4429] chan_iax2.c: Received packet 0, (6, 1)
[May 12 23:52:45] DEBUG[4429] chan_iax2.c: IAX subclass 1 received
[May 12 23:52:45] DEBUG[4429] chan_iax2.c: For call=13703, set last=8
[May 12 23:52:45] DEBUG[4437] chan_iax2.c: Sending 10 on 13703/5011 to 82.95.233.223:4569
[May 12 23:52:45] DEBUG[4427] chan_iax2.c: Received packet 1, (6, 9)
[May 12 23:52:45] DEBUG[4427] chan_iax2.c: Cancelling transmission of packet 0
[May 12 23:52:45] DEBUG[4427] chan_iax2.c: IAX subclass 9 received
[May 12 23:52:45] DEBUG[4427] chan_iax2.c: For call=13703, set last=24
[May 12 23:52:45] DEBUG[4427] chan_iax2.c: We don't do requested format alaw, falling back to peer capability 60030
[May 12 23:52:45] DEBUG[4437] chan_iax2.c: Sending 26 on 13703/5011 to 82.95.233.223:4569
[May 12 23:52:45] DEBUG[4435] chan_iax2.c: Received packet 2, (6, 4)
[May 12 23:52:45] DEBUG[4435] chan_iax2.c: Cancelling transmission of packet 1
[May 12 23:52:45] DEBUG[4435] chan_iax2.c: IAX subclass 4 received
[May 12 23:52:45] DEBUG[4432] chan_iax2.c: Received packet 2, (2, 4)
[May 12 23:52:45] DEBUG[4432] chan_iax2.c: Ooh, voice format changed to 4
[May 12 23:52:45] DEBUG[4432] chan_iax2.c: Sending 60 on 13703/5011 to 82.95.233.223:4569
[May 12 23:52:45] DEBUG[4432] chan_iax2.c: For call=13703, set last=60
[May 12 23:52:45] DEBUG[4428] chan_iax2.c: For call=13703, set last=80
[May 12 23:52:46] DEBUG[4433] chan_iax2.c: For call=13703, set last=100
[May 12 23:52:46] DEBUG[17095] chan_iax2.c: New max nontrunk callno is 13704
[May 12 23:52:46] DEBUG[17095] chan_iax2.c: Creating new call structure 845
[May 12 23:52:46] DEBUG[4437] chan_iax2.c: Sending 3 on 845/0 to 82.95.233.223:4569
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 82.95.233.223
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 82.95.233.223
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: Received mini frame before first full voice frame
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: Sending 10 on 845/5011 to 82.95.233.223:4569
[May 12 23:52:46] DEBUG[4434] chan_iax2.c: Raw Hangup 82.95.233.223:4569, src=845, dst=10037
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: Received packet 0, (6, 10)
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: IAX subclass 10 received
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: Immediately destroying 845, having received INVAL
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: Destroying call 845
[May 12 23:52:46] DEBUG[4430] chan_iax2.c: Received mini frame before first full voice frame
[May 12 23:52:46] DEBUG[4427] chan_iax2.c: Received mini frame before first full voice frame
[May 12 23:52:46] DEBUG[17095] chan_iax2.c: We're hanging up IAX2/82.95.233.223:4569-845 with cause 0 now...
[May 12 23:52:46] DEBUG[17095] chan_iax2.c: Really destroying IAX2/82.95.233.223:4569-845 now...
[May 12 23:52:46] DEBUG[17096] chan_iax2.c: New max nontrunk callno is 13704
[May 12 23:52:46] DEBUG[17096] chan_iax2.c: Creating new call structure 8460
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 82.95.233.223
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 82.95.233.223
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 88.207.241.223
[May 12 23:52:46] DEBUG[4420] chan_iax2.c: Checking device state for device 88.207.241.223
[May 12 23:52:46] DEBUG[4437] chan_iax2.c: Sending 4 on 8460/0 to 88.207.241.223:4569
[May 12 23:52:46] DEBUG[4435] chan_iax2.c: For call=13703, set last=180
[May 12 23:52:46] DEBUG[4432] chan_iax2.c: For call=13703, set last=200
[May 12 23:52:46] DEBUG[4426] chan_iax2.c: Received packet 0, (6, 8)
[May 12 23:52:46] DEBUG[4426] chan_iax2.c: Cancelling transmission of packet 0
[May 12 23:52:46] DEBUG[4426] chan_iax2.c: IAX subclass 8 received
[May 12 23:52:46] DEBUG[4426] chan_iax2.c: For call=8460, set last=4
[May 12 23:52:46] DEBUG[4437] chan_iax2.c: Sending 39 on 8460/3 to 88.207.241.223:4569
[May 12 23:52:46] DEBUG[4428] chan_iax2.c: For call=13703, set last=220
[May 12 23:52:46] DEBUG[4433] chan_iax2.c: For call=13703, set last=240
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: Received packet 1, (6, 7)
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: Cancelling transmission of packet 1
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: IAX subclass 7 received
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: For call=8460, set last=38
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: Sending 38 on 8460/3 to 88.207.241.223:4569
[May 12 23:52:46] DEBUG[4434] chan_iax2.c: For call=13703, set last=260
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: Received packet 2, (4, 3)
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: Sending 41 on 8460/3 to 88.207.241.223:4569
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: For call=8460, set last=41
[May 12 23:52:46] DEBUG[17094] chan_iax2.c: Indicating condition 3
[May 12 23:52:46] DEBUG[4437] chan_iax2.c: Sending 268 on 13703/5011 to 82.95.233.223:4569
[May 12 23:52:46] DEBUG[4430] chan_iax2.c: For call=13703, set last=280
[May 12 23:52:46] DEBUG[4427] chan_iax2.c: Received packet 3, (6, 4)
[May 12 23:52:46] DEBUG[4427] chan_iax2.c: Cancelling transmission of packet 2
[May 12 23:52:46] DEBUG[4427] chan_iax2.c: IAX subclass 4 received
[May 12 23:52:46] DEBUG[4435] chan_iax2.c: For call=13703, set last=300
[May 12 23:52:46] DEBUG[4432] chan_iax2.c: For call=13703, set last=320
[May 12 23:52:46] DEBUG[4426] chan_iax2.c: For call=13703, set last=340
[May 12 23:52:46] DEBUG[4428] chan_iax2.c: For call=13703, set last=360
[May 12 23:52:46] DEBUG[4433] chan_iax2.c: For call=13703, set last=380
[May 12 23:52:46] DEBUG[4431] chan_iax2.c: For call=13703, set last=400
[May 12 23:52:46] DEBUG[4434] chan_iax2.c: For call=13703, set last=420
[May 12 23:52:46] DEBUG[4429] chan_iax2.c: For call=13703, set last=440
[May 12 23:52:46] DEBUG[4430] chan_iax2.c: For call=13703, set last=460
[May 12 23:52:46] DEBUG[4427] chan_iax2.c: For call=13703, set last=480
[May 12 23:52:46] DEBUG[4435] chan_iax2.c: For call=13703, set last=500

Comments: By: Russell Bryant (russell) 2008-05-12 17:22:24

iax2 debug output?
By: Lionel Elie Mamane (lmamane) 2008-05-12 17:24:16

I pasted it in the "description"! Where has it disappeared?
By: Lionel Elie Mamane (lmamane) 2008-05-12 17:27:31

It seems Mantis doesn't like my bug description as a description or as note, it comes out blank. I put it in the attached file "foo" which I attached.
By: Russell Bryant (russell) 2008-05-13 13:16:18

The changes I did in 1.4.19.1 for the security issue destroyed IAX2 performance. :( However, 1.4.19.2 is now available which addresses those issues. Please give it a try to see if your issue goes away. It's possible that it was a side effect ...
By: Lionel Elie Mamane (lmamane) 2008-05-17 19:23:22

I've upgraded to 1.4.19.2 on both sides and cannot reproduce the issue anymore. Whether this is because it is solved at its root or the race condition window got smaller, I don't know.
By: Digium Subversion (svnbot) 2008-05-29 13:42:56

Repository: asterisk
Revision: 119009

_U branches/1.4/
U branches/1.4/channels/chan_iax2.c

------------------------------------------------------------------------
r119009 | russell | 2008-05-29 13:42:55 -0500 (Thu, 29 May 2008) | 16 lines

Merged revisions 119008 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.2

........
r119008 | russell | 2008-05-29 13:45:21 -0500 (Thu, 29 May 2008) | 7 lines

Merge changes from team/russell/iax2-another-fix-to-the-fix

As described in the following post to the asterisk-dev mailing list, only
enforce destination call numbers when processing an ACK.

http://lists.digium.com/pipermail/asterisk-dev/2008-May/033217.html

(closes issue ASTERISK-12009)
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=119009
By: Digium Subversion (svnbot) 2008-05-29 13:47:59

Repository: asterisk
Revision: 119010

_U trunk/
U trunk/channels/chan_iax2.c

------------------------------------------------------------------------
r119010 | russell | 2008-05-29 13:47:58 -0500 (Thu, 29 May 2008) | 24 lines

Merged revisions 119009 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

................
r119009 | russell | 2008-05-29 13:49:12 -0500 (Thu, 29 May 2008) | 16 lines

Merged revisions 119008 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.2

........
r119008 | russell | 2008-05-29 13:45:21 -0500 (Thu, 29 May 2008) | 7 lines

Merge changes from team/russell/iax2-another-fix-to-the-fix

As described in the following post to the asterisk-dev mailing list, only
enforce destination call numbers when processing an ACK.

http://lists.digium.com/pipermail/asterisk-dev/2008-May/033217.html

(closes issue ASTERISK-12009)
........

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=119010
By: Digium Subversion (svnbot) 2008-05-29 13:51:04

Repository: asterisk
Revision: 119011

_U branches/1.6.0/
U branches/1.6.0/channels/chan_iax2.c

------------------------------------------------------------------------
r119011 | russell | 2008-05-29 13:51:04 -0500 (Thu, 29 May 2008) | 32 lines

Merged revisions 119010 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r119010 | russell | 2008-05-29 13:54:11 -0500 (Thu, 29 May 2008) | 24 lines

Merged revisions 119009 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

................
r119009 | russell | 2008-05-29 13:49:12 -0500 (Thu, 29 May 2008) | 16 lines

Merged revisions 119008 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.2

........
r119008 | russell | 2008-05-29 13:45:21 -0500 (Thu, 29 May 2008) | 7 lines

Merge changes from team/russell/iax2-another-fix-to-the-fix

As described in the following post to the asterisk-dev mailing list, only
enforce destination call numbers when processing an ACK.

http://lists.digium.com/pipermail/asterisk-dev/2008-May/033217.html

(closes issue ASTERISK-12009)
........

................

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=119011