Status QUEUE in vicidial_log

[heinz]

Hi,

since I ugraded to version 2.0.4rc2 I experience that a quite a few vicidial_log entries don't get updated with the users disposition status (i.e. SALE) and the users id.
These entries just remain in status = 'QUEUE' and user = 'VDAD'.

That problem messes up my custom statistics a bit.
Any ideas where that problem might come from?

Thanks,
heinz

[mflorell]

In order to debug the problem you would really need to post some agiout logfile output of calls in agi-VDAD that show this problem.

I would of course suggest that you upgrade to 2.0.4.1rc4 first.

[heinz]

I still have problems with this issue.
Here is some log output:

Code: Select all

Oct 31 11:31:10 VERBOSE[17108] logger.c:     -- Zap/31-1 answered Local/XXXXXXXX@default-0034,2
Oct 31 11:31:10 VERBOSE[17106] logger.c:        > Channel Local/XXXXXXXX@default-0034,1 was answered.
Oct 31 11:31:10 VERBOSE[17236] logger.c:     -- Executing Playback("Local/XXXXXXXX@default-0034,1", "sip-silence") in new stack
Oct 31 11:31:10 DEBUG[17108] channel.c: Planning to masquerade channel Zap/31-1 into the structure of Local/XXXXXXXX@default-0034,1
Oct 31 11:31:10 DEBUG[17108] channel.c: Done planning to masquerade channel Zap/31-1 into the structure of Local/XXXXXXXX@default-0034,1
Oct 31 11:31:10 DEBUG[17108] chan_local.c: Not posting to queue since already masked on 'Local/XXXXXXXX@default-0034,2'
Oct 31 11:31:10 DEBUG[17108] channel.c: Didn't get a frame from channel: Local/XXXXXXXX@default-0034,2
Oct 31 11:31:10 DEBUG[17108] channel.c: Bridge stops bridging channels Local/XXXXXXXX@default-0034,2 and Local/XXXXXXXX@default-0034,1<ZOMBIE>
Oct 31 11:31:10 DEBUG[17236] channel.c: Released clone lock on 'Local/XXXXXXXX@default-0034,1<ZOMBIE>'
Oct 31 11:31:10 VERBOSE[17108] logger.c:   == Spawn extension (default, XXXXXXXX, 7) exited non-zero on 'Local/XXXXXXXX@default-0034,2'
Oct 31 11:31:10 VERBOSE[17108] logger.c:     -- Executing DeadAGI("Local/XXXXXXXX@default-0034,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG----------ANSWER-----15-----0)") in new stack
Oct 31 11:31:10 DEBUG[17108] pbx.c: Function result is 'Local/XXXXXXXX@default-0034,2'
Oct 31 11:31:46 DEBUG[17236] pbx.c: Function result is 'Local/XXXXXXXX@default-0034,1'


The problem is that there are several agents waiting for call, ouitgoing calls are answered but they are not transfered to the waiting agents. vicidial_log shows they remain in status QUEUE.

Any ideas?

[mflorell]

Still waiting for some agiout logfile output.

[heinz]

Sorry Matt,
here is some agiout data:

Code: Select all

2008-11-03 19:31:11|agi-VDADtransfer.agi|Perl Environment Dump:
2008-11-03 19:31:11|agi-VDADtransfer.agi|0|8365
2008-11-03 19:31:11|agi-VDADtransfer.agi|callerID changed: V1103193049000952499
2008-11-03 19:31:11|agi-VDADtransfer.agi|AGI Environment Dump:
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- accountcode =
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- callerid = 0000000000
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- calleridname = V1103193049000952499
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- callingani2 = 0
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- callingpres = 35
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- callingtns = 0
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- callington = 0
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- channel = Zap/108-1
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- context = default
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- dnid = unknown
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- enhanced = 0.0
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- extension = 8365
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- language = en
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- priority = 3
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- rdnis = unknown
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- request = agi-VDADtransfer.agi
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- type = Zap
2008-11-03 19:31:11|agi-VDADtransfer.agi| -- uniqueid = 1225737052.259592
2008-11-03 19:31:11|agi-VDADtransfer.agi|AGI Variables: |1225737052.259592|Zap/108-1|8365|Zap|V1103193049000952499|V1103193049000952499|3|
2008-11-03 19:31:11|agi-VDADtransfer.agi|+++++ VDAD START : |952499|2008-11-03 19:31:11|1.2.18|3|
2008-11-03 19:31:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V1103193049000952499';|
2008-11-03 19:31:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V1103193049000952499' and status IN('LIVE','XFER');|
2008-11-03 19:31:11|agi-VDADtransfer.agi|--    VDAD : |1|update of vac table: V1103193049000952499
2008-11-03 19:31:11|agi-VDADtransfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1225737052.259592','952499','MAXBEST','2008-11-03 19:31:11','1225737071','QUEUE','49','XXX','VDAD','N')|


