[Home]

Summary:ASTERISK-08067: iax2 qualify - false "peer unreachable"
Reporter:pj (pj)Labels:
Date Opened:2006-11-04 07:59:48.000-0600Date Closed:2011-06-07 14:07:56
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) iaxdebug2.txt
( 1) log_patch.diff
Description:my asterisk messages log is full with UNREACHABLE/REACHABLE messages,
even in case, that two asterisks are in LAN environment,
please take a look into this iax debug,
I can't find any problem with packet loss, all qualify requests are replied and acknowledged ...

****** ADDITIONAL INFORMATION ******

BILL-GW (Asterisk 1.2.9.1):
bill*CLI> iax2 show peer ipbx-gw
Status       : OK (4 ms)
Qualify        : every 20000ms when OK, every 10000ms when UNREACHABLE (sample smoothing On)

[Nov  4 11:06:58] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00002  DCall: 00000 [193.179.bbb.bbb:4569]
[Nov  4 11:06:58] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00001  DCall: 00002 [193.179.bbb.bbb:4569]
[Nov  4 11:06:58] Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00002  DCall: 00001 [193.179.bbb.bbb:4569]

[Nov  4 11:07:01] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
[Nov  4 11:07:01]    Timestamp: 00018ms  SCall: 00019  DCall: 00000 [193.179.bbb.bbb:4569]
[Nov  4 11:07:01] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
[Nov  4 11:07:01]    Timestamp: 00018ms  SCall: 00003  DCall: 00019 [193.179.bbb.bbb:4569]
[Nov  4 11:07:01] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
[Nov  4 11:07:01]    Timestamp: 00018ms  SCall: 00019  DCall: 00003 [193.179.bbb.bbb:4569]




IPBX-GW (Asterisk SVN-branch-1.4-r46822M):
ipbx*CLI> iax2 show peer bill-gw
Status       : OK (3 ms)
Qualify      : every 12000ms when OK, every 3000ms when UNREACHABLE (sample smoothing Off)

[Nov  4 11:06:58] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00002  DCall: 00000 [193.179.iii.iii:13526]
[Nov  4 11:06:58] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00001  DCall: 00002 [193.179.iii.iii:13526]
[Nov  4 11:06:58] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
[Nov  4 11:06:58]    Timestamp: 00019ms  SCall: 00002  DCall: 00001 [193.179.iii.iii:13526]
[Nov  4 11:06:59] NOTICE[9502]: chan_iax2.c:7853 __iax2_poke_noanswer: Peer 'bill-gw' is now UNREACHABLE! Time: 3

[Nov  4 11:07:02] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
[Nov  4 11:07:02]    Timestamp: 00018ms  SCall: 00019  DCall: 00000 [193.179.iii.iii:13526]
[Nov  4 11:07:02] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
[Nov  4 11:07:02]    Timestamp: 00018ms  SCall: 00003  DCall: 00019 [193.179.iii.iii:13526]
[Nov  4 11:07:02] NOTICE[9504]: chan_iax2.c:7067 socket_process: Peer 'bill-gw' is now REACHABLE! Time: 3
[Nov  4 11:07:02] Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
[Nov  4 11:07:02]    Timestamp: 00018ms  SCall: 00019  DCall: 00003 [193.179.iii.iii:13526]



Comments:By: Anthony LaMantia (alamantia) 2006-11-06 14:55:21.000-0600

can you see if this behavior changes with the patch i just uploaded?
By: pj (pj) 2006-11-08 01:53:11.000-0600

hello, tried tried with this patch last 12 hours, it working maybe better, but still not perfekt, look at my console log....
also I'm not sure, if qualifysmoothing working as expected - to eliminate false lagged peers...

iax2 show peer honzat-gw
 Status       : OK (127 ms)
 Qualify      : every 10000ms when OK, every 4000ms when UNREACHABLE (sample smoothing On)


[Nov  8 08:39:35] NOTICE[7283] chan_iax2.c: Peer 'honzat-gw' is now UNREACHABLE! Time: 127
[Nov  8 08:39:39] NOTICE[7285] chan_iax2.c: Peer 'honzat-gw' is now REACHABLE! Time: 129
[Nov  8 08:40:53] NOTICE[7285] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (2304 ms)!
[Nov  8 08:41:37] NOTICE[7283] chan_iax2.c: Peer 'honzat-gw' is now UNREACHABLE! Time: 144
[Nov  8 08:41:41] NOTICE[7284] chan_iax2.c: Peer 'honzat-gw' is now REACHABLE! Time: 129
[Nov  8 08:43:36] NOTICE[7284] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (3857 ms)!
[Nov  8 08:44:00] NOTICE[7290] chan_iax2.c: Peer 'honzat-gw' is now UNREACHABLE! Time: 127
[Nov  8 08:44:05] NOTICE[7290] chan_iax2.c: Peer 'honzat-gw' is now REACHABLE! Time: 148
[Nov  8 08:44:38] NOTICE[7289] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (2926 ms)!
[Nov  8 08:45:02] NOTICE[7283] chan_iax2.c: Peer 'honzat-gw' is now UNREACHABLE! Time: 125
[Nov  8 08:45:06] NOTICE[7285] chan_iax2.c: Peer 'honzat-gw' is now REACHABLE! Time: 122
By: Joshua C. Colp (jcolp) 2006-11-09 22:04:09.000-0600

Back to new so this pokes Anthony.
By: Anthony LaMantia (alamantia) 2006-11-10 17:17:02.000-0600

humm, let me trying something else with this one.
By: Anthony LaMantia (alamantia) 2006-11-14 11:45:16.000-0600

