[Home]

Summary:ASTERISK-21762: IAX2 call problem
Reporter:newborn (newborn838)Labels:
Date Opened:2013-05-07 07:32:31Date Closed:2013-05-21 09:08:50
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:1.8.21.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:CentOS 6.4 2.6.32-358.6.1.el6.i686 #1 SMP Tue Apr 23 18:13:20 UTC 2013 i686 i686 i386 GNU/LinuxAttachments:
Description:There are 2 Asterisk boxes A and B.

A sends call to B.
B cannot accept call.

This bug comes up randomly, i cannot reproduce it.

From A log:
[May  7 16:03:49] WARNING[1997] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>
[May  7 16:04:03] WARNING[1996] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>
[May  7 16:04:17] WARNING[2003] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>
[May  7 16:04:31] WARNING[1997] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>
[May  7 16:04:42] WARNING[1998] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>
[May  7 16:04:46] WARNING[2004] chan_iax2.c: Call rejected by *.*.*.*: <Unknown>


From B log:
[May  7 16:03:49] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*
[May  7 16:04:03] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*
[May  7 16:04:17] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*
[May  7 16:04:31] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*
[May  7 16:04:42] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*
[May  7 16:04:45] WARNING[7416] chan_iax2.c: Too much delay in IAX2 calltoken timestamp from address *.*.*.*

After restarting Asterisk B , everything is OK
Comments:By: Matt Jordan (mjordan) 2013-05-07 09:16:13.311-0500

Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. You may find it helpful to read the Asterisk Issue Guidelines http://www.asterisk.org/developers/bug-guidelines. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need:

1. the specific steps or actions you took that caused you to encounter the problem,
2. the behavior you expected, and
3. the behavior you actually encountered (in as much detail as possible).

This likely includes output from the console with debug level logging, a SIP trace (if this is SIP related), and configuration information such as dialplan (e.g. extensions.conf) and channel configuration (e.g. sip.conf). Thanks!


By: newborn (newborn838) 2013-05-08 01:48:55.189-0500

1. Server A places the call on server B via IAX
2. Normal behavior expected
3. Already wrote about it. The call is not accepted by server B. Only restart of asterisk process helps.

By: Matt Jordan (mjordan) 2013-05-08 08:11:04.849-0500

"A calls B" is not sufficient information. Please go read the linked issue guidelines. You need to provide:

* A DEBUG log illustrating the problem with IAX debugging enabled
* Your configuration ({{extensions.conf}}, {{iax.conf}}) for both machines involved
* When you have a log illustrating the problem, provide a description of what occurred leading up to the problem and the channels involved

By: Matt Jordan (mjordan) 2013-05-21 09:08:40.822-0500

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.  Further information can be found at http://www.asterisk.org/developers/bug-guidelines


By: Jean-Francois Lemieux (jflemieux227) 2014-01-28 16:48:45.602-0600

I got same trouble.

We are using Asterisk 1.8.13.1, running centOS 6.3 x64, kernel 2.6.32-279.22.1.el6.x86_64 #1 SMP, dahdi with HPET source clock

IAX trunks are used to connect servers between them. We are used successfully one Asterisk 1.8.13.1 and all the remaining servers running Asterisk 1.4.22 without any trouble for many years. We upgraded the 1.4.22 servers for the same 1.8.13.1 to the get the same version accross the servers group. Since this upgrade, we have about 1 time per week a server that all IAX2 trunks are frozen with "Too much delay in IAX2 calltoken timestamp"..


For the example, figure two server running 18.13.1 involved. Server ASTC (10.0.4.43) showing iax2 show peers correctly, Server ASTA's (10.0.4.41) IAX show peers show UNAVAILABLE. Homever, server ASTC shows iax2 show peers AVAILABLE for the ASTA trunk.

When it happens, the only way to solve is to kill asterisk daemon (on ASTA server) and restart; core stop now or core reload isn't working.



here is IAX2 set debug ... from ASTA server when trying to make an inbound call from server ASTC:


