Missing Recordings for Manual (Callback) Calls

[duncanb]

Hi,

We're experiencing an issue where calls for manual (scheduled callback) calls are being recorded intermittently. We initially has a similar problem even with the normal Vicidial outbound calls, but we resolved that by setting the campaign's "Routing Initiated Recording" setting to "Y". However this setting does not apply to manual calls as per the Vicidial help. We still find that some calls are just not recorded at all - we checked the Asterisk full log and the dialplan that calls MixMonitor was not called at all.

Another symptom we're seeing is that the recording_log table is not being updated reliably. Sometimes there is no entry at all matching a vicidial_log entry, and sometimes there is no data in the end_epoch, length_in_sec and length_in_min columns for the matching vicidial_log entry.

Currently we are ensuring recordings are being made (and often duplicated) by updating the dialplan that dials the ITSP to check if this is a manual call (by checking if the first character of CALLERID(name) is "M"), but this is not ideal as we have no way of linking this recordings back to the lead and updating the database so it is available via the Vicidial GUI.

We have other big Vicidial sites running without this problem. The major difference at this site is that the agent workstations are running Ubuntu Linux with Firefox, rather than Windows workstations. Could this be related?

Any suggestions that assist in resolving this issue would be much appreciated.

Regards,
Duncan

* System Info:

Vicidial Version: 2.14-581a
Vicidial Build: 161207-1953
Linux Info:
CentOS release 6.8 (Final)
Linux vicidial.localdomain 2.6.32-642.15.1.el6.x86_64 #1 SMP Fri Feb 24 14:31:22 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
Perl: v5.10.1
Asterisk: 1.8.28-cert5
MySQL: 5.6.35
PHP: 5.3.3
with Zend Engine v2.3.0

[mflorell]

My first thought from hearing your symptoms is that there are network issues at this location, between the agents and the dialer systems. When these type of issues happen, it's usually because of a bad local network switch, or a carrier that the traffic is going through.

[duncanb]

Thanks for the response Matt.

We're going down the network route too. I'll update this thread once we have any more information.

Regards,
Duncan

[duncanb]

Just an update:

This problem is not yet resolved. We have been monitoring the network (SmokePing) and have not picked up any concerns there.

Our current focus is on ensuring that no users go via a proxy to connect to Vicidial as we have discovered that a number of PCs are going via proxy. Hopefully this will resolve our issue.

I noticed all the manual calls (which are the ones giving problems) have a caller ID starting with "M" when they reach the outbound dialplan, so in the interim I've put some code in this dialplan to check whether the call is manual and run a "backup" recording in case Vicidial didn't trigger it:

exten => s,n,ExecIf($["${CALLERID(name):0:1}"="M"]?MixMonitor(${RECFILE}M.wav,,/home/vicidial/bin/rec_process.sh ${RECFILE}M))

We just have to live with the duplicate recordings until we can find the source of this.

Regards,
Duncan

[duncanb]

Hi,

This is still not resolved. We did identify one issue where calls to the CRM backend (via Dispo URL / Strat call URL / etc) were taking anywhere from 1 up to 30 seconds. Resolving this made a lot of our problems go away. However we're still seeing some problems with databases not being updated correctly.

We've tracked things down to gaps of time where we see no packets from the agent workstations. We don't think it's network (based on lots of testing), so think it's more likely something on the Ubuntu/Firefox/Jitsi agent workstations.

I've had to remove some useful info from the below notes as there was some private data included when I sent this summary to the client's technical team.

When investigating reported discrepancies between the agent activity log and the agent’s recordings, we found a substantial amount of missing entries in the vicidial_log table (which is used for the agent activity report).

If we run the following 2 queries on Benoni for a specific user:

select *
from vicidial_log
where call_date >= '2017-10-11 00:00:00'
and call_date <= '2017-10-11 23:59:59'
and user = 'XXX';

select *
from recording_log
where start_time >= '2017-10-11 00:00:00'
and start_time <= '2017-10-11 23:59:59'
and user = 'XXX';

We can see a lot of entries in the recording log without a matching entry in the vicidial_log. The recording_log is updated server-side, and vicidial_log updates are mostly triggered by the agent workstations. The following screenshot shows items in the recording log (highlighted in grey) that have corresponding entries in the vicidial_log. The white entries are where the problems lie:

[screenshot note available]

