Random issues with manual dial

[arrrrr]

We've recently upgraded to the latest vicidial version from a very old installation. This was basically a new setup (vicibox, Version: 2.14b0.5, svn rev 3701) with some existing agents/leads/dids imported in the new db.
Everything works fine except a very annoying issue: some manual dial calls (nearly 5-7%) are not properly detected as live upon connection and therefore all agent actions are disabled (hangup, pause, etc). The only way to end up the call and continue working is log out, however this makes the lead to end up in ERI status without any closer records for this call.
We are still unable to reliably replicate the issue, however here is what we found out by now:
- The issue only exists on the new agent screen. The old one (vicidial-grey.php) works fine.
- Hardware is perfectly fine: it's a beefy asterisk server with dedicated db server and loads are well below 1
- Agents do not have any connectivity issues
- Asterisk log has multiple "func_hangupcause.c:140 hangupcause_read: Unable to find information for channel ", but as far, as I see that might be okay.
- Both servers have high open files/mysql connections/apache forks limits, so this is not the issue.
- Agents do not have any errors or warnings
- Agent debug log does not have anything suspicious (at least I don't see it):

Code: Select all

| operator56           | 2023-04-02 09:27:08 | 2023-04-02 09:27:08 | 0.01136    | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:07 | 2023-04-02 09:27:07 | 0.012479   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:07 | 2023-04-02 09:27:07 | 0.00889    | vdc_db_query.php     | CALLSINQUEUEview                    | 0          | 1580                                                                   |
| operator56           | 2023-04-02 09:27:06 | 2023-04-02 09:27:06 | 0.012213   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:05 | 2023-04-02 09:27:05 | 0.011292   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:05 | 2023-04-02 09:27:05 | 0.008488   | vdc_db_query.php     | CALLSINQUEUEview                    | 0          | 1580                                                                   |
| operator56           | 2023-04-02 09:27:02 | 2023-04-02 09:27:04 | 0          | vicidial.php         | Browser_Visibility                  | 0          | 0|WENT HIDDEN 12 1680416823                                            |
| operator56           | 2023-04-02 09:27:04 | 2023-04-02 09:27:04 | 0.011979   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:03 | 2023-04-02 09:27:03 | 0.013859   | vdc_db_query.php     | CalLBacKCounT                       | 0          | *****SUP|0|0                                                           |
| operator56           | 2023-04-02 09:27:03 | 2023-04-02 09:27:03 | 0.013259   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:03 | 2023-04-02 09:27:03 | 0.008925   | vdc_db_query.php     | CALLSINQUEUEview                    | 0          | 1580                                                                   |
| operator56           | 2023-04-02 09:27:02 | 2023-04-02 09:27:02 | 0.011104   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:00 | 2023-04-02 09:27:00 | 0.011801   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:27:00 | 2023-04-02 09:27:00 | 0.00934    | vdc_db_query.php     | CALLSINQUEUEview                    | 0          | 1580                                                                   |
| operator56           | 2023-04-02 09:26:57 | 2023-04-02 09:26:59 | 0          | vicidial.php         | NeWManuaLDiaLCalLSubmiT             | 0          | 1|NOW                                                                  |
| operator56           | 2023-04-02 09:26:57 | 2023-04-02 09:26:59 | 0          | vicidial.php         | safe_pause_CFAI                     | 0          | 0|1 PAUSED                                                             |
| operator56           | 2023-04-02 09:26:59 | 2023-04-02 09:26:59 | 0.012099   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:26:59 | 2023-04-02 09:26:59 | 0.032489   | vdc_db_query.php     | manDiaLnextCaLL                     | 4213084    | lookup|RIR|9906712|PAUSED|MANUAL_DIALNOW|**************|CAMPAIGN_CID|    |

Really nothing goes on for the next couple of minutes, but then agent logs out without any prior actions:

Code: Select all

| operator56           | 2023-04-02 09:28:50 | 2023-04-02 09:28:50 | 0.013859   | vdc_db_query.php     | CalLBacKCounT                       | 0          | *****SUP|0|0                                                           |
| operator56           | 2023-04-02 09:28:50 | 2023-04-02 09:28:50 | 0          | vicidial.php         | LOGIN                               | 0          | 0|2.14-682c 230306-2034 /agc/vicidial.php                              |
| operator56           | 2023-04-02 09:28:50 | 2023-04-02 09:28:50 | 0.011924   | conf_exten_check.php | refresh                             | 0          | PAUSED|9906724                                                         |
| operator56           | 2023-04-02 09:28:47 | 2023-04-02 09:28:48 | 1.01205    | vdc_db_query.php     | userLOGout                          | 0          | NORMAL 2.14-424 230309-1005                                            |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:47 | 0          | vicidial.php         | Browser_Visibility                  | 0          | 3|WENT VISIBLE 0 1680416927                                            |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:47 | 0          | vicidial.php         | Browser_Visibility                  | 0          | 2|WENT HIDDEN 4 1680416927                                             |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:47 | 0          | vicidial.php         | LogouT                              | 0          | 1|NORMAL                                                               |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:47 | 0          | vicidial.php         | NormalLogout                        | 0          | 0|                                                                     |
| operator56           | 2023-04-02 09:28:47 | 2023-04-02 09:28:47 | 0.013476   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:28:47 | 2023-04-02 09:28:47 | 0.011062   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:46 | 0.011845   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712                                                         |
| operator56           | 2023-04-02 09:28:46 | 2023-04-02 09:28:46 | 0.008313   | vdc_db_query.php     | CALLSINQUEUEview                    | 0          | 1580                                                                   |
| operator56           | 2023-04-02 09:28:45 | 2023-04-02 09:28:45 | 0.011321   | conf_exten_check.php | refresh                             | 0          | INCALL|9906712   

All other issues have almost exactly the same debug log: manual dial => multiple refresh/visibility records => logout. No errors or anything like that.
At the moment I have no ideas and we ended up moving all agents to vicidail-grey, however using this old version is not future-proof.
Any help is highly appreciated.

[mflorell]

What version of Asterisk are you using?

Do you see anything in the apache error_log related to these issues?

[arrrrr]

What version of Asterisk are you using?

Do you see anything in the apache error_log related to these issues?

Asterisk 13.38.3-vici
Nothing in apache log too

[mflorell]

I noticed that the browser "WENT HIDDEN" right after dialing, Are you using any of the javascript throttling countermeasures on your system?
https://www.vicidial.org/docs/WEB_BROWS ... TTLING.txt

Also, these debug logs seem to show that the agent was already INCALL when they placed that manual dial call. Could you post more data from the debug logs before and after the first segment?

[arrrrr]

I noticed that the browser "WENT HIDDEN" right after dialing, Are you using any of the javascript throttling countermeasures on your system?
https://www.vicidial.org/docs/WEB_BROWS ... TTLING.txt

Yes, we are using 20mhz tone played every 10 sec:

https://shottr.cc/s/NRh5/SCR-20230408-hlk.png

and it works (at lease according to the agent log:

https://shottr.cc/s/NPk0/SCR-20230408-hqy.png

+ "AGENT SCREEN TIMER" is set to 'EventSource'

I played with these settings: changed tones, intervals and volume levels, but it did not change anything.

Also, these debug logs seem to show that the agent was already INCALL when they placed that manual dial call. Could you post more data from the debug logs before and after the first segment?

Agent was paused when placing the manual call:

https://shottr.cc/s/NStG/SCR-20230408-hrp.png

[mflorell]

It seems like there are some agent debug entries missing for this manual dial call, like "manDiaLlookCaLL" and "manDiaLlogCaLL" which usually happens between the initiation of the call and the agent going to INCALL status. I'm not sure what would cause that, since I've never seen it happen before, but that does seem like it might be an issue.

[martinch]

Hey, couple of questions from me.

- What dial method is this using? Looks like safe_pause_CFAI is being logged so possibly some kind of Inbound is enabled.
- Does this problem occur in other Throttling Methods (perhaps try with Agent Screen Timer: EventSource).
- Can you capture the output from the Network Analyzer in Chrome? That will tell us exactly what your problem is. It could be data related to the lead you're trying to dial or could be campaign settings or something else completely. In Chrome, hit F12, click the network tab, hit the record button in the top left (little grey circle) or Control + E, make your manual dial, then click the downward pointing arrow "Export Har" and then share that. That will help pinpoint the issue.

Thanks.

[arrrrr]

It's been a while, however we are still having the same problem and are currently using the old gui (which, however does not have any throttling handling)

Hey, couple of questions from me.

- What dial method is this using? Looks like safe_pause_CFAI is being logged so possibly some kind of Inbound is enabled.

That's mostly inbound campaign with some outbound manual dialing

- Does this problem occur in other Throttling Methods (perhaps try with Agent Screen Timer: EventSource).

We are using EventSource

- Can you capture the output from the Network Analyzer in Chrome? That will tell us exactly what your problem is. It could be data related to the lead you're trying to dial or could be campaign settings or something else completely. In Chrome, hit F12, click the network tab, hit the record button in the top left (little grey circle) or Control + E, make your manual dial, then click the downward pointing arrow "Export Har" and then share that. That will help pinpoint the issue.

That's tricky, cuz the issue is not permanent (and only appears in 5-7% calls), so catching it with the console open may take a while.

[martinch]

Oh hey, thanks for coming back with more info. Couple more things from me;

• Observe the agent latency (you can use the newly releases Latency reporting to check or Chrome Developer Tools on the machine). For optimal operation, I would say ping of no more than 500ms would be considered optimal. Anything about that I would troubleshoot the machine, network connection etc
• Enabled Agent Logging. If you can, strip all the personal info from the agent click log and provide it here. That allows us to build the picture.

Cheers