thr3ads.net - asterisk users - [asterisk-users] 9 becomes 99 ? And other strangeness [Sep 2006]

If this information is useful, please help other people find it:
Share via:

Brian Candler

2006-Sep-14 04:35 UTC

[asterisk-users] 9 becomes 99 ? And other strangeness

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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@internal:2] Playback("Zap/1-1",
"vm-nobodyavail") in new stack
    -- Playing 'vm-nobodyavail' (language 'en')
    -- Executing [901@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@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@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@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@internal:2] Playback("Zap/1-1",
"vm-nobodyavail") in new stack
    -- Playing 'vm-nobodyavail' (language 'en')
    -- Executing [901@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@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@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@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@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.

Rich Adamson

2006-Sep-14 07:00 UTC

head link

[asterisk-users] 9 becomes 99 ? And other strangeness

Brian Candler wrote:> 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:
> 
> ---------------------------------------------------------------------------
> [outbound]
> exten => _9.,1,Dial(Zap/4/${EXTEN:1})             <<<< NOTE
HERE
> exten => _9.,2,Congestion()
> exten => _9.,102,Congestion()
> 
Try replacing the first step above with:
  exten => _9.,1,Dial(Zap/4/w${EXTEN:1})

Note the "w" in the above means wait for about a 1/4 second before 
sending the number to the central office.

Some central offices are not ready to receive digits as quickly as 
asterisk sends them out. In fact, some users have to use multiple w's 
(as in Zap/4/www${EXTEN:1} to wait for the equipment to settle down.

Give that a try and let us know if it corrected the problem.

Steven Totaro

2006-Sep-14 08:49 UTC

head link

[asterisk-users] 9 becomes 99 ? And other strangeness

> -----Original Message-----
> From: asterisk-users-bounces@lists.digium.com [mailto:asterisk-users-
> bounces@lists.digium.com] On Behalf Of Brian Candler
> Sent: Thursday, September 14, 2006 10:44 AM
> To: radamson@routers.com; Asterisk Users Mailing List - Non-Commercial
> Discussion
> Subject: Re: [asterisk-users] 9 becomes 99 ? And other strangeness
> 
> On Thu, Sep 14, 2006 at 09:00:57AM -0500, Rich Adamson wrote:
> > >[outbound]
> > >exten => _9.,1,Dial(Zap/4/${EXTEN:1})            
<<<< NOTE HERE
> > >exten => _9.,2,Congestion()
> > >exten => _9.,102,Congestion()
> > >
> >
> > Try replacing the first step above with:
> >  exten => _9.,1,Dial(Zap/4/w${EXTEN:1})
> >
> > Note the "w" in the above means wait for about a 1/4 second
before
> > sending the number to the central office.
> >
> > Some central offices are not ready to receive digits as quickly as
> > asterisk sends them out.
> 
> Interesting feature, thank you, but I don't think that's the
problem.
> 
> Notice that Asterisk's own log shows that it thinks the number called
is> 99XXXXX and therefore dials out to 9XXXXX, where in fact I only
dialled> 9XXXXX and so it should be dialling XXXXX.
> 
> Console:
> 
>     -- Starting simple switch on 'Zap/1-1'
>     -- Executing [9907974XXXXXX@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'
> 
> If this were consistent I could use ${EXTEN:2} to strip off the two
9's,> but
> it isn't.
> 
> Regards,
> 
> Brian.
Are you dialing from a sip phone?  How is DTMF configured in asterisk?
How is configured on the phone?  What kind of phone are you using?

Thanks,
Steve

asterisk users - Sep 2006 - 9 becomes 99 ? And other strangeness

[asterisk-users] 9 becomes 99 ? And other strangeness

[asterisk-users] 9 becomes 99 ? And other strangeness

[asterisk-users] 9 becomes 99 ? And other strangeness