Problem : Very slow *8 pickup

Hi Everyone,

This has been driving me nuts for a few weeks, so hopefully someone will be able to help. Here are the system details…

Core 2.8.1.2 FreePBX Enabled
DAHDi Config 2.8.0.1 Digium Enabled
Fax Configuration 2.8.0.5 Schmoozecom.com Disabled
Feature Code Admin 2.8.0.1 FreePBX Enabled
FreePBX ARI Framework 2.8.0.6 FreePBX Enabled
FreePBX FOP Framework 2.8.0.6 FreePBX Enabled
FreePBX Framework 2.8.1.4 FreePBX Enabled
FreePBX Localization Updates 2.8.1.1 FreePBX Enabled
SIPSTATION 2.8.0.5 Bandwidth.com Disabled
System Dashboard 2.8.0.3 FreePBX Enabled
Voicemail 2.8.0.0 FreePBX Enabled

The system has a mix of Yealink phones and older phones with Linksys PAP2T units to hook them in. These are spread over two sites with a VPN link between them. Been running fine for almost 2 months without any other problems.

The issue was initially reported as 8* pickup not working, although I’ve now established that it does actually work - it just takes 10 or more seconds to achieve the pickup. Initially I was investigating dial plans on the Yealink phones as I suspected at that time that the 8* code was never reaching FreePBX.

The phones are split simply into two locations with the call and pickup groups set to 1 or 2. Nothing complicated there.

Inbound calls use a simple ring group. SIP trunk.

Any ideas why the pickup is so slow? At this time I can’t be sure if something in the Yealinks is causing issues but it seems that the slow pickup happens from the older PAP2T linked phones as well as the Yealinks.

Come back to me if you need more details.

Thanks

Paul.

Sounds like your DNS got broken some how.

Hi SkykingOH and thanks for the fast response.

Good thought, but DNS seems to check out and I can do a NSLOOKUP from the root prompt without delay or issue. Any other checks you’d suggest on this?

Also could you please tell me how the DNS configuration related to the pickup? Not doubting you for a moment here; just trying to puzzle out if I have accidentally introduced the issue into the server.

Thanks

Paul.

To this day I still don’t completely understand why Asterisk is so dependent on DNS. I really should do a tcpdump and see what it is doing.

Systems go to a crawl without DNS.

The logs will help you figure this out? If you turn up the debug and verbose logs you should be able to figure out what is occupying the systems attention.

Ok I have had a good dig around in the logs and I can’t see anything amiss with the DNS setup within the box itself. Also performance on the FreePBX system is pretty snappy - so I can’t see something which would suggest a big configuration foul-up by me.

BUT… SkyKingOH’s comment has got me thinking about the DNS setup. The phones and PAP2Ts on the local LAN get reserved DHCP addresses from a Microsoft SBS (Small Business Server) 2008 box. The DHCP leases point back to the SBS2008 box for DNS, which then forwards the requests out to the internet. My original thinking was that by having the FreePBX server pointed at the same DNS IP address as the phones would ensure consistency. I haven’t seen any SIP errors or anything else in the behavior of the FreePBX box which would suggest that a DNS request is timing out.

I’m now considering changing the DNS configuration to point directly to the ISP’s DNS for the primary and the SBS2008 box as the secondary.

Does anyone have any comments on this proposed change before I make it?

Thanks

Paul.

if it were DNS I would expect to see a lot of other issues.

If you have not already done so, do a tcpdump and make sure the phones are immediately sending the *8 invite to Asterisk. (You may just be able to turn on SIP debug). That will help you determine exactly where the delay is and you can look for the issue form there as it sounds like that may be what is up.

Thanks for the suggestion Philippe.

I did actually try the change last night and it had no effect on the issue or the system operation. All the same I’m grateful to SkyKingOH for the suggestion. In the interests of keeping the playing field as level as possible I’ve returned the system’s DNS configuration back to the original.

I have done debugs already as my first thought when this issue surfaced was that the Yealink phones were doing something odd that needed an adjustment to their own internal dial plans. That didn’t give me anything concrete to go one - that’s why I created this post.

Having said that I’ll take another swing at the traces and see if I can do some testing. I normally don’t get this deep into the system stuff so it’s possible that I’m overlooking something. Can you offer any pointers or advice on the best way to approach this?

Thanks

Paul.

The only odd thing I can spot in the latest debug log is some references to music on hold. Probably nothing but it’s a little odd as MoH is off on everything and certainly didn’t show up when I was originally setting up the system.

