Calls sometimes hanging up when they shouldn't

[chrisbIT]

Hi all,

I was hoping somebody could help me track down a small issue we have been experiencing.

We seem to be experiencing problems with phone calls getting hung up during mid conversation.
This happens both on manual and auto dialling. It is not all the time, probably 1 for every 100 calls and it's not after any fixed amount of time either.

I am struggling to see whether the call is getting killed by asterisk or by our sip endpoint (A Quintum Tenor CMS connected to PSTN (E1 lines)). Must point out it's the customer that gets hungup, the agent never gets booted out of the conference.

I am not certain whether it started happening when we went to a multi-dialler set up but it seems like it might be. We have also noticed a pop-up occassionally on the agent interface informing that the "Channel has Changed"? It is not these agents that get the cut off though...but is it related? It seems as though the wrong channel could be getting hung up occassionally when an agent dispositions....is this possible when it seems fairly infrequent?

Hope somebody can shed a little light as where to look.

Many Thanks.

Chris

[chrisbIT]

further to the above.....

We have ruled out load (0.25 average 0.7 ish when call mixing).
We have both Debian and CentOS diallers (1000hz, pre-emption server), some with x100p some ztdummy (we are experimenting with all possible configs) full time recording to tmpfs then mixed and offloaded to an nfs share. diallers between 10-20 agents.
asterisk 1.2.24, 1.2.29 and 1.2.30 (with associated levels of libpri/zaptel)
The problem is on all servers.

The database is separate and on a beast of a machine that is running with very little load. The web server is also separate and experiences no issues.

Thanks.

Chris

[chrisbIT]

looking through the latest files in svn, I notice that FastAGI has this:

80303-1438 - Fixed problem with false hangupcause data

maybe this is what I need? could I use this FAST AGI with the current 2.04 stable?

[mflorell]

We have had a few clients with this kind of problem and it is always traced back to being the carrier that causes these kind of hangups.

In SVN there is a new term_reason field that denotes who hung the call up, it doesn't really have anything to do with hanging up a call or detecting that a call has been hung up. The SVN version of FastAGI_log will not work with 2.0.4.

[chrisbIT]

Thanks for the response Matt. We have had our carrier (Telewest) monitor our lines and they say the calls are terminating at our end. That probably points towards the Quintum CMS or the Asterisk boxes. We have two quintums (one at each site) both running slightly different firmwares hooked up to their own bunch of E1's and we experience the problem equally everywhere.

We also have a couple of other Asterisk (non v'dial) boxes that service agents on old campaigns and we do not see the issue with these. This leans me towards issues with meetme conferences or possibly some config that could be wrong......then again 99% of the time things are fine

We never saw this issue at the beginning of the year when we started out with an "all in one" box.

Thanks

Chris

[chrisbIT]

Matt, what is the significance of the "Channel has changed" message?

Thanks

Chris

[mflorell]

How exactly is the message displayed?

Where is it displayed?

Is that all that appears on the message?

When exactly is that message displayed?

[chrisbIT]

it appears occasionally on the agent interface (as a javascript popup) along with the channel info. the code for it is in the php script:

Code: Select all

if (xmlhttp.readyState == 4 && xmlhttp.status == 200)
                                        {
                                        var recheck_incoming = null;
                                        recheck_incoming = xmlhttp.responseText;
                                //      alert(xmlhttp.responseText);
                                        var recheck_VDIC_array=recheck_incoming.split("\n");
                                        if (recheck_VDIC_array[0] == '1')
                                                {
                                                var reVDIC_data_VDAC=recheck_VDIC_array[1].split("|");
                                                if (reVDIC_data_VDAC[3] == lastcustchannel)
                                                        {
                                                // do nothing
                                                        }
                                                else
                                                        {
                                       alert("Channel has changed from:\n" + lastcustchannel + '|' + lastcustserverip + "\nto:\n" + reVDIC_data_VDAC[3] + '|' + reVDIC_data_VDAC[4]);
                                                        document.vicidial_form.callchannel.value        = reVDIC_data_VDAC[3];
                                                        lastcustchannel = reVDIC_data_VDAC[3];
                                                        document.vicidial_form.callserverip.value       = reVDIC_data_VDAC[4];
                                                        lastcustserverip = reVDIC_data_VDAC[4];
                                                        custchannellive = 1;
                                                        }
                                                }
                                        }
                                }



