[Home]

Summary:ASTERISK-00476: codec 64 wrongly identified: IAX2 connection refused
Reporter:philipp (philipp)Labels:
Date Opened:2003-11-04 12:42:52.000-0600Date Closed:2004-09-25 02:49:15
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Error message on serverA (public IP): Asked to transmit frame type 64, while native formats is 2.

On both serverA and serverB (dynamic IP, registers at serverA) I have disallow=all and then allow= for gsm, ilbc and ulaw. SIP calls (X-Lite) at serverB can be successfully moved to serverA, but it won't work the other way around. serverA displays "Call accepted by 213.132.134.156 (format GSM)" while serverB shows "-- Accepting AUTHENTICATED call from 134.130.104.81, requested format = 2, actual format = 2" and then right way hangs up. Note that there are two iax.conf entries for serverA (user) and serverAp (peer) and vice versa for serverB and serverBp.

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

Log history - only the last line should be relevant:

Nov  4 17:44:42 NOTICE[54293]: File app_dial.c, Line 516 (dial_exec): Unable to create channel of type 'IAX2'
Nov  4 17:47:42 WARNING[55317]: File pbx.c, Line 3638 (ast_add_extension2): Unable to register extension '8644', priority 2 in 'default', already in use
Nov  4 17:47:42 WARNING[55317]: File pbx_config.c, Line 1621 (pbx_load_module): Unable to register extension at line 302
Nov  4 17:47:42 WARNING[55317]: File chan_iax2.c, Line 5170 (set_config): Ignoring port for now
Nov  4 17:47:42 NOTICE[55317]: File indications.c, Line 373 (ast_unregister_indication_country): Removed default indication country 'us'
Nov  4 17:47:52 WARNING[10251]: File chan_sip.c, Line 451 (retrans_pkt): Maximum retries exceeded on call 2b36eff34f83e94f539c70746dee438c@aaa.bbb.ccc.ddd for seqno 102 (Request)
Nov  4 17:49:27 WARNING[56342]: File chan_sip.c, Line 1148 (sip_write): Asked to transmit frame type 64, while native formats is 2 (read/write = 2/2)


serverA debug:
karl*CLI> iax2 debug
IAX2 Debugging Enabled
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: REGREQ
  Timestamp: 00001ms  SCall: 00004  DCall: 00000 [ipServBp:4569]
  USERNAME        : ServBp
  REFRESH         : 60

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: REGAUTH
  Timestamp: 00001ms  SCall: 00003  DCall: 00004 [ipServBp:4569]
  AUTHMETHODS     : 2
  CHALLENGE       : 1454517648
  USERNAME        : ServBp

Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: REGREQ
  Timestamp: 00038ms  SCall: 00004  DCall: 00003 [ipServBp:4569]
  USERNAME        : ServBp
  REFRESH         : 60
  MD5 RESULT      : 4c399467315c3effef384e87861d4a3c

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: REGACK
  Timestamp: 00057ms  SCall: 00003  DCall: 00004 [ipServBp:4569]
  USERNAME        : ServBp
  REFRESH         : 60
  APPARENT ADDRES : IPV4 ipServBp:4569