To illustrate the log file - X200 & X204 are Yealink phones, both contained in Ring Group 550 which is the initial destination of the inbound SIP trunk. This group then cascades after 5 seconds into Ring Group 551 which calls the same phones plus X220 ( another Yealink phone ) for a further 5 seconds, before cascading once again into a ‘ring all’ group where anyone can pickup before the call terminates.

The reason for this approach is that the person using the system dislikes automated phone systems and prefers that people talk to a human rather than a machine.

Here’s the relevant chunk of the log…

[2012-05-02 10:56:53] VERBOSE[3927] res_agi.c: – <SIP/T0-00003dbd>AGI Script dialparties.agi completed, returning 0
[2012-05-02 10:56:53] VERBOSE[3927] pbx.c: – Executing [[email protected]:7] Dial(“SIP/T0-00003dbd”, “SIP/200&SIP/204,5,m(none)tM(auto-blkvm)”) in new stack
[2012-05-02 10:56:53] VERBOSE[3927] netsock2.c: == Using SIP RTP TOS bits 184
[2012-05-02 10:56:53] VERBOSE[3927] netsock2.c: == Using SIP RTP CoS mark 5
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – Called SIP/200
[2012-05-02 10:56:53] VERBOSE[3927] netsock2.c: == Using SIP RTP TOS bits 184
[2012-05-02 10:56:53] VERBOSE[3927] netsock2.c: == Using SIP RTP CoS mark 5
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – Called SIP/204
[2012-05-02 10:56:53] VERBOSE[3927] res_musiconhold.c: – Started music on hold, class ‘none’, on SIP/T0-00003dbd
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – SIP/200-00003dbe connected line has changed. Saving it until answer for SIP/T0-00003dbd
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – SIP/204-00003dbf connected line has changed. Saving it until answer for SIP/T0-00003dbd
[2012-05-02 10:56:53] WARNING[3927] format_wav.c: Read failed (type)
[2012-05-02 10:56:53] WARNING[3927] file.c: Unable to open format wav
[2012-05-02 10:56:53] WARNING[3927] res_musiconhold.c: Unable to open file ‘/var/lib/asterisk/mohmp3/.nomusic_reserved/silence’: No such file or directory
[2012-05-02 10:56:53] VERBOSE[3927] res_musiconhold.c: – Stopped music on hold on SIP/T0-00003dbd
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – SIP/200-00003dbe is ringing
[2012-05-02 10:56:53] VERBOSE[3927] app_dial.c: – SIP/204-00003dbf is ringing
[2012-05-02 10:56:56] VERBOSE[3927] app_dial.c: – SIP/204-00003dbf connected line has changed. Saving it until answer for SIP/T0-00003dbd
[2012-05-02 10:56:56] VERBOSE[3927] app_dial.c: – SIP/204-00003dbf answered SIP/T0-00003dbd
[2012-05-02 10:56:56] VERBOSE[3927] pbx.c: – Executing [[email protected]:1] Set(“SIP/204-00003dbf”, “__MACRO_RESULT=”) in new stack
[2012-05-02 10:56:56] VERBOSE[3927] pbx.c: – Executing [[email protected]:2] NoOp(“SIP/204-00003dbf”, “Deleting: BLKVM/550/SIP/T0-00003dbd TRUE”) in new stack
[2012-05-02 10:58:05] VERBOSE[3927] pbx.c: – Executing [[email protected]:1] Macro(“SIP/T0-00003dbd”, “hangupcall”) in new stack

Any ideas?

Paul.

I don’t think the MOH would cause it however I would fix the issue. Make sure your paths are correct in advanced settings.

Lastly, set the inbound route to the ring all group. Try and do the pickup from a softphone and see if the delay is still there.

Lastly, does a directed call pickup result in the same delay?

  1. This is not normal behavior.
  2. Have you posted a snippet of the Asterisk logs showing the behavior occurring? I don’t see it.
  3. Phillipe’s suggestion seems the most logical. Check the dialplan on the phones and make sure that they send the *8 out immediately.
  4. Do you have any feature codes that could conflict, i.e. if you have a feature code *855 and *853 and *85, Asterisk may be holding the *8 for a period to see if another digit is coming.

Try changing *8 to something else. I prefer *PU. To make sure it isn’t issue #4, try changing it to something really long and use the redial key to test it, i.e.

*8008675309