Autodial ringing calls passed to agents

[mstopkey]

I have a situation where Ratio auto dial campaign has started passing ringing calls to my agents. Agent has to hangup the call for it to stop dialing the number. I tried lowering the dial timeout to 12 seconds. Still the same. Routing Extension is set to 8368. Searched forum, re-read manual, tried debug on CLI but can't find the problem. Ideas?

[mflorell]

This is almost always a carrier issue, try a different carrier or report the problem to your existing carrier.

[mstopkey]

Thanks Matt. Was beating my head trying to find the problem.

[mstopkey]

Well, the carrier insists it is not them. I created a new predictive campaign (without using copy campaign) with minimal settings to see if that would cure it. No luck. Below is the log from a predictive dialed call that was passed to the agent while ringing. I have the campaign dial timeout set to 18 seconds.

Code: Select all

ast1:/var/log/asterisk # grep 3615470509 messages
[Mar 29 14:12:20] VERBOSE[23061] logger.c: [Mar 29 14:12:20]     -- Executing [913615470509@default:1] AGI("Local/913615470509@default-0299,2", "agi://127.0.0.1:4577/call_log") in new stack
[Mar 29 14:12:20] VERBOSE[23061] logger.c: [Mar 29 14:12:20]     -- Executing [913615470509@default:2] Dial("Local/913615470509@default-0299,2", "SIP/voipinnooutast1/13615470509||tToR") in new stack
[Mar 29 14:12:20] VERBOSE[23061] logger.c: [Mar 29 14:12:20]     -- Called voipinnooutast1/13615470509
[Mar 29 14:12:24] VERBOSE[23061] logger.c: [Mar 29 14:12:24]     -- SIP/voipinnooutast1-000013e0 is making progress passing it to Local/913615470509@default-0299,2
[Mar 29 14:12:28] VERBOSE[23061] logger.c: [Mar 29 14:12:28]     -- SIP/voipinnooutast1-000013e0 is making progress passing it to Local/913615470509@default-0299,2
[Mar 29 14:12:30] VERBOSE[23061] logger.c: [Mar 29 14:12:30]     -- SIP/voipinnooutast1-000013e0 answered Local/913615470509@default-0299,2
[Mar 29 14:12:30] VERBOSE[23060] logger.c: [Mar 29 14:12:30]        > Channel Local/913615470509@default-0299,1 was answered.
[Mar 29 14:12:30] VERBOSE[23123] logger.c: [Mar 29 14:12:30]     -- Executing [8368@default:1] Playback("Local/913615470509@default-0299,1", "sip-silence") in new stack
[Mar 29 14:12:30] VERBOSE[23123] logger.c: [Mar 29 14:12:30]     -- <Local/913615470509@default-0299,1> Playing 'sip-silence' (language 'en')
[Mar 29 14:12:30] VERBOSE[23123] logger.c: [Mar 29 14:12:30]     -- Executing [8368@default:2] AGI("Local/913615470509@default-0299,1", "agi://127.0.0.1:4577/call_log") in new stack
[Mar 29 14:12:30] VERBOSE[23061] logger.c: [Mar 29 14:12:30]     -- Executing [h@default:1] DeadAGI("Local/913615470509@default-0299,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----10-----0") in new stack
[Mar 29 14:12:31] VERBOSE[23061] logger.c: [Mar 29 14:12:31]   == Spawn extension (default, 913615470509, 2) exited non-zero on 'Local/913615470509@default-0299,2'


It appears to me that the carrier is sending the 'ANSWER' signal to us when in fact the phone is ringing.
Any clues?

[mflorell]

Again, I suggest trying another carrier. It will literally cost you $5 to set up a simple carrier account on a carrier like Vitelity to test this.

We have seen a lot of this, and yes it is the carrier(or if you are using an aggregate carrier, it is one of their downstream carriers).

If you are getting an answer signal while the call is ringing, that is actually illegal and constitutes fraud. We have had clients that sued their carriers for that.

[mstopkey]

Thanks Matt, after all I have checked on I am positive it is the carrier myself.

[mstopkey]

