vicidial_log and call_log times do not match

[cjonesmo]

The vicidial_log length_in_sec is significantly lower than that of the asterisk call_log table. The asterisk call_log table is tracking VERY closely with my carrier, but the vicidial_log is way too low. The problem is that my clients are looking at the campaign outbound report and seeing low minute utilization when in fact, they have used quite a bit more.

My call counts only differ by 150 (out of around 8000 calls), so that doesn't account for the difference. The following join query shows that almost none of the calls match up on time....how can I get vicidial_log to match the time/duration of call_log?

select phone_number,vicidial_log.length_in_sec,call_log.number_dialed,call_log.length_in_sec from vicidial_log inner join call_log on phone_number=right(number_dialed,10) where call_date>'2009-09-24';

Thanks in advance.
CJ

[williamconley]

we noticed this and modified vicidial logs to add 2 seconds to each call (if i recall correctly), basically expecting it was just a matter of the handoff time causing vicidial to be "unaware" of the extra seconds and/or "billable" seconds calculation. After all, vicidial is made aware of the call AFTER asterisk (since it is asterisk that notifies vicidial) and when vicidial initiates the hangup, it creates its log immediately, then asterisk hangs up the call and logs separately ... one second on each side could be the entire issue.

although i admit i didn't actually get "into" it.

worked for our stats (and for billing the client in question).

[cjonesmo]

Nope - that's not it...here are some stats if I can paste them...the numbers are RARELY, but sometimes higher for vicidial and are typically significantly lower for vici - as if it's starting the timer at the point the call is picked up or something:

Try this query - and note that my numbers were only called once - no redials:
select status,vicidial_log.length_in_sec as vici_log_seconds,call_log.length_in_sec as call_log_seconds from vicidial_log inner join call_log on phone_number=right(number_dialed,10) where call_date>'2009-09-25';

And Check the results - here's a small sample:
status,vici_log_seconds,call_log_seconds
'PM', 45, 25
'NA', 1, 60
'PM', 45, 37
'PU', 18, 15
'NA', 1, 15
'PU', 22, 13
'NA', 1, 16
'NA', 1, 15
'PU', 6, 7
'PU', 4, 12
'PM', 46, 56
'NA', 1, 17
'PM', 45, 2
'NA', 1, 60
'PU', 8, 14
'NA', 1, 60
'NA', 1, 50
'NA', 1, 60
'NA', 1, 60
'NA', 1, 61
'PU', 20, 8
'NA', 1, 21
'NA', 1, 60
'XFER', 18, 21
'NA', 1, 24
'XFER', 13, 25
'NA', 1, 62
'XFER', 8, 11
'XFER', 9, 12
'B', 1, 8
'XFER', 10, 5
'NA', 1, 60
'XFER', 8, 7
'XFER', 68, 10
'XFER', 37, 23
'NA', 1, 61

[mflorell]

vicidial.php version and build?

[cjonesmo]

VERSION: 2.0.5-173
BUILD: 90320-0424

This is from the admin page - if you need something else, please just let me know where to get it from.

I was thinking of creating a db job (or cron job for the db) that updates vicidial_log from call_log but would prefer to fix it properly if possible...

CJ

[mflorell]

We've made all sorts of logging fixes in the SVN trunk version(which is what we install at client sites). You should consider giving it a try.

[cjonesmo]

OK. I've upgraded to 2.2 - and today, so far, I have 7246 records in the call_log which are 10 digits in length and only 5700 records in vicidial_log. Our CDRS show 7249 calls - so we're within shouting distance regarding call_log matching up with the carrier....

Can anyone please give some insight into why records would write to call_log and not to vicidial_log?

I intend to pay support to try and resolve this issue next if no-one has any other ideas. This is costing me money every day.

Note that this box isn't being used for anything else. Only vicidial, and only for 1 client.

Thanks for trying to help guys.

CJ

[williamconley]

is there a pattern, call type, noticeable at all for which calls do/don't log?

have you looked into testing a few different call types to see if you can watch the difference happen (especially those NOT showing in vicidial_log)?

after you can create the issue on demand, then you can (under controlled conditions) turn on debug/sipdebug/agidebug and perhaps even super debugging in vicidial ... and find where the ball is dropped, or looked at through warped sunglasses.

[cjonesmo]

