Wiating for ring and dial timeout on live call

[jcuzens]

I believe that the issue is similar to the one below:

/viewtopic.php?f=4&t=32971

MANUAL DIAL ALL AGENTS

On a small number of calls (I would say it every one of our 23 agents at least once daily) we see a problem where the agent dials and subsequently is connected to a live customer but the screen never goes "LIVE". We added some logging to the vicidial.php and could see the queries that are being done against the vicidial_manager table. E.g.

Code: Select all

manDiaLlook_query:  server_ip=192.168.0.35&session_name=1418154988_41112794242&ACTION=manDiaLlookCaLL&conf_exten=8600056&user=411&pass=1234&MDnextCID=M2091203040000053232&agent_log_id=104574&lead_id=53232&DiaL_SecondS=0&stage=
vicidial2.php:3787 MDlookResponse:  NO

This will continue for 50 seconds until our dial timeout is reached but the agent is actually on the phone with the customer.

There are several places the vicidial_manager table is inserted into but we believe that the problem may be related to the AST_manager_listen.pl not seeing the state of the call change. A good call will have the "Newstate" like the below (omitting phone numbers):

Code: Select all

Event: Newstate
Privilege: call,all
Channel: SIP/bandwidthcom-00000d9c
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 858XXXXXXX
CallerIDName: M2092300390000052563
ConnectedLineNum: 858XXXXXXX
ConnectedLineName: M2092300390000052563
Uniqueid: 1418194839.17149

Where it seems a bad call never generates this log. These messages are from the Asterisk Manager Interface so it may just be that the AMI isn't generating these events and so this is some kind of bug. We are thinking about upgrading our Asterisk to the latest version to see if that helps but confirming that we are barking up the right tree...

Thanks!

[mflorell]

Does the Asterisk CLI show that the call is Answered?

Have you tried another carrier?

[jcuzens]

Does the Asterisk CLI show that the call is Answered?

Yes, in the Asterisk CLI I can see this:

Code: Select all

