vicidial.org

Posted: **Thu Apr 24, 2008 7:41 pm**

I am making all sorts of statistics of inbound calls and I noticed some 15 minute blocks with huge call times. It turns out some calls get 'stuck' in the database for a really long time only to dissapear randomly (or it seems to be)

I think the actual Zap channel is not getting stuck, because I can see it appear again in the list, sometimes several times. I am running 2.0.4 with the agc directory replaced with the one Matt told me to to fix the 'old channel in your session' problem, but I have had the problem before that.

DB is in another machine, with 0.X load. This machines load is also 0.XX (0.32 at this time with 35 agents and a queue of 45 calls).

Is this a known problem? Should I just make a cron script to purge the DB of over 20 minutes calls? (average call is 3 minutes and over 15 minutes is rare)

Here is a sample:

VICIDIAL: Time On VDAD TRUNK SHORT: 0 2008-04-24 20:23:27

+---------------------+--------+--------------+--------------------+----------+---------+
| CHANNEL | STATUS | CAMPAIGN | PHONE NUMBER | CALLTIME | MINUTES |
+---------------------+--------+--------------+--------------------+----------+---------+
| Zap/4-1 | LIVE | TelmexTec | 56990515792 | 20:23:25 | 0:02 |
| Zap/21-1 | CLOSER | TelmexTec | 5645406424 | 20:23:19 | 0:08 |
| Zap/18-1 | CLOSER | TelmexTec | 5642222383 | 20:22:47 | 0:40 |
| Zap/7-1 | CLOSER | TelmexTec | 56968408830 | 20:22:41 | 0:46 |
| Zap/19-1 | CLOSER | TelmexCom | 56412984724 | 20:22:38 | 0:49 |
| Zap/45-1 | CLOSER | TelmexCom | 5625455242 | 20:21:56 | 1:31 |
| Zap/25-1 | CLOSER | TelmexTec | 5627455152 | 20:21:51 | 1:36 |
| Zap/14-1 | CLOSER | TelmexTec | 5625437558 | 20:21:41 | 1:46 |
| Zap/12-1 | CLOSER | TelmexTec | 5626873893 | 20:21:39 | 1:48 |
| Zap/30-1 | CLOSER | TelmexTec | 56977086928 | 20:21:37 | 1:50 |
| Zap/15-1 | CLOSER | TelmexTec | 5628521247 | 20:21:20 | 2:07 |
| Zap/23-1 | CLOSER | TelmexTec | 5625258865 | 20:20:57 | 2:30 |
| Zap/10-1 | CLOSER | TelmexTec | 56985880554 | 20:20:57 | 2:30 |
| Zap/26-1 | CLOSER | TelmexTec | 5628149592 | 20:20:50 | 2:37 |
| Zap/8-1 | CLOSER | TelmexTec | 5628129263 | 20:20:20 | 3:07 |
| Zap/2-1 | CLOSER | TelmexCom | 5622157796 | 20:20:18 | 3:09 |
| Zap/6-1 | CLOSER | TelmexTec | 5628213871 | 20:20:03 | 3:24 |
| Zap/40-1 | CLOSER | TelmexTec | 56Y04242016230 | 20:20:01 | 3:26 |
| Zap/17-1 | CLOSER | TelmexTec | 56Y04242017540 | 20:19:56 | 3:31 |
| Zap/24-1 | CLOSER | TelmexTec | 56997662994 | 20:19:51 | 3:36 |
| Zap/3-1 | CLOSER | TelmexTec | 5626494211 | 20:19:45 | 3:42 |
| Zap/9-1 | CLOSER | TelmexTec | 56977589937 | 20:19:38 | 3:49 |
| Zap/22-1 | CLOSER | TelmexCom | 56977064540 | 20:19:21 | 4:06 |
| Zap/13-1 | CLOSER | TelmexTec | 5622398192 | 20:19:08 | 4:19 |
| Zap/1-1 | CLOSER | TelmexTec | 56412987609 | 20:19:08 | 4:19 |
| Zap/31-1 | CLOSER | TelmexTec | 5625614995 | 20:19:08 | 4:19 |
| Zap/28-1 | CLOSER | TelmexTec | 5628440352 | 20:18:05 | 5:22 |
| Zap/20-1 | CLOSER | TelmexTec | 56998206636 | 20:15:56 | 7:31 |
| Zap/27-1 | CLOSER | TelmexTec | 5628600242 | 20:13:39 | 9:48 |
| Zap/29-1 | CLOSER | TelmexTec | 56322911311 | 20:11:47 | 11:40 |
| Zap/11-1 | CLOSER | TelmexCom | 5628599488 | 20:10:15 | 13:12 |
| Zap/5-1 | CLOSER | TelmexTec | 5625617830 | 20:04:56 | 18:31 |
| Zap/29-1 | CLOSER | TelmexCom | 5664231674 | 19:00:45 | 82:42 |
| Zap/23-1 | CLOSER | TelmexTec | 5643323124 | 17:06:29 | 196:58 |
| Zap/19-1 | CLOSER | TelmexTec | 5624493971 | 15:46:54 | 276:33 |
| Zap/6-1 | CLOSER | TelmexTec | 5625852663 | 15:26:55 | 296:32 |
| Zap/19-1 | CLOSER | TelmexTec | 5633716391 | 13:10:18 | 433:09 |
+---------------------+--------+--------------+--------------------+----------+---------+
37 calls being placed on server 192.168.0.13

