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
Possibly Parallel Threads
Wisdom of the Ancients