[Dec  9 12:03:10] VERBOSE[32767] app_dial.c: [Dec  9 12:03:10]     -- SIP/bandwidthcom-0000005d answered Local/8600056@default-00000098;1
[Dec  9 12:03:06] VERBOSE[32767] app_dial.c: [Dec  9 12:03:06]     -- SIP/bandwidthcom-0000005d is making progress passing it to Local/8600056@default-00000098;1
[Dec  9 12:04:23] VERBOSE[32767] pbx.c: [Dec  9 12:04:23]     -- Executing [h@default:1] AGI("Local/8600056@default-00000098;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----79-----73") in new stack
[Dec  9 12:04:23] VERBOSE[32767] res_agi.c: [Dec  9 12:04:23]     -- <Local/8600056@default-00000098;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----79-----73 completed, returning 0
[Dec  9 12:04:23] VERBOSE[32767] pbx.c: [Dec  9 12:04:23]   == Spawn extension (default, 912137455042, 2) exited non-zero on 'Local/8600056@default-00000098;1'
[Dec  9 12:04:23] VERBOSE[32766] pbx.c: [Dec  9 12:04:23]   == Spawn extension (default, 8600056, 1) exited non-zero on 'Local/8600056@default-00000098;2'
[Dec  9 12:04:23] VERBOSE[32766] pbx.c: [Dec  9 12:04:23]     -- Executing [h@default:1] AGI("Local/8600056@default-00000098;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Dec  9 12:04:23] VERBOSE[32766] res_agi.c: [Dec  9 12:04:23]     -- <Local/8600056@default-00000098;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0

Have you tried another carrier?

No, we haven't tried using anyone other than Bandwidth. This is more of a last resort for us. The issue certainly doesn't appear *ALL* the time. It's a small number of cases but considering we track agents talk time and they are accountable for hitting certain metrics we are trying to ensure things are as accurate as possible.

I think that upgrading Asterisk to the latest 1.8.32 might be a first recourse before switching carriers.

[jcuzens]

I don't know if this would be possible or not but would adjusting the dial plan for the carrier help? Would it be possible to do an "Answer" and then trigger "NewState" in AMI? My current carrier settings:

Code: Select all

exten => _91XXXXXXXXXX,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _91XXXXXXXXXX,2,Dial(SIP/+${EXTEN:1}@bandwidthcom,,tTo)
exten => _91XXXXXXXXXX,3,Hangup

To

Code: Select all

exten => _91XXXXXXXXXX,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _91XXXXXXXXXX,2,Dial(SIP/+${EXTEN:1}@bandwidthcom,,rtTo)
exten => _91XXXXXXXXXX,3,Hangup

[jcuzens]

Unfortunately changing the dial plan to:

exten => _91XXXXXXXXXX,2,Dial(SIP/+${EXTEN:1}@bandwidthcom,,rtTo)

Had no effect. We were still able to reproduce our issue where the call was live but the agent screen was not Live.

[jcuzens]

Just checked a log when this happened and noticed that the output in the AST Listen process appears truncated:

Code: Select all

2014-12-16 11:16:33|Event: Newstate
Privilege: call,all
Channel: SIP/bandwidthcom-000048f0
Cha

Event: PeerStatus
Privilege: system,all
ChannelType: SIP
Peer: SIP/206
PeerStatus: Registered
Address: 192.168.0.35:5066


I wonder if the Listen process sometimes is unable to read all the data.

[jcuzens]

Hmmm, yes I see this on multiple events where the output appears truncated:

Code: Select all

|
2014-12-16 10:38:37|Event: MonitorStop
Pr

Event: PeerStatus
Privilege: system,all
ChannelType: SIP
Peer: SIP/202
PeerStatus: Registered
Address: 192.168.0.35:5066

|


Going to try and turn on the telnet log and see if it has the full output or not to determine if it's how the buffer is handled or not.

[jcuzens]

Well, I can see a difference from the input_log dump from Net::Telnet and what the ASTListen dumps. The inpu_log has Newstate, Newstate, MonitorStart, MeetMeJoin whereas the ASTListen log has a truncated Newstate followed by MeetMeJoin. Not sure if it's related to the keepalive (see the show uptime which should be core show uptime) resetting the buffer or not. But missing events would cause *some* issues.

input_log

Code: Select all

Event: Newstate
Privilege: call,all
Channel: Local/58600066@default-0000c1b1;2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName: 20141217-102938_XXXXXX_ALLINZIP_409
ConnectedLineNum:
ConnectedLineName: 20141217-102938_XXXXXX_ALLINZIP_409
Uniqueid: 1418840979.125033

Event: Newstate
Privilege: call,all
Channel: Local/58600066@default-0000c1b1;1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName: 20141217-102938_XXXXXX_ALLINZIP_409
ConnectedLineNum:
ConnectedLineName: 20141217-102938_XXXXXX_ALLINZIP_409
Uniqueid: 1418840979.125032

Event: MonitorStart
Privilege: call,all
Channel: Local/58600066@default-0000c1b1;1
Uniqueid: 1418840979.125032

Response: Follows
Privilege: Command
No such command 'show uptime' (type 'core show help show uptime' for other possible commands)
--END COMMAND--

Event: MeetmeJoin
Privilege: call,all
Channel: Local/8600066@default-0000c1b0;2
Uniqueid: 1418840978.125030
Meetme: 8600066
Usernum: 2
CallerIDnum: XXXXXX
CallerIDname: M2171029380000046818
ConnectedLineNum: XXXXXX
ConnectedLineName: M2171029380000046818


ASTListen log (listen.2014-12-17)

Code: Select all

2014-12-17 10:29:39|Event: Newstate
Privilege: call,all
Channel: Local/58600066@default-0000c1b1;2
ChannelState: 6
[color=#FF0000]Ch[/color]

Event: MeetmeJoin
Privilege: call,all
Channel: Local/8600066@default-0000c1b0;2
Uniqueid: 1418840978.125030
Meetme: 8600066
Usernum: 2
CallerIDnum: XXXXXX
CallerIDname: M2171029380000046818
ConnectedLineNum: 8582308216
ConnectedLineName: M2171029380000046818

|
2014-12-17 10:29:39|Event: MeetmeJoin
Privilege: call,all
Channel: Local/58600066@default-0000c1b1;2
Uniqueid: 1418840979.125033
Meetme: 8600066
Usernum: 3
CallerIDnum: <unknown>
CallerIDname: 20141217-102938_7607471424_ALLINZIP_409
ConnectedLineNum: <unknown>
ConnectedLineName: 20141217-102938_7607471424_ALLINZIP_409


[jcuzens]

Ok, so it does indeed seem to be related to the keepalive function. For every 50 events that are read by the ASTlisten process a keepalive gets generated and sent to the AST manager as below:

Code: Select all

@list_lines = $tn->cmd(String => "Action: Command\nCommand: show uptime\n\n", Prompt => '/--END COMMAND--.*/', Errmode    => Return, Timeout    => 1);

Ignoring the "show uptime" which can be changed to the correct "core show uptime" what this will do is send the action and then wait for the END COMMAND prompt. Unfortunately, what it also appears to do is absorb any events that would be in the buffer (not the partial buffer but the telnet buffer) into the @list_lines variable which is not used.

For our purposes we have disabled this command and if the connection was to go dead (which is what this was intended to avoid) then the process would restart anyway given how it's currently written.

[jcuzens]

Tracked as issue: http://www.vicidial.org/VICIDIALmantis/view.php?id=809

[mflorell]

Very interesting indeed. That part of the code hasn't been touched in years, and strangely enough we haven't traced any problems with this at all.

Do you have an easy way to replicate and trace the problem so we can begin to test this?

[mflorell]

I uploaded a new version of the AST_manager_listen.pl script to the Issue Tracker Ticket. Please try it out and let me know if if fixes your issues.

There are two changes:
1. When your system is busy(50 actions in less than 40 seconds) it will not send the keepalive
2. When the keepalive is run, it will now include the input received in the input buffer