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