[asterisk-bugs] [Asterisk 0012631]: Asterisk replies with VNAK (and wrong destination call) to AUTHREQ to its NEW (sometimes) when call bounced back.
noreply at bugs.digium.com
noreply at bugs.digium.com
Mon May 12 17:22:25 CDT 2008
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=12631
======================================================================
Reported By: lmamane
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 12631
Category: Channels/chan_iax2
Reproducibility: random
Severity: major
Priority: normal
Status: new
Asterisk Version: 1.4.19
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 05-12-2008 17:19 CDT
Last Modified: 05-12-2008 17:22 CDT
======================================================================
Summary: Asterisk replies with VNAK (and wrong destination
call) to AUTHREQ to its NEW (sometimes) when call bounced back.
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 at lemfat-lookup&Local/1012 at lemfat-lookup&SIP/lionel&IAX2/lionel)
Local/1010 at lemfat-lookup itself through a DUNDi lookup is an IAX2 call
back to T, of the form:
dundi:SECRET at 82.95.233.223/1010 at 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 at incoming-lemfat:1] Dial("IAX2/dundi-11958",
"Local/1010 at lemfat-lookup&Local/1012 at lemfat-lookup&SIP/lionel&IAX2/lionel")
in new stack
-- Called 1010 at lemfat-lookup
-- Called 1012 at lemfat-lookup
-- Called dundi:SECRET at 88.207.241.223/1012 at incoming-lemfat
-- Called dundi:SECRET at 82.95.233.223/1010 at 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
======================================================================
----------------------------------------------------------------------
russell - 05-12-08 17:22
----------------------------------------------------------------------
iax2 debug output?
Issue History
Date Modified Username Field Change
======================================================================
05-12-08 17:22 russell Note Added: 0086756
======================================================================
More information about the asterisk-bugs
mailing list