thr3ads.net - asterisk users - [Asterisk-Users] IAX problem - Bug or Compatibility issue? [Dec 2005]

If this information is useful, please help other people find it:
Share via:

Aryanto Rachmad

2005-Dec-30 10:38 UTC

[Asterisk-Users] IAX problem - Bug or Compatibility issue?

Hello All,

I am looking for more thorough debug than the one provided by the command
"iax2 debug". Could anybody point me a good documentation about this?

I have a issue with IAX connection. Sometimes it stucked. If so, I have to
restart my asterisk through CLI command "restart now".

Comparing the debug messages of working and non working sequences, I have
noticed that when it does not work, the following debug messages are missing:

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)
   Timestamp: 01581ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 01581ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
    -- IAX2/sipdiscount_outbound-16385 is making progress passing it to Zap/1-1
Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4791 zt_indicate: Requested indication
14 on channel Zap/1-1
Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4857 zt_indicate: Received
AST_CONTROL_PROGRESS on Zap/1-1
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE   Subclass: 4
   Timestamp: 01732ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Dec 30 17:12:31 DEBUG[12569]: chan_iax2.c:6653 socket_read: Ooh, voice format
changed to 4
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 01732ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]

I have a few questions, especially about the following message:
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)

1. Is the number 14 in (14?), in decimal or hexadecimal?
2. If that is in decimal, why is it not translated into its descriptions, i.e.
Call Progress, according to the IAX2 protocol document I have (Internet-Draft,
Expires: July 5, 2005).
3. Why is that number question marked? Is it because asterisk was not sure?
4. If asterisk was not sure, so sometimes it decodes the message sometimes it
could not, is there any debug to confirm this?

Or, am I looking at the wrong place? Which maybe the problem is so obvious and I
missed that?

I am running asterisk on IBM xSeries 330 with the following detail:
CLI> show version
Asterisk 1.2.1 built by root @ atvie-asterisk on a i686 running Linux on
2005-12-28 07:52:36 UTC
# uname -a
Linux atvie-asterisk 2.6.14-1.1653_FC4smp #1 SMP Tue Dec 13 21:46:01 EST 2005
i686 i686 i386 GNU/Linux

Please find also below the detail of IAX debug messages.

Cheers,

Anto
----

------------------------------------------------------------------------------------------------------------------------
MESSAGES WHEN IAX DOES NOT WORK
------------------------------------------------------------------------------------------------------------------------
    -- Call accepted by 213.61.187.147 (format ulaw)
    -- Format for call is ulaw
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00057ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 4
   Timestamp: 00080ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
Dec 30 17:04:25 DEBUG[12488]: chan_iax2.c:3699 find_tpeer: Created trunk peer
for '213.61.187.147:4569'
Dec 30 17:04:25 DEBUG[12488]: chan_iax2.c:3725 iax2_trunk_queue: Expanded trunk
'213.61.187.147:4569' to 6400 bytes
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00080ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
                                                                              
<------- Some messages are missing here
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: IAX     Subclass: LAGRQ
   Timestamp: 10008ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10016ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRP
   Timestamp: 10016ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: LAGRP
   Timestamp: 10008ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10008ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 10016ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: HANGUP
   Timestamp: 10262ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
   CAUSE CODE      : 0
------------------------------------------------------------------------------------------------------------------------


------------------------------------------------------------------------------------------------------------------------
MESSAGES AFTER ISSUING "CLI> restart now" command
------------------------------------------------------------------------------------------------------------------------
    -- Call accepted by 213.61.187.157 (format ulaw)
    -- Format for call is ulaw
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00040ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 4
   Timestamp: 00100ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Dec 30 17:12:30 DEBUG[12600]: chan_iax2.c:3699 find_tpeer: Created trunk peer
for '213.61.187.157:4569'
Dec 30 17:12:30 DEBUG[12600]: chan_iax2.c:3725 iax2_trunk_queue: Expanded trunk
'213.61.187.157:4569' to 6400 bytes
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00100ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)
   Timestamp: 01581ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 01581ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
    -- IAX2/sipdiscount_outbound-16385 is making progress passing it to Zap/1-1
Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4791 zt_indicate: Requested indication
14 on channel Zap/1-1
Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4857 zt_indicate: Received
AST_CONTROL_PROGRESS on Zap/1-1
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE   Subclass: 4
   Timestamp: 01732ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Dec 30 17:12:31 DEBUG[12569]: chan_iax2.c:6653 socket_read: Ooh, voice format
