[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
Sat May 17 19:23:23 CDT 2008


A NOTE has been added to this issue. 
====================================================================== 
http://bugs.digium.com/view.php?id=12631 
====================================================================== 
Reported By:                lmamane
Assigned To:                russell
====================================================================== 
Project:                    Asterisk
Issue ID:                   12631
Category:                   Channels/chan_iax2
Reproducibility:            random
Severity:                   major
Priority:                   normal
Status:                     feedback
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-17-2008 19:23 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

====================================================================== 

---------------------------------------------------------------------- 
 lmamane - 05-17-08 19:23  
---------------------------------------------------------------------- 
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. 

Issue History 
Date Modified   Username       Field                    Change               
====================================================================== 
05-17-08 19:23  lmamane        Note Added: 0086982                          
======================================================================




More information about the asterisk-bugs mailing list