I have gone over the situations that could lead to this problem quite a bit, and really need more debugging information before i can pinpoint any issue here,

can you apply this patch which will produce some usefull debugging output for us to look at, and upload the result to this bug..

also i am going to see to see at least 6-10 rx/tx pokes from the 1.4svn server with all of the infomraiton..

the patch is for 1.4 please only apply it to that server and not the 1.2.x machine
By: pj (pj) 2006-11-14 14:50:17.000-0600

seems, that something goes wrong, if qualify Callno=18 for my one peer, look at attached debug...
By: Anthony LaMantia (alamantia) 2006-11-17 14:45:29.000-0600

the real flow problem for callno 18 seems to be
[Nov 14 21:29:05] NOTICE[20884]: chan_iax2.c:7884 iax2_poke_peer: Sending POKE to peer 'prec-gw' Callno: '18'
[Nov 14 21:29:05] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
[Nov 14 21:29:05]    Timestamp: 00004ms  SCall: 00018  DCall: 00000 [62.40.xxx.xxx:4569]
[Nov 14 21:29:05] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 006 Type: IAX     Subclass: ACK
[Nov 14 21:29:05]    Timestamp: 00004ms  SCall: 00009  DCall: 00018 [62.40.xxx.xxx:4569]

the remote server is responding with an ack to Dcall 18 which is correct but the PONG seems to be missing when ever it sends a reply. which seems quite strange.. is this happening.. is this happening with any other callno's or just 18 on your system?
By: Anthony LaMantia (alamantia) 2006-11-17 14:53:36.000-0600

Pj, do you have the debugging output from the machine that is on the target end of these POKES?
By: Anthony LaMantia (alamantia) 2006-11-20 19:08:37.000-0600


By: pi (pi) 2006-11-20 23:23:49.000-0600

I believe you added the wrong person to this bug. I'm no longer active with an Asterisk system. Sorry for the noise.
By: pj (pj) 2006-11-21 04:12:11.000-0600

hello, yesterday I restarted asterisk peer prec-gw (1.2.23) which sends wrong qualify acknoledges, as you say 11-17-06 14:45,
seems, this solved the issue, because the false unreachables doesn't longer appear.
so, please let this tiket some days stalled.

here is my last console log, before I restarted prec-gw peer - problem was only when Callno: 18.


[Nov 20 12:48:38] NOTICE[20884] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 10 Callno: 18
[Nov 20 12:48:42] NOTICE[20877] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 9
[Nov 20 12:49:46] NOTICE[20883] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 9 Callno: 18
[Nov 20 12:49:50] NOTICE[20878] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 11
[Nov 20 12:50:54] NOTICE[20883] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 15 Callno: 18
[Nov 20 12:50:58] NOTICE[20876] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 9
[Nov 20 13:07:33] NOTICE[20884] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 9 Callno: 18
[Nov 20 13:07:37] NOTICE[20877] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 10
[Nov 20 13:16:11] NOTICE[20879] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 10 Callno: 18
[Nov 20 13:16:15] NOTICE[20881] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 6
[Nov 20 13:17:19] NOTICE[20884] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 12 Callno: 18
[Nov 20 13:17:23] NOTICE[20884] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 9
[Nov 20 13:19:27] NOTICE[20877] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 9 Callno: 18
[Nov 20 13:19:32] NOTICE[20878] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 9
[Nov 20 13:21:36] NOTICE[20876] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 9 Callno: 18
[Nov 20 13:21:40] NOTICE[20883] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 9
[Nov 20 13:30:14] NOTICE[20876] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 11 Callno: 18
[Nov 20 13:30:18] NOTICE[20879] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 10
[Nov 20 13:31:22] NOTICE[20881] chan_iax2.c: Peer 'prec-gw' is now UNREACHABLE! Time: 10 Callno: 18
[Nov 20 13:31:26] NOTICE[20882] chan_iax2.c: Peer 'prec-gw' is now REACHABLE! Time: 11
By: Anthony LaMantia (alamantia) 2006-11-28 16:21:29.000-0600

Pj,

do you think we need to keep this issue open still?
By: pj (pj) 2006-11-29 04:11:21.000-0600

hello, I think, that you can close this tiket, after I restart remote asterisk, the unreachable/reacheble issue doesn't longer appear.
I still have lot of LAGGED peer messages (even I have sample smoothing On), but I don't know, if this can be currently solved, because using iax qualify settings I can't set reply timeout threshold, like in SIP, where qualify=3000 means, that I'm accepting "lag" of 3sec, in IAX qualify=3000 actualy means "check peer every 3sec".

[Nov 28 16:11:17] NOTICE[18411] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2009 ms)!
[Nov 28 16:13:19] NOTICE[18409] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2004 ms)!
[Nov 28 16:29:22] NOTICE[18413] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2010 ms)!
[Nov 28 16:34:56] NOTICE[18413] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2022 ms)!
[Nov 28 16:36:58] NOTICE[18411] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2013 ms)!
[Nov 28 17:03:35] NOTICE[18411] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (2879 ms)!
[Nov 28 17:06:32] NOTICE[18410] chan_iax2.c: Peer 'wilder-gw' is now TOO LAGGED (2024 ms)!
[Nov 28 17:09:43] NOTICE[18411] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (2710 ms)!
[Nov 28 17:14:47] NOTICE[18410] chan_iax2.c: Peer 'honzat-gw' is now TOO LAGGED (2861 ms)!
By: Joshua C. Colp (jcolp) 2006-11-29 21:32:43.000-0600

Closed per request of reporter. Peace!