[asterisk-dev] iax failure?

Mon Mar 20 13:45:48 MST 2006

> 
> I have upgraded yesterday evening (about 24h minus) a well running Asterisk
> box (mine), and I have a strange thing like you : no sound or ringing after
> place a call (only one call from time to time is ok). If I take a look on
> IAX2 DEBUG mode, I can see lot of INVALID iax frames :
> 
> Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
>    Timestamp: 00000ms  SCall: 00116  DCall: 28941 [192.168.1.102:4569]
> Rx-Frame Retry[Yes] -- OSeqno: 003 ISeqno: 001 Type: IAX     Subclass: PING
>    Timestamp: 12008ms  SCall: 28941  DCall: 00116 [192.168.1.102:4569]
> Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
>    Timestamp: 00000ms  SCall: 00116  DCall: 28941 [192.168.1.102:4569]
> Rx-Frame Retry[Yes] -- OSeqno: 002 ISeqno: 001 Type: IAX     Subclass: PING
>    Timestamp: 02003ms  SCall: 28941  DCall: 00116 [192.168.1.102:4569]
> Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
>    Timestamp: 00000ms  SCall: 00116  DCall: 28941 [192.168.1.102:4569]
> 
> Is this what it is happening for your cases ?

I just completed an iax2 debug, and there isn't any indication of a 
problem. Here's what I see in a debug:
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: 
AUTHREP
    Timestamp: 00094ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
    PASSWORD        : npiiax

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: 
ACCEPT
    Timestamp: 00123ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
    FORMAT          : 16

     -- Call accepted by 12.189.61.245 (format g726)
     -- Format for call is g726
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
    Timestamp: 00123ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: 
RINGING
    Timestamp: 00324ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
    Timestamp: 00324ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: 
(255?)
    Timestamp: 02607ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
    Timestamp: 02607ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 002 Type: CONTROL Subclass: 
ANSWER
    Timestamp: 02610ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
    Timestamp: 02610ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 002 Type: VOICE   Subclass: 16
    Timestamp: 02934ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 006 Type: IAX     Subclass: ACK
    Timestamp: 02934ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 002 Type: IAX     Subclass: LAGRQ
    Timestamp: 10013ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 007 Type: IAX     Subclass: LAGRP
    Timestamp: 10013ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 003 Type: IAX     Subclass: ACK
    Timestamp: 10013ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]

*** No audio at this point ***

Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 003 Type: IAX     Subclass: 
HANGUP
    Timestamp: 13877ms  SCall: 00002  DCall: 00001 [12.189.61.245:4569]
    CAUSE CODE      : 16

Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 008 Type: IAX     Subclass: ACK
    Timestamp: 13877ms  SCall: 00001  DCall: 00002 [12.189.61.245:4569]
Mar 20 13:48:36 NOTICE[6908]: sched.c:286 ast_sched_del: Attempted to 
delete nonexistent schedule entry 23!
     -- Hungup 'IAX2/cotad-out-1'

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

If I compare the above debug to another one from the same boxes (but 
with the commented out Define), the two debug's look the same.

If I do a 'iax2 show threads' while a bad call is in progress, I get:
phoenix*CLI> iax2 show threads
IAX2 Thread Information
Idle Threads:
Thread 9: state=0, update=1, actions=26, refcnt=1, func =''
Thread 10: state=0, update=1, actions=26, refcnt=1, func =''
Thread 1: state=0, update=0, actions=28, refcnt=1, func =''
Thread 2: state=0, update=0, actions=28, refcnt=1, func =''
Thread 3: state=0, update=0, actions=28, refcnt=1, func =''
Thread 4: state=0, update=0, actions=28, refcnt=1, func =''
Thread 5: state=0, update=0, actions=28, refcnt=1, func =''
Thread 6: state=0, update=0, actions=28, refcnt=1, func =''
Thread 7: state=0, update=0, actions=27, refcnt=1, func =''
Thread 8: state=0, update=0, actions=27, refcnt=1, func =''
Active Threads:
10 of 10 threads accounted for
Mar 20 13:47:34 NOTICE[6907]: sched.c:286 ast_sched_del: Attempted to 
delete nonexistent schedule entry 17!
     -- Hungup 'IAX2/cozad-out-3'

The only difference here is the last NOTICE statement. That notice does 
not appear in test calls with the Define commented out. All tests were 
completed with one call in progress within the system.

Rich