for now I have commented out the alert prompt.

[mflorell]

Is this only on the Closer side of a Consultative transfer?

[chrisbIT]

no we are not doing closer or transfer. Currently just simple outbound.

Thanks

Chris

[chrisbIT]

hmm, your comments on xfer got me thinking. Just had a cut off reported so grabbed the relevant log entries and found this (number hidden for privacy):

Is vdial deleting the call thinking it's dead when it isn't?

Code: Select all

2008-08-01 12:55:28||     dead call vac deleted|1875927|1178839|M0801125519001178839|1217591727|1|||
2008-08-01 12:55:28||     dead call vac XFERd do nothing|1178839|NUMBER HIDDEN|XFER||
2008-08-01 12:55:28||     lagged call vla agent PAUSED 0E0|20080801125458|20080801125518|20080801125528||
2008-08-01 12:55:28||     lagged call vac agent DELETED 0E0|2008-08-01 12:53:28||
2008-08-01 12:55:28||     lastcalldate UPDATED 1|'5404131'||
2008-08-01 12:55:28||     logindate UPDATED 3|'540413','69999','54041'||
2008-08-01 12:55:28||     lagged call vac agent DELETED 0E0|2008-08-01 12:45:28|LIVE||
2008-08-01 12:55:28||     updating server parameters 96|8367|0.00|default||
2008-08-01 12:55:32|LIVE AGENTS LOGGED IN: 6   ACTIVE CALLS: 4|
2008-08-01 12:55:32|OLD TRUNK SHORTS CLEARED: 1 |'','540413','69999','54041'||
2008-08-01 12:55:32|540413 10.3.10.102: agents: 1     dial_level: 1.000|
2008-08-01 12:55:32|540413 10.3.10.102: Calls to place: 1 (3 - 2) 5 |




we shouldn't have any trunk shortages (set as 96).

This would indicate VD is cutting the call off (again number hidden)

Code: Select all

Aug  1 14:10:28 DEBUG[16945] manager.c: Manager received command 'Hangup'
Aug  1 14:10:28 VERBOSE[16826] logger.c:   == Spawn extension (default, 8600075, 1) exited non-zero on 'SIP/SIPtrunk-18313050'
Aug  1 14:10:28 VERBOSE[16826] logger.c:     -- Executing DeadAGI("SIP/SIPtrunk-18313050", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---
Aug  1 14:10:28 VERBOSE[16826] logger.c:     -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------) completed, returnin
Aug  1 14:10:28 DEBUG[16826] chan_sip.c: update_call_counter(XXXXXXXXXX) - decrement call limit counter
Aug  1 14:10:28 VERBOSE[16826] logger.c: Scheduling destruction of call '0f78c1681b756160134937b3699edd69@10.3.10.102' in 32000 ms
Aug  1 14:10:28 VERBOSE[16826] logger.c: set_destination: Parsing <sip:XXXXXXXXXX@10.5.0.100> for address/port to send to
Aug  1 14:10:28 VERBOSE[16826] logger.c: set_destination: set destination to 10.5.0.100, port 5060
Aug  1 14:10:28 VERBOSE[16826] logger.c: Reliably Transmitting (no NAT) to 10.5.0.100:5060:
BYE sip:XXXXXXXXXX@10.5.0.100 SIP/2.0^M
Via: SIP/2.0/UDP 10.3.10.102:5060;branch=z9hG4bK5541fe1d;rport^M
From: "V0801140957001210716" <sip:00000000000@10.3.10.102>;tag=as72316026^M
To: <sip:XXXXXXXXXX@10.5.0.100>;tag=a050064-683b3^M
Call-ID: 0f78c1681b756160134937b3699edd69@10.3.10.102^M
CSeq: 103 BYE^M
User-Agent: Asterisk PBX^M
Max-Forwards: 70^M
Content-Length: 0^M


But it certainly is not the agent doing it (call recordings continue until they hit hangup)

Thanks

Chris

[chrisbIT]

