pbxer

Everything was working fine on this particular asterisk PBX install. It was for a home office, with a single extension.

Incoming callers would get a welcome message, and press 2 to ring the actual phone. (This little extra step stops virtually all automated dialers and telemarketers from getting through.)

The only problem with the system was that it was taking about 8 seconds from the time the 2 was pressed for the extension to ring. What was going on?

Here is the relevant part of the dialplan:

[tom-incoming]
exten => s,1,Noop(Tom: Incoming call from: ${CALLERID(all)})
exten => s,n,Set(TIMEOUT(response)=10)
exten => s,n,Ringing
exten => s,n,Wait(2)
exten => s,n,Answer
exten => s,n(restart),Background(/root/tom-intro)
					  ; hello...
						; To reach Tom press 2,
exten => s,n,WaitExten			; Wait for an extension to be dialed.

exten => 2,1,Noop("Calling Tom")
exten => 2,n,Wait(1)
exten => 2,n,Dial(SIP/office,20) ; aastra - 20 secs
exten => 2,n,Goto(2-${DIALSTATUS},1) ; Jump based on status (NOANSWER,BUSY,CHANUNAVAIL,CONGESTION,ANSWER)
exten => 2-NOANSWER,1,Voicemail(30,us) ; If unavailable, send to voicemail w/ unavail announce
exten => 2-NOANSWER,n,Playback(vm-goodbye)
exten => 2-NOANSWER,n,Hangup
exten => 2-BUSY,1,Voicemail(30,bs) ; If busy, send to voicemail w/ busy announce
exten => 2-BUSY,n,Goto(tom-moore-incoming,s,1) ; If they press #, return to start
exten => _2-.,1,Goto(s-NOANSWER,1) ; Treat anything else as no answer

exten => 700,1,VoicemailMain(30)
exten => i,1,Goto(s,restart)		;; if they type the wrong key, play into again
exten => i,n,Hangup
exten => t,1,Playback(vm-goodbye)
exten => t,n,Hangup

exten => 2800,1,Wait(1)
exten => 2800,n,Record('/tmp/outgoing-message-tom-%d.wav') ; stop record with #
exten => 2800,n,Wait(2)
exten => 2800,n,Playback(${RECORDED_FILE})
exten => 2800,n,Goto(s,restart)

My first reaction was to add an explicit “Ringing” command. No change.

exten => 2,1,Noop("Calling Tom")
exten => 2,n,Ringing ;; do i need this?
exten => 2,n,Wait(1)
exten => 2,n,Dial(SIP/office,20) ; aastra - 20 secs

My next thought was that perhaps my key presses were not being received. If I pushed the 2 and held it for a long time, I was able to ring the extension. I turned on the key press debugging (dtmf) in the log settings.

messages => notice,warning,error,verbose,dtmf

And from the logs it was clear that they were being received.

[Jul 10 11:07:39] DTMF[23488] channel.c: DTMF end passthrough '2' on SIP/e61-007920a0
[Jul 10 11:07:40] DTMF[23488] channel.c: DTMF end '2' received on SIP/e61-007920a0, duration 0 ms
[Jul 10 11:07:40] DTMF[23488] channel.c: DTMF end accepted without begin '2' on SIP/e61-007920a0
[Jul 10 11:07:40] DTMF[23488] channel.c: DTMF end passthrough '2' on SIP/e61-007920a0

Ok… So, it’s clear that the 2 is being received, but the 8 second delay before ringing still doesn’t make sense.

My next thought was that it might be some sort of latency in the router. I didn’t know how long it would be before I was able to go on site and look at the router, so though that by adding a “please wait while I try that extension” message, at least callers wouldn’t be confused by the delay.

I added the “Background” command to the dialplan to play the transferring message.

exten => 2,1,Noop("Calling Tom")
exten => 2,n,Ringing
exten => 2,n,Wait(1)
exten => 2,n,Background(transfer)	; notify caller that this might take a while
exten => 2,n,Dial(SIP/office,20) ; aastra - 20 secs

But after pressing 2 it still took 8 seconds before the message was played. Weird. But at least I now knew that it was a problem in the asterisk server, not with the phone, the router or the DSL internet connection.

While testing, I would press 2 repeatedly - thinking that maybe the button wasn’t registering. I then noticed this message in the logs:

[Jul 10 11:07:40] DTMF[23488] channel.c: DTMF end passthrough '2' on SIP/e61-007920a0
[Jul 10 11:07:45] VERBOSE[23488] logger.c:   == CDR updated on SIP/e61-007920a0
[Jul 10 11:07:45] VERBOSE[23488] logger.c:     -- Executing [2222222@tom-incoming:1] Goto("SIP/e61-007920a0", "s-NOANSWER|1") in new stack

So, all of the keypresses were being registered, and now asterisk was trying to dial the extension ‘2222222′.

Ah ha!

The PBX was allowing me to push 2 several times before acting on the keypresses. Why? Because if you look at the valid extensions, there is a ‘2′ and a ‘2800′. It doesn’t know which one is being dialed, so it waits after the first 2 because it doesn’t know if the 2 or 2800 is being dialed. Makes total sense.

So, I commented out the 2800 extension, reloaded the config,

and the phone started to ring immediately after pushing 2.

Lessons Learned

• Remove extensions that you aren’t using
• If you have extensions with different lengths (single and multiple digits) make sure their initial digits are different.

Tags: troubleshooting asterisk dtmf dialplan