Calls Drop to Music on Hold

[adymeblack]

Over the past couple of days i have had a strange issue with one of my server clusters that i cannot figure out. Agent will be on a call for a random amount of time (anywhere between 30s and 30m) then the call will drop and all the agent hears is the Vicidial music on hold. When i look at the call log, sometimes it shows the agent hung up, others will show the person on the other end hung up. Looking through the SIP logs all i can find is the call originates, then hangs up. I can't seem to find any common ground with this issue. It isn't picking on any particular agent or extension, the numbers dialed are from all over the place so i don't think it is any kind of routing issue, also these servers are OB only so there aren't any special dial plans or anything. Server loads are running steady at about a 0.3-0.45.

Code: Select all

Executing [8600065@default:1] MeetMe("Local/8600065@default-00000d50;2", "8600065,F") in new stack
       > Channel Local/8600065@default-00000d50;1 was answered.
    -- Executing [91XXXXXXXXXX@default:1] AGI("Local/8600065@default-00000d50;1", "agi://127.0.0.1:4577/call_log") in new stack
    -- <Local/8600065@default-00000d50;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
    -- Executing [91XXXXXXXXXX@default:2] Dial("Local/8600065@default-00000d50;1", "SIP/V6BlueTone/1XXXXXXXXXX,,To") in new stack
    -- SIP/V6BlueTone-00000623 answered Local/8600065@default-00000d50;1
    -- Started music on hold, class 'default', on Local/8600065@default-00000d50;1
    -- Executing [h@default:1] AGI("Local/8600065@default-00000d50;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----60-----36") in new stack
    -- <Local/8600065@default-00000d50;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----60-----36 completed, returning 0
  == Spawn extension (default, 91XXXXXXXXXX, 2) exited non-zero on 'Local/8600065@default-00000d50;1'
    -- Stopped music on hold on Local/8600065@default-00000d50;1
  == Spawn extension (default, 8600065, 1) exited non-zero on 'Local/8600065@default-00000d50;2'
    -- Executing [h@default:1] AGI("Local/8600065@default-00000d50;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/8600065@default-00000d50;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0

Anyone have any ideas or even a general direction to look?

Version: 2.12-485a
Build: 150512-2225
OS: Suse 12.3
CPU: 2x 3.0GHz Intel Xeon Quad-Core
RAM: 16GB
Asterisk: 1.8.25.0-vici
(Please let me know if i forgot anything)

[adymeblack]

Anyone have any ideas? I'm about to pull my hair out.........

[adymeblack]

Anyone at all?

[mflorell]

How frequently does this happen?

How long into the call does it take before this happens?

[adymeblack]

For the past few days, it usually happens between 10-30 times per day, sometimes more sometimes less. Across a 2 server cluster.

The agent can try to dial and it will immediately happen or sometimes they can be 20-30 mins into a call then it drops and hold music.

[mflorell]

I don't think I've seen this happen before, the first place to check would be in the action logfiles in /var/log/astguiclient to see if some kind of action was executed on the channel at the time the MoH starts.

Also, does this happen with an alternate carrier?

[adymeblack]

Sorry it took so long to reply, been in and out of town this week.

Anyway, i have checked all of the action logs and as far as i can tell everything looks normal. I see calls originate and terminate, and not a lot in between. But to be completely honest, i'm not really sure exactly what i'm looking for.

As for the carriers, i currently only have one to work with (i'm in the process of being on-boarded with another one). I have spoken with the engineers of my current trunk and all they can really tell me is the signal to terminate the call is coming from our end (i.e. the vicidial server).

[adymeblack]

Digging deeper into the logs i managed to come across this guy:

Code: Select all

2015-08-04 09:55:22|park_CID.agi|AGI Environment Dump:
2015-08-04 09:55:22|park_CID.agi| -- accountcode =
2015-08-04 09:55:22|park_CID.agi| -- callerid = XXXXXXXXXX
2015-08-04 09:55:22|park_CID.agi| -- calleridname = M8040937190000632234
2015-08-04 09:55:22|park_CID.agi| -- callingani2 = 0
2015-08-04 09:55:22|park_CID.agi| -- callingpres = 0
2015-08-04 09:55:22|park_CID.agi| -- callingtns = 0
2015-08-04 09:55:22|park_CID.agi| -- callington = 0
2015-08-04 09:55:22|park_CID.agi| -- channel = SIP/V6BlueTone-000003bf
2015-08-04 09:55:22|park_CID.agi| -- context = default
2015-08-04 09:55:22|park_CID.agi| -- dnid = unknown
2015-08-04 09:55:22|park_CID.agi| -- enhanced = 0.0
2015-08-04 09:55:22|park_CID.agi| -- extension = 8301
2015-08-04 09:55:22|park_CID.agi| -- language = en
2015-08-04 09:55:22|park_CID.agi| -- priority = 2
2015-08-04 09:55:22|park_CID.agi| -- rdnis = unknown
2015-08-04 09:55:22|park_CID.agi| -- request = park_CID.agi
2015-08-04 09:55:22|park_CID.agi| -- threadid = 139903032866560
2015-08-04 09:55:22|park_CID.agi| -- type = SIP
2015-08-04 09:55:22|park_CID.agi| -- uniqueid = 1438700122.5542
2015-08-04 09:55:22|park_CID.agi| -- version = 1.8.32.2-vici
2015-08-04 09:55:22|park_CID.agi|AGI Variables: |1438700122.5542|SIP/V6BlueTone-000003bf|8301|SIP|M8040937190000632234|
2015-08-04 09:55:22|park_CID.agi|CALL BEING PARKED
2015-08-04 09:55:22|park_CID.agi||UPDATE parked_channels set channel_group='M8040937190000632234' where server_ip='10.0.0.60' and channel='SIP/V6BlueTone-000003bf';|
2015-08-04 09:55:22|park_CID.agi|--    Park record updated: |1|   |M8040937190000632234|SIP/V6BlueTone-000003bf|10.0.0.60
2015-08-04 09:55:22|park_CID.agi|--    Context empty, switching to default: ||1|0|   |M8040937190000632234|
2015-08-04 09:55:22|park_CID.agi|--    Starting MoH: |default|   |M8040937190000632234|

So i can somewhat see when it is happening, but i still cannot figure out why. I have gone through all the dialplans with a fine-toothed comb and just cannot figure this out.

[adymeblack]

I think i found a full log of an instance of this happening from the FASTAgi logs:

Code: Select all

2015-08-04 08:13:15|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2015-08-04 08:13:15|VDfastAGI|begin|Perl Environment Dump:
2015-08-04 08:13:15|VDfastAGI|begin|0|--debug
2015-08-04 08:13:15|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2015-08-04 08:13:15|VDfastAGI|begin|AGI Environment Dump:
2015-08-04 08:13:15|VDfastAGI|begin| -- accountcode =
2015-08-04 08:13:15|VDfastAGI|begin| -- callerid = XXXXXXXXXX
2015-08-04 08:13:15|VDfastAGI|begin| -- calleridname = M8040812060000631502
2015-08-04 08:13:15|VDfastAGI|begin| -- callingani2 = 0
2015-08-04 08:13:15|VDfastAGI|begin| -- callingpres = 0
2015-08-04 08:13:15|VDfastAGI|begin| -- callingtns = 0
2015-08-04 08:13:15|VDfastAGI|begin| -- callington = 0
2015-08-04 08:13:15|VDfastAGI|begin| -- channel = Local/8600062@default-000001a3;1
2015-08-04 08:13:15|VDfastAGI|begin| -- context = default
2015-08-04 08:13:15|VDfastAGI|begin| -- dnid = unknown
2015-08-04 08:13:15|VDfastAGI|begin| -- enhanced = 0.0
2015-08-04 08:13:15|VDfastAGI|begin| -- extension = h
2015-08-04 08:13:15|VDfastAGI|begin| -- language = en
2015-08-04 08:13:15|VDfastAGI|begin| -- network = yes
2015-08-04 08:13:15|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----69-----18
2015-08-04 08:13:15|VDfastAGI|begin| -- priority = 1
2015-08-04 08:13:15|VDfastAGI|begin| -- rdnis = unknown
2015-08-04 08:13:15|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----69-----18
2015-08-04 08:13:15|VDfastAGI|begin| -- threadid = 139903040993024
2015-08-04 08:13:15|VDfastAGI|begin| -- type = Local
2015-08-04 08:13:15|VDfastAGI|begin| -- uniqueid = 1438693926.1070
2015-08-04 08:13:15|VDfastAGI|begin| -- version = 1.8.32.2-vici
2015-08-04 08:13:15|VDfastAGI|begin|AGI Variables: |1438693926.1070|Local/8600062@default-000001a3;1|h|Local|M8040812060000631502|
2015-08-04 08:13:15|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----69-----18|call_log|END|
2015-08-04 08:13:15|VDfastAGI|call_log||CALL HUNG UP|
2015-08-04 08:13:15|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|ANSWER|69|51|
2015-08-04 08:13:15|VDfastAGI|call_log|1|SELECT sip_hangup_cause,sip_hangup_reason FROM vicidial_dial_log where lead_id='631502' and server_ip='10.0.0.60' and caller_code='M8040812060000631502' order by call_date desc limit 1;|0||
2015-08-04 08:13:15|VDfastAGI|call_log||INSERT IGNORE INTO vicidial_carrier_log set uniqueid='1438693926.1072',call_date='2015-08-04 08:13:15',server_ip='10.0.0.60',lead_id='631502',hangup_cause='16',dialstatus='ANSWER',channel='Local/8600062@default-000001a3;1',dial_time='69',answered_time='18',sip_hangup_cause='0',sip_hangup_reason='',caller_code='M8040812060000631502';|
2015-08-04 08:13:15|VDfastAGI|call_log|--    CARRIER LOG insert: |1|631502|16|0||
2015-08-04 08:13:15|VDfastAGI|call_log||1438693926.1072|1438693926|SIP/V6BlueTone-000000d9|0|
2015-08-04 08:13:15|VDfastAGI|call_log||UPDATE call_log set end_time='2015-08-04 08:13:15',end_epoch='1438693995',length_in_sec=69,length_in_min='    1.15',channel='SIP/V6BlueTone-000000d9' where uniqueid='1438693926.1072'|
2015-08-04 08:13:15|VDfastAGI|call_log|QUERY done: start time = 1438693926 | sec: 69 | min:     1.15 |1
2015-08-04 08:13:15|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1438693926.1072','1438693926.1072') and server_ip='10.0.0.60'|
2015-08-04 08:13:15|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1438693926.1072|SIP/V6BlueTone-000000d9|h|2015-08-04 08:13:15|min:     1.15|
2015-08-04 08:13:15|VDfastAGI|call_log|DEBUG: NODEBUG
2015-08-04 08:13:15|VDfastAGI|call_log|VD_hangup : M8040812060000631502 SIP/V6BlueTone-000000d9 1 631502
2015-08-04 08:13:15|VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time),uniqueid,status,call_time,phone_code,phone_number,queue_position FROM vicidial_auto_calls where uniqueid = '1438693926.1072' or callerid = 'M8040812060000631502' limit 1;|
2015-08-04 08:13:15|VDfastAGI|call_log||SELECT channel from parked_channels where channel_group='M8040812060000631502';|
2015-08-04 08:13:15|VDfastAGI|call_log|--    VDAC record deleted: |1|   |631502|1438693926.1072|1438693926.1072|M8040812060000631502|10.0.0.60|XFER|
2015-08-04 08:13:15|VDfastAGI|call_log||SELECT start_epoch,status,user,term_reason,comments FROM vicidial_log FORCE INDEX(lead_id) where lead_id = '631502' and uniqueid LIKE "1438693926%" limit 1;|
2015-08-04 08:13:15|VDfastAGI|call_log||UPDATE vicidial_log FORCE INDEX(lead_id) set term_reason='CALLER', end_epoch='1438693995',length_in_sec='66' where lead_id = '631502' and uniqueid LIKE "1438693926%";|
2015-08-04 08:13:15|VDfastAGI|call_log|--    VDAD vicidial_log update: |1|1438693926.1072|INCALL|
2015-08-04 08:13:15|VDfastAGI|call_log|no VDCL record found: 1438693926.1072|M8040812060000631502|631502|1438693926.1072|1438693926.1072|1|
2015-08-04 08:13:15|VDfastAGI|call_log||SELECT auto_alt_dial,auto_alt_dial_statuses,use_internal_dnc,use_campaign_dnc,use_other_campaign_dnc FROM vicidial_campaigns where campaign_id='7500';|

I can't help but notice the "DELETE from live_inbound" line. I have no clue why it would be "inbound" in the first place since this is an outbound only system......

[adymeblack]

Any thoughts at all? I'm almost out of hair to pull......

[mflorell]

Did you try another carrier like we suggested?

[adymeblack]

Trying to, but paperwork is holding up the provisioning.

Also, i have two other 6 server clusters using the same carrier and they are not having this issue. It only seems to be effecting this particular cluster.