Incoming Call when Agent Logs In Auto Disconnecting

[ujwalmakhija]

Hello,

I have setup Vicidial 2.7rc1, freepbx 2.11.0.11 with Asterisk 1.8.23.

Freepbx Extensions are able to talk to each other, extn 201 can call 202 and they can speak. So can Vicidial phone cc101 with station 202 (of FreePBX). But we are facing a problem whenever the agent tries to login; here, immidiately upon answer of the incoming call, the call disconnects. Wireshark gives a BYE from server to asterisk agent (without any RTP packet at all). I checked, uLaw is enabled both on xlite and Vicidial Phone. SDP header also has the available codecs.

Asterisk logs are as below:
************************logs for incoming call to agent station.
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
> Channel SIP/cc101-0000000e was answered.
-- Executing [8600051@default:1] MeetMe("SIP/cc101-0000000e", "8600051,F") in new stack
== Parsing '/etc/asterisk/meetme.conf': == Found
== Parsing '/etc/asterisk/meetme_additional.conf': == Found
== Parsing '/etc/asterisk/meetme_vicidial.conf': == Found
== Parsing '/etc/asterisk/meetme-vicidial.conf': == Found
== Spawn extension (default, 8600051, 1) exited non-zero on 'SIP/cc101-0000000e'
-- Executing [h@default:1] AGI("SIP/cc101-0000000e", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
-- <SIP/cc101-0000000e>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
********************************************************Receive BYE from server and call disconnects.


************************call between 202 and cc101 works fine************************
[2013-10-16 16:37:27] NOTICE[2487]: chan_sip.c:13728 sip_reg_timeout: -- Registration for 'testcarrier@192.168.1.240' timed out, trying again (Attempt #96)
[2013-10-16 16:37:47] NOTICE[2487]: chan_sip.c:13728 sip_reg_timeout: -- Registration for 'testcarrier@192.168.1.240' timed out, trying again (Attempt #97)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
-- Executing [202@default:1] Set("SIP/cc101-0000000f", "__RINGTIMER=15") in new stack
-- Executing [202@default:2] Macro("SIP/cc101-0000000f", "exten-vm,novm,202,0,0,0") in new stack
-- Executing [s@macro-exten-vm:1] Macro("SIP/cc101-0000000f", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/cc101-0000000f", "TOUCH_MONITOR=1381921672.17") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/cc101-0000000f", "AMPUSER=0000000000") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/cc101-0000000f", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("SIP/cc101-0000000f", "1?Set(REALCALLERIDNUM=0000000000)") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/cc101-0000000f", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:6] Set("SIP/cc101-0000000f", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:7] GotoIf("SIP/cc101-0000000f", "1?report") in new stack
-- Goto (macro-user-callerid,s,14)
-- Executing [s@macro-user-callerid:14] GotoIf("SIP/cc101-0000000f", "0?continue") in new stack
-- Executing [s@macro-user-callerid:15] Set("SIP/cc101-0000000f", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:16] GotoIf("SIP/cc101-0000000f", "1?continue") in new stack
-- Goto (macro-user-callerid,s,27)
-- Executing [s@macro-user-callerid:27] Set("SIP/cc101-0000000f", "CALLERID(number)=0000000000") in new stack
-- Executing [s@macro-user-callerid:28] Set("SIP/cc101-0000000f", "CALLERID(name)=station 101") in new stack
-- Executing [s@macro-user-callerid:29] Set("SIP/cc101-0000000f", "CDR(cnum)=0000000000") in new stack
-- Executing [s@macro-user-callerid:30] Set("SIP/cc101-0000000f", "CDR(cnam)=station 101") in new stack
-- Executing [s@macro-user-callerid:31] Set("SIP/cc101-0000000f", "CHANNEL(language)=en") in new stack
-- Executing [s@macro-exten-vm:2] Set("SIP/cc101-0000000f", "RingGroupMethod=none") in new stack
-- Executing [s@macro-exten-vm:3] Set("SIP/cc101-0000000f", "__EXTTOCALL=202") in new stack
-- Executing [s@macro-exten-vm:4] Set("SIP/cc101-0000000f", "__PICKUPMARK=202") in new stack
-- Executing [s@macro-exten-vm:5] Set("SIP/cc101-0000000f", "RT=") in new stack
-- Executing [s@macro-exten-vm:6] Gosub("SIP/cc101-0000000f", "sub-record-check,s,1(exten,202,)") in new stack
-- Executing [s@sub-record-check:1] Set("SIP/cc101-0000000f", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:2] GotoIf("SIP/cc101-0000000f", "1?check") in new stack
-- Goto (sub-record-check,s,7)
-- Executing [s@sub-record-check:7] Set("SIP/cc101-0000000f", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:8] GotoIf("SIP/cc101-0000000f", "1?next") in new stack
-- Goto (sub-record-check,s,11)
-- Executing [s@sub-record-check:11] ExecIf("SIP/cc101-0000000f", "0?Return()") in new stack
-- Executing [s@sub-record-check:12] ExecIf("SIP/cc101-0000000f", "0?Set(__REC_POLICY_MODE=)") in new stack
-- Executing [s@sub-record-check:13] GotoIf("SIP/cc101-0000000f", "0?exten,1") in new stack
-- Executing [s@sub-record-check:14] Set("SIP/cc101-0000000f", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:15] Set("SIP/cc101-0000000f", "NOW=1381921672") in new stack
-- Executing [s@sub-record-check:16] Set("SIP/cc101-0000000f", "__DAY=16") in new stack
-- Executing [s@sub-record-check:17] Set("SIP/cc101-0000000f", "__MONTH=10") in new stack
-- Executing [s@sub-record-check:18] Set("SIP/cc101-0000000f", "__YEAR=2013") in new stack
-- Executing [s@sub-record-check:19] Set("SIP/cc101-0000000f", "__TIMESTR=20131016-163752") in new stack
-- Executing [s@sub-record-check:20] Set("SIP/cc101-0000000f", "__FROMEXTEN=0000000000") in new stack
-- Executing [s@sub-record-check:21] Set("SIP/cc101-0000000f", "__CALLFILENAME=exten-202-0000000000-20131016-163752-1381921672.17") in new stack
-- Executing [s@sub-record-check:22] Goto("SIP/cc101-0000000f", "exten,1") in new stack
-- Goto (sub-record-check,exten,1)
-- Executing [exten@sub-record-check:1] GotoIf("SIP/cc101-0000000f", "0?callee") in new stack
-- Executing [exten@sub-record-check:2] Set("SIP/cc101-0000000f", "__REC_POLICY_MODE=dontcare") in new stack
-- Executing [exten@sub-record-check:3] GotoIf("SIP/cc101-0000000f", "1?caller") in new stack
-- Goto (sub-record-check,exten,10)
-- Executing [exten@sub-record-check:10] Set("SIP/cc101-0000000f", "__REC_POLICY_MODE=") in new stack
-- Executing [exten@sub-record-check:11] GosubIf("SIP/cc101-0000000f", "0?record,1(exten,202,0000000000)") in new stack
-- Executing [exten@sub-record-check:12] Return("SIP/cc101-0000000f", "") in new stack
-- Executing [s@macro-exten-vm:7] Macro("SIP/cc101-0000000f", "dial-one,,Ttr,202") in new stack
-- Executing [s@macro-dial-one:1] Set("SIP/cc101-0000000f", "DEXTEN=202") in new stack
-- Executing [s@macro-dial-one:2] Set("SIP/cc101-0000000f", "DIALSTATUS_CW=") in new stack
-- Executing [s@macro-dial-one:3] GosubIf("SIP/cc101-0000000f", "0?screen,1()") in new stack
-- Executing [s@macro-dial-one:4] GosubIf("SIP/cc101-0000000f", "0?cf,1()") in new stack
-- Executing [s@macro-dial-one:5] GotoIf("SIP/cc101-0000000f", "1?skip1") in new stack
-- Goto (macro-dial-one,s,8)
-- Executing [s@macro-dial-one:8] GotoIf("SIP/cc101-0000000f", "0?nodial") in new stack
-- Executing [s@macro-dial-one:9] GotoIf("SIP/cc101-0000000f", "0?continue") in new stack
-- Executing [s@macro-dial-one:10] Set("SIP/cc101-0000000f", "EXTHASCW=ENABLED") in new stack
-- Executing [s@macro-dial-one:11] GotoIf("SIP/cc101-0000000f", "0?next1:cwinusebusy") in new stack
-- Goto (macro-dial-one,s,23)
-- Executing [s@macro-dial-one:23] GotoIf("SIP/cc101-0000000f", "1?next3:continue") in new stack
-- Goto (macro-dial-one,s,24)
-- Executing [s@macro-dial-one:24] ExecIf("SIP/cc101-0000000f", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
-- Executing [s@macro-dial-one:25] GotoIf("SIP/cc101-0000000f", "0?nodial") in new stack
-- Executing [s@macro-dial-one:26] GosubIf("SIP/cc101-0000000f", "1?dstring,1():dlocal,1()") in new stack
-- Executing [dstring@macro-dial-one:1] Set("SIP/cc101-0000000f", "DSTRING=") in new stack
-- Executing [dstring@macro-dial-one:2] Set("SIP/cc101-0000000f", "DEVICES=202") in new stack
-- Executing [dstring@macro-dial-one:3] ExecIf("SIP/cc101-0000000f", "0?Return()") in new stack
-- Executing [dstring@macro-dial-one:4] ExecIf("SIP/cc101-0000000f", "0?Set(DEVICES=02)") in new stack
-- Executing [dstring@macro-dial-one:5] Set("SIP/cc101-0000000f", "LOOPCNT=1") in new stack
-- Executing [dstring@macro-dial-one:6] Set("SIP/cc101-0000000f", "ITER=1") in new stack
-- Executing [dstring@macro-dial-one:7] Set("SIP/cc101-0000000f", "THISDIAL=SIP/202") in new stack
-- Executing [dstring@macro-dial-one:8] GosubIf("SIP/cc101-0000000f", "1?zap2dahdi,1()") in new stack
-- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/cc101-0000000f", "0?Return()") in new stack
-- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/cc101-0000000f", "NEWDIAL=") in new stack
-- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/cc101-0000000f", "LOOPCNT2=1") in new stack
-- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/cc101-0000000f", "ITER2=1") in new stack
-- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/cc101-0000000f", "THISPART2=SIP/202") in new stack
-- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/cc101-0000000f", "0?Set(THISPART2=DAHDI/202)") in new stack
-- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/cc101-0000000f", "NEWDIAL=SIP/202&") in new stack
-- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/cc101-0000000f", "ITER2=2") in new stack
-- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/cc101-0000000f", "0?begin2") in new stack
-- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/cc101-0000000f", "THISDIAL=SIP/202") in new stack
-- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/cc101-0000000f", "") in new stack
-- Executing [dstring@macro-dial-one:9] Set("SIP/cc101-0000000f", "DSTRING=SIP/202&") in new stack
-- Executing [dstring@macro-dial-one:10] Set("SIP/cc101-0000000f", "ITER=2") in new stack
-- Executing [dstring@macro-dial-one:11] GotoIf("SIP/cc101-0000000f", "0?begin") in new stack
-- Executing [dstring@macro-dial-one:12] Set("SIP/cc101-0000000f", "DSTRING=SIP/202") in new stack
-- Executing [dstring@macro-dial-one:13] Return("SIP/cc101-0000000f", "") in new stack
-- Executing [s@macro-dial-one:27] GotoIf("SIP/cc101-0000000f", "0?nodial") in new stack
-- Executing [s@macro-dial-one:28] GotoIf("SIP/cc101-0000000f", "0?skiptrace") in new stack
-- Executing [s@macro-dial-one:29] GosubIf("SIP/cc101-0000000f", "1?ctset,1():ctclear,1()") in new stack
-- Executing [ctset@macro-dial-one:1] Set("SIP/cc101-0000000f", "DB(CALLTRACE/202)=0000000000") in new stack
-- Executing [ctset@macro-dial-one:2] Return("SIP/cc101-0000000f", "") in new stack
-- Executing [s@macro-dial-one:30] Set("SIP/cc101-0000000f", "D_OPTIONS=Ttr") in new stack
-- Executing [s@macro-dial-one:31] ExecIf("SIP/cc101-0000000f", "0?SIPAddHeader(Alert-Info: )") in new stack
-- Executing [s@macro-dial-one:32] ExecIf("SIP/cc101-0000000f", "0?SIPAddHeader()") in new stack
-- Executing [s@macro-dial-one:33] ExecIf("SIP/cc101-0000000f", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [s@macro-dial-one:34] GosubIf("SIP/cc101-0000000f", "0?qwait,1()") in new stack
-- Executing [s@macro-dial-one:35] Set("SIP/cc101-0000000f", "__CWIGNORE=") in new stack
-- Executing [s@macro-dial-one:36] Set("SIP/cc101-0000000f", "__KEEPCID=TRUE") in new stack
-- Executing [s@macro-dial-one:37] GotoIf("SIP/cc101-0000000f", "0?usegoto,1") in new stack
-- Executing [s@macro-dial-one:38] GotoIf("SIP/cc101-0000000f", "1?godial") in new stack
-- Goto (macro-dial-one,s,42)
-- Executing [s@macro-dial-one:42] Dial("SIP/cc101-0000000f", "SIP/202,,Ttr") in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
-- Called SIP/202
-- SIP/202-00000010 is ringing
-- SIP/202-00000010 is ringing
-- SIP/202-00000010 answered SIP/cc101-0000000f
[2013-10-16 16:37:57] DEBUG[19974]: channel.c:6390 ast_set_owners_and_peers: setting peeraccount to cc101 for SIP/202-00000010 from data on channel SIP/cc101-0000000f
[2013-10-16 16:37:57] DEBUG[19974]: channel.c:6395 ast_set_owners_and_peers: setting peeraccount to cc101 for SIP/cc101-0000000f from data on channel SIP/202-00000010
-- Executing [h@macro-dial-one:1] Macro("SIP/cc101-0000000f", "hangupcall,") in new stack
-- Executing [s@macro-hangupcall:1] GotoIf("SIP/cc101-0000000f", "1?theend") in new stack
-- Goto (macro-hangupcall,s,3)
-- Executing [s@macro-hangupcall:3] ExecIf("SIP/cc101-0000000f", "0?Set(CDR(recordingfile)=)") in new stack
-- Executing [s@macro-hangupcall:4] Hangup("SIP/cc101-0000000f", "") in new stack
== Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/cc101-0000000f' in macro 'hangupcall'
== Spawn extension (macro-dial-one, h, 1) exited non-zero on 'SIP/cc101-0000000f'
== Spawn extension (macro-dial-one, s, 42) exited non-zero on 'SIP/cc101-0000000f' in macro 'dial-one'
== Spawn extension (macro-exten-vm, s, 7) exited non-zero on 'SIP/cc101-0000000f' in macro 'exten-vm'
== Spawn extension (default, 202, 2) exited non-zero on 'SIP/cc101-0000000f'


Any advise please?

Thanks.

[ujwalmakhija]

Here's the FastAGiout log:
2013-10-16 17:56:28|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2013-10-16 17:56:28|VDfastAGI|begin|Perl Environment Dump:
2013-10-16 17:56:28|VDfastAGI|begin|0|--debug
2013-10-16 17:56:28|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-10-16 17:56:28|VDfastAGI|begin|AGI Environment Dump:
2013-10-16 17:56:28|VDfastAGI|begin| -- accountcode =
2013-10-16 17:56:28|VDfastAGI|begin| -- callerid = 0000000000
2013-10-16 17:56:28|VDfastAGI|begin| -- calleridname = ACagcW1381926312101101101101
2013-10-16 17:56:28|VDfastAGI|begin| -- callingani2 = 0
2013-10-16 17:56:28|VDfastAGI|begin| -- callingpres = 0
2013-10-16 17:56:28|VDfastAGI|begin| -- callingtns = 0
2013-10-16 17:56:28|VDfastAGI|begin| -- callington = 0
2013-10-16 17:56:28|VDfastAGI|begin| -- channel = SIP/cc102-0000001f
2013-10-16 17:56:28|VDfastAGI|begin| -- context = default
2013-10-16 17:56:28|VDfastAGI|begin| -- dnid = unknown
2013-10-16 17:56:28|VDfastAGI|begin| -- enhanced = 0.0
2013-10-16 17:56:28|VDfastAGI|begin| -- extension = h
2013-10-16 17:56:28|VDfastAGI|begin| -- language = en
2013-10-16 17:56:28|VDfastAGI|begin| -- network = yes
2013-10-16 17:56:28|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2013-10-16 17:56:28|VDfastAGI|begin| -- priority = 1
2013-10-16 17:56:28|VDfastAGI|begin| -- rdnis = unknown
2013-10-16 17:56:28|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2013-10-16 17:56:28|VDfastAGI|begin| -- threadid = -1231398032
2013-10-16 17:56:28|VDfastAGI|begin| -- type = SIP
2013-10-16 17:56:28|VDfastAGI|begin| -- uniqueid = 1381926385.35
2013-10-16 17:56:28|VDfastAGI|begin| -- version = 1.8.23.1
2013-10-16 17:56:28|VDfastAGI|begin|AGI Variables: |1381926385.35|SIP/cc102-0000001f|h|SIP|ACagcW1381926312101101101101|
2013-10-16 17:56:28|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2013-10-16 17:56:28|VDfastAGI|call_log||CALL HUNG UP|
2013-10-16 17:56:28|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|||0|
2013-10-16 17:56:28|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1381926385.35','1381926385.35') and server_ip='192.168.1.232'|
2013-10-16 17:56:28|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1381926385.35|SIP/cc102-0000001f|h|2013-10-16 17:56:28|min: |
2013-10-16 17:56:28|VDfastAGI|call_log|DEBUG: NODEBUG
2013-10-16 17:56:28|VDfastAGI|call_log|VD_hangup : ACagcW1381926312101101101101 SIP/cc102-0000001f 1 9263121011
2013-10-16 17:56:28|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 = '1381926385.35' or callerid = 'ACagcW1381926312101101101101' limit 1;|
2013-10-16 17:56:28|VDfastAGI|call_log|VD hangup: no VDAC record found: 1381926385.35 ACagcW1381926312101101101101