And here some FASTagi:

Code: Select all

2008-11-03 19:31:11|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-11-03 19:31:11|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-11-03 19:31:11|TEST_VDfastAGI|begin|0|--debug
2008-11-03 19:31:11|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG||CANCEL||)|
2008-11-03 19:31:11|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- accountcode =
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- calleridname = V1103193049000952499
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingpres = 35
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingtns = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callington = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- channel = Zap/108-1
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- context = default
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- dnid = unknown
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- extension = 8365
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- language = en
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- network = yes
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- network_script = call_log
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- priority = 2
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- type = Zap
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- uniqueid = 1225737052.259592
2008-11-03 19:31:11|TEST_VDfastAGI|begin|AGI Variables: |1225737052.259592|Zap/108-1|8365|Zap|V1103193049000952499|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|+++++ CALL LOG START : 2008-11-03 19:31:11
2008-11-03 19:31:11|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-11-03 19:31:11|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-11-03 19:31:11|TEST_VDfastAGI|begin|0|--debug
2008-11-03 19:31:11|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG||||)|
2008-11-03 19:31:11|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- accountcode =
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- calleridname = V1103193049000952499
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingpres = 35
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callingtns = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- callington = 0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- channel = Local/XXXX@default-9cbd,2
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- context = default
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- dnid = unknown
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- extension = h
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- language = en
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- network = yes
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG----------ANSWER-----19-----0)
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- priority = 1
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG----------ANSWER-----19-----0)
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- type = Local
2008-11-03 19:31:11|TEST_VDfastAGI|begin| -- uniqueid = 1225737052.259593
2008-11-03 19:31:11|TEST_VDfastAGI|begin|AGI Variables: |1225737052.259593|Local/XXXX@default-9cbd,2|h|Local|V1103193049000952499|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG----------ANSWER-----19-----0)|call_log|END|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG||ANSWER|19|0)|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log||1225737052.2595930|1225737052|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|QUERY done: start time = 1225737052 | sec: 19 | min:     0.32 |
2008-11-03 19:31:11|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-11-03 19:31:11',end_epoch='1225737071',length_in_sec=19,length_in_min='    0.32',channel='Local/XXXX@default-9cbd,2' where uniqueid='1225737052.259593'|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1225737052.259593' and server_ip='192.168.2.5'|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1225737052.259593|Local/XXXX@default-9cbd,2|h|2008-11-03 19:31:11|min:     0.32|
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|VD_hangup : V1103193049000952499 Local/42100497031631576@default-9cbd,2 1 952499
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V1103193049000952499|ANSWER||
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-11-03 19:31:11|TEST_VDfastAGI|call_log|Local Zap phone: 0|108-1|
2008-11-03 19:31:11|TEST_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('1225737052.259592','Zap/108-1','Zap Trunk Line','Zap','192.168.2.5','8365','V1103193049000952499','2008-11-03 19:31:11','1225737071','','','','','V1103193049000952499')|


This is an example for a lead with status 'NA' which was called, the line was answered and there where agents waiting for calls but the call didn't get transfered to the agent. In vicidial_log the status is 'QUEUE' with no end_epoch entry. The status in vicidial_list remains 'NA'.

[mflorell]

Is that it for the agiout logfile? There should be some more output after that if it was a call to be transferred.

What is the Asterisk version?

What is the loadavg on this system when it's dialing?

[heinz]

For me it seems like that this is all agiout-data for this call. Next entries are related to other calls...

We are using Asterisk 1.2.21 , the load avg on the machine is about 0.5.
It could be that our databaseserver and the webserver were around 1.5 load avg at the time happening.

I'll go through the log-files again and try to find some more example-data

Thanks Matt