I changed the extensions.conf earlier to use the non-registered sip trunk extensions to see if it made any diff and also now notice this:

Code: Select all

Event: Rename
Privilege: call,all
Oldname: Local/XXXXXXXXXX@default-12b3,1
Newname: SIP/SIPtrunk-18313050
Uniqueid: 1217596197.22599

Event: Rename
Privilege: call,all
Oldname: SIP/SIPtrunk-18313050<MASQ>
Newname: Local/XXXXXXXXXX@default-12b3,1<ZOMBIE>
Uniqueid: 1217596197.22601

Event: Unlink
Privilege: call,all
Channel1: Local/9XXXXXXXXXX@default-12b3,2
Channel2: Local/XXXXXXXXXX@default-12b3,1<ZOMBIE>
Uniqueid1: 1217596197.22600
Uniqueid2: 1217596197.22601
CallerID1: 00000000000
CallerID2: 00000000000

Event: Hangup
Privilege: call,all
Channel: Local/XXXXXXXXXX@default-12b3,1<ZOMBIE>
Uniqueid: 1217596197.22601
Cause: 16
Cause-txt: Normal Clearing



Is it trying to ring twice, connecting with first but timing out or something with second and then cutting off?

[chrisbIT]

This seems to be very similar:


http://www.eflo.net/VICIDIALforum/viewt ... =8157#8157


However I can rule out load and there is nothing older than an hour in the vicidial_manager table. I am using the current libpri also. IS there anything else that could cause this?

(apologies for the high number of posts).

Thanks

Chris

[mflorell]

bandwidth issues(capacity and latency) can cause this as well as carrier capacity issues.

[chrisbIT]

Is the "channel changed" bit normal then or should we only see that if using closers?

Thanks

Chris

[mflorell]

I have not run into the channel changed issue recently. Do you only see it on the closer side?

[chrisbIT]

We are not using closers, the agents are doing straightforward outbound calling, bit of market research then hangup and dispo.

Thanks

Chris

[mflorell]

What is the vicidial.php version and build?

[chrisbIT]

Thanks for looking at this Matt.

Code: Select all

$version = '2.0.4-142';
$build = '71129-2025';


The lagged hangup thing got me thinking, could this be a possible scenario:

Agent1 is on a call to customer1

Agent2 is on a call to customer2

customer2 hangs up, but agent2 does not press hangup. DeadAGI clears the call and frees up channel LOCALXXX (example)

Agent1 finishes his call, hangs up and gets the next call, asterisk assigns this call to the recently free'd LOCALXXX channel.

Agent2 wakes up and presses hangup, but the agent interface still thinks the current channel is LOCALXXX and so Agent1 gets an unexpected hangup?

Thanks

Chris

[/list]

[mflorell]

It doesn't actually work that way, IAX/SIP/Local channels have random alphanumeric characters at the end of their names that mean you do not have duplicate channelnames that close to each other.

I would suggest upgrading to 2.0.4.1rc3

[chrisbIT]

Hi Matt,

yes, looks like what you say should be the case, but it doesn't seem to be.

I have two calls one after the other in my asterisk messages with identical sip channels.

Just taken a glance at vicidial_manager and notice three seperate hangup calls (at slightly different times) to the same channel.

Code: Select all

509224           2008-08-05 12:19:41     SENT     N     10.3.10.102           Hangup     HLvdcW1217934765eman     Channel: SIP/SIPtrunk-03b37640

514205           2008-08-05 12:56:25     SENT     N     10.3.10.102           Hangup     HLvdcW1217937032ades     Channel: SIP/SIPtrunk-03b37640

514584           2008-08-05 12:59:18     SENT     N     10.3.10.102           Hangup     HLvdcW1217937005eake     Channel: SIP/SIPtrunk-03b37640


This indicates perhaps that the random channel ID is not being created very randomly and this could explain why we are getting the hangups.

This is evident on asterisk 1.2.24,29 & 30

Thanks

Chris

[mflorell]

Do these channels exist at the same time ever?

how many calls are you making per 15 minutes?

[chrisbIT]

Not obviously. It looks like a channel is reused a few seconds after it has been hungup.