Posted: **Fri Apr 25, 2008 1:00 am**

Do you have the 'h' extension with AGI in every context of your dialplan?

Posted: **Fri Apr 25, 2008 5:13 am**

mflorell wrote:Do you have the 'h' extension with AGI in every context of your dialplan?

I will triple check, but I have at least 4 h extensions...

Posted: **Fri Apr 25, 2008 9:08 pm**

ekaftan wrote:
mflorell wrote:Do you have the 'h' extension with AGI in every context of your dialplan?

I will triple check, but I have at least 4 h extensions...

I added 10 more 'h' extensions (one to every context) and today I have more stuck calls than yesterday...

Zap/29-1 | CLOSER | TelmexTec | 5645525474 | 19:45:26 | 141:36 |
| Zap/30-1 | CLOSER | TelmexTec | 5634461709 | 18:53:07 | 193:55 |
| Zap/21-1 | CLOSER | TelmexCom | 5625740000 | 14:00:21 | 486:41 |
| Zap/14-1 | CLOSER | TelmexTec | 56322496545 | 13:26:58 | 520:04 |
| Zap/17-1 | CLOSER | TelmexTec | 5627722348 | 11:56:19 | 610:43 |
| Zap/20-1 | CLOSER | TelmexTec | 56989735116 | 11:13:18 | 653:44 |
| Zap/18-1 | CLOSER | TelmexTec | 56983769057 | 10:53:50 | 673:12 |
| Zap/3-1 | CLOSER | TelmexCom | 56412204000 | 10:18:30 | 708:32 |
+---------------------+--------+--------------+--------------------+----------+-

Posted: **Sat Apr 26, 2008 1:02 am**

Did you reload Asterisk after you made the changes?

This is almost always an 'h' exten omission problem.

Posted: **Sat Apr 26, 2008 5:40 am**

mflorell wrote:Did you reload Asterisk after you made the changes?

This is almost always an 'h' exten omission problem.

I know... yes I did reload, I have two servers and a script to sync and reload them
when I change something.... and DeadAgi seems to be running... (several times, I think I have too many)

Here is the relevant lines from messages for one of the stuck calls:

