vicidial log time is wrong

[shail2206]

Hello ,

I have some problem with vicidial_log end_epoch time, in my case vicidial_log.end_epoch and vicidial_log.start_epoch both time are same and status is "PDROP".
sceanrio is

1. first auto calls get generated from system on client cell phone
2. user pick the call
3. he/she provides input (ex. 1 or 2)
4. after that calls get hangup
but in this case vicidial_log.start_epoch & vicidial_log.end_epoch time both is same and vicidial_log.length_in_sec = 0 ....
Actually I am new for asterisk that's why I am not able to debug this ....

Thanks in advance

[shail2206]

strange !!! 356 View but not reply ?

[mcargile]

Moved to Support as this is not a development issue.

More than likely this is a misconfiguration. Among other things:

PDROP - Pre-routing dropped call, call hung up the instant the Answer signal is received

That is why the two times are matching. Vicidial is registering it as having hung up already. If one of your agents is getting this call something is very wrong with your setup. Please post the Asterisk CLI output for one of these calls.

[shail2206]

first of all sorry (mcargile and team), actually I am new that's why I don't know it's development issue or programming.. (Thanks for moving the same)


this is my CLI output

[Oct 18 07:27:06] == Parsing '/etc/asterisk/manager.conf': [Oct 18 07:27:06] Found
[Oct 18 07:27:06] == Manager 'sendcron' logged on from 127.0.0.1
[Oct 18 07:27:06] == Manager 'sendcron' logged off from 127.0.0.1
[Oct 18 07:27:09] == Parsing '/etc/asterisk/manager.conf': [Oct 18 07:27:09] Found
[Oct 18 07:27:09] == Manager 'sendcron' logged on from 127.0.0.1
[Oct 18 07:27:09] -- Executing [7769973837@default:1] AGI("Local/7769973837@default-8b9b,2", "agi://127.0.0.1:4577/call_log") in new stack
[Oct 18 07:27:09] AGI Tx >> agi_network: yes
[Oct 18 07:27:09] AGI Tx >> agi_network_script: call_log
[Oct 18 07:27:09] AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log
[Oct 18 07:27:09] AGI Tx >> agi_channel: Local/7769973837@default-8b9b,2
[Oct 18 07:27:09] AGI Tx >> agi_language: en
[Oct 18 07:27:09] AGI Tx >> agi_type: Local
[Oct 18 07:27:09] AGI Tx >> agi_uniqueid: 1382061429.374
[Oct 18 07:27:09] AGI Tx >> agi_callerid: 0000000000
[Oct 18 07:27:09] AGI Tx >> agi_calleridname: V0180727090000000100
[Oct 18 07:27:09] AGI Tx >> agi_callingpres: 0
[Oct 18 07:27:09] AGI Tx >> agi_callingani2: 0
[Oct 18 07:27:09] AGI Tx >> agi_callington: 0
[Oct 18 07:27:09] AGI Tx >> agi_callingtns: 0
[Oct 18 07:27:09] AGI Tx >> agi_dnid: unknown
[Oct 18 07:27:09] AGI Tx >> agi_rdnis: unknown
[Oct 18 07:27:09] AGI Tx >> agi_context: default
[Oct 18 07:27:09] AGI Tx >> agi_extension: 7769973837
[Oct 18 07:27:09] AGI Tx >> agi_priority: 1
[Oct 18 07:27:09] AGI Tx >> agi_enhanced: 0.0
[Oct 18 07:27:09] AGI Tx >> agi_accountcode:
[Oct 18 07:27:09] AGI Tx >>
[Oct 18 07:27:09] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Oct 18 07:27:09] -- Executing [7769973837@default:2] Dial("Local/7769973837@default-8b9b,2", "DAHDI/g0/7769973837||tToR") in new stack
[Oct 18 07:27:09] -- Requested transfer capability: 0x00 - SPEECH
[Oct 18 07:27:09] -- Called g0/7769973837
[Oct 18 07:27:09] DEBUG[2495]: chan_dahdi.c:11719 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
[Oct 18 07:27:09] -- DAHDI/1-1 is proceeding passing it to Local/7769973837@default-8b9b,2
[Oct 18 07:27:09] -- DAHDI/1-1 is ringing
[Oct 18 07:27:12] DEBUG[2495]: chan_dahdi.c:11684 pri_dchannel: Queuing frame from PRI_EVENT_PROGRESS on channel 0/1 span 1
[Oct 18 07:27:12] -- DAHDI/1-1 is making progress passing it to Local/7769973837@default-8b9b,2
[Oct 18 07:27:15] DEBUG[2495]: chan_dahdi.c:2429 dahdi_enable_ec: Echo cancellation already on
[Oct 18 07:27:15] -- DAHDI/1-1 answered Local/7769973837@default-8b9b,2
[Oct 18 07:27:15] > Channel Local/7769973837@default-8b9b,1 was answered.
[Oct 18 07:27:15] -- Executing [8888@default:1] Goto("Local/7769973837@default-8b9b,1", "ServiceFeedback|s|1") in new stack
[Oct 18 07:27:15] DEBUG[11310]: chan_dahdi.c:6717 dahdi_indicate: Requested indication 20 on channel DAHDI/1-1
[Oct 18 07:27:15] -- Goto (ServiceFeedback,s,1)
[Oct 18 07:27:15] -- Executing [s@ServiceFeedback:1] Answer("Local/7769973837@default-8b9b,1", "") in new stack
[Oct 18 07:27:15] -- Executing [s@ServiceFeedback:2] AGI("Local/7769973837@default-8b9b,1", "agi-VDAD_inbound_calltime_check.agi|CALLMENU-----YES-----ServiceFeedback-------------------------NO") in new stack
[Oct 18 07:27:15] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_inbound_calltime_check.agi
[Oct 18 07:27:15] AGI Tx >> agi_request: agi-VDAD_inbound_calltime_check.agi
[Oct 18 07:27:15] AGI Tx >> agi_channel: Local/7769973837@default-8b9b,1
[Oct 18 07:27:15] AGI Tx >> agi_language: en
[Oct 18 07:27:15] AGI Tx >> agi_type: Local
[Oct 18 07:27:15] AGI Tx >> agi_uniqueid: 1382061429.373
[Oct 18 07:27:15] AGI Tx >> agi_callerid: 0000000000
[Oct 18 07:27:15] AGI Tx >> agi_calleridname: V0180727090000000100
[Oct 18 07:27:15] AGI Tx >> agi_callingpres: 0
[Oct 18 07:27:15] AGI Tx >> agi_callingani2: 0
[Oct 18 07:27:15] AGI Tx >> agi_callington: 0
[Oct 18 07:27:15] AGI Tx >> agi_callingtns: 0
[Oct 18 07:27:15] AGI Tx >> agi_dnid: unknown
[Oct 18 07:27:15] AGI Tx >> agi_rdnis: unknown
[Oct 18 07:27:15] AGI Tx >> agi_context: ServiceFeedback
[Oct 18 07:27:15] AGI Tx >> agi_extension: s
[Oct 18 07:27:15] AGI Tx >> agi_priority: 2
[Oct 18 07:27:15] AGI Tx >> agi_enhanced: 0.0
[Oct 18 07:27:15] AGI Tx >> agi_accountcode:
[Oct 18 07:27:15] AGI Tx >>
[Oct 18 07:27:15] DEBUG[11321]: chan_dahdi.c:4895 dahdi_fixup: New owner for channel 1 is DAHDI/1-1
[Oct 18 07:27:15] -- Executing [h@default:1] DeadAGI("Local/7769973837@default-8b9b,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----6-----0") in new stack
[Oct 18 07:27:15] AGI Tx >> agi_network: yes
[Oct 18 07:27:15] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----6-----0
[Oct 18 07:27:15] AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses ... ---6-----0
[Oct 18 07:27:15] AGI Tx >> agi_channel: Local/7769973837@default-8b9b,2
[Oct 18 07:27:15] DEBUG[11321]: chan_dahdi.c:6717 dahdi_indicate: Requested indication 21 on channel DAHDI/1-1
[Oct 18 07:27:15] AGI Tx >> agi_language: en
[Oct 18 07:27:15] AGI Tx >> agi_type: Local
[Oct 18 07:27:15] AGI Tx >> agi_uniqueid: 1382061429.374
[Oct 18 07:27:15] AGI Tx >> agi_callerid: 0000000000
[Oct 18 07:27:15] AGI Tx >> agi_calleridname: V0180727090000000100
[Oct 18 07:27:15] AGI Tx >> agi_callingpres: 0
[Oct 18 07:27:15] AGI Tx >> agi_callingani2: 0
[Oct 18 07:27:15] AGI Tx >> agi_callington: 0
[Oct 18 07:27:15] AGI Tx >> agi_callingtns: 0
[Oct 18 07:27:15] AGI Tx >> agi_dnid: unknown
[Oct 18 07:27:15] AGI Tx >> agi_rdnis: unknown
[Oct 18 07:27:15] AGI Tx >> agi_context: default
[Oct 18 07:27:15] AGI Tx >> agi_extension: h
[Oct 18 07:27:15] AGI Tx >> agi_priority: 1
[Oct 18 07:27:15] AGI Tx >> agi_enhanced: 0.0
[Oct 18 07:27:15] AGI Tx >> agi_accountcode:
[Oct 18 07:27:15] AGI Tx >>
[Oct 18 07:27:15] -- AGI Script agi-VDAD_inbound_calltime_check.agi completed, returning 0
[Oct 18 07:27:15] -- Executing [s@ServiceFeedback:3] Set("DAHDI/1-1", "INVCOUNT=0") in new stack
[Oct 18 07:27:15] -- Executing [s@ServiceFeedback:4] BackGround("DAHDI/1-1", "GSM/WelcomethiscallisfromBSNLPleaseprovideFeedbackaboutourservice") in new stack
[Oct 18 07:27:15] -- <DAHDI/1-1> Playing 'GSM/WelcomethiscallisfromBSNLPleaseprovideFeedbackaboutourservice' (language 'en')
[Oct 18 07:27:16] == Manager 'sendcron' logged off from 127.0.0.1
[Oct 18 07:27:16] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---6-----0 completed, returning 0
[Oct 18 07:27:16] == Spawn extension (default, 7769973837, 2) exited non-zero on 'Local/7769973837@default-8b9b,2'
[Oct 18 07:27:23] -- Executing [s@ServiceFeedback:5] WaitExten("DAHDI/1-1", "1") in new stack
[Oct 18 07:27:24] -- Timeout on DAHDI/1-1, continuing...
[Oct 18 07:27:24] -- Executing [s@ServiceFeedback:6] AGI("DAHDI/1-1", "dial/servicefdbk.agi|gsm-----6000-----ServiceFeedback-----AutoDial") in new stack
[Oct 18 07:27:24] -- Launched AGI Script /var/lib/asterisk/agi-bin/dial/servicefdbk.agi
[Oct 18 07:27:24] AGI Tx >> agi_request: dial/servicefdbk.agi
[Oct 18 07:27:24] AGI Tx >> agi_channel: DAHDI/1-1
[Oct 18 07:27:24] AGI Tx >> agi_language: en
[Oct 18 07:27:24] AGI Tx >> agi_type: DAHDI
[Oct 18 07:27:24] AGI Tx >> agi_uniqueid: 1382061429.373
[Oct 18 07:27:24] AGI Tx >> agi_callerid: 0000000000
[Oct 18 07:27:24] AGI Tx >> agi_calleridname: V0180727090000000100
[Oct 18 07:27:24] AGI Tx >> agi_callingpres: 0
[Oct 18 07:27:24] AGI Tx >> agi_callingani2: 0
[Oct 18 07:27:24] AGI Tx >> agi_callington: 0
[Oct 18 07:27:24] AGI Tx >> agi_callingtns: 0
[Oct 18 07:27:24] AGI Tx >> agi_dnid: unknown
[Oct 18 07:27:24] AGI Tx >> agi_rdnis: unknown
[Oct 18 07:27:24] AGI Tx >> agi_context: ServiceFeedback
[Oct 18 07:27:24] AGI Tx >> agi_extension: s
[Oct 18 07:27:24] AGI Tx >> agi_priority: 6
[Oct 18 07:27:24] AGI Tx >> agi_enhanced: 0.0
[Oct 18 07:27:24] AGI Tx >> agi_accountcode:
[Oct 18 07:27:24] AGI Tx >>
[Oct 18 07:27:24] AGI Rx << GET DATA GSM/press1satifiedpress2notsatisfied 500 1
[Oct 18 07:27:24] -- <DAHDI/1-1> Playing 'GSM/press1satifiedpress2notsatisfied' (language 'en')
[Oct 18 07:27:26] DTMF[11321]: channel.c:2455 __ast_read: DTMF end '1' received on DAHDI/1-1, duration 0 ms
[Oct 18 07:27:26] DTMF[11321]: channel.c:2510 __ast_read: DTMF end accepted without begin '1' on DAHDI/1-1
[Oct 18 07:27:26] DTMF[11321]: channel.c:2521 __ast_read: DTMF end passthrough '1' on DAHDI/1-1
[Oct 18 07:27:26] AGI Tx >> 200 result=1
[Oct 18 07:27:26] AGI Rx << STREAM FILE GSM/ThankYou ""
[Oct 18 07:27:26] -- Playing 'GSM/ThankYou' (escape_digits=) (sample_offset 0)
[Oct 18 07:27:27] AGI Tx >> 200 result=0 endpos=7360
[Oct 18 07:27:27] AGI Rx << HANGUP
[Oct 18 07:27:27] AGI Tx >> 200 result=1
[Oct 18 07:27:27] DEBUG[11321]: res_agi.c:1938 run_agi: DAHDI/1-1 hungup
[Oct 18 07:27:27] == Spawn extension (ServiceFeedback, s, 6) exited non-zero on 'DAHDI/1-1'
[Oct 18 07:27:27] -- Executing [h@ServiceFeedback:1] DeadAGI("DAHDI/1-1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Oct 18 07:27:27] AGI Tx >> agi_network: yes
[Oct 18 07:27:27] AGI Tx >> agi_network_script: call_log--HVcauses--PRI-----NODEBUG-----0---------------
[Oct 18 07:27:27] AGI Tx >> agi_request: agi://127.0.0.1:4577/call_log--HVcauses ... ----------
[Oct 18 07:27:27] AGI Tx >> agi_channel: DAHDI/1-1
[Oct 18 07:27:27] AGI Tx >> agi_language: en
[Oct 18 07:27:27] AGI Tx >> agi_type: DAHDI
[Oct 18 07:27:27] AGI Tx >> agi_uniqueid: 1382061429.373
[Oct 18 07:27:27] AGI Tx >> agi_callerid: 0000000000
[Oct 18 07:27:27] AGI Tx >> agi_calleridname: V0180727090000000100
[Oct 18 07:27:27] AGI Tx >> agi_callingpres: 0
[Oct 18 07:27:27] AGI Tx >> agi_callingani2: 0
[Oct 18 07:27:27] AGI Tx >> agi_callington: 0
[Oct 18 07:27:27] AGI Tx >> agi_callingtns: 0
[Oct 18 07:27:27] AGI Tx >> agi_dnid: unknown
[Oct 18 07:27:27] AGI Tx >> agi_rdnis: unknown
[Oct 18 07:27:27] AGI Tx >> agi_context: ServiceFeedback
[Oct 18 07:27:27] AGI Tx >> agi_extension: h
[Oct 18 07:27:27] AGI Tx >> agi_priority: 1
[Oct 18 07:27:27] AGI Tx >> agi_enhanced: 0.0
[Oct 18 07:27:27] AGI Tx >> agi_accountcode:
[Oct 18 07:27:27] AGI Tx >>
[Oct 18 07:27:27] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Oct 18 07:27:27] DEBUG[11321]: chan_dahdi.c:4334 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on DAHDI/1-1
[Oct 18 07:27:27] DEBUG[11321]: chan_dahdi.c:3943 dahdi_hangup: Not yet hungup... Calling hangup once with icause, and clearing call
[Oct 18 07:27:27] DEBUG[11321]: chan_dahdi.c:4330 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on DAHDI/1-1
[Oct 18 07:27:27] -- Hungup 'DAHDI/1-1'

once again thanks mcargile