Timestamp: 00015ms SCall: 00119 DCall: 00000 [10.0.4.43:4569]
VERSION : 2
CALLED NUMBER : 5223
CODEC_PREFS : (ulaw|alaw|gsm)
CALLING NUMBER : anonymous
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : Anonymous
LANGUAGE : fr
USERNAME : ASTA-ASTC
FORMAT : 4
FORMAT2 : ulaw
CAPABILITY : 14
CAPABILITY2 : unknown
ADSICPE : 2
DATE TIME : 2014-01-28 17:00:08
CALLTOKEN : 51 bytes

Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00015ms SCall: 00119 DCall: 00000 [10.0.4.43:4569]
VERSION : 2
CALLED NUMBER : 5223
CODEC_PREFS : (ulaw|alaw|gsm)
CALLING NUMBER : anonymous
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : Anonymous
LANGUAGE : fr
USERNAME : ASTA-ASTC
FORMAT : 4
FORMAT2 : ulaw
CAPABILITY : 14
CAPABILITY2 : unknown
ADSICPE : 2
DATE TIME : 2014-01-28 17:00:08
CALLTOKEN : 51 bytes

Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00015ms SCall: 00119 DCall: 00000 [10.0.4.43:4569]
VERSION : 2
CALLED NUMBER : 5223
CODEC_PREFS : (ulaw|alaw|gsm)
CALLING NUMBER : anonymous
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : Anonymous
LANGUAGE : fr
USERNAME : ASTA-ASTC
FORMAT : 4
FORMAT2 : ulaw
CAPABILITY : 14
CAPABILITY2 : unknown
ADSICPE : 2
DATE TIME : 2014-01-28 17:00:08
CALLTOKEN : 51 bytes

[Jan 28 17:00:21] WARNING[23985]: chan_iax2.c:4936 handle_call_token: Too much delay in IAX2 calltoken timestamp from address 10.0.4.43
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
Timestamp: 00015ms SCall: 00119 DCall: 00001 [10.0.4.43:4569]


from server ASTC, the only log is that ASTA rejected call



from server ASTA:

asta*CLI> iax2 show netstats
-------- LOCAL --------------------- -------- REMOTE --------------------
Channel RTT Jit Del Lost % Drop OOO Kpkts Jit Del Lost % Drop OOO Kpkts FirstMsg LastMsg
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
IAX2/ASTA-ASTB-1192 1 -1 0 -1 -1 0 -1 1 0 40 0 0 0 0 0 Rx:NEW Rx:ACK
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:PING
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:REJECT
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ
(None) 1000 -1 0 -1 -1 0 -1 0 0 0 0 0 0 0 0 Rx:NEW Tx:LAGRQ

asta*CLI> iax2 show threads
IAX2 Thread Information
Idle Threads:
Thread 3: state=0, update=1, actions=181951, func=''
Thread 1: state=0, update=1, actions=181955, func=''
Thread 5: state=0, update=1, actions=181962, func=''
Thread 8: state=0, update=0, actions=181950, func=''
Thread 7: state=0, update=0, actions=181958, func=''
Thread 4: state=0, update=0, actions=181931, func=''
Active Threads:
Thread P2: state=2, update=3933, actions=176135, func='socket_process'
Dynamic Threads:
7 of 10 threads accounted for with 0 dynamic threads



asta*CLI> iax2 show callnumber usage
Address Callno Usage Callno Limit
10.0.4.43 78 2048
10.0.4.42 13 2048
10.0.4.45 26 2048

Non-CallToken Validation Callno Limit: 8192
Non-CallToken Validated Callno Used: 0
Total Available Callno: 32650
Regular Callno Available: 16265
Trunk Callno Available: 16385