Apr 25 09:33:33 VERBOSE[2718] logger.c: -- Accepting call from '412204000' to '1021249' on channel 0/22, span 1
Apr 25 09:33:33 DEBUG[2718] chan_zap.c: Enabled echo cancellation on channel 22
Apr 25 09:33:33 VERBOSE[1295] logger.c: -- Executing Wait("Zap/22-1", "1") in new stack
Apr 25 09:33:33 DEBUG[30405] manager.c: Manager received command 'Command'
Apr 25 09:33:34 DEBUG[30405] manager.c: Manager received command 'Command'
Apr 25 09:33:34 VERBOSE[1295] logger.c: -- Executing Answer("Zap/22-1", "") in new stack
Apr 25 09:33:34 VERBOSE[1295] logger.c: -- Executing SetCDRUserField("Zap/22-1", "in-telmex") in new stack
Apr 25 09:33:34 VERBOSE[1295] logger.c: -- Executing AGI("Zap/22-1", "agi-VDAD_ALL_inbound.agi|CIDLOOKUPRC-----LB-----TelmexCom-----1021249-----Closer-----park----------8000-----56-----TelmexIN") in new stack
Apr 25 09:33:34 VERBOSE[1295] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
Apr 25 09:33:38 VERBOSE[1295] logger.c: -- Started music on hold, class 'dmt', on Zap/22-1
Apr 25 09:33:51 VERBOSE[1295] logger.c: -- Stopped music on hold on Zap/22-1
Apr 25 09:33:52 VERBOSE[1378] logger.c: -- Executing MeetMe("Local/78603011@default-8026,2", "8603011|q") in new stack
Apr 25 09:33:52 DEBUG[2630] channel.c: Avoiding initial deadlock for 'Local/78603011@default-8026,2'
Apr 25 09:33:52 DEBUG[1378] app_meetme.c: Placed channel Local/78603011@default-8026,2 in ZAP conf 1013
Apr 25 09:33:52 VERBOSE[1379] logger.c: -- Executing Answer("Local/78603011@default-8026,1", "") in new stack
Apr 25 09:33:52 VERBOSE[1379] logger.c: -- Executing Monitor("Local/78603011@default-8026,1", "gsm|/var/spool/asterisk/
monitor/vicidial/TELMEXIN-20080425-093350-412204000") in new stack
Apr 25 09:33:52 VERBOSE[1379] logger.c: -- Executing Wait("Local/78603011@default-8026,1", "3600") in new stack
Apr 25 09:33:52 DEBUG[30405] manager.c: Manager received command 'Command'
Apr 25 09:33:52 VERBOSE[1295] logger.c: -- AGI Script agi-VDAD_ALL_inbound.agi completed, returning 0
Apr 25 09:33:52 VERBOSE[1295] logger.c: -- Executing Goto("Zap/22-1", "vicidial|8603011|1") in new stack
Apr 25 09:33:52 VERBOSE[1295] logger.c: -- Goto (vicidial,8603011,1)
Apr 25 09:33:52 VERBOSE[1295] logger.c: -- Executing MeetMe("Zap/22-1", "8603011") in new stack
Apr 25 09:33:52 DEBUG[1295] chan_zap.c: Requested indication -1 on channel Zap/22-1
Apr 25 09:33:52 DEBUG[1295] app_meetme.c: Placed channel Zap/22-1 in ZAP conf 1013
Apr 25 09:37:19 VERBOSE[1295] logger.c: == Spawn extension (vicidial, 8603011, 1) exited non-zero on 'Zap/22-1'
Apr 25 09:37:19 VERBOSE[1295] logger.c: -- Executing DeadAGI("Zap/22-1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-
----NODEBUG-----0---------------)") in new stack
Apr 25 09:37:19 VERBOSE[1378] logger.c: == Spawn extension (default, 78603011, 1) exited non-zero on 'Local/78603011@defa
ult-8026,2'
Apr 25 09:37:19 VERBOSE[1378] logger.c: -- Executing DeadAGI("Local/78603011@default-8026,2", "agi://127.0.0.1:4577/cal
l_log--HVcauses--PRI-----NODEBUG-----0---------------)") in new stack
Apr 25 09:37:19 VERBOSE[1378] logger.c: -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... G-----0---
------------) completed, returning 0
Apr 25 09:37:19 VERBOSE[1379] logger.c: == Spawn extension (default, 8310, 3) exited non-zero on 'Local/78603011@default-
8026,1'
Apr 25 09:37:19 VERBOSE[1379] logger.c: -- Executing DeadAGI("Local/78603011@default-8026,1", "agi://127.0.0.1:4577/cal
l_log--HVcauses--PRI-----NODEBUG-----0---------------)") in new stack
Apr 25 09:37:19 DEBUG[1378] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 25 09:37:19 DEBUG[1378] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dc
ontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2008-04-25
09:33:52','TELMEXIN-20080425-093350-412204000','','78603011','default', 'Local/78603011@default-8026,2','','MeetMe','86030
11|q',207,207,'ANSWERED',3,'','')
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'TELMEXIN-20080425-093350-412204000'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '78603011'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'default'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'Local/78603011@default-8026,2'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'MeetMe'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '8603011|q'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '2008-04-25 09:33:52'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '2008-04-25 09:33:52'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '2008-04-25 09:37:19'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '207'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '207'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'ANSWERED'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is 'DOCUMENTATION'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '1209130432.564192'
Apr 25 09:37:19 DEBUG[1378] pbx.c: Function result is '(null)'
Apr 25 09:37:19 VERBOSE[1295] logger.c: -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... G-----0---
------------) completed, returning 0
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/22-1
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Hangup: channel: 22 index = 0, normal = 38, callwait = -1, thirdcall = -1
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: disabled echo cancellation on channel 22
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/22-1
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Updated conferencing on 22, with 0 conference users
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/22-1
Apr 25 09:37:19 DEBUG[1295] chan_zap.c: disabled echo cancellation on channel 22
Apr 25 09:37:19 VERBOSE[1295] logger.c: -- Hungup 'Zap/22-1'
Apr 25 09:37:19 DEBUG[1295] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 25 09:37:19 DEBUG[1295] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dc
ontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2008-04-25
09:33:33','"Y042593334004333289" <412204000>','412204000','8603011','vicidial', 'Zap/22-1','','MeetMe','8603011',226,225
,'ANSWERED',3,'','in-telmex')
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '"Y042593334004333289" <412204000>'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '412204000'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '8603011'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'vicidial'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'Zap/22-1'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'MeetMe'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '8603011'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '2008-04-25 09:33:33'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '2008-04-25 09:33:34'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '2008-04-25 09:37:19'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '226'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '225'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'ANSWERED'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'DOCUMENTATION'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is '1209130413.564179'
Apr 25 09:37:19 DEBUG[1295] pbx.c: Function result is 'in-telmex'
Apr 25 09:37:19 VERBOSE[1379] logger.c: -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... G-----0---
------------) completed, returning 0
Apr 25 09:37:19 DEBUG[1379] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 25 09:37:19 DEBUG[1379] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dc
ontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2008-04-25
09:33:52','TELMEXIN-20080425-093350-412204000','','8310','default', 'Local/78603011@default-8026,1','','Wait','3600',207,2
07,'ANSWERED',3,'','')
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'TELMEXIN-20080425-093350-412204000'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '8310'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'default'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'Local/78603011@default-8026,1'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'Wait'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '3600'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '2008-04-25 09:33:52'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '2008-04-25 09:33:52'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '2008-04-25 09:37:19'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '207'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '207'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'ANSWERED'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is 'DOCUMENTATION'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '(null)'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '1209130432.564191'
Apr 25 09:37:19 DEBUG[1379] pbx.c: Function result is '(null)'

