[asterisk-users] 9 becomes 99 ? And other strangeness
Brian Candler
B.Candler at pobox.com
Thu Sep 14 04:35:34 MST 2006
I'm getting a strange situation with the first digit being doubled on
outbound dialling, and other oddities. I think something strange is going on
in my dialplan, rather than a DTMF decoding issue, but see what you think.
The platform is CentOS 4.4 plus Asterisk SVN trunk as of yesterday, and a
TDM400P with 2 x FXS and 1 x FXO.
Here's my extensions.conf, based heavily on the simple examples from the
O'Reilly Starfish book:
---------------------------------------------------------------------------
[incoming]
; incoming calls from the FXO port are directed to this context from zapata.conf
include => extensions
exten => s,1,Answer()
exten => s,n,Wait(1)
exten => s,n,Background(enter-ext-of-person)
exten => i,1,Playback(pbx-invalid)
exten => i,n,Goto(incoming,s,1)
exten => t,1,Playback(vm-goodbye)
exten => t,n,Hangup()
[extensions]
exten => 101,1,Dial(Zap/1,10)
exten => 101,2,Playback(vm-nobodyavail)
exten => 101,3,Hangup()
exten => 101,102,Playback(tt-allbusy)
exten => 101,103,Hangup()
exten => 102,1,Dial(Zap/2,10)
exten => 102,2,Playback(vm-nobodyavail)
exten => 102,3,Hangup()
exten => 102,102,Playback(tt-allbusy)
exten => 102,103,Hangup()
[outbound]
exten => _9.,1,Dial(Zap/4/${EXTEN:1}) <<<< NOTE HERE
exten => _9.,2,Congestion()
exten => _9.,102,Congestion()
[internal]
include => extensions
include => outbound
exten => 611,1,Answer()
exten => 611,2,Playback(hello-world)
exten => 611,3,Hangup()
---------------------------------------------------------------------------
As you can see, the two FXS ports are given extensions 101 and 102; they can
dial each other, or dial out onto the PSTN by prefixing with 9 (see NOTE
HERE). The FXO port accepts incoming calls and allows the extensions to be
dialled. I factored out the 101/102 extensions into a separate context so it
could be included into both [internal] and [incoming]; that's the only
vaguely clever thing I've done.
Initially, the problem is when dialling out to the PSTN.
If I carefully dial 9 followed my own mobile phone number, which is
07974XXXXXX, sometimes it works and sometimes it doesn't. Looking at the
logs, sometimes asterisk sees 907974XXXXXX, and sometimes 9907974XXXXXX
*CLI> -- Starting simple switch on 'Zap/1-1'
-- Executing [907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [9907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/907974XXXXXX") in new stack
-- Called 4/907974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 9907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [9907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/907974XXXXXX") in new stack
-- Called 4/907974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 9907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [9907974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/907974XXXXXX") in new stack
-- Called 4/907974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 9907974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
In every case I'm leaving a one-second gap after dialing the first '9'.
If asterisk sees two '9's then clearly it fails, because I'm only stripping
off one '9' before passing the call to the PSTN.
However, dialing '102' from extension 101 never seems to have this problem.
This makes me think it might be a dialplan issue (in particular the _9.
pattern) rather than a DTMF issue.
OK, so to test this theory I changed extensions.conf so that the extensions
were 901 and 902, and use prefix 1 for the outside line.
Now the behaviour is even stranger. At first I was able to call extension
902 from 901 without problems. I then dialled 1 + my mobile number several
times and it worked again. But then Asterisk got stuck: pressing '9' caused
the call to be dropped immediately and a busy tone given. Here's the console
log:
*CLI> -- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:07:45] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [902 at internal:1] Dial("Zap/1-1", "Zap/2|10") in new stack
-- Called 2
-- Zap/2-1 is ringing
-- Zap/2-1 is ringing
[Sep 14 13:07:54] WARNING[4591]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/2-1 is ringing
-- Hungup 'Zap/2-1'
== Spawn extension (internal, 902, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:07:56] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Executing [902 at internal:1] Dial("Zap/1-1", "Zap/2|10") in new stack
-- Called 2
-- Zap/2-1 is ringing
-- Zap/2-1 is ringing
[Sep 14 13:08:00] WARNING[4592]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/2-1 is ringing
-- Hungup 'Zap/2-1'
== Spawn extension (internal, 902, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [902 at internal:1] Dial("Zap/1-1", "Zap/2|10") in new stack
-- Called 2
-- Zap/2-1 is ringing
-- Zap/2-1 is ringing
[Sep 14 13:08:04] WARNING[4593]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/2-1 is ringing
-- Hungup 'Zap/2-1'
== Spawn extension (internal, 902, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:08:05] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Executing [902 at internal:1] Dial("Zap/1-1", "Zap/2|10") in new stack
-- Called 2
-- Zap/2-1 is ringing
-- Zap/2-1 is ringing
[Sep 14 13:08:08] WARNING[4594]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/2-1 is ringing
-- Hungup 'Zap/2-1'
== Spawn extension (internal, 902, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [107974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 107974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [107974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 107974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [107974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 107974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:08:51] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Executing [107974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 107974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [107974XXXXXX at internal:1] Dial("Zap/1-1", "Zap/4/07974XXXXXX") in new stack
-- Called 4/07974XXXXXX
-- Zap/4-1 answered Zap/1-1
-- Native bridging Zap/1-1 and Zap/4-1
-- Hungup 'Zap/4-1'
== Spawn extension (internal, 107974XXXXXX, 1) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [901 at internal:1] Dial("Zap/1-1", "Zap/1|10") in new stack
[Sep 14 13:09:34] WARNING[4600]: app_dial.c:1077 dial_exec_full: Unable to create channel of type 'Zap' (cause 17 - User busy)
== Everyone is busy/congested at this time (1:1/0/0)
-- Executing [901 at internal:2] Playback("Zap/1-1", "vm-nobodyavail") in new stack
-- Playing 'vm-nobodyavail' (language 'en')
-- Executing [901 at internal:3] Hangup("Zap/1-1", "") in new stack
== Spawn extension (internal, 901, 3) exited non-zero on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:09:40] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
For the last ten lines of that, what I'm doing is:
* pick up handset connected to first FXS port
* hear dialtone, asterisk logs "Starting simple switch"
* press 9
* immediately hear busy tone, and asterisk logs "Hungup"
Just to be sure, I picked up the second FXS phone (heard dialtone) and put
it back:
-- Starting simple switch on 'Zap/2-1'
-- Hungup 'Zap/2-1'
It makes no difference. Picking up the first phone and pressing '9' gives me
an immediate busy tone.
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
Now it gets really weird. Despite this problem on the first line, if I pick
up the second FXS phone and dial '901', it works!
-- Starting simple switch on 'Zap/2-1'
-- Executing [901 at internal:1] Dial("Zap/2-1", "Zap/1|10") in new stack
-- Called 1
-- Zap/1-1 is ringing
-- Zap/1-1 is ringing
[Sep 14 13:19:10] WARNING[4617]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/1-1 is ringing
-- Hungup 'Zap/1-1'
== Spawn extension (internal, 901, 1) exited non-zero on 'Zap/2-1'
-- Hungup 'Zap/2-1'
To avoid all possibility of me making a stupid mistake, here's my modified
extensions.conf in full:
--------------------------------------------------------------------------
*CLI> !cat /etc/asterisk/extensions.conf
[incoming]
; incoming calls from the FXO port are directed to this context from zapata.conf
include => extensions
exten => s,1,Answer()
exten => s,n,Wait(1)
exten => s,n,Background(enter-ext-of-person)
exten => i,1,Playback(pbx-invalid)
exten => i,n,Goto(incoming,s,1)
exten => t,1,Playback(vm-goodbye)
exten => t,n,Hangup()
[extensions]
exten => 901,1,Dial(Zap/1,10)
exten => 901,2,Playback(vm-nobodyavail)
exten => 901,3,Hangup()
exten => 901,102,Playback(tt-allbusy)
exten => 901,103,Hangup()
exten => 902,1,Dial(Zap/2,10)
exten => 902,2,Playback(vm-nobodyavail)
exten => 902,3,Hangup()
exten => 902,102,Playback(tt-allbusy)
exten => 902,103,Hangup()
[outbound]
exten => _1.,1,Dial(Zap/4/${EXTEN:1})
exten => _1.,2,Congestion()
exten => _1.,102,Congestion()
[internal]
include => extensions
include => outbound
exten => 611,1,Answer()
exten => 611,2,Playback(hello-world)
exten => 611,3,Hangup()
*CLI>
--------------------------------------------------------------------------
Nope - I can stare at that for minutes and I cannot see what would make 901
and 902 behave asymmetrically.
OK. So then I typed
*CLI> debug level 10
Debugging level set to 10, file '<any>'
and did some more testing. It has now become intermittent. I find sometimes
I can pick up the first handset and dial "902" successfully:
*CLI> -- Starting simple switch on 'Zap/1-1'
-- Executing [902 at internal:1] Dial("Zap/1-1", "Zap/2|10") in new stack
-- Called 2
-- Zap/2-1 is ringing
-- Zap/2-1 is ringing
[Sep 14 13:22:35] WARNING[4619]: chan_zap.c:4051 zt_handle_event: Didn't finish Caller-ID spill. Cancelling.
-- Zap/2-1 is ringing
-- Hungup 'Zap/2-1'
-- Hungup 'Zap/1-1'
but sometimes pressing '9' immediately gives me a busy tone:
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
[Sep 14 13:24:10] WARNING[4586]: chan_zap.c:1636 zt_set_hook: zt hook failed: Device or resource busy
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
Here's a further log, dialling '901' which is itself. In some cases I get an
explicit busy logged after dialling all three digits, and in other cases
just the 'Starting / Hangup' pair after dialling just the '9'.
-- Starting simple switch on 'Zap/1-1'
-- Executing [901 at internal:1] Dial("Zap/1-1", "Zap/1|10") in new stack
[Sep 14 13:24:20] WARNING[4622]: app_dial.c:1077 dial_exec_full: Unable to create channel of type 'Zap' (cause 17 - User busy)
== Everyone is busy/congested at this time (1:1/0/0)
-- Executing [901 at internal:2] Playback("Zap/1-1", "vm-nobodyavail") in new stack
-- Playing 'vm-nobodyavail' (language 'en')
-- Executing [901 at internal:3] Hangup("Zap/1-1", "") in new stack
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [901 at internal:1] Dial("Zap/1-1", "Zap/1|10") in new stack
[Sep 14 13:24:38] WARNING[4624]: app_dial.c:1077 dial_exec_full: Unable to create channel of type 'Zap' (cause 17 - User busy)
== Everyone is busy/congested at this time (1:1/0/0)
-- Executing [901 at internal:2] Playback("Zap/1-1", "vm-nobodyavail") in new stack
-- Playing 'vm-nobodyavail' (language 'en')
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Executing [901 at internal:1] Dial("Zap/1-1", "Zap/1|10") in new stack
[Sep 14 13:24:48] WARNING[4625]: app_dial.c:1077 dial_exec_full: Unable to create channel of type 'Zap' (cause 17 - User busy)
== Everyone is busy/congested at this time (1:1/0/0)
-- Executing [901 at internal:2] Playback("Zap/1-1", "vm-nobodyavail") in new stack
-- Playing 'vm-nobodyavail' (language 'en')
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
Can anybody save my sanity? I know that trunk isn't supposed to be
production-quality, but I did expect to be able to make test calls between
two ports on the same device :-( Or am I doing something forbidden in the
dialplan?
Thanks,
Brian Candler.
More information about the asterisk-users
mailing list