Mike Tubby
2007-Oct-29 20:27 UTC
[asterisk-users] IAX2 weirdness and rejected calls: Invalid BYTE
All, I run a bunch of (well 20+ actually) Asterisk boxes at home, work, friends and the lie with our own dialplan in the form 8EEXXXX where 'EE' is the exchange number and 'XXXX' is the extension number. This arrangement has been in for 2+ years and worked well with a central box (asterisk.thorcom.net) acting as the routing hub and SIP exchange point with various public providers and 'exchanges' as leaf-nodes. This allows centralised call rouing with only a single entry in iax.conf at the edges and a big, pattern based, routing table in the middle. As long as everyone accepts the same codecs then the central box hands off the calls and the endpoints talk directly. A little over a week ago I upgraded my home box to Asterisk 1.4.12 - I have been using 1.4.xx here for some time but the rest of the boxes lag and are typically 1.2.16. Shortly after upgrading my home box (gate.tubby.org) - known as [tubby] in the config files - calls in from SIPgate to DDI numbers at home stopped working. Also calls from remote phones on another exchange to me stopped working - both resulted in the re-order tone (fast busy) and if called from a GSM phone then the mobile would display "Call not allowed" - for this the call path was: T-mobile --[GSM/Q.931/SS7]--> Magrethea Telecom --[SIP]--> asterisk.thorcom.net --[IAX2]--> gate.tubby.org If I ran debug on the central box (asterisk.thorcom.net) I could clearly see the call coming in and being placed on gate.tubby.org but it was being rejected with the message: [Oct 29 19:47:16] WARNING[16974]: chan_iax2.c:770 iax_error_output: Expecting causecode to be single byte but was 2 [Oct 29 19:47:16] WARNING[16974]: chan_iax2.c:7450 socket_process: Call rejected by 193.82.116.194: No supported codec found Now, over at gate.tubby.org a 'tcpdump' clearly showed the exchange of IAX packets, but enabling debug on IAX showed nothing!? I upgraded both gate.tubby.org and asterisk.thorcom.net to Asterisk 1.4.13 and tried again -- same results -- now confused I set about further testing to see what was going on and it just magically mended itself and started working... Here's a trace I had running over at asterisk.thorcom.net of a call failing: -- Unregistered IAX2 'vikki' (UNAUTHENTICATED) ;; this is a friend's Zoiper soft phone registering at the same time Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGACK Timestamp: 00004ms SCall: 00002 DCall: 10100 [193.82.116.194:4569] USERNAME : vikki DATE TIME : 2007-10-29 19:46:36 Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00004ms SCall: 10100 DCall: 00002 [193.82.116.194:4569] -- Executing [01905888007 at sip-default:1] SIPDtmfMode("SIP/213.166.5.134-086112f8", "inband") in new stack -- Executing [01905888007 at sip-default:2] NoOp("SIP/213.166.5.134-086112f8", "01905888007 ") in new stack -- Executing [01905888007 at sip-default:3] Dial("SIP/213.166.5.134-086112f8", "IAX2/tubby/888007") in new stack -- Called tubby/888007 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00017ms SCall: 00001 DCall: 00000 [193.82.116.194:4569] VERSION : 2 CALLED NUMBER : 888007 CODEC_PREFS : (alaw|ulaw) CALLING NUMBER : 07939465009 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : 07939465009 LANGUAGE : en FORMAT : 8 CAPABILITY : 57356 ADSICPE : 2 DATE TIME : 2007-10-29 19:47:16 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 10101 DCall: 00001 [193.82.116.194:4569] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REJECT Timestamp: 00005ms SCall: 10101 DCall: 00001 [193.82.116.194:4569] CAUSE : No supported codec found CAUSE CODE : Invalid BYTE [Oct 29 19:47:16] WARNING[16974]: chan_iax2.c:770 iax_error_output: Expecting causecode to be single byte but was 2 [Oct 29 19:47:16] WARNING[16974]: chan_iax2.c:7450 socket_process: Call rejected by 193.82.116.194: No supported codec found Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00005ms SCall: 00001 DCall: 10101 [193.82.116.194:4569] -- Hungup 'IAX2/tubby-1' [Oct 29 19:47:16] NOTICE[17128]: cdr.c:434 ast_cdr_free: CDR on channel 'IAX2/tubby-1' not posted == Everyone is busy/congested at this time (1:0/0/1) -- Executing [01905888007 at sip-default:4] Hangup("SIP/213.166.5.134-086112f8", "") in new stack == Spawn extension (sip-default, 01905888007, 4) exited non-zero on 'SIP/213.166.5.134-086112f8' So... was the problem "no supported codec" or "invalid BYTE" ? And a short while later, without even stopping or re-starting anything it started working again: -- Executing [01905888007 at sip-default:1] SIPDtmfMode("SIP/213.166.5.134-0860a750", "inband") in new stack -- Executing [01905888007 at sip-default:2] NoOp("SIP/213.166.5.134-0860a750", "01905888007 ") in new stack -- Executing [01905888007 at sip-default:3] Dial("SIP/213.166.5.134-0860a750", "IAX2/tubby/888007") in new stack -- Called tubby/888007 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00014ms SCall: 00001 DCall: 00000 [193.82.116.194:4569] VERSION : 2 CALLED NUMBER : 888007 CODEC_PREFS : (alaw|ulaw) CALLING NUMBER : 07939465009 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : 07939465009 LANGUAGE : en FORMAT : 8 CAPABILITY : 57356 ADSICPE : 2 DATE TIME : 2007-10-29 19:52:56 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACCEPT Timestamp: 00001ms SCall: 00001 DCall: 00001 [193.82.116.194:4569] FORMAT : 8 -- Call accepted by 193.82.116.194 (format alaw) -- Format for call is alaw Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK Timestamp: 00001ms SCall: 00001 DCall: 00001 [193.82.116.194:4569] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass: RINGING Timestamp: 00004ms SCall: 00001 DCall: 00001 [193.82.116.194:4569] Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00004ms SCall: 00001 DCall: 00001 [193.82.116.194:4569] -- IAX2/tubby-1 is ringing -- Hungup 'IAX2/tubby-1' The central box (asterisk.thorcom.net) was running Asterisk 1.4.13 in forground: asterisk -vvvgc on Fedora FC4, while the box at home (gate.tubby.org) was running Asterisk 1.4.13 in forground on an FC7 box. Questions: 1. what does "Expecting causecode to be single byte but was 2" mean? 2. what does "Invalid BYTE" mean in this context? 3. why/how did it just fix itself while I was testing? 4. how come the box receiving the call (gate.tubby.org) answers the call request with a Reject but doesn't display any debug? My guess/hunch is that there is some sort of multibyte coding (UTF-8?) problem with some result codes, sequence numbers, or something?? Anyone come across this before? Mike