Posted: **Sat Apr 26, 2008 8:23 am**

debug output doesn't help much, do you have agiout logfile output for the DeadAGI?

Posted: **Sat Apr 26, 2008 12:02 pm**

mflorell wrote:debug output doesn't help much, do you have agiout logfile output for the DeadAGI?

Yes I have....

2008-04-25 9:37:19|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-04-25 9:37:19|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin|0|--debug
2008-04-25 9:37:19|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||)|
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- accountcode =
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callerid = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- calleridname = TELMEXIN-20080425-093350-412204000
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingpres = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingtns = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callington = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- channel = Local/78603011@default-8026,2
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- context = default
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- dnid = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- extension = h
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- language = en
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209130413.564179' and server_ip='192.
168.0.13'|
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network = yes
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- priority = 1
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... --0-------
--------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- type = Local
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- uniqueid = 1209130432.564192
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Variables: |1209130432.564192|Local/78603011@default-8026,2|h|Local|S0804250820
568603013|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-
--------------)|call_log|END|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209130432.564192' and server_ip='192.
168.0.13'|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209130413.564179|Zap/22-1|h|2008-04-25 9:37:19|min:
0.10|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|VD_hangup : S0804250831208603013 Zap/22-1 1 208603013
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time) FROM vicidial_auto_calls where uniqueid = '1209130413.564179' limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209130432.564192|Local/78603011@default-8026,2|h|2008-0
4-25 9:37:19|min: 0.62|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|VD_hangup : S0804250820568603013 Local/78603011@default-8026,2 1 568603013
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VD_hangup Local DEBUG: |PRI|S0804250820568603013||16|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDAC record deleted: |1| |4333289|1209130413.564179|Y042593334004333289|
192.168.0.13
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT start_epoch,status FROM vicidial_log where uniqueid='1209130413.564179'
and lead_id='4333289' limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|no VDL record found: 1209130413.564179 S0804250831208603013 4333289 1209130413.5
64179
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT start_epoch,status,closecallid FROM vicidial_closer_log where lead_id =
'4333289' and call_date > "2008-04-25 03:37:19" order by call_date desc limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||UPDATE vicidial_log set end_epoch='1209130639',length_in_sec='225' where uniqu
eid = '1209130413.564179';|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDAD vicidial_log update: |0E0|1209130413.564179|INCALL|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|||INCALL|
|UPDATE vicidial_closer_log set end_epoch='1209130639',length_in_sec='225' where closecallid = '178795';|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDCL update: |1|1209130413.564179|178795|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT auto_alt_dial,auto_alt_dial_statuses FROM vicidial_campaigns where campa
ign_id='TelmexCom';|
2008-04-25 9:37:19|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-04-25 9:37:19|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin|0|--debug
2008-04-25 9:37:19|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||)|
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- accountcode =
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callerid = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- calleridname = TELMEXIN-20080425-093350-412204000
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingpres = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingtns = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callington = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- channel = Local/78603011@default-8026,1
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- context = default
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- dnid = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- extension = h
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- language = en
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network = yes
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0---------------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- priority = 1
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... --0-------
--------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- type = Local
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- uniqueid = 1209130432.564191
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Variables: |1209130432.564191|Local/78603011@default-8026,1|h|Local|S0804250906
548603017|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-
--------------)|call_log|END|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209130432.564191' and server_ip='192.
168.0.13'|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209130432.564191|Local/78603011@default-8026,1|h|2008-0
4-25 9:37:19|min: 2.03|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|VD_hangup : S0804250906548603017 Local/78603011@default-8026,1 1 548603017
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VD_hangup Local DEBUG: |PRI|S0804250906548603017||0|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-04-25 9:37:19|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-04-25 9:37:19|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin|0|--debug
2008-04-25 9:37:19|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||)|
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- accountcode =
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callerid = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- calleridname = Y042592712004886547
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingpres = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callingtns = 0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- callington = 33
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- channel = Zap/25-1
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- context = vicidial
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- dnid = 1021248
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- extension = h
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- language = cl
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network = yes
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- priority = 1
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... --16------
---------)
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- type = Zap
2008-04-25 9:37:19|TEST_VDfastAGI|begin| -- uniqueid = 1209130031.564104
2008-04-25 9:37:19|TEST_VDfastAGI|begin|AGI Variables: |1209130031.564104|Zap/25-1|h|Zap|S0804250901068603016|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16
---------------)|call_log|END|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209130031.564104' and server_ip='192.
168.0.13'|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209130031.564104|Zap/25-1|h|2008-04-25 9:37:19|min:
0.00|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|VD_hangup : S0804250901068603016 Zap/25-1 1 68603016
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time) FR
OM vicidial_auto_calls where uniqueid = '1209130031.564104' limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDAC record deleted: |1| |4886547|1209130031.564104|Y042592712004886547|
192.168.0.13
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT start_epoch,status FROM vicidial_log where uniqueid='1209130031.564104'
and lead_id='4886547' limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|no VDL record found: 1209130031.564104 S0804250901068603016 4886547 1209130031.5
64104
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT start_epoch,status,closecallid FROM vicidial_closer_log where lead_id =
'4886547' and call_date > "2008-04-25 03:37:19" order by call_date desc limit 1;|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||UPDATE vicidial_log set end_epoch='1209130639',length_in_sec='607' where uniqu
eid = '1209130031.564104';|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDAD vicidial_log update: |0E0|1209130031.564104|INCALL|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|||INCALL|
|UPDATE vicidial_closer_log set end_epoch='1209130639',length_in_sec='607' where closecallid = '178772';|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log|-- VDCL update: |1|1209130031.564104|178772|
2008-04-25 9:37:19|TEST_VDfastAGI|call_log||SELECT auto_alt_dial,auto_alt_dial_statuses FROM vicidial_campaigns where campa
ign_id='TelmexTec';|