If Asterisk has hung this up (or it hung up at the other end), but then the agent a few seconds later presses hangup, will this not issue a hangup for that channel (which has now been re-used by a new call/agent)?

Thanks

Chris

[mflorell]

That should not be a problem, because in the world of T1 channels you do not have unique channel names, you just have Zap/22-1 and such which are reused very quickly, and I have done a lot of installs on systems using T1s and this has not been a problem.

[deck7uk]

Hi Matt,

I have worked out (finally) what is going wrong and have written some fixes. How do I access Mantis to contribute code (get a 403 error and cannot see where to register?)?

Thanks

Chris

[felfel]

Hi,

can you explain what was the problem, becuse I have a similar one and want to know if it can solve mine.

thanks

[deck7uk]

Hi felfel,

There are two things I have found so far that cause the cut offs.
The first is manual dialing.

Upon pressing hangup, if the call is a manual dial the hangup request is inserted straight in to vicidial_manager. This causes a problem in the following scenario.

Campaign: Maual Dial method.

Agent A:
places a call and gets allocated channel Zap/1-1.
They speak to a customer for 5 minutes and then the customer hangs up.

Agent B:
Places a call and gets allocated the now free channel Zap/1-1.

Agent A:
Click hangup on the agent interface (even though the customer hung up 1-2 mins ago).
The hangup request for channel Zap/1-1 gets inserted into vicidial_manager.

Asterisk duly hangs up the channel, but Agent B gets cut off.

This scenario also happens for us when using sip channels. We have several of our dialers going through a Quintum Tenor CMS via SIP. For some reason, even though sip channels should be unique each time, they are not and get reused very often. This problem is very much amplified for manual dialing despite having sip reinvite disabled.

Another cause is that quite frequently (we get 10 - 20 occurrences per day) the sip channel will change during the life of the call. I believe this happens when the call connects - and more often when traveling across IAX trunks in a multi server setup. This can result in the customer not getting hung up at all and also recreate the previous example if the channel gets reused.

The solution is quite simple and involves just adding some checks into the hangup function of vicidial_manager.php

It also requires that all meetme rooms are numbered uniquely across all dialers for the "active_channel" check to work. The code will need some tidying/refactroring for the generic case as my code currently only really caters for our exact setup (iax agents, sip team leaders with extensions 2XX & 3XX and sip/zap trunks). But if you are suffering from the same scenario then just adjust the two queries to match your case.

You will notice I also log the hangups in a table called hangup_logs with the following schema:

Code: Select all


--
-- Table structure for table `hangup_logs`
--

CREATE TABLE IF NOT EXISTS `hangup_logs` (
  `id` int(11) NOT NULL auto_increment,
  `action` varchar(100) default NULL,
  `delayed` varchar(10) default 'N',
  `hangup_permission_given_by` varchar(100) default NULL,
  `user` varchar(100) default NULL,
  `server_ip` varchar(50) default NULL,
  `call_server_ip` varchar(100) default NULL,
  `extension` varchar(100) default NULL,
  `channel` varchar(100) default NULL,
  `original_channel` varchar(100) default NULL,
  `last_channel` varchar(100) default NULL,
  `session_name` varchar(100) default NULL,
  `queryCID` varchar(100) default NULL,
  `CallCID` varchar(100) default NULL,
  `auto_dial_level` varchar(50) default NULL,
  `seconds` varchar(100) default NULL,
  `exten` varchar(100) default NULL,
  `time` timestamp NOT NULL default CURRENT_TIMESTAMP,
  `changed` varchar(5) NOT NULL default 'N',
  PRIMARY KEY  (`id`)
) ENGINE=MyISAM  DEFAULT CHARSET=latin1 AUTO_INCREMENT=105219 ;


the new hangup function - this probably does not yet cover transfers as we currently don't do this (I will add it later).

Code: Select all