Rx-Frame Retry[No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00057ms  SCall: 00004  DCall: 00003 [ipServBp:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
  Timestamp: 00001ms  SCall: 00005  DCall: 00000 [ipServBp:4569]
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
  Timestamp: 00001ms  SCall: 00005  DCall: 00005 [ipServBp:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
  Timestamp: 00001ms  SCall: 00005  DCall: 00005 [ipServBp:4569]
   -- Executing Playback("SIP/athlete-368c", "transfer") in new stack
   -- Playing 'transfer' (language 'en')
   -- Executing Ringing("SIP/athlete-368c", "") in new stack
   -- Executing Wait("SIP/athlete-368c", "1") in new stack
   -- Executing Dial("SIP/athlete-368c", "IAX2/ServA:pwServA@ServBp/8616") in new stack
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
  Timestamp: 00001ms  SCall: 00001  DCall: 00000 [ipServBp:4569]
  VERSION         : 2
  CALLED NUMBER   : 8616
  CALLING NUMBER  : 8602
  CALLING NAME    : ME on ServA
  LANGUAGE        : en
  USERNAME        : ServA
  FORMAT          : 2
  CAPABILITY      : 2147483647
  ADSICPE         : 2
  DATE TIME       : 124030746

   -- Called ServA:pwServA@ServBp/8616
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX     Subclass: HANGUP
  Timestamp: 00011ms  SCall: 00001  DCall: 00000 [ipServBp:4569]
   -- Hungup 'IAX2[ServBp]/1'
 == Spawn extension (default, 98616, 4) exited non-zero on 'SIP/athlete-368c'
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00001ms  SCall: 00001  DCall: 00001 [ipServBp:4569]
  AUTHMETHODS     : 2
  CHALLENGE       : 603628937
  USERNAME        : ServA

Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00027ms  SCall: 00001  DCall: 00001 [ipServBp:4569]
  MD5 RESULT      : 41cafece8454e111d3ef8312d5763f64

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00011ms  SCall: 00001  DCall: 00001 [ipServBp:4569]
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 00001  DCall: 00001 [ipServBp:4569]


serverB debug:
robert*CLI> iax2 debug
IAX2 Debugging Enabled
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
  Timestamp: 00001ms  SCall: 00003  DCall: 00000 [aaa.bbb.ccc.ddd:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
  Timestamp: 00001ms  SCall: 00003  DCall: 00003 [aaa.bbb.ccc.ddd:4569]
Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
  Timestamp: 00001ms  SCall: 00003  DCall: 00003 [aaa.bbb.ccc.ddd:4569]
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
  Timestamp: 00001ms  SCall: 00004  DCall: 00000 [aaa.bbb.ccc.ddd:4569]
  VERSION         : 2
  CALLED NUMBER   : 8616
  CALLING NUMBER  : 8602
  CALLING NAME    : ME on ServA
  LANGUAGE        : en
  USERNAME        : ServA
  FORMAT          : 2
  CAPABILITY      : 2147483647
  ADSICPE         : 2
  DATE TIME       : 124030613

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00001ms  SCall: 00004  DCall: 00004 [aaa.bbb.ccc.ddd:4569]
  AUTHMETHODS     : 2
  CHALLENGE       : 952200421
  USERNAME        : ServA

Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 000 Type: IAX     Subclass: HANGUP
  Timestamp: 00018ms  SCall: 00004  DCall: 00000 [aaa.bbb.ccc.ddd:4569]
Tx-Frame Retry[-01] -- OSeqno: 000 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00018ms  SCall: 00004  DCall: 00004 [aaa.bbb.ccc.ddd:4569]
Rx-Frame Retry[No] -- OSeqno: 002 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00033ms  SCall: 00004  DCall: 00004 [aaa.bbb.ccc.ddd:4569]
  MD5 RESULT      : c483f0a6f8241bf643e107d862f0038a


I've been sitting on this for more than two weeks now and tried different codecs etc etc, also today tried the latest CVS again but -- no success.

See also:
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg14560.html

http://www.mail-archive.com/asterisk-users@lists.digium.com/msg12648.html
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg05602.html
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg03242.html
http://www.mail-archive.com/asterisk-users@lists.digium.com/msg01139.html
Comments:By: Mark Spencer (markster) 2003-11-04 23:52:17.000-0600

Find me on IRC and i can try to ssh in and look, time permitting.
By: x martinp (martinp) 2003-11-05 11:14:37.000-0600

can you also send 'sip debug' trace or tell what codec you're using with SIP phone ?
By: philipp (philipp) 2003-11-05 12:35:15.000-0600

SIP codec: GSM (let me know if you need more info)
By: Paul Cadach (pcadach) 2003-11-05 13:59:45.000-0600

Reminder sent to markster

I found this problem some time ago - just Dial app don't stop indications when calls ast_channel_make_compatible() (when "single" flag is set). After ast_channel_make_compatible() call both channels have the same read/write format, but indications still sent by SLINEAR frames. Fix is simple (but not right for me) - just stop any indications BEFORE calling ast_channel_make_compatible() like next (I've don't produce diff-file because it's just a hack, not solution, and it's single line patch!):
--- app_dial.c.indicate Sun Nov  2 00:39:39 2003
+++ app_dial.c  Sun Nov  2 00:39:39 2003
@@ -127,6 +127,7 @@
       single = (outgoing && !outgoing->next && !outgoing->musiconhold && !outgoing->ringbackonly);

       if (single) {
+               ast_indicate(in, -1);
               /* If we are calling a single channel, make them compatible for in-band tone purpose */
               ast_channel_make_compatible(outgoing->chan, in);
       }

By: philipp (philipp) 2003-11-05 14:14:40.000-0600

restricting X-Lite, servA and servB to GSM only doesn't solve the issue, no change
By: Paul Cadach (pcadach) 2003-11-05 14:47:17.000-0600

Just try to replace Ringing application with NoOp app in dialplan and check again. Also, you can try to use 'r' option to Dial application (which is not works for me :( ) instead of using Ringing/Wait(1) sequence...
By: philipp (philipp) 2003-11-05 15:03:32.000-0600

Wow - that did it! By removing Ringing and Wait(1) the problem went away. Rather weird. :-) Now I don't get that nice 1 sec of full ring tone, but I guess I can live with that...
Anyway, I understood markster will apply the patch outlined above.
By: Paul Cadach (pcadach) 2003-11-09 14:16:59.000-0600

I see my "hack" in the CVS so I would like to ask about providing next scheme to handle outgoing calls:
1) replace ast_channel_make_compatible() call when "single" is set to something like ast_set_write_format(in, outgoing->chan->nativeformats)
2) don't stop indications/moh/etc. until remote side don't sets up incoming RTP connections or not answered;
3) as remote side answers (or successfully brings incoming RTP stream up), stop anything and do ast_set_read_format(in, outgoing->chan->nativeformats);
4) check that double call to ast_indicate(<channel>, <indication code>) with same <indication code> doesn't restart a generator (to not "chop" already listening sound).
By: Brian West (bkw918) 2003-11-22 14:03:26.000-0600

This appears to be fixed.  If not post feedback.