Autodial hangs up when customer answers, manual works fine

[steffen123]

Hi,
I've been working on our vicidial setup and it's almost working, but I've run into a problem and I can't figure it out. When using manual dialing (off a list, so Agent just clicks Dial Next Lead) it works perfectly fine, but when I switch to RATIO it immediately hangs up when the call is answered. The person called then just hears a busy tone (I think it's the busy tone, just goes beep beep beep with only a very very brief pause between). Initially I thought it might be due to a problem in the NAT/Routing or the sound hardware/drivers, but since it works in manual mode it can't be that.

Seeing the asterisk log I suspect it is something to do with /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi, but do note that in the webagent it does say the customer answered, but ofc (correctly) changes to hung up. Rebooting doesn't help.

I should mention that I did have it working at one point, but I'm not sure what I have changed since then. More importantly I'm not sure when that was, as I did much of my testing/developing with manual mode, or else I could get the then-current configs from my git

Here's the asterisk log (removed " == Manager 'sendcron' logged" lines) first for a manual call, logoff, and logon (changed campaign mode before logon):

Code: Select all

    -- Executing [8600052@default:1] MeetMe("Local/8600052@default-00000003;2", "8600052,F") in new stack
       > Channel Local/8600052@default-00000003;1 was answered.
    -- Executing [03412228680@default:1] NoOp("Local/8600052@default-00000003;1", "nationalf") in new stack
    -- Executing [03412228680@default:2] AGI("Local/8600052@default-00000003;1", "agi://127.0.0.1:4577/call_log") in new stack
    -- <Local/8600052@default-00000003;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
    -- Executing [03412228680@default:3] Set("Local/8600052@default-00000003;1", "SIPFROMUSER=1595970t0@sipconnect.sipgate.de") in new stack
    -- Executing [03412228680@default:4] SIPAddHeader("Local/8600052@default-00000003;1", "P-Preferred-Identity: <sip:4930231882322@sipconnect.sipgate.de>") in new stack
    -- Executing [03412228680@default:5] Dial("Local/8600052@default-00000003;1", "SIP/03412228680@testcarrier,,r") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/03412228680@testcarrier
    -- Executing [58600052@default:1] MeetMe("Local/58600052@default-00000004;2", "8600052,Fmq") in new stack
       > Channel Local/58600052@default-00000004;1 was answered.
    -- Executing [8309@default:1] Answer("Local/58600052@default-00000004;1", "") in new stack
    -- Executing [8309@default:2] Monitor("Local/58600052@default-00000004;1", "wav,11472_20130611-132448_8002_3412228680") in new stack
    -- Executing [8309@default:3] Wait("Local/58600052@default-00000004;1", "3600") in new stack
    -- SIP/testcarrier-00000009 is ringing
    -- SIP/testcarrier-00000009 is making progress passing it to Local/8600052@default-00000003;1
    -- SIP/testcarrier-00000009 answered Local/8600052@default-00000003;1
    -- Executing [h@default:1] AGI("Local/8600052@default-00000003;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----24-----20") in new stack
    -- <Local/8600052@default-00000003;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----24-----20 completed, returning 0
  == Spawn extension (default, 03412228680, 5) exited non-zero on 'Local/8600052@default-00000003;1'
  == Spawn extension (default, 8600052, 1) exited non-zero on 'Local/8600052@default-00000003;2'
    -- Executing [h@default:1] AGI("Local/8600052@default-00000003;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/8600052@default-00000003;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
  == Spawn extension (default, 58600052, 1) exited non-zero on 'Local/58600052@default-00000004;2'
    -- Executing [h@default:1] AGI("Local/58600052@default-00000004;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/58600052@default-00000004;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
  == Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600052@default-00000004;1'
    -- Executing [h@default:1] AGI("Local/58600052@default-00000004;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/58600052@default-00000004;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
    -- Hungup 'DAHDI/pseudo-2137390417'
  == Spawn extension (default, 8600052, 1) exited non-zero on 'SIP/202-00000008'
    -- Executing [h@default:1] AGI("SIP/202-00000008", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
    -- <SIP/202-00000008>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0
    -- Executing [55558600052@default:1] MeetMeAdmin("Local/55558600052@default-00000005;2", "8600052,K") in new stack
[Jun 11 13:27:13] WARNING[22809]: app_meetme.c:4658 admin_exec: Conference number '8600052' not found!
    -- Executing [55558600052@default:2] Hangup("Local/55558600052@default-00000005;2", "") in new stack
  == Spawn extension (default, 55558600052, 2) exited non-zero on 'Local/55558600052@default-00000005;2'
    -- Executing [h@default:1] AGI("Local/55558600052@default-00000005;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
    -- <Local/55558600052@default-00000005;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0
  == Using SIP RTP CoS mark 5
       > Channel SIP/202-0000000a was answered.
    -- Executing [8600052@default:1] MeetMe("SIP/202-0000000a", "8600052,F") in new stack
  == Parsing '/etc/asterisk/meetme.conf':   == Found
  == Parsing '/etc/asterisk/meetme-vicidial.conf':   == Found
    -- Created MeetMe conference 1022 for conference '8600052'
    -- <SIP/202-0000000a> Playing 'conf-onlyperson.ulaw' (language 'en')


and for an automatic call:

Code: Select all

 == Manager 'sendcron' logged off from 127.0.0.1
    -- Executing [03412228680@default:1] NoOp("Local/03412228680@default-00000006;2", "nationalf") in new stack
    -- Executing [03412228680@default:2] AGI("Local/03412228680@default-00000006;2", "agi://127.0.0.1:4577/call_log") in new stack
    -- <Local/03412228680@default-00000006;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
    -- Executing [03412228680@default:3] Set("Local/03412228680@default-00000006;2", "SIPFROMUSER=1595970t0@sipconnect.sipgate.de") in new stack
    -- Executing [03412228680@default:4] SIPAddHeader("Local/03412228680@default-00000006;2", "P-Preferred-Identity: <sip:4930231882322@sipconnect.sipgate.de>") in new stack
    -- Executing [03412228680@default:5] Dial("Local/03412228680@default-00000006;2", "SIP/03412228680@testcarrier,,r") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/03412228680@testcarrier
    -- SIP/testcarrier-0000000b is ringing
    -- SIP/testcarrier-0000000b is making progress passing it to Local/03412228680@default-00000006;2
    -- SIP/testcarrier-0000000b answered Local/03412228680@default-00000006;2
       > Channel Local/03412228680@default-00000006;1 was answered.
    -- Executing [8368@default:1] Playback("Local/03412228680@default-00000006;1", "sip-silence") in new stack
    -- <Local/03412228680@default-00000006;1> Playing 'sip-silence.gsm' (language 'en')
    -- Executing [h@default:1] AGI("Local/03412228680@default-00000006;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----0") in new stack
    -- Executing [8368@default:2] NoOp("SIP/testcarrier-0000000b", "fooa") in new stack
    -- Executing [8368@default:3] AGI("SIP/testcarrier-0000000b", "agi://127.0.0.1:4577/call_log") in new stack
    -- <SIP/testcarrier-0000000b>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
    -- Executing [8368@default:4] NoOp("SIP/testcarrier-0000000b", "foob") in new stack
    -- Executing [8368@default:5] AGI("SIP/testcarrier-0000000b", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
    -- <SIP/testcarrier-0000000b>AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
    -- Executing [010*129*119*010*8600052@default:1] NoOp("SIP/testcarrier-0000000b", "nationalf") in new stack
    -- Executing [010*129*119*010*8600052@default:2] Hangup("SIP/testcarrier-0000000b", "") in new stack
  == Spawn extension (default, 010*129*119*010*8600052, 2) exited non-zero on 'SIP/testcarrier-0000000b'
    -- Executing [h@default:1] AGI("SIP/testcarrier-0000000b", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
    -- <SIP/testcarrier-0000000b>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0
    -- <Local/03412228680@default-00000006;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----0 completed, returning 0
  == Spawn extension (default, 03412228680, 5) exited non-zero on 'Local/03412228680@default-00000006;2'
    -- Executing [58600052@default:1] MeetMe("Local/58600052@default-00000007;2", "8600052,Fmq") in new stack
       > Channel Local/58600052@default-00000007;1 was answered.
    -- Executing [8309@default:1] Answer("Local/58600052@default-00000007;1", "") in new stack
    -- Executing [8309@default:2] Monitor("Local/58600052@default-00000007;1", "wav,11473_20130611-132730_8002_3412228680") in new stack
    -- Executing [8309@default:3] Wait("Local/58600052@default-00000007;1", "3600") in new stack
  == Spawn extension (default, 58600052, 1) exited non-zero on 'Local/58600052@default-00000007;2'
    -- Executing [h@default:1] AGI("Local/58600052@default-00000007;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/58600052@default-00000007;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
  == Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600052@default-00000007;1'
    -- Executing [h@default:1] AGI("Local/58600052@default-00000007;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
    -- <Local/58600052@default-00000007;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
       > Refreshing DNS lookups.
       > ast_get_srv: SRV lookup for '_sip._udp.sipconnect.sipgate.de' mapped to host sipconnect.sipgate.de, port 5060
       > ast_get_srv: SRV lookup for '_sip._udp.sipconnect.sipgate.de' mapped to host sipconnect.sipgate.de, port 5060


Vicidial Version: VERSION: 2.6-366c BUILD: 130402-2250 Server: 10.129.119.10
Asterisk: 1.8.19.0-vici-beta
Server Specs: 2*8core Opteron with vmware esxi 4.1. 8 CPUs and 6 GB RAM assigned to the VM in which this runs.
Load average on the server: below 0.2 (with 8 cores, so >>90% idle)
Codec used: ulaw
VoIP: pjsua from pjsip as softphone for the agents, then sipgate as carrier
OS: Zentyal 3.0 (a derivative of Ubuntu LTS 12.04), fully updated as of 11am or noon today (UTC+2)
Status: System has not gone into production yet, but outbound dialling did work at one point.

Well, thanks for making it this far, if I forgot anything please ask.
Steffen

Edit: the relevant snipped from extensions.conf:

Code: Select all

 
; VICIDIAL_auto_dialer transfer script Load Balanced:
exten => 8368,1,Playback(sip-silence)
exten => 8368,n,NoOp(fooa)
exten => 8368,n,AGI(agi://127.0.0.1:4577/call_log)
exten => 8368,n,NoOp(foob)
exten => 8368,n,AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LB)
exten => 8368,n,NoOp(fooc)
exten => 8368,n,AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LB)
exten => 8368,n,NoOp(food)
exten => 8368,n,Hangup()

Also, I know that support for Asterisk-1.8 is in beta, but it seemed to work fine for me, so I would very much like to stick to the newer version. Plus, it's less risky to test things on a new install like mine than to have people upgrade their production systems
Would be most grateful for any ideas, pointers or suspicions!

[mflorell]

Take a look at your agiout log file output, it may show that the Local/ channel is not resolving. If manual dial calls are showing properly, then you may just have a delay in the channel resolution, but sometimes this can be carrier related or there might be a firewall issue either on the local server or the network.

[steffen123]

I've had a look at agiout and FASTagiout, and both look normal to me. However, the agiout file doesnt change when I make a manual call (I mean the mode where you click "Dial Next Number" in the webinterface). FASTagiout however has more. It looked more detailed overall as well so I went by that. Unfortunately I can't see anything that looks wrong. Well, except that there is a 5 HUNGUP messages like " 2013-06-12 14:36:45|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040594.45|SIP/testcarrier-0000000a|h|2013-06-12 14:36:45|min: 0.18|" There are no such messages in the agiout at all. Any other ideas? Or did I miss something in the log?

Thanks, Steffen

Here's the added lines to it with mode RATIO or ADAPT:

Code: Select all

2013-06-12 14:24:58|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:24:58|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:24:58|VDfastAGI|begin|0|--debug
2013-06-12 14:24:58|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:24:58|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:24:58|VDfastAGI|begin| -- accountcode =
2013-06-12 14:24:58|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:24:58|VDfastAGI|begin| -- calleridname = V6121424540000011490
2013-06-12 14:24:58|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:24:58|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:24:58|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:24:58|VDfastAGI|begin| -- callington = 0
2013-06-12 14:24:58|VDfastAGI|begin| -- channel = Local/03412228680@default-00000008;1
2013-06-12 14:24:58|VDfastAGI|begin| -- context = default
2013-06-12 14:24:58|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:24:58|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:24:58|VDfastAGI|begin| -- extension = 8368
2013-06-12 14:24:58|VDfastAGI|begin| -- language = en
2013-06-12 14:24:58|VDfastAGI|begin| -- network = yes
2013-06-12 14:24:58|VDfastAGI|begin| -- network_script = call_log
2013-06-12 14:24:58|VDfastAGI|begin| -- priority = 3
2013-06-12 14:24:58|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:24:58|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2013-06-12 14:24:58|VDfastAGI|begin| -- threadid = 140026534000384
2013-06-12 14:24:58|VDfastAGI|begin| -- type = Local
2013-06-12 14:24:58|VDfastAGI|begin| -- uniqueid = 1371039894.25
2013-06-12 14:24:58|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:24:58|VDfastAGI|begin|AGI Variables: |1371039894.25|Local/03412228680@default-00000008;1|8368|Local|V6121424540000011490|
2013-06-12 14:24:58|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2013-06-12 14:24:58|VDfastAGI|call_log|+++++ CALL LOG START : 2013-06-12 14:24:58
2013-06-12 14:24:58|VDfastAGI|call_log|Local Channel Line: 0|03412228680|
2013-06-12 14:24:58|VDfastAGI|call_log||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1371039894.25','Local/03412228680@default-00000008;1','Local Channel Line','Local','10.129.119.10','8368','8368','2013-06-12 14:24:58','1371039898','','','','','V6121424540000011490')|
2013-06-12 14:24:59|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:24:59|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:24:59|VDfastAGI|begin|0|--debug
2013-06-12 14:24:59|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:24:59|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:24:59|VDfastAGI|begin| -- accountcode =
2013-06-12 14:24:59|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:24:59|VDfastAGI|begin| -- calleridname = V6121424540000011490
2013-06-12 14:24:59|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:24:59|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:24:59|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:24:59|VDfastAGI|begin| -- callington = 0
2013-06-12 14:24:59|VDfastAGI|begin| -- channel = Local/03412228680@default-00000008;2
2013-06-12 14:24:59|VDfastAGI|begin| -- context = default
2013-06-12 14:24:59|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:24:59|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:24:59|VDfastAGI|begin| -- extension = h
2013-06-12 14:24:59|VDfastAGI|begin| -- language = en
2013-06-12 14:24:59|VDfastAGI|begin| -- network = yes
2013-06-12 14:24:59|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----1
2013-06-12 14:24:59|VDfastAGI|begin| -- priority = 1
2013-06-12 14:24:59|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:24:59|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----1
2013-06-12 14:24:59|VDfastAGI|begin| -- threadid = 140026529249024
2013-06-12 14:24:59|VDfastAGI|begin| -- type = Local
2013-06-12 14:24:59|VDfastAGI|begin| -- uniqueid = 1371039894.26
2013-06-12 14:24:59|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:24:59|VDfastAGI|begin|AGI Variables: |1371039894.26|Local/03412228680@default-00000008;2|h|Local|V6121424540000011490|
2013-06-12 14:24:59|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----1|call_log|END|
2013-06-12 14:24:59|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:24:59|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|ANSWER|5|4|
2013-06-12 14:24:59|VDfastAGI|call_log||INSERT IGNORE INTO vicidial_carrier_log set uniqueid='1371039894.26',call_date='2013-06-12 14:24:59',server_ip='10.129.119.10',lead_id='11490',hangup_cause='16',dialstatus='ANSWER',channel='Local/03412228680@default-00000008;2',dial_time='5',answered_time='1';|
2013-06-12 14:24:59|VDfastAGI|call_log|--    CARRIER LOG insert: |1|11490|16
2013-06-12 14:24:59|VDfastAGI|call_log||1371039894.26|1371039894|Local/03412228680@default-00000008;2|0|
2013-06-12 14:24:59|VDfastAGI|call_log||UPDATE call_log set end_time='2013-06-12 14:24:59',end_epoch='1371039899',length_in_sec=5,length_in_min='    0.08',channel='Local/03412228680@default-00000008;2' where uniqueid='1371039894.26'|
2013-06-12 14:24:59|VDfastAGI|call_log|QUERY done: start time = 1371039894 | sec: 5 | min:     0.08 |1
2013-06-12 14:24:59|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371039894.26','1371039894.26') and server_ip='10.129.119.10'|
2013-06-12 14:24:59|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371039894.26|Local/03412228680@default-00000008;2|h|2013-06-12 14:24:59|min:     0.08|
2013-06-12 14:24:59|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:24:59|VDfastAGI|call_log|VD_hangup : V6121424540000011490 Local/03412228680@default-00000008;2 1 11490
2013-06-12 14:24:59|VDfastAGI|call_log|0||SELECT result FROM vicidial_cpd_log where callerid='V6121424540000011490' and result NOT IN('Voice','Unknown','???','') order by cpd_id desc limit 1;|
2013-06-12 14:24:59|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V6121424540000011490|ANSWER|16|0||
2013-06-12 14:24:59|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2013-06-12 14:25:00|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:25:00|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:25:00|VDfastAGI|begin|0|--debug
2013-06-12 14:25:00|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:25:00|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:25:00|VDfastAGI|begin| -- accountcode =
2013-06-12 14:25:00|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:25:00|VDfastAGI|begin| -- calleridname = V6121424540000011490
2013-06-12 14:25:00|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:25:00|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:25:00|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:25:00|VDfastAGI|begin| -- callington = 0
2013-06-12 14:25:00|VDfastAGI|begin| -- channel = SIP/testcarrier-00000006
2013-06-12 14:25:00|VDfastAGI|begin| -- context = default
2013-06-12 14:25:00|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:25:00|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:25:00|VDfastAGI|begin| -- extension = h
2013-06-12 14:25:00|VDfastAGI|begin| -- language = en
2013-06-12 14:25:00|VDfastAGI|begin| -- network = yes
2013-06-12 14:25:00|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:25:00|VDfastAGI|begin| -- priority = 1
2013-06-12 14:25:00|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:25:00|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:25:00|VDfastAGI|begin| -- threadid = 140026534000384
2013-06-12 14:25:00|VDfastAGI|begin| -- type = SIP
2013-06-12 14:25:00|VDfastAGI|begin| -- uniqueid = 1371039894.25
2013-06-12 14:25:00|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:25:00|VDfastAGI|begin|AGI Variables: |1371039894.25|SIP/testcarrier-00000006|h|SIP|V6121424540000011490|
2013-06-12 14:25:00|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2013-06-12 14:25:00|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:25:00|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:25:00|VDfastAGI|call_log||1371039894.25|1371039898|Local/03412228680@default-00000008;1|0|
2013-06-12 14:25:00|VDfastAGI|call_log||UPDATE call_log set end_time='2013-06-12 14:25:00',end_epoch='1371039900',length_in_sec=2,length_in_min='    0.03',channel='SIP/testcarrier-00000006' where uniqueid='1371039894.25'|
2013-06-12 14:25:00|VDfastAGI|call_log|QUERY done: start time = 1371039898 | sec: 2 | min:     0.03 |1
2013-06-12 14:25:00|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371039894.25','1371039894.25') and server_ip='10.129.119.10'|
2013-06-12 14:25:00|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371039894.25|SIP/testcarrier-00000006|h|2013-06-12 14:25:00|min:     0.03|
2013-06-12 14:25:00|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:25:00|VDfastAGI|call_log|VD_hangup : V6121424540000011490 SIP/testcarrier-00000006 1 11490
2013-06-12 14:25:00|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 = '1371039894.25' or callerid = 'V6121424540000011490' limit 1;|
2013-06-12 14:25:00|VDfastAGI|call_log||SELECT channel from parked_channels where channel_group='V6121424540000011490';|
2013-06-12 14:25:00|VDfastAGI|call_log|--    VDAC record deleted: |1|   |11490|1371039894.25|1371039894.25|V6121424540000011490|10.129.119.10|XFER|
2013-06-12 14:25:00|VDfastAGI|call_log||SELECT start_epoch,status,user,term_reason,comments FROM vicidial_log FORCE INDEX(lead_id) where lead_id = '11490' and uniqueid LIKE "1371039894%" limit 1;|
2013-06-12 14:25:00|VDfastAGI|call_log||UPDATE vicidial_log FORCE INDEX(lead_id) set term_reason='CALLER', end_epoch='1371039900',length_in_sec='1' where lead_id = '11490' and uniqueid LIKE "1371039894%";|
2013-06-12 14:25:00|VDfastAGI|call_log|--    VDAD vicidial_log update: |1|1371039894.25|LRERR|
2013-06-12 14:25:00|VDfastAGI|call_log|no VDCL record found: 1371039894.25|V6121424540000011490|11490|1371039894.25|1371039894.25|1|
2013-06-12 14:25:00|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='CUSTOMCA';|
2013-06-12 14:25:09|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:25:09|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:25:09|VDfastAGI|begin|0|--debug
2013-06-12 14:25:09|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:25:09|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:25:09|VDfastAGI|begin| -- accountcode =
2013-06-12 14:25:09|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- calleridname = 11490_20130612-142501_8001_3412228680
2013-06-12 14:25:09|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callington = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- channel = Local/58600051@default-00000009;2
2013-06-12 14:25:09|VDfastAGI|begin| -- context = default
2013-06-12 14:25:09|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:25:09|VDfastAGI|begin| -- extension = h
2013-06-12 14:25:09|VDfastAGI|begin| -- language = en
2013-06-12 14:25:09|VDfastAGI|begin| -- network = yes
2013-06-12 14:25:09|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:25:09|VDfastAGI|begin| -- priority = 1
2013-06-12 14:25:09|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:25:09|VDfastAGI|begin| -- threadid = 140026529249024
2013-06-12 14:25:09|VDfastAGI|begin| -- type = Local
2013-06-12 14:25:09|VDfastAGI|begin| -- uniqueid = 1371039902.29
2013-06-12 14:25:09|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:25:09|VDfastAGI|begin|AGI Variables: |1371039902.29|Local/58600051@default-00000009;2|h|Local|11490_20130612-142501_8001_3412228680|
2013-06-12 14:25:09|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------|call_log|END|
2013-06-12 14:25:09|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:25:09|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:25:09|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371039902.29','1371039902.29') and server_ip='10.129.119.10'|
2013-06-12 14:25:09|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371039902.29|Local/58600051@default-00000009;2|h|2013-06-12 14:25:09|min:     0.52|
2013-06-12 14:25:09|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:25:09|VDfastAGI|call_log|VD_hangup : 11490_20130612-142501_8001_3412228680 Local/58600051@default-00000009;2 1 612
2013-06-12 14:25:09|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|11490_20130612-142501_8001_3412228680||0|0||
2013-06-12 14:25:09|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2013-06-12 14:25:09|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:25:09|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:25:09|VDfastAGI|begin|0|--debug
2013-06-12 14:25:09|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:25:09|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:25:09|VDfastAGI|begin| -- accountcode =
2013-06-12 14:25:09|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- calleridname = 11490_20130612-142501_8001_3412228680
2013-06-12 14:25:09|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- callington = 0
2013-06-12 14:25:09|VDfastAGI|begin| -- channel = Local/58600051@default-00000009;1
2013-06-12 14:25:09|VDfastAGI|begin| -- context = default
2013-06-12 14:25:09|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:25:09|VDfastAGI|begin| -- extension = h
2013-06-12 14:25:09|VDfastAGI|begin| -- language = en
2013-06-12 14:25:09|VDfastAGI|begin| -- network = yes
2013-06-12 14:25:09|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:25:09|VDfastAGI|begin| -- priority = 1
2013-06-12 14:25:09|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:25:09|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:25:09|VDfastAGI|begin| -- threadid = 140026528741120
2013-06-12 14:25:09|VDfastAGI|begin| -- type = Local
2013-06-12 14:25:09|VDfastAGI|begin| -- uniqueid = 1371039902.28
2013-06-12 14:25:09|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:25:09|VDfastAGI|begin|AGI Variables: |1371039902.28|Local/58600051@default-00000009;1|h|Local|11490_20130612-142501_8001_3412228680|
2013-06-12 14:25:09|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------|call_log|END|
2013-06-12 14:25:09|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:25:09|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:25:09|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371039902.28','1371039902.28') and server_ip='10.129.119.10'|
2013-06-12 14:25:09|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371039902.28|Local/58600051@default-00000009;1|h|2013-06-12 14:25:09|min:     0.35|
2013-06-12 14:25:09|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:25:09|VDfastAGI|call_log|VD_hangup : 11490_20130612-142501_8001_3412228680 Local/58600051@default-00000009;1 1 612
2013-06-12 14:25:09|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|11490_20130612-142501_8001_3412228680||0|0||
2013-06-12 14:25:09|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1


And the FASTagiout log for a manually made call ("Dial next leed":.

Code: Select all

2013-06-12 14:36:34|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:34|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:34|VDfastAGI|begin|0|--debug
2013-06-12 14:36:34|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:36:34|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:34|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:34|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:36:34|VDfastAGI|begin| -- calleridname = M6121436340000011492
2013-06-12 14:36:34|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:34|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:34|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:34|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:34|VDfastAGI|begin| -- channel = Local/8600051@default-0000000e;1
2013-06-12 14:36:34|VDfastAGI|begin| -- context = default
2013-06-12 14:36:34|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:34|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:34|VDfastAGI|begin| -- extension = 03412228680
2013-06-12 14:36:34|VDfastAGI|begin| -- language = en
2013-06-12 14:36:34|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:34|VDfastAGI|begin| -- network_script = call_log
2013-06-12 14:36:34|VDfastAGI|begin| -- priority = 2
2013-06-12 14:36:34|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:34|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2013-06-12 14:36:34|VDfastAGI|begin| -- threadid = 140026528233216
2013-06-12 14:36:34|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:34|VDfastAGI|begin| -- uniqueid = 1371040594.43
2013-06-12 14:36:34|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:34|VDfastAGI|begin|AGI Variables: |1371040594.43|Local/8600051@default-0000000e;1|03412228680|Local|M6121436340000011492|
2013-06-12 14:36:34|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2013-06-12 14:36:34|VDfastAGI|call_log|+++++ CALL LOG START : 2013-06-12 14:36:34
2013-06-12 14:36:34|VDfastAGI|call_log|Local Channel Line: 0|8600051|
2013-06-12 14:36:34|VDfastAGI|call_log||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1371040594.43','Local/8600051@default-0000000e;1','Local Channel Line','Local','10.129.119.10','03412228680','03412228680','2013-06-12 14:36:34','1371040594','','','','','M6121436340000011492')|
2013-06-12 14:36:45|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:45|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:45|VDfastAGI|begin|0|--debug
2013-06-12 14:36:45|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:36:45|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:45|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:45|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:36:45|VDfastAGI|begin| -- calleridname = M6121436340000011492
2013-06-12 14:36:45|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- channel = Local/8600051@default-0000000e;1
2013-06-12 14:36:45|VDfastAGI|begin| -- context = default
2013-06-12 14:36:45|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:45|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:45|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:45|VDfastAGI|begin| -- language = en
2013-06-12 14:36:45|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:45|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----11-----7
2013-06-12 14:36:45|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:45|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:45|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----11-----7
2013-06-12 14:36:45|VDfastAGI|begin| -- threadid = 140026528233216
2013-06-12 14:36:45|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:45|VDfastAGI|begin| -- uniqueid = 1371040594.43
2013-06-12 14:36:45|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:45|VDfastAGI|begin|AGI Variables: |1371040594.43|Local/8600051@default-0000000e;1|h|Local|M6121436340000011492|
2013-06-12 14:36:45|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----11-----7|call_log|END|
2013-06-12 14:36:45|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:45|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|ANSWER|11|4|
2013-06-12 14:36:45|VDfastAGI|call_log||INSERT IGNORE INTO vicidial_carrier_log set uniqueid='1371040594.45',call_date='2013-06-12 14:36:45',server_ip='10.129.119.10',lead_id='11492',hangup_cause='16',dialstatus='ANSWER',channel='Local/8600051@default-0000000e;1',dial_time='11',answered_time='7';|
2013-06-12 14:36:45|VDfastAGI|call_log|--    CARRIER LOG insert: |1|11492|16
2013-06-12 14:36:45|VDfastAGI|call_log||1371040594.45|1371040594|SIP/testcarrier-0000000a|0|
2013-06-12 14:36:45|VDfastAGI|call_log||UPDATE call_log set end_time='2013-06-12 14:36:45',end_epoch='1371040605',length_in_sec=11,length_in_min='    0.18',channel='SIP/testcarrier-0000000a' where uniqueid='1371040594.45'|
2013-06-12 14:36:45|VDfastAGI|call_log|QUERY done: start time = 1371040594 | sec: 11 | min:     0.18 |1
2013-06-12 14:36:45|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040594.45','1371040594.45') and server_ip='10.129.119.10'|
2013-06-12 14:36:45|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040594.45|SIP/testcarrier-0000000a|h|2013-06-12 14:36:45|min:     0.18|
2013-06-12 14:36:45|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:45|VDfastAGI|call_log|VD_hangup : M6121436340000011492 SIP/testcarrier-0000000a 1 11492
2013-06-12 14:36:45|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 = '1371040594.45' or callerid = 'M6121436340000011492' limit 1;|
2013-06-12 14:36:45|VDfastAGI|call_log||SELECT channel from parked_channels where channel_group='M6121436340000011492';|
2013-06-12 14:36:45|VDfastAGI|call_log|--    VDAC record deleted: |1|   |11492|1371040594.45|1371040594.45|M6121436340000011492|10.129.119.10|XFER|
2013-06-12 14:36:45|VDfastAGI|call_log||SELECT start_epoch,status,user,term_reason,comments FROM vicidial_log FORCE INDEX(lead_id) where lead_id = '11492' and uniqueid LIKE "1371040594%" limit 1;|
2013-06-12 14:36:45|VDfastAGI|call_log||UPDATE vicidial_log FORCE INDEX(lead_id) set term_reason='CALLER', end_epoch='1371040605',length_in_sec='8' where lead_id = '11492' and uniqueid LIKE "1371040594%";|
2013-06-12 14:36:45|VDfastAGI|call_log|--    VDAD vicidial_log update: |1|1371040594.45|INCALL|
2013-06-12 14:36:45|VDfastAGI|call_log|no VDCL record found: 1371040594.45|M6121436340000011492|11492|1371040594.45|1371040594.45|1|
2013-06-12 14:36:45|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='CUSTOMCA';|
2013-06-12 14:36:45|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:45|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:45|VDfastAGI|begin|0|--debug
2013-06-12 14:36:45|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:45|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:45|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:45|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:36:45|VDfastAGI|begin| -- calleridname = M6121436340000011492
2013-06-12 14:36:45|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:45|VDfastAGI|begin| -- channel = Local/8600051@default-0000000e;2
2013-06-12 14:36:45|VDfastAGI|begin| -- context = default
2013-06-12 14:36:45|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:45|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:45|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:45|VDfastAGI|begin| -- language = en
2013-06-12 14:36:45|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:45|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:45|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:45|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:45|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:45|VDfastAGI|begin| -- threadid = 140026534000384
2013-06-12 14:36:45|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:45|VDfastAGI|begin| -- uniqueid = 1371040594.44
2013-06-12 14:36:45|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:45|VDfastAGI|begin|AGI Variables: |1371040594.44|Local/8600051@default-0000000e;2|h|Local|M6121436340000011492|
2013-06-12 14:36:45|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------|call_log|END|
2013-06-12 14:36:45|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:45|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:45|VDfastAGI|call_log||1371040594.45|1371040594|SIP/testcarrier-0000000a|1371040605|
2013-06-12 14:36:45|VDfastAGI|call_log||UPDATE call_log set end_time='2013-06-12 14:36:45',end_epoch='1371040605',length_in_sec=11,length_in_min='    0.18',channel='SIP/testcarrier-0000000a' where uniqueid='1371040594.45'|
2013-06-12 14:36:45|VDfastAGI|call_log|QUERY done: start time = 1371040594 | sec: 11 | min:     0.18 |1
2013-06-12 14:36:45|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040594.45','1371040594.44') and server_ip='10.129.119.10'|
2013-06-12 14:36:45|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040594.45|SIP/testcarrier-0000000a|h|2013-06-12 14:36:45|min:     0.18|
2013-06-12 14:36:45|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:45|VDfastAGI|call_log|VD_hangup : M6121436340000011492 SIP/testcarrier-0000000a 1 11492
2013-06-12 14:36:45|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 = '1371040594.45' or callerid = 'M6121436340000011492' limit 1;|
2013-06-12 14:36:45|VDfastAGI|call_log|VD hangup: no VDAC record found: 1371040594.45 M6121436340000011492
2013-06-12 14:36:48|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:48|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:48|VDfastAGI|begin|0|--debug
2013-06-12 14:36:48|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:36:48|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:48|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:48|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- calleridname = 11492_20130612-143633_8005_3412228680
2013-06-12 14:36:48|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- channel = Local/58600051@default-0000000f;2
2013-06-12 14:36:48|VDfastAGI|begin| -- context = default
2013-06-12 14:36:48|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:48|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:48|VDfastAGI|begin| -- language = en
2013-06-12 14:36:48|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:48|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:48|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:48|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:48|VDfastAGI|begin| -- threadid = 140026529249024
2013-06-12 14:36:48|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:48|VDfastAGI|begin| -- uniqueid = 1371040594.47
2013-06-12 14:36:48|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:48|VDfastAGI|begin|AGI Variables: |1371040594.47|Local/58600051@default-0000000f;2|h|Local|11492_20130612-143633_8005_3412228680|
2013-06-12 14:36:48|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------|call_log|END|
2013-06-12 14:36:48|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:48|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:48|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040594.47','1371040594.47') and server_ip='10.129.119.10'|
2013-06-12 14:36:48|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040594.47|Local/58600051@default-0000000f;2|h|2013-06-12 14:36:48|min:     0.03|
2013-06-12 14:36:48|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:48|VDfastAGI|call_log|VD_hangup : 11492_20130612-143633_8005_3412228680 Local/58600051@default-0000000f;2 1 612
2013-06-12 14:36:48|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|11492_20130612-143633_8005_3412228680||0|0||
2013-06-12 14:36:48|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2013-06-12 14:36:48|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:48|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:48|VDfastAGI|begin|0|--debug
2013-06-12 14:36:48|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:48|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:48|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:48|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- calleridname = 11492_20130612-143633_8005_3412228680
2013-06-12 14:36:48|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:48|VDfastAGI|begin| -- channel = Local/58600051@default-0000000f;1
2013-06-12 14:36:48|VDfastAGI|begin| -- context = default
2013-06-12 14:36:48|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:48|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:48|VDfastAGI|begin| -- language = en
2013-06-12 14:36:48|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:48|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:48|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:48|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:48|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------
2013-06-12 14:36:48|VDfastAGI|begin| -- threadid = 140026528741120
2013-06-12 14:36:48|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:48|VDfastAGI|begin| -- uniqueid = 1371040594.46
2013-06-12 14:36:48|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:48|VDfastAGI|begin|AGI Variables: |1371040594.46|Local/58600051@default-0000000f;1|h|Local|11492_20130612-143633_8005_3412228680|
2013-06-12 14:36:48|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------|call_log|END|
2013-06-12 14:36:48|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:48|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:48|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040594.46','1371040594.46') and server_ip='10.129.119.10'|
2013-06-12 14:36:48|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040594.46|Local/58600051@default-0000000f;1|h|2013-06-12 14:36:48|min:     0.08|
2013-06-12 14:36:48|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:48|VDfastAGI|call_log|VD_hangup : 11492_20130612-143633_8005_3412228680 Local/58600051@default-0000000f;1 1 612
2013-06-12 14:36:48|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|11492_20130612-143633_8005_3412228680||0|0||
2013-06-12 14:36:48|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2013-06-12 14:36:53|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:53|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:53|VDfastAGI|begin|0|--debug
2013-06-12 14:36:53|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:53|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:53|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:53|VDfastAGI|begin| -- callerid = 0000000000
2013-06-12 14:36:53|VDfastAGI|begin| -- calleridname = S1306121436258600051
2013-06-12 14:36:53|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- channel = SIP/201-00000009
2013-06-12 14:36:53|VDfastAGI|begin| -- context = default
2013-06-12 14:36:53|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:53|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:53|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:53|VDfastAGI|begin| -- language = en
2013-06-12 14:36:53|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:53|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:36:53|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:53|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:53|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:36:53|VDfastAGI|begin| -- threadid = 140026531968768
2013-06-12 14:36:53|VDfastAGI|begin| -- type = SIP
2013-06-12 14:36:53|VDfastAGI|begin| -- uniqueid = 1371040585.41
2013-06-12 14:36:53|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:53|VDfastAGI|begin|AGI Variables: |1371040585.41|SIP/201-00000009|h|SIP|S1306121436258600051|
2013-06-12 14:36:53|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2013-06-12 14:36:53|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:53|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:36:53|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040585.41','1371040585.41') and server_ip='10.129.119.10'|
2013-06-12 14:36:53|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040585.41|SIP/201-00000009|h|2013-06-12 14:36:53|min:     0.03|
2013-06-12 14:36:53|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:53|VDfastAGI|call_log|VD_hangup : S1306121436258600051 SIP/201-00000009 1 6258600051
2013-06-12 14:36:53|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 = '1371040585.41' or callerid = 'S1306121436258600051' limit 1;|
2013-06-12 14:36:53|VDfastAGI|call_log|VD hangup: no VDAC record found: 1371040585.41 S1306121436258600051
2013-06-12 14:36:53|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-06-12 14:36:53|VDfastAGI|begin|Perl Environment Dump:
2013-06-12 14:36:53|VDfastAGI|begin|0|--debug
2013-06-12 14:36:53|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||0|
2013-06-12 14:36:53|VDfastAGI|begin|AGI Environment Dump:
2013-06-12 14:36:53|VDfastAGI|begin| -- accountcode =
2013-06-12 14:36:53|VDfastAGI|begin| -- callerid = unknown
2013-06-12 14:36:53|VDfastAGI|begin| -- calleridname = ULGH34581371040613
2013-06-12 14:36:53|VDfastAGI|begin| -- callingani2 = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callingpres = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callingtns = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- callington = 0
2013-06-12 14:36:53|VDfastAGI|begin| -- channel = Local/55558600051@default-00000010;2
2013-06-12 14:36:53|VDfastAGI|begin| -- context = default
2013-06-12 14:36:53|VDfastAGI|begin| -- dnid = unknown
2013-06-12 14:36:53|VDfastAGI|begin| -- enhanced = 0.0
2013-06-12 14:36:53|VDfastAGI|begin| -- extension = h
2013-06-12 14:36:53|VDfastAGI|begin| -- language = en
2013-06-12 14:36:53|VDfastAGI|begin| -- network = yes
2013-06-12 14:36:53|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:36:53|VDfastAGI|begin| -- priority = 1
2013-06-12 14:36:53|VDfastAGI|begin| -- rdnis = unknown
2013-06-12 14:36:53|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-06-12 14:36:53|VDfastAGI|begin| -- threadid = 140026534000384
2013-06-12 14:36:53|VDfastAGI|begin| -- type = Local
2013-06-12 14:36:53|VDfastAGI|begin| -- uniqueid = 1371040613.49
2013-06-12 14:36:53|VDfastAGI|begin| -- version = 1.8.19.0-vici-beta
2013-06-12 14:36:53|VDfastAGI|begin|AGI Variables: |1371040613.49|Local/55558600051@default-00000010;2|h|Local|ULGH34581371040613|
2013-06-12 14:36:53|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2013-06-12 14:36:53|VDfastAGI|call_log||CALL HUNG UP|
2013-06-12 14:36:53|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-06-12 14:36:53|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1371040613.49','1371040613.49') and server_ip='10.129.119.10'|
2013-06-12 14:36:53|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1371040613.49|Local/55558600051@default-00000010;2|h|2013-06-12 14:36:53|min:     0.18|
2013-06-12 14:36:53|VDfastAGI|call_log|DEBUG: NODEBUG
2013-06-12 14:36:53|VDfastAGI|call_log|VD_hangup : ULGH34581371040613 Local/55558600051@default-00000010;2 1 71040613
2013-06-12 14:36:53|VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|ULGH34581371040613||16|0||
2013-06-12 14:36:53|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1


[striker]

can you post your dialplan used to dial via your carrier
seems you are missing Tto in your dialplan ....

[steffen123]

Hi,
first of all sorry for the long delay. I ended up restoring a (fairly old) VM snapshot and it's working now. Not sure what is different, if I have some time leftover I'll try to track down the problem. But thanks for the assistance in any case!