I've looked at the records and there's no pattern that I can see. I pulled the status from vicidial_list for these leads, and, unfortunately many of them still say "NEW". I've open a ticket with vici support and will pay for them to try and figure it out. I looked at it all weekend and put my hope into the upgrade and that didn't fix it. Here are the status counts from vicidial_list. Not that this is a survey campaign with remote agents:

+--------+---------------+
| status | count(status) |
+--------+---------------+
| AA | 399 |
| AB | 17 |
| NEW | 1293 |
| PM | 238 |
| PU | 1 |
+--------+---------------+

[williamconley]

If this is a campaign with remote agents, how do the status's get put into the system?

[cjonesmo]

Um...what do you mean? With remote agents, you create the remote agent, specify a number of channels for the agents, and put in a phone number to transfer the calls to...that's it...

[williamconley]

AB vs PU?

[cjonesmo]

There's a survey menu that plays to the client. Client presses a button to transfer to an agent which dispos the calls "SVYEXT", otherwise, they can select 9 for DNC which disposes it as DNC.

Agents don't have to dispo for Survey campaigns.

[williamconley]

(Not to sound like I think this is the case, but I have to ask, in case you haven't checked)

And you are sure that the press X script isn't the issue? (specific dispositions or paths in the press x do not result in it being "missing" from the call log ...?)

[cjonesmo]

I don't think tha tthis is the case. We basically have two options - 1 for TRANSFER and 9 for DNC. That's it...I guess the only other option is pressing nothing - but my understanding is that those should transfer through based on the OPTIN/OPTOUT settings.

[williamconley]

can you correlate the result (or lack thereof) with your missing calls?

and again with your incorrect length calls? just to see ...

it may be related to one, the other, or both. an error in the script or a logical issue related to the recording vs the transfer call length.

[cjonesmo]

I'm paying vici support to look at this. I was thinking that maybe we just overloaded the server. 83,000 calls last friday, but then, the call_log has them all, so I just think that either:

1) There's a bug

or

2) The way the vicidial_log gets written is somehow less efficient that the process that writes call_log.

I feel like I know the system fairly well, at least *nix and asterisk, but wrt Vici, I'm still learning - that said, I may have screwed something up, but I've been able to get this running and keep it running, starting to fine-tune things, write my own sql jobs, cron jobs, etc... but this log thing is KILLING my billing...Last friday, we billed about 50k out of the 80k calls.

If Vici support finds a resolution, I'll post it, or hopefully it will go into a patch if it's a code change/bug.

[williamconley]

well spoken.

we've had some discrepancies, but only on one or two clients, and most don't care as long as they know where to adjust.

to date they have all appeared to be explainable by the miniscule differences in controlling the channel. (an extra second to route here, the provider may not instantly disconnect when vicidial SAYS disconnect, so there's an extra second or two there, etc.)

so if you are having some more serious differences in vicidial's logs vs reality, i would definitely say you have chosen the best course of action.

in our case, we just added 1 or 2 seconds here and there based on the call sequencing to make up for differences for specific call types and controls, and it worked quite nicely. we ended with a roughly 1% difference in our favor for billing (so the principle is happy, of course).

the issue was the billing increments in most situations, cuz an extra second matters not EXCEPT when it seems to almost always push it to the next increment. lol

[cjonesmo]

No word back from vici support, so I hope they're watching this forum. I had installed ViciNow from the iso and it installed Asterisk 1.2 (I guess - our NOC installed it not me). At any rate, I found the following error on the console this morning while it was dialing and the is definitely one of the missing calls.

Does this mean that I need a patch to agi_res.c or to try and update asterisk from 1.2 to 1.4 or at least patch it?



[Oct 13 10:06:56] -- Executing AGI("Local/91712338XXXX@default-f947,2", "agi://127.0.0.1:4577/call_log") in new stack
[Oct 13 10:06:56] Found
[Oct 13 10:06:56] -- AMD: Word detected. iWordsCount:3
[Oct 13 10:06:57] WARNING[12892]: res_agi.c:1925 run_agi: unable to send SIGHUP to AGI process 13499: No such process

[williamconley]

i wouldn't go nuts and assume this is your issue. it may not be related at all. it may be that the process in question had completed because the AMD application was finished, or several other possibilities.

however, if you can demonstrate that this same error message does NOT occur in calls that are not missing, but always happens with calls that ARE missing ... that would be a different story.

in addition, i would not expect a change from 1.2 to 1.4 asterisk to resolve anything. honestly.

can you create or cause the issue to occur in any predictable manner? (under controlled circumstances?)