After extensive testing even with other carriers, I still have this issue. I have called several of the phone numbers from my cell and they either are ringing with no voicemail or ring until voicemail answers. I dropped the dial timeout to 14 seconds and the dialer will not hangup 'CANCEL' a ringing call at 14 seconds mark. It continues to call. It is also passing these calls to agents. Quite a bit of these I have verified as working numbers by calling them from my cell. Server loads are very good, database has been checked for corruption. Any ideas?

[mstopkey]

Update: I set the campaign to dial timeout of 10 seconds. The following call went to an agent and was just ringing.

Code: Select all

grep '2146643206' messages
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Executing [912146643206@default:1] AGI("Local/912146643206@default-dcfb,2", "agi://127.0.0.1:4577/call_log") in new stack
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Executing [912146643206@default:2] Dial("Local/912146643206@default-dcfb,2", "SIP/voipinnooutast2/12146643206||tToR") in new stack
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Called voipinnooutast2/12146643206
[Apr 18 13:37:57] VERBOSE[2183] logger.c: [Apr 18 13:37:57]   == Spawn extension (default, 912146643206, 2) exited non-zero on 'Local/912146643206@default-dcfb,2'
[Apr 18 13:37:57] VERBOSE[2183] logger.c: [Apr 18 13:37:57]     -- Executing [h@default:1] DeadAGI("Local/912146643206@default-dcfb,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
[Apr 18 13:38:40] VERBOSE[2345] logger.c: [Apr 18 13:38:40]     -- Executing [8309@default:2] Monitor("Local/58600055@default-e7e6,1", "wav|86_000504219_20160418-133839_2146643206") in new stack


\

Is the event at 13:35:57 the stop dialing that number command? DeadAGI? If so, why did it pass that lead to agent and keep ringing? Help me understand so if this is actually all carrier, I can continue my fight with them.

[mstopkey]

FYI, in the process of building new cluster on ViciBox 7.0.2

[mstopkey]

Another Update. Signed up with another different carrier. Same results. Obviously a dialer issue.

[teleinx]

You stated that you tested the number with your cell however when you test a number with a cell, it will show duration while ringing. I suggest to test it with a POTS line or a VoIP PBX line where you can clearly see if its ringing only or if its ringing and connected the call as well.

Having said that I have seen some numbers just do very odd things. Usually, customers automatically assume that its FAS. However testing further it turns out that the number(s) has odd behavior.
Another thing to check is are you dialing the same area. Maybe the CLEC who has the numbers is doing something funny on purpose? (seen this as well) Try completely different areas.

Lastly, we are a carrier, if you with contact me and we will give you a free test account and our support will investigate the issue with you.

[mstopkey]

Hello Teleinx and thank you for the response. The NPANXX is all over the place this is happening on. Area codes 210,956 214 etc. I have been looking for a pattern figuring I would find an exchange that is the bulk of the problem, but that has not been so. I did find one area that was sending ANSWER when the phone number was actually disconnected and my primary carrier took care of that with the downstream carrier. I have found no others like this. Yesterday out of 20,980 calls placed, 547 of those were what we now terminate with dispo code of CTR. The problem is getting worse. I am very open to testing with you and invite to be additional carrier. BTW, I need origination and termination in Colombia now. We opened an office there.

[mstopkey]

So, I looked at the dialing report for yesterday, out of 20,980 calls placed, only 5 came back as DC (Disconnected)? That cannot be right. I think it could be a combination of carrier and dialer issue. I did capture PCAP on port 5060 on one of the CTR calls, looked at the PCAP but I really do not totally understand what is going on in the PCAP.

[williamconley]

Update: I set the campaign to dial timeout of 10 seconds. The following call went to an agent and was just ringing.

Code: Select all

grep '2146643206' messages
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Executing [912146643206@default:1] AGI("Local/912146643206@default-dcfb,2", "agi://127.0.0.1:4577/call_log") in new stack
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Executing [912146643206@default:2] Dial("Local/912146643206@default-dcfb,2", "SIP/voipinnooutast2/12146643206||tToR") in new stack
[Apr 18 13:37:47] VERBOSE[2183] logger.c: [Apr 18 13:37:47]     -- Called voipinnooutast2/12146643206
[Apr 18 13:37:57] VERBOSE[2183] logger.c: [Apr 18 13:37:57]   == Spawn extension (default, 912146643206, 2) exited non-zero on 'Local/912146643206@default-dcfb,2'
[Apr 18 13:37:57] VERBOSE[2183] logger.c: [Apr 18 13:37:57]     -- Executing [h@default:1] DeadAGI("Local/912146643206@default-dcfb,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
[Apr 18 13:38:40] VERBOSE[2345] logger.c: [Apr 18 13:38:40]     -- Executing [8309@default:2] Monitor("Local/58600055@default-e7e6,1", "wav|86_000504219_20160418-133839_2146643206") in new stack


\

Is the event at 13:35:57 the stop dialing that number command? DeadAGI? If so, why did it pass that lead to agent and keep ringing? Help me understand so if this is actually all carrier, I can continue my fight with them.

This call should not have gone to an agent. It shows cancel. But you did not provide the rest of the cli output showing it going to an agent so there's no way to actually know what happened. Also: without that cli output (showing the call going to an agent) it's very likely that a misunderstanding will occur while chasing what we can't see. You could have a conflicting dialplan extension or custom entry breaking the vicidial core functions and intercepting the call .. or any one of myriad other oddities.

Please show this same call type, with the 10 second dial timeout, and hopefully with that CANCEL line ... and then the call actually being sent to an agent in a campaign.

Please show All lines for this call. In fact, it's best to have this with no other phones or carriers even registered to the system, no other calls in progress so you can provide the entire cli output for a single call with no distractions (not even a registration, LOL).

You may also provide the carrier entries and the campaign settings (at least the campaign routing exten, but the rest of the settings couldn't hurt, LOL). Note that the routing exten is HOW the calls get to agents ... but it's only invoked if the call is answered and converted from local (still awaiting connection) to the carrier channel (which means the call is live, and has a viable sound pathway).

[mstopkey]

Thanks William. Yeah it's been hard to capture complete info on 1 offending call since we have 20 agents on and dialing fairly fast. You mentioned something that triggered my brain! Extensions, I have programmed whisper extensions in extensions.conf. It works great! This 'CTR' was not a problem with this until a few months ago and guess what? I added whisper extension for a new office we opened in Colombia. Those extensions are 4 digit in 79XX range. Maybe I stepped on ViciDial's internal extensions usage?

[williamconley]

That's what "messages" is for in var/log/asterisk ... so you can peruse at your leisure to trace a call. Note that each call may have several legs, but those legs are each conveniently indexed in the first few characters of each line so you can "reassemble" each of them at will after the fact. So when an agent receives a ringing call, they mark the phone number, you check for that phone number in messages and follow it to origin through any other channels that may have been linked and to termination ... then collect all of them in order for the full pictures. It'll probably be awakening. Especially if (as I suspect) that call will actually show ANSWER and not CANCEL. Just a feelin' ... *)

[mstopkey]

Well, I disabled my whisper extensions and watched for 'CTRs', still get them and caught one full record. Telco is sending me 'ANSWERED' just like Matt Florell and William Conley suggested.

Code: Select all

[Apr 19 13:19:47] VERBOSE[13664] logger.c: [Apr 19 13:19:47]     -- SIP/voipinnooutast2-0000012f answered Local/919562861410@default-a1da,2
[Apr 19 13:19:47] VERBOSE[13663] logger.c: [Apr 19 13:19:47]        > Channel Local/919562861410@default-a1da,1 was answered.
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- Executing [8368@default:1] Playback("Local/919562861410@default-a1da,1", "sip-silence") in new stack
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- <Local/919562861410@default-a1da,1> Playing 'sip-silence' (language 'en')
[Apr 19 13:19:47] WARNING[13682] file.c: Unexpected control subclass '-1'
[Apr 19 13:19:47] VERBOSE[13663] logger.c: [Apr 19 13:19:47]   == Manager 'sendcron' logged off from 192.168.25.222
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- Executing [8368@default:2] AGI("Local/919562861410@default-a1da,1", "agi://127.0.0.1:4577/call_log") in new stack
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- Executing [8368@default:3] AGI("Local/919562861410@default-a1da,1", "agi-VDAD_ALL_outbound.agi|NORMAL-----LB") in new stack
[Apr 19 13:19:47] VERBOSE[13682] logger.c: [Apr 19 13:19:47]     -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
[Apr 19 13:19:47] VERBOSE[13664] logger.c: [Apr 19 13:19:47]     -- Executing [h@default:1] DeadAGI("Local/919562861410@default-a1da,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----10-----0") in new stack

Time to get the PCAP's to the Telco "Again!"

[williamconley]

Good postback, thanks for actually posting the response (a lot of managers just walk away instead of helping us to determine what really happens each time!)

[mstopkey]

Tks William. I want to keep this post fully updated in case anyone else runs across the same issue. Now the telco is giving me fits on my ticket. You were right Matt, it's turning into a fight. I realize it is not 'our' provider but the down streams.

[mstopkey]

Just in case any one else runs across this same situation, I am posting how to get the data needed for the telco's to be able to diagnose and fix this problem. I had to learn how to do this myself. So here goes.
1: Make sure ngrep is installed on your asterisk box(s). It was pre-installed on the version of ViciBox we are using. I won't go into details on how to install here. Look it up.
2: If running a cluster, I suggest temporarily running only one asterisk box if possible to alleviate difficulty tracking call from one machine to another.
3: Create a bash script as follows to run the ngrep command at will and to output results to a file. From asterisk box root CLI, nano PCAP.sh and enter the following.

Code: Select all

#!/bin/bash

##############################################
# Created to capture SIP and UDP packets                 #
# to analyze for false 'ANSWER' signals from carriers #
#############################################

ngrep-sip -t -M port 5060 -O CTRs_PCAP_$(date +%Y-%M-%d)


Save the file, then chmod u+x PCAP.sh to make it executable.
4: On the dialer autodialing campaign, create a dispo code of CTR (or something to indicate this call example) and instruct agents to only use this disposition code when VDAD passes a call to them that just constantly rings with no answer. This is most likely a call to a phone number that is disconnected and the telco sent you the 'ANSWER' code so the dialer of course passes it to an agent. Do not let agents use this dispo code when manually dialing as they could actually get a working phone with no voicemail service and the call was not answered.
5: Connect to the dialer database with a GUI, (we use Navicat) create and save a query with the following.

Code: Select all

SELECT
l.call_date,
l.`status`,
l.phone_number,
c.campaign_cid,
l.`user`
FROM
vicidial_log l
JOIN
vicidial_campaigns c ON l.campaign_id = c.campaign_id
WHERE
l.`status` = 'CTR' AND
l.call_date > '2016-04-20 16:27:59'
ORDER BY l.call_date


This will output data that the telco and yourself will need. (The l.call_date XXXXXXXXXX in the where clause, edit to get only current data each time you run the query)
6: When ready to start capture, run the PCAP.sh with ./PCAP.sh and start running the query to watch for CTR dispo'ed calls. Once you have several examples showing in the query, stop the PCAP with Ctrl+C.
7: Grab a copy of asterisk messages file with: cp /var/lag/asterisk/messages /root.
8: Save the SQL results to file, then lookup the recordings for those calls (Hence the need in query for agent `user` and phone number. Listen to the recordings to verify was actually a CTR example. (Don't supply false info to the telco. Try to stay on their good side)
9: Zip up the messages, generated PCAP output file and the SQL query results and send them to your telco.

Now you have provided them with data that they cannot argue with you about. I am currently having to do this several times a day to get all the affected NPANXX's to the telco.
I hope this helps some one in need.

[williamconley]

Brilliant postback.

[mstopkey]

Ok, now my carrier is asking for this: Could you provide us with a specific example of one receiving a FAS as it could have traversed a different termination carrier? Any suggestions as to find a call that traversed other termination carrier? My PCAP is filtering to provide UDP/SIP only. Do I not filter to get what they are asking for or would the example be in /var/log/asterisk/messages with call out to my carrier, then 'ANSWER' provided by different carrier IP or FQDN?

[williamconley]

You have no knowledge of which carrier your carrier uplines the call through. They are actually asking for a single example of an offending call, which you've already provided ... but they may not be able to handle the detail level of your pcaps. We usually provide the extension (asterisk cli) debug. This provides number dialed and exact time of day. Anything beyond that is for troubleshooting (which is not what's happening).

[mstopkey]

Hello William, sounds like time to get a new carrier that is actually willing to track and fix problems. This surprises me because I have been with this carrier for a long time and they have always handled trouble tickets very well. I think they are trying to make me do more work and give up. I can't just let this go. We are averaging about 600 'FAS' calls per day. They get passed to agents, let's say it takes 30 seconds for an agent to handle and dispo the call, that's 3 Hours of lost agent time per day!

[teleinx]

There has been a quite a big change in the voice termination industry as of about 1 month ago. Also much much more traffic with elections = more demand then supply. Its possible that your carrier is no longer capable of terminating your traffic. But regardless of this, once you provide your carrier a CDR (not even a PCAP) it should be enough to isolate the issue and resolve it.

[mstopkey]

I have written new bash scripts that run ngrep to capture PCP and iftop to capture iface traffic simultaneously and it ties the offending 'FAS' call to the iface traffic. Iface traffic shows me the endpoint connection of the call. Running it now.

[mstopkey]

Update: After refining bash script, we are able to generate a single PCAP file per call with dialed phone number and timestamp in the file name. This turned out to be very useful. Here is the code.

Code: Select all

#!/bin/bash

############################################################
# Created on 4/27/2016 to capture SIP and UDP packets                     #
# to analyze for false 'ANSWER' signals from carriers                           #
############################################################

#now=`date +%Y-%m-%d.%H:%M:%S`
#ngrep-sip -t -M port 5060 -O /root/CTR/DATA/CTRs_PCAP_$now.pcap

pcapsipdump -i eth1 -d /tmp/
#sleep 10

#exit 0


Running this for about 6 hours one day and using the DB query to get calls dispo'd with our agent CTR dispo, we were able to identify FAS's and supply the carriers with individual offending call PCAP's. As a result, we have gone from over 650 FAS's per day down to around 125 FAS's per day. The remainder is not much we can do about. Mostly disconnected cell phone and that is another story! Feel free to use this code and go fight with your carriers!

[williamconley]

Um ...

the provided bash script appears to just capture indescriminately using an app called pcapsipdump which I presume is a capture app.

There is a commented out line to create a date variable for use in ngrep-sip (which is also commented out), but still this offers no filtering from a DB entry from Vicidial. Is there a previous post which includes use of pcapsipdump to accomplish the "get a call with CTR from Vicidial"?

[mstopkey]

Previous in the post, I use SQl query to ident CTR calls. Don't use the ngrep-sip. That was a first attempt. And yes, I forgot to mention we install pcapsipdump on the Asterisk boxes. The script builds a PCAP for every call. I just run it for a while, the use the DB query to ident the calls dispoe'd with CTR and get the dialed phone number, the grep the PCAP's for that phone number. Here is the DB query.

Code: Select all

SELECT
l.call_date,
l.`status`,
l.phone_number,
c.campaign_cid
FROM
vicidial_log l
JOIN
vicidial_campaigns c ON l.campaign_id = c.campaign_id
WHERE
l.`status` = 'CTR' AND
l.call_date > '2016-05-06 09:00:00'
ORDER BY l.phone_number

This gives the call info our carriers ask for and lets you find the PCAP file.

[williamconley]

OK: so the process is to install pcapsipdump, then run it all day capturing all the control packet data. Then you run the DB query to identify calls and use the output of that to identify which calls to send in ...

How do the calls get correlated? The output from MySQL shows date/time called number and CID ... how does this correlate to the pcapsipdump information?

[mstopkey]

Yes except date time not 100% but close. Use the dialed number to find the PCAP. The dialed number will be in the name of the PCAP.

[williamconley]

Could the method to assign the name be adjusted to include the Outbound CallerID Name? That would definitely identify the call precisely. Also using the "Unique ID" would work to "hit it'. Then this could be completely automated (beginning to end).

[mstopkey]

Yes it could. But, I was frantically trying to get this working so I could "consult" with our carriers and when I got it to this point, good nuff fer me.

[williamconley]

Good to know. Maybe the next person who has this problem will take it a little farther ... eventually it could even become full-auto and generate complaint emails to the carrier without any effort.

[lasthuman]

i got same problem with only some area codes on USA, porblem with big carriers is the comunication, you can send call list, i made a disposition on vici for get all numbers and sent to carrier, they identified wich route was causing that, and changed.

better if you can get any carrier that use NPANXX filter.