Posted: **Sat Apr 26, 2008 2:58 pm**

can you find one of the records that is not deleted in the agiout logfile?

Posted: **Sat Apr 26, 2008 3:37 pm**

mflorell wrote:can you find one of the records that is not deleted in the agiout logfile?

I thought I posted that... but the DeadAGI call is not there.

So you are right, DeadAgi does not get called... problem is why... its in every context (and you can see it gets called a lot)

Could this be because the call goes in via one E1 and out via a second E1? (this asterisk server uses a Nortel meridian as a channel back to reach the agents)

Posted: **Sat Apr 26, 2008 7:56 pm**

What contexts do you have defined in your zapata.conf, sip.conf and iax.conf files?

Posted: **Sat Apr 26, 2008 11:15 pm**

mflorell wrote:What contexts do you have defined in your zapata.conf, sip.conf and iax.conf files?

in zapata.conf its defined that calls come in via the 'intelmex' context.

intelmex is:

[intelmex]
exten => h,1,DeadAGI(agi://127.0.0.1:4577/call_log--HVcauses ... EBUG-----${HANGUPCAUSE}-----${DIALSTATUS}-----${DIALEDTIME}-----${ANSWEREDTIME}))

exten => 1021249,1,Wait(1) ; Wait 1 second for CID delivery from PRI
exten => 1021249,n,Answer ; Answer the line
exten => 1021249,n,SetCDRUserField('in-telmex')
exten => 1021249,n,AGI(agi-VDAD_ALL_inbound.agi,CIDLOOKUPRC-----B-----TelmexCom-----1021249-----Closer-----park----------8000-----56-----TelmexIN)
exten => 1021249,n,Hangup

I also have a 'vicidial' context, included in 'default' with all the vicidial specific extensions. There is also a 'h' extension there and another one in the default context itself.

Calls between servers are routed via iax, all entering small contexts only an 'h' extension and the intelmex context.

vicidial.org

Old calls still in active list

Old calls still in active list