We wrote a quick script (x.php here), that looks for packets coming from a specific IP address and prints the amount of time since the web server last saw a packet from that IP if it's longer than 2 seconds ago). The below web server log extract was run on the same day for the same user (using the IP address instead of user name). What each “Warning” line is showing is a when there has been a delay of more than 2 seconds since the last packet from the workstation hit the web server. For instance the following line means that at 08:29:58 the web server received a packet from the PC, and the last packet the web server received was 7 seconds before that:

08:29:58 Warning 7

[root@vicidial-benoni support]# zcat /var/log/httpd/access_log-20171012.gz | grep "192\.168\.21\.124 " | sed "s/^.*2017:\(.*\) +0200.*$/\1/" | php x.php
08:29:50 Warning 1503988190 // this line can be ignored as there is no previous log entry for this IP today
08:29:58 Warning 7
08:30:01 Warning 3
08:37:01 Warning 264
08:57:43 Warning 913
09:17:10 Warning 676
09:26:00 Warning 344
09:40:49 Warning 319
09:55:13 Warning 100
09:55:21 Warning 3
09:55:39 Warning 6
09:55:42 Warning 3
09:55:46 Warning 4
09:59:08 Warning 149
09:59:13 Warning 4
09:59:18 Warning 5
10:14:23 Warning 226
10:43:22 Warning 1119
10:55:18 Warning 716
11:07:54 Warning 751
11:07:57 Warning 3
11:21:52 Warning 3
13:20:42 Warning 6513
13:30:40 Warning 5
13:59:27 Warning 811
14:17:41 Warning 3
14:50:55 Warning 1074
15:41:47 Warning 70
17:28:00 Warning 1321
17:39:40 Warning 649
17:41:39 Warning 95
17:49:14 Warning 112
18:00:13 Warning 594
18:00:44 Warning 31
18:01:16 Warning 24

If we compare the above web server log extract to the “whitespace” entries in the screenshot above, there appears to be a correlation. Importantly, it seems in every case where there is a delay in the web server log extract, there are no entries in vicidial_log that match the recording_log table for that period. Note that I have only checked this manually thus far. I also checked user Mandla and saw the same symptoms.

I have also performed a packet capture on the Ethernet interface to confirm that we stop receiving packets from the workstation where we see these warnings in the web server log extract, so it is not just a web server logging problem.

Does anybody perhaps have any ideas? I saw a post from Matt in the forums recently that spoke about Firefox auto-update breaking AJAX calls or something. Is this still an issue and could that have something to do with this?

[mflorell]

That Firefox issue was pretty old, we haven't seen it in years.

I do want to mention on the recording issue, that we have a hosted client that recently fixed this same issue by getting new network switches at their office location. It seems that their old network switches had all of the "deep packet inspection" features enabled, and the old switches weren't able to handle the load of all of the VOIP packets going through them, so packets would get delayed or dropped entirely on the local network.

[duncanb]

Hi Matt,

Thanks for the response. We're looking into that too now. I'll update again once we find anything useful.

Regards,
Duncan

[duncanb]

Just some feedback on how this issue was ultimately resolved...

It appears that running Vicidial in a separate web browser to their Javascript-heavy CRM software did the trick, although it's difficult to be 100% sure as other things were changed at the same time. Obviously the browser changed. Also more users were excluded from going via proxy. Also we do not know what else changed in the environment as the client never kept us up-to-date with these things.

[mflorell]

Thank you very much for the follow-up post. We have also had a client recently that pretty closely mirrors your experiences as well. It's good to get these notes here on the forums. Thanks again!

[ccabrera]

Hello,

I'm having "almost" the same issue. Some random calls are not being recorded, even though ROUTING INITIATED RECORDING = Y, but my case is different: I have all entries in vicidial_log, but some entries in recording_log are missing. At the beginning, this only happened in manual calls, but after some research I've found that automatic calls are not being recorded.

I've already turned on the ajax log, and I've noticed that when recordings go missing, there's no MonitorConf event.

I've also searched through the manager logs, and there's no event which initiates the recording (no call to extension 8309).


Right now I have ajax log turned on, and I have missing recordings as fresh as today. Any suggestion on where should I start digging?

As extra info: the client where this happens uses a rather heavy custom_fields form (about 40 fields).

Regards,

[mflorell]

This is almost always an issue caused by either network problems or an overloaded database server.