asta*CLI> iax2 show channels
Channel Peer Username ID (Lo/Rem) Seq (Tx/Rx) Lag Jitter JitBuf Format FirstMsg LastMsg
(None) 10.0.4.43 ASTA-ASTC 00074/11420 00124/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 00118/06634 00231/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 00229/08046 00028/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 00306/00515 00134/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 00355/15304 00035/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 00390/11397 00114/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 00562/01620 00075/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 00589/02809 00228/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 00606/03986 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 00610/00708 00163/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 00718/10010 00240/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 00737/11397 00114/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.42 ASTA-ASTB 00893/01383 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 00943/07620 00127/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01038/12699 00137/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 01134/11190 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
IAX2/ASTA-ASTB-1192 10.0.4.42 ASTA-ASTB 01192/13654 00030/00024 00040ms -0001ms 0000ms ulaw Rx:NEW Rx:ACK
(None) 10.0.4.43 ASTA-ASTC 01229/03423 00234/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01315/07078 00125/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.42 ASTA-ASTB 01502/08926 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.42 ASTA-ASTB 01513/01383 00012/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01589/12699 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 01596/11030 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 01693/09453 00007/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01718/10010 00240/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01813/04377 00122/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 01856/12699 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 01913/10355 00032/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 02155/01935 00120/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 02196/14190 00004/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 02331/10985 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 02392/10010 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 02439/10355 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 02489/01620 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 02511/01620 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 02720/03902 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 02787/00342 00078/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 02807/09559 00137/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 02809/02343 00190/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 02817/11190 00050/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 02907/09453 00007/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 02933/04504 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 03002/04504 00194/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 03257/04377 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 03282/07078 00125/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 03342/10985 00119/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 03549/07685 00072/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 03581/00708 00163/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 03608/00708 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 03852/04504 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 04075/03423 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 04163/02343 00191/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 04226/11030 00131/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 04532/04305 00151/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.42 ASTA-ASTB 04555/06079 00111/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 04560/03902 00047/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 04616/07119 00011/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 04689/10355 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 04946/01935 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 05061/06634 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 05078/11420 00123/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 05089/03986 00139/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 05111/02809 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.42 ASTA-ASTB 05211/06079 00112/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 05251/09559 00137/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 05267/08046 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 05343/10985 00118/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 05431/07620 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.42 ASTA-ASTB 05747/08926 00238/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 05766/01519 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.42 ASTA-ASTB 05951/06079 00112/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 06236/02343 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 06583/07620 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 06725/15304 00035/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 06748/10096 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 06763/00515 00134/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 06852/01793 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 06918/15304 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 07121/07119 00011/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 07315/01935 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 07821/08046 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 07934/01519 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 08334/04305 00151/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 08682/07685 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 08750/03423 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 08760/10096 00232/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 08929/11420 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 09085/01793 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 09140/04305 00151/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.42 ASTA-ASTB 09654/01383 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 09890/07078 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 09969/03902 00047/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.43 ASTA-ASTC 10094/11397 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 10250/01519 00081/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.45 ASTA-ASTE 10264/07119 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.45 ASTA-ASTE 10329/14190 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 10947/04377 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 11408/11030 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 12078/09559 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 12230/01793 00111/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ
(None) 10.0.4.45 ASTA-ASTE 12716/11190 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 12796/00515 00001/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:REJECT
(None) 10.0.4.43 ASTA-ASTC 12912/07685 00072/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:PING
(None) 10.0.4.43 ASTA-ASTC 12987/06634 00231/00001 00000ms -0001ms 0000ms unknow Rx:NEW Tx:LAGRQ

still from server ASTA:

asta*CLI> core show channels
Channel Location State Application(Data)
SIP/...
...
IAX2/ASTA-ASTB-13329 (None) Up AppDial((Outgoing Line))
IAX2/ASTA-ASTB-1192 s@macro-dialout-trun Up Dial(IAX2/ASTA-ASTB/6226,300,)

I checked from server ASTB and theses IAX channels aren't running, but ASTB IAX stack is running fine except when trying to make a call to server ASTA, got ASTA is rejecting call.

There is not IAX trunks (core show channels) running on ASTC, but every server from the group showing IAX2/ASTA.. AVAILABLE through iax2 show peers.


Here is iax2.conf setting for ASTA server:
[ASTA-ASTC]
host=10.0.4.43
username=ASTC-ASTA
secret=****secret****
type=friend
context=from-internal
qualify=yes
requirecalltoken=no


Here is iax2.conf settings for ASTC server:
[ASTC-ASTA]
host=10.0.4.41
username=ASTA-ASTC
secret=***secret***
type=friend
context=from-internal
qualify=200
requirecalltoken=no


I checked server's clock and they are all synchronised on the same source NTP clock


An idea ?

Regards,
By: Jean-Francois Lemieux (jflemieux227) 2014-03-11 14:15:03.936-0500

Hi everyone; just to give you my cookbook to solve (or bypass ?) the issue

I change in my trunks configuration:

requirecalltoken=yes
and I added:
transfer=no


I suspect there is a bug in calltoken negociation, even if we put requirecalltoken=no, it will try to negociate call token if the third party support it. I suspect that the trouble start when Asterisk try to transfer a IAX channel, so that's the reason i put transfer=no

Many weeks without the trouble, Before theses changes, I got a crash each week. Maybe a deadlock issue, but I didn't found evidence.