######################
# ACTION=Hangup  - insert Hangup Manager statement
######################
if ($ACTION=="Hangup")
{
   $row='';   $rowx='';
   $channel_live=1;
   $changed='N';
        $original_channel=$channel;
    $hangup_permission_given_by = "no check - blind hangup";
    //if ( (strlen($channel)<3) or (strlen($queryCID)<15) )
   if ( (strlen($channel)<3))
   {
      $channel_live=0;
      echo "Channel $channel is not valid or queryCID $queryCID is not valid, Hangup command not inserted\n";
   }
   else
   {
      if (strlen($call_server_ip)<7) {$call_server_ip = $server_ip;}
         
         //Find live channel connected to conf and hang it up after sleeping for x seconds.
         sleep(2);
      $stmt="SELECT channel FROM live_channels WHERE server_ip = '$call_server_ip' and extension LIKE '%$exten%' and channel NOT LIKE 'SIP/2%' and channel NOT LIKE 'SIP/3%' and channel NOT LIKE 'IAX%' limit 1;";
       $rslt=mysql_query($stmt, $link);
            $row=mysql_fetch_row($rslt);
            $current_channel = $row[0];
           
            //see if channel is in use by someone else
            $stmt="SELECT channel FROM live_channels WHERE (server_ip = '$call_server_ip' or server_ip = '$server_ip') and channel LIKE '$channel' and extension NOT LIKE '%$exten%' and extension NOT LIKE 'ring' and channel NOT LIKE 'SIP/2%' and channel NOT LIKE 'IAX%' and channel NOT LIKE 'SIP/3%' limit 1;";
       $rslt=mysql_query($stmt, $link);
            $row=mysql_fetch_row($rslt);
            $active_channel = $row[0];
           
            if (!$current_channel) {
               //nothing connected, but may still be ringing and need hanging up.
               $hangup_permission_given_by = "original channel (ringing or dead and not in use)";
               if ($auto_dial_level > 0) {
                  //this was an autodial - but there is no customer
                  $channel_live=1;
                  $hangup_permission_given_by = "customer has hungup - but channel not in use";
               }
               if ($active_channel){
                  //channel is now in use by someone else - dont hangup
                  $channel_live=0;
                  $hangup_permission_given_by = "not given - channel in use";
               }
            } else {
               if ($channel != $current_channel ) {
                      $changed = 'Y';
                }
               if ($active_channel){
                  //channel is now in use by someone else - dont hangup
                  $channel_live=0;
                  $hangup_permission_given_by = "not given - channel in use";
               } else {
                   $hangup_permission_given_by = "live_channels";                  
                   $channel = $current_channel;       
                                   
                }
            }
         
         
      }
      if ($channel_live==1)
      {

                //CHRIS Log the hangup request

                $QUERY="INSERT INTO hangup_logs (user,action,hangup_permission_given_by,server_ip,call_server_ip,extension,channel,original_channel,last_channel,session_name,queryCID,CallCID,auto_dial_level,seconds,exten,changed) values('$user','HANGUP SENT','$hangup_permission_given_by','$server_ip','$call_server_ip','$exten','$channel','$original_channel','$current_channel','$session_name','$queryCID','$CalLCID','$auto_dial_level','$secondS','$exten','$changed')";
      $rslt=mysql_query($QUERY, $link);
                   
      $stmt="INSERT INTO vicidial_manager values('','','$NOW_TIME','NEW','N','$call_server_ip','','Hangup','$queryCID','Channel: $channel','','','','','','','','','');";
         if ($format=='debug') {echo "\n<!-- $stmt -->";}
      $rslt=mysql_query($stmt, $link);
      echo "Hangup command sent for Channel $channel on $call_server_ip\n";
      } else {
                //LOG no hangup
//                $hangup_permission_given_by = "no permission given - no live call";
                $QUERY="INSERT INTO hangup_logs (user,action,hangup_permission_given_by,server_ip,call_server_ip,extension,channel,original_channel,last_channel,session_name,queryCID,CallCID,auto_dial_level,seconds,exten,changed) values('$user','HANGUP NOT SENT','$hangup_permission_given_by','$server_ip','$call_server_ip','$exten','$channel','$original_channel','$current_channel','$session_name','$queryCID','$CalLCID','$auto_dial_level','$secondS','$exten','$changed')";
      $rslt=mysql_query($QUERY, $link);

                }
   }
}



[felfel]

thanks a lot,

I'll try to do this on my system and give you the result

[deck7uk]

how did you get on?