changed to 4
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 01732ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: LAGRQ
   Timestamp: 10029ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10007ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 10007ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: LAGRP
   Timestamp: 10029ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 10029ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 10007ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: PING
   Timestamp: 20032ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 006 Type: IAX     Subclass: LAGRQ
   Timestamp: 20035ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: PING
   Timestamp: 20042ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 007 Type: IAX     Subclass: PONG
   Timestamp: 20042ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
   RR_JITTER       : 0
   RR_LOSS         : 0
   RR_PKTS         : 1
   RR_DELAY        : 40
   RR_DROPPED      : 0
   RR_OUTOFORDER   : 0
------------------------------------------------------------------------------------------------------------------------
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
http://lists.digium.com/pipermail/asterisk-users/attachments/20051230/55fddef1/attachment.htm

Aryanto Rachmad

2005-Dec-30 18:05 UTC

head link

[Asterisk-Users] IAX problem - Bug or Compatibility issue?

Nevermind. I think I found it. I didn't realise that Ethereal can decode
IAX2 protocol.

When IAX does not work, sometimes I got the following message as well:

DEBUG[2213] chan_iax2.c: Immediately destroying 16384, having received INVAL

What else can we say about that a part from my asterisk received frame with
INVAL (Invalid call) or in other word incompatible frame?

I also found a very quick and dirty workaround which is enough for me at the
moment.
  ----- Original Message ----- 
  From: Aryanto Rachmad 
  To: asterisk-users@lists.digium.com 
  Sent: Friday, December 30, 2005 6:38 PM
  Subject: [Asterisk-Users] IAX problem - Bug or Compatibility issue?


  Hello All,

  I am looking for more thorough debug than the one provided by the command
"iax2 debug". Could anybody point me a good documentation about this?

  I have a issue with IAX connection. Sometimes it stucked. If so, I have to
restart my asterisk through CLI command "restart now".

  Comparing the debug messages of working and non working sequences, I have
noticed that when it does not work, the following debug messages are missing:

  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)
     Timestamp: 01581ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK
     Timestamp: 01581ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
      -- IAX2/sipdiscount_outbound-16385 is making progress passing it to
Zap/1-1
  Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4791 zt_indicate: Requested
indication 14 on channel Zap/1-1
  Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4857 zt_indicate: Received
AST_CONTROL_PROGRESS on Zap/1-1
  Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE   Subclass: 4
     Timestamp: 01732ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Dec 30 17:12:31 DEBUG[12569]: chan_iax2.c:6653 socket_read: Ooh, voice format
changed to 4
  Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
     Timestamp: 01732ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]

  I have a few questions, especially about the following message:
  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)

  1. Is the number 14 in (14?), in decimal or hexadecimal?
  2. If that is in decimal, why is it not translated into its descriptions, i.e.
Call Progress, according to the IAX2 protocol document I have (Internet-Draft,
Expires: July 5, 2005).
  3. Why is that number question marked? Is it because asterisk was not sure?
  4. If asterisk was not sure, so sometimes it decodes the message sometimes it
could not, is there any debug to confirm this?

  Or, am I looking at the wrong place? Which maybe the problem is so obvious and
I missed that?

  I am running asterisk on IBM xSeries 330 with the following detail:
  CLI> show version
  Asterisk 1.2.1 built by root @ atvie-asterisk on a i686 running Linux on
2005-12-28 07:52:36 UTC
  # uname -a
  Linux atvie-asterisk 2.6.14-1.1653_FC4smp #1 SMP Tue Dec 13 21:46:01 EST 2005
i686 i686 i386 GNU/Linux

  Please find also below the detail of IAX debug messages.

  Cheers,

  Anto
  ----

 
------------------------------------------------------------------------------------------------------------------------
  MESSAGES WHEN IAX DOES NOT WORK
 
------------------------------------------------------------------------------------------------------------------------
      -- Call accepted by 213.61.187.147 (format ulaw)
      -- Format for call is ulaw
  Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
     Timestamp: 00057ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
  Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 4
     Timestamp: 00080ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
  Dec 30 17:04:25 DEBUG[12488]: chan_iax2.c:3699 find_tpeer: Created trunk peer
for '213.61.187.147:4569'
  Dec 30 17:04:25 DEBUG[12488]: chan_iax2.c:3725 iax2_trunk_queue: Expanded
trunk '213.61.187.147:4569' to 6400 bytes
  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
     Timestamp: 00080ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
                                                                                
<------- Some messages are missing here
  Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: IAX     Subclass: LAGRQ
     Timestamp: 10008ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: LAGRQ
     Timestamp: 10016ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
  Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRP
     Timestamp: 10016ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
  Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: LAGRP
     Timestamp: 10008ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
  Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
     Timestamp: 10008ms  SCall: 16384  DCall: 00070 [213.61.187.147:4569]
  Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: ACK
     Timestamp: 10016ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
  Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: HANGUP
     Timestamp: 10262ms  SCall: 00070  DCall: 16384 [213.61.187.147:4569]
     CAUSE CODE      : 0
 
------------------------------------------------------------------------------------------------------------------------


 
------------------------------------------------------------------------------------------------------------------------
  MESSAGES AFTER ISSUING "CLI> restart now" command
 
------------------------------------------------------------------------------------------------------------------------
      -- Call accepted by 213.61.187.157 (format ulaw)
      -- Format for call is ulaw
  Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
     Timestamp: 00040ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 4
     Timestamp: 00100ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Dec 30 17:12:30 DEBUG[12600]: chan_iax2.c:3699 find_tpeer: Created trunk peer
for '213.61.187.157:4569'
  Dec 30 17:12:30 DEBUG[12600]: chan_iax2.c:3725 iax2_trunk_queue: Expanded
trunk '213.61.187.157:4569' to 6400 bytes
  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
     Timestamp: 00100ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: (14?)
     Timestamp: 01581ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK
     Timestamp: 01581ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
      -- IAX2/sipdiscount_outbound-16385 is making progress passing it to
Zap/1-1
  Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4791 zt_indicate: Requested
indication 14 on channel Zap/1-1
  Dec 30 17:12:31 DEBUG[12600]: chan_zap.c:4857 zt_indicate: Received
AST_CONTROL_PROGRESS on Zap/1-1
  Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE   Subclass: 4
     Timestamp: 01732ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Dec 30 17:12:31 DEBUG[12569]: chan_iax2.c:6653 socket_read: Ooh, voice format
changed to 4
  Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
     Timestamp: 01732ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: LAGRQ
     Timestamp: 10029ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRQ
     Timestamp: 10007ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: LAGRP
     Timestamp: 10007ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: LAGRP
     Timestamp: 10029ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX     Subclass: ACK
     Timestamp: 10029ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
     Timestamp: 10007ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: PING
     Timestamp: 20032ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 006 Type: IAX     Subclass: LAGRQ
     Timestamp: 20035ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
  Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: PING
     Timestamp: 20042ms  SCall: 00052  DCall: 16385 [213.61.187.157:4569]
  Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 007 Type: IAX     Subclass: PONG
     Timestamp: 20042ms  SCall: 16385  DCall: 00052 [213.61.187.157:4569]
     RR_JITTER       : 0
     RR_LOSS         : 0
     RR_PKTS         : 1
     RR_DELAY        : 40
     RR_DROPPED      : 0
     RR_OUTOFORDER   : 0
 
------------------------------------------------------------------------------------------------------------------------



------------------------------------------------------------------------------


  _______________________________________________
  --Bandwidth and Colocation provided by Easynews.com --

  Asterisk-Users mailing list
  To UNSUBSCRIBE or update options visit:
     http://lists.digium.com/mailman/listinfo/asterisk-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
http://lists.digium.com/pipermail/asterisk-users/attachments/20051230/17fa6137/attachment.htm

asterisk users - Dec 2005 - IAX problem - Bug or Compatibility issue?

[Asterisk-Users] IAX problem - Bug or Compatibility issue?

[Asterisk-Users] IAX problem - Bug or Compatibility issue?