ATA not ringing the phone

ledude · September 24, 2013, 11:23pm

Hi all.

I have this random problem that just confuse the heck out of me. My incoming sometime ring my ATA box but most of the time just throw the caller into voicemail. Here is my log.

Calling to: 206-555-1212
Calling from: 206-555-1234

Freepbx: 2.11
Asterisk 11.
OS: Centos 6.4 64 Bit
ATA: Handytone 286

I’m speculating this has something to do with the setting in the ATA but I’m not quite sure. Is there anything else I need to provide to help me debug this issue? Please help? Many thanks.


Connected to Asterisk 11.4.0 currently running on myfreepbx (pid = 23168)
 == Using SIP RTP TOS bits 184
 == Using SIP RTP CoS mark 5
 -- Executing [2065551212@from-trunk:1] Set("SIP/2065551212_VOIPO-00000000", "__FROM_DID=2065551212") in new stack
 -- Executing [2065551212@from-trunk:2] Gosub("SIP/2065551212_VOIPO-00000000", "app-blacklist-check,s,1()") in new stack
 -- Executing [s@app-blacklist-check:1] GotoIf("SIP/2065551212_VOIPO-00000000", "0?blacklisted") in new stack
 -- Executing [s@app-blacklist-check:2] Set("SIP/2065551212_VOIPO-00000000", "CALLED_BLACKLIST=1") in new stack
 -- Executing [s@app-blacklist-check:3] Return("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [2065551212@from-trunk:3] Set("SIP/2065551212_VOIPO-00000000", "CIDSFSCHEME=QUxMfEFMTA==") in new stack
 -- Executing [2065551212@from-trunk:4] AGI("SIP/2065551212_VOIPO-00000000", "/var/www/html/admin/modules/superfecta/agi/superfecta.agi") in new stack
 -- Launched AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta is Answering the Channel
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Scheme is ALL
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The DID passed from Asterisk is: 2065551212
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The number passed from Asterisk is: 2065551234
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The CID name passed from Asterisk is: SEATTLE WA
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Executing Scheme..
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: CID Determined to be: 'SEATTLE WA'
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Attempting to set lookupcid
 /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Success!
 -- AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi completed, returning 0
 -- Executing [2065551212@from-trunk:5] Set("SIP/2065551212_VOIPO-00000000", "CALLERID(name)=SEATTLE WA") in new stack
 -- Executing [2065551212@from-trunk:6] Set("SIP/2065551212_VOIPO-00000000", "CDR(did)=2065551212") in new stack
 -- Executing [2065551212@from-trunk:7] ExecIf("SIP/2065551212_VOIPO-00000000", "0 ?Set(CALLERID(name)=2065551234)") in new stack
[2013-09-24 16:09:56] WARNING[23229][C-00000000]: func_callerid.c:905 callerpres_read: CALLERPRES is deprecated. Use CALLERID(name-pres) or CALLERID(num-pres) instead.
 -- Executing [2065551212@from-trunk:8] Set("SIP/2065551212_VOIPO-00000000", "__CALLINGPRES_SV=allowed_not_screened") in new stack
 -- Executing [2065551212@from-trunk:9] Set("SIP/2065551212_VOIPO-00000000", "CALLERPRES()=allowed_not_screened") in new stack
 -- Executing [2065551212@from-trunk:10] Goto("SIP/2065551212_VOIPO-00000000", "from-did-direct,8881,1") in new stack
 -- Goto (from-did-direct,8881,1)
 -- Executing [8881@from-did-direct:1] Set("SIP/2065551212_VOIPO-00000000", "__RINGTIMER=28") in new stack
 -- Executing [8881@from-did-direct:2] Macro("SIP/2065551212_VOIPO-00000000", "exten-vm,8881,8881,0,0,0") in new stack
 -- Executing [s@macro-exten-vm:1] Macro("SIP/2065551212_VOIPO-00000000", "user-callerid,") in new stack
 -- Executing [s@macro-user-callerid:1] Set("SIP/2065551212_VOIPO-00000000", "TOUCH_MONITOR=1380064195.0") in new stack
 -- Executing [s@macro-user-callerid:2] Set("SIP/2065551212_VOIPO-00000000", "AMPUSER=2065551234") in new stack
 -- Executing [s@macro-user-callerid:3] GotoIf("SIP/2065551212_VOIPO-00000000", "0?report") in new stack
 -- Executing [s@macro-user-callerid:4] ExecIf("SIP/2065551212_VOIPO-00000000", "1?Set(REALCALLERIDNUM=2065551234)") in new stack
 -- Executing [s@macro-user-callerid:5] Set("SIP/2065551212_VOIPO-00000000", "AMPUSER=") in new stack
 -- Executing [s@macro-user-callerid:6] Set("SIP/2065551212_VOIPO-00000000", "AMPUSERCIDNAME=") in new stack
 -- Executing [s@macro-user-callerid:7] GotoIf("SIP/2065551212_VOIPO-00000000", "1?report") in new stack
 -- Goto (macro-user-callerid,s,15)
 -- Executing [s@macro-user-callerid:15] GotoIf("SIP/2065551212_VOIPO-00000000", "0?continue") in new stack
 -- Executing [s@macro-user-callerid:16] Set("SIP/2065551212_VOIPO-00000000", "__TTL=64") in new stack
 -- Executing [s@macro-user-callerid:17] GotoIf("SIP/2065551212_VOIPO-00000000", "1?continue") in new stack
 -- Goto (macro-user-callerid,s,28)
 -- Executing [s@macro-user-callerid:28] Set("SIP/2065551212_VOIPO-00000000", "CALLERID(number)=2065551234") in new stack
 -- Executing [s@macro-user-callerid:29] Set("SIP/2065551212_VOIPO-00000000", "CALLERID(name)=SEATTLE WA") in new stack
 -- Executing [s@macro-user-callerid:30] Set("SIP/2065551212_VOIPO-00000000", "CDR(cnum)=2065551234") in new stack
 -- Executing [s@macro-user-callerid:31] Set("SIP/2065551212_VOIPO-00000000", "CDR(cnam)=SEATTLE WA") in new stack
 -- Executing [s@macro-user-callerid:32] Set("SIP/2065551212_VOIPO-00000000", "CHANNEL(language)=en") in new stack
 -- Executing [s@macro-exten-vm:2] Set("SIP/2065551212_VOIPO-00000000", "RingGroupMethod=none") in new stack
 -- Executing [s@macro-exten-vm:3] Set("SIP/2065551212_VOIPO-00000000", "__EXTTOCALL=8881") in new stack
 -- Executing [s@macro-exten-vm:4] Set("SIP/2065551212_VOIPO-00000000", "__PICKUPMARK=8881") in new stack
 -- Executing [s@macro-exten-vm:5] Set("SIP/2065551212_VOIPO-00000000", "RT=28") in new stack
 -- Executing [s@macro-exten-vm:6] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Macro(vm,8881,DIRECTDIAL,)") in new stack
 -- Executing [s@macro-exten-vm:7] ExecIf("SIP/2065551212_VOIPO-00000000", "0?MacroExit()") in new stack
 -- Executing [s@macro-exten-vm:8] Gosub("SIP/2065551212_VOIPO-00000000", "sub-record-check,s,1(exten,8881,)") in new stack
 -- Executing [s@sub-record-check:1] Set("SIP/2065551212_VOIPO-00000000", "REC_POLICY_MODE_SAVE=") in new stack
 -- Executing [s@sub-record-check:2] GotoIf("SIP/2065551212_VOIPO-00000000", "1?check") in new stack
 -- Goto (sub-record-check,s,7)
 -- Executing [s@sub-record-check:7] Set("SIP/2065551212_VOIPO-00000000", "__MON_FMT=wav") in new stack
 -- Executing [s@sub-record-check:8] GotoIf("SIP/2065551212_VOIPO-00000000", "1?next") in new stack
 -- Goto (sub-record-check,s,11)
 -- Executing [s@sub-record-check:11] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Return()") in new stack
 -- Executing [s@sub-record-check:12] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(__REC_POLICY_MODE=)") in new stack
 -- Executing [s@sub-record-check:13] GotoIf("SIP/2065551212_VOIPO-00000000", "0?exten,1") in new stack
 -- Executing [s@sub-record-check:14] Set("SIP/2065551212_VOIPO-00000000", "__REC_STATUS=INITIALIZED") in new stack
 -- Executing [s@sub-record-check:15] Set("SIP/2065551212_VOIPO-00000000", "NOW=1380064196") in new stack
 -- Executing [s@sub-record-check:16] Set("SIP/2065551212_VOIPO-00000000", "__DAY=24") in new stack
 -- Executing [s@sub-record-check:17] Set("SIP/2065551212_VOIPO-00000000", "__MONTH=09") in new stack
 -- Executing [s@sub-record-check:18] Set("SIP/2065551212_VOIPO-00000000", "__YEAR=2013") in new stack
 -- Executing [s@sub-record-check:19] Set("SIP/2065551212_VOIPO-00000000", "__TIMESTR=20130924-160956") in new stack
 -- Executing [s@sub-record-check:20] Set("SIP/2065551212_VOIPO-00000000", "__FROMEXTEN=2065551234") in new stack
 -- Executing [s@sub-record-check:21] Set("SIP/2065551212_VOIPO-00000000", "__CALLFILENAME=exten-8881-2065551234-20130924-160956-1380064195.0") in new stack
 -- Executing [s@sub-record-check:22] Goto("SIP/2065551212_VOIPO-00000000", "exten,1") in new stack
 -- Goto (sub-record-check,exten,1)
 -- Executing [exten@sub-record-check:1] GotoIf("SIP/2065551212_VOIPO-00000000", "0?callee") in new stack
 -- Executing [exten@sub-record-check:2] Set("SIP/2065551212_VOIPO-00000000", "__REC_POLICY_MODE=dontcare") in new stack
 -- Executing [exten@sub-record-check:3] GotoIf("SIP/2065551212_VOIPO-00000000", "1?caller") in new stack
 -- Goto (sub-record-check,exten,10)
 -- Executing [exten@sub-record-check:10] Set("SIP/2065551212_VOIPO-00000000", "__REC_POLICY_MODE=") in new stack
 -- Executing [exten@sub-record-check:11] GosubIf("SIP/2065551212_VOIPO-00000000", "0?record,1(exten,8881,2065551234)") in new stack
 -- Executing [exten@sub-record-check:12] Return("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s@macro-exten-vm:9] GotoIf("SIP/2065551212_VOIPO-00000000", "1?macrodial") in new stack
 -- Goto (macro-exten-vm,s,15)
 -- Executing [s@macro-exten-vm:15] GosubIf("SIP/2065551212_VOIPO-00000000", "0?clrheader,1()") in new stack
 -- Executing [s@macro-exten-vm:16] Macro("SIP/2065551212_VOIPO-00000000", "dial-one,28,Ttr,8881") in new stack
 -- Executing [s@macro-dial-one:1] Set("SIP/2065551212_VOIPO-00000000", "DEXTEN=8881") in new stack
 -- Executing [s@macro-dial-one:2] Set("SIP/2065551212_VOIPO-00000000", "DIALSTATUS_CW=") in new stack
 -- Executing [s@macro-dial-one:3] GosubIf("SIP/2065551212_VOIPO-00000000", "0?screen,1()") in new stack
 -- Executing [s@macro-dial-one:4] GosubIf("SIP/2065551212_VOIPO-00000000", "0?cf,1()") in new stack
 -- Executing [s@macro-dial-one:5] GotoIf("SIP/2065551212_VOIPO-00000000", "1?skip1") in new stack
 -- Goto (macro-dial-one,s,8)
 -- Executing [s@macro-dial-one:8] GotoIf("SIP/2065551212_VOIPO-00000000", "0?nodial") in new stack
 -- Executing [s@macro-dial-one:9] GotoIf("SIP/2065551212_VOIPO-00000000", "0?continue") in new stack
 -- Executing [s@macro-dial-one:10] Set("SIP/2065551212_VOIPO-00000000", "EXTHASCW=ENABLED") in new stack
 -- Executing [s@macro-dial-one:11] GotoIf("SIP/2065551212_VOIPO-00000000", "0?next1:cwinusebusy") in new stack
 -- Goto (macro-dial-one,s,23)
 -- Executing [s@macro-dial-one:23] GotoIf("SIP/2065551212_VOIPO-00000000", "1?next3:continue") in new stack
 -- Goto (macro-dial-one,s,24)
 -- Executing [s@macro-dial-one:24] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
 -- Executing [s@macro-dial-one:25] GotoIf("SIP/2065551212_VOIPO-00000000", "0?nodial") in new stack
 -- Executing [s@macro-dial-one:26] GosubIf("SIP/2065551212_VOIPO-00000000", "1?dstring,1():dlocal,1()") in new stack
 -- Executing [dstring@macro-dial-one:1] Set("SIP/2065551212_VOIPO-00000000", "DSTRING=") in new stack
 -- Executing [dstring@macro-dial-one:2] Set("SIP/2065551212_VOIPO-00000000", "DEVICES=8881") in new stack
 -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Return()") in new stack
 -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(DEVICES=881)") in new stack
 -- Executing [dstring@macro-dial-one:5] Set("SIP/2065551212_VOIPO-00000000", "LOOPCNT=1") in new stack
 -- Executing [dstring@macro-dial-one:6] Set("SIP/2065551212_VOIPO-00000000", "ITER=1") in new stack
 -- Executing [dstring@macro-dial-one:7] Set("SIP/2065551212_VOIPO-00000000", "THISDIAL=SIP/8881") in new stack
 -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/2065551212_VOIPO-00000000", "1?zap2dahdi,1()") in new stack
 -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Return()") in new stack
 -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/2065551212_VOIPO-00000000", "NEWDIAL=") in new stack
 -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/2065551212_VOIPO-00000000", "LOOPCNT2=1") in new stack
 -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/2065551212_VOIPO-00000000", "ITER2=1") in new stack
 -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/2065551212_VOIPO-00000000", "THISPART2=SIP/8881") in new stack
 -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(THISPART2=DAHDI/8881)") in new stack
 -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/2065551212_VOIPO-00000000", "NEWDIAL=SIP/8881&") in new stack
 -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/2065551212_VOIPO-00000000", "ITER2=2") in new stack
 -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/2065551212_VOIPO-00000000", "0?begin2") in new stack
 -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/2065551212_VOIPO-00000000", "THISDIAL=SIP/8881") in new stack
 -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [dstring@macro-dial-one:9] Set("SIP/2065551212_VOIPO-00000000", "DSTRING=SIP/8881&") in new stack
 -- Executing [dstring@macro-dial-one:10] Set("SIP/2065551212_VOIPO-00000000", "ITER=2") in new stack
 -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/2065551212_VOIPO-00000000", "0?begin") in new stack
 -- Executing [dstring@macro-dial-one:12] Set("SIP/2065551212_VOIPO-00000000", "DSTRING=SIP/8881") in new stack
 -- Executing [dstring@macro-dial-one:13] Return("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s@macro-dial-one:27] GotoIf("SIP/2065551212_VOIPO-00000000", "0?nodial") in new stack
 -- Executing [s@macro-dial-one:28] GotoIf("SIP/2065551212_VOIPO-00000000", "0?skiptrace") in new stack
 -- Executing [s@macro-dial-one:29] GosubIf("SIP/2065551212_VOIPO-00000000", "1?ctset,1():ctclear,1()") in new stack
 -- Executing [ctset@macro-dial-one:1] Set("SIP/2065551212_VOIPO-00000000", "DB(CALLTRACE/8881)=2065551234") in new stack
 -- Executing [ctset@macro-dial-one:2] Return("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s@macro-dial-one:30] Set("SIP/2065551212_VOIPO-00000000", "D_OPTIONS=Ttr") in new stack
 -- Executing [s@macro-dial-one:31] ExecIf("SIP/2065551212_VOIPO-00000000", "0?SIPAddHeader(Alert-Info: )") in new stack
 -- Executing [s@macro-dial-one:32] ExecIf("SIP/2065551212_VOIPO-00000000", "0?SIPAddHeader()") in new stack
 -- Executing [s@macro-dial-one:33] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(CHANNEL(musicclass)=)") in new stack
 -- Executing [s@macro-dial-one:34] GosubIf("SIP/2065551212_VOIPO-00000000", "0?qwait,1()") in new stack
 -- Executing [s@macro-dial-one:35] Set("SIP/2065551212_VOIPO-00000000", "__CWIGNORE=") in new stack
 -- Executing [s@macro-dial-one:36] Set("SIP/2065551212_VOIPO-00000000", "__KEEPCID=TRUE") in new stack
 -- Executing [s@macro-dial-one:37] GotoIf("SIP/2065551212_VOIPO-00000000", "0?usegoto,1") in new stack
 -- Executing [s@macro-dial-one:38] GotoIf("SIP/2065551212_VOIPO-00000000", "1?godial") in new stack
 -- Goto (macro-dial-one,s,42)
 -- Executing [s@macro-dial-one:42] Dial("SIP/2065551212_VOIPO-00000000", "SIP/8881,28,Ttr") in new stack
 == Using SIP RTP TOS bits 184
 == Using SIP RTP CoS mark 5
 -- Called SIP/8881
 == Everyone is busy/congested at this time (1:0/0/1)
 -- Executing [s@macro-dial-one:43] ExecIf("SIP/2065551212_VOIPO-00000000", "0?MacroExit()") in new stack
 -- Executing [s@macro-dial-one:44] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(DIALSTATUS=)") in new stack
 -- Executing [s@macro-dial-one:45] GosubIf("SIP/2065551212_VOIPO-00000000", "0?s-CHANUNAVAIL,1()") in new stack
 -- Executing [s@macro-dial-one:46] MacroExit("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s@macro-exten-vm:17] Set("SIP/2065551212_VOIPO-00000000", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
 -- Executing [s@macro-exten-vm:18] GosubIf("SIP/2065551212_VOIPO-00000000", "0?docfu,1()") in new stack
 -- Executing [s@macro-exten-vm:19] GosubIf("SIP/2065551212_VOIPO-00000000", "0?docfb,1()") in new stack
 -- Executing [s@macro-exten-vm:20] Set("SIP/2065551212_VOIPO-00000000", "DIALSTATUS=CHANUNAVAIL") in new stack
 -- Executing [s@macro-exten-vm:21] ExecIf("SIP/2065551212_VOIPO-00000000", "0?MacroExit()") in new stack
 -- Executing [s@macro-exten-vm:22] GotoIf("SIP/2065551212_VOIPO-00000000", "0?s-CHANUNAVAIL,1") in new stack
 -- Executing [s@macro-exten-vm:23] Macro("SIP/2065551212_VOIPO-00000000", "vm,8881,CHANUNAVAIL,") in new stack
 -- Executing [s@macro-vm:1] Macro("SIP/2065551212_VOIPO-00000000", "user-callerid,SKIPTTL") in new stack
 -- Executing [s@macro-user-callerid:1] Set("SIP/2065551212_VOIPO-00000000", "TOUCH_MONITOR=1380064195.0") in new stack
 -- Executing [s@macro-user-callerid:2] Set("SIP/2065551212_VOIPO-00000000", "AMPUSER=2065551234") in new stack
 -- Executing [s@macro-user-callerid:3] GotoIf("SIP/2065551212_VOIPO-00000000", "0?report") in new stack
 -- Executing [s@macro-user-callerid:4] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(REALCALLERIDNUM=2065551234)") in new stack
 -- Executing [s@macro-user-callerid:5] Set("SIP/2065551212_VOIPO-00000000", "AMPUSER=") in new stack
 -- Executing [s@macro-user-callerid:6] Set("SIP/2065551212_VOIPO-00000000", "AMPUSERCIDNAME=") in new stack
 -- Executing [s@macro-user-callerid:7] GotoIf("SIP/2065551212_VOIPO-00000000", "1?report") in new stack
 -- Goto (macro-user-callerid,s,15)
 -- Executing [s@macro-user-callerid:15] GotoIf("SIP/2065551212_VOIPO-00000000", "1?continue") in new stack
 -- Goto (macro-user-callerid,s,28)
 -- Executing [s@macro-user-callerid:28] Set("SIP/2065551212_VOIPO-00000000", "CALLERID(number)=2065551234") in new stack
 -- Executing [s@macro-user-callerid:29] Set("SIP/2065551212_VOIPO-00000000", "CALLERID(name)=SEATTLE WA") in new stack
 -- Executing [s@macro-user-callerid:30] Set("SIP/2065551212_VOIPO-00000000", "CDR(cnum)=2065551234") in new stack
 -- Executing [s@macro-user-callerid:31] Set("SIP/2065551212_VOIPO-00000000", "CDR(cnam)=SEATTLE WA") in new stack
 -- Executing [s@macro-user-callerid:32] Set("SIP/2065551212_VOIPO-00000000", "CHANNEL(language)=en") in new stack
 -- Executing [s@macro-vm:2] Set("SIP/2065551212_VOIPO-00000000", "VMGAIN=") in new stack
 -- Executing [s@macro-vm:3] Macro("SIP/2065551212_VOIPO-00000000", "blkvm-check,") in new stack
 -- Executing [s@macro-blkvm-check:1] Set("SIP/2065551212_VOIPO-00000000", "GOSUB_RETVAL=") in new stack
 -- Executing [s@macro-blkvm-check:2] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
 -- Executing [s@macro-blkvm-check:3] MacroExit("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s@macro-vm:4] GotoIf("SIP/2065551212_VOIPO-00000000", "1?vmx,1") in new stack
 -- Goto (macro-vm,vmx,1)
 -- Executing [vmx@macro-vm:1] Set("SIP/2065551212_VOIPO-00000000", "MEXTEN=8881") in new stack
 -- Executing [vmx@macro-vm:2] Set("SIP/2065551212_VOIPO-00000000", "MMODE=CHANUNAVAIL") in new stack
 -- Executing [vmx@macro-vm:3] Set("SIP/2065551212_VOIPO-00000000", "RETVM=") in new stack
 -- Executing [vmx@macro-vm:4] Set("SIP/2065551212_VOIPO-00000000", "MODE=unavail") in new stack
 -- Executing [vmx@macro-vm:5] GotoIf("SIP/2065551212_VOIPO-00000000", "1?chknomsg") in new stack
 -- Goto (macro-vm,vmx,7)
 -- Executing [vmx@macro-vm:7] GotoIf("SIP/2065551212_VOIPO-00000000", "0?s-CHANUNAVAIL,1") in new stack
 -- Executing [vmx@macro-vm:8] GotoIf("SIP/2065551212_VOIPO-00000000", "1?notdirect") in new stack
 -- Goto (macro-vm,vmx,10)
 -- Executing [vmx@macro-vm:10] NoOp("SIP/2065551212_VOIPO-00000000", "Checking if ext 8881 is enabled: ") in new stack
 -- Executing [vmx@macro-vm:11] GotoIf("SIP/2065551212_VOIPO-00000000", "1?s-CHANUNAVAIL,1") in new stack
 -- Goto (macro-vm,s-CHANUNAVAIL,1)
 -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/2065551212_VOIPO-00000000", "get-vmcontext,8881") in new stack
 -- Executing [s@macro-get-vmcontext:1] Set("SIP/2065551212_VOIPO-00000000", "VMCONTEXT=default") in new stack
 -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/2065551212_VOIPO-00000000", "0?200:300") in new stack
 -- Goto (macro-get-vmcontext,s,300)
 -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/2065551212_VOIPO-00000000", "") in new stack
 -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/2065551212_VOIPO-00000000", "8881@default,u") in new stack
 --  Playing 'vm-theperson.ulaw' (language 'en')
 --  Playing 'digits/8.ulaw' (language 'en')
 --  Playing 'digits/8.ulaw' (language 'en')
 --  Playing 'digits/8.ulaw' (language 'en')
 --  Playing 'digits/1.ulaw' (language 'en')
 --  Playing 'vm-isunavail.ulaw' (language 'en')
 --  Playing 'vm-intro.ulaw' (language 'en')
 == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/2065551212_VOIPO-00000000' in macro 'vm'
 == Spawn extension (macro-exten-vm, s, 23) exited non-zero on 'SIP/2065551212_VOIPO-00000000' in macro 'exten-vm'
 == Spawn extension (from-did-direct, 8881, 2) exited non-zero on 'SIP/2065551212_VOIPO-00000000'
 -- Executing [h@from-did-direct:1] Macro("SIP/2065551212_VOIPO-00000000", "hangupcall,") in new stack
 -- Executing [s@macro-hangupcall:1] GotoIf("SIP/2065551212_VOIPO-00000000", "1?theend") in new stack
 -- Goto (macro-hangupcall,s,3)
 -- Executing [s@macro-hangupcall:3] ExecIf("SIP/2065551212_VOIPO-00000000", "0?Set(CDR(recordingfile)=)") in new stack
 -- Executing [s@macro-hangupcall:4] Hangup("SIP/2065551212_VOIPO-00000000", "") in new stack
 == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/2065551212_VOIPO-00000000' in macro 'hangupcall'
 == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/2065551212_VOIPO-00000000'

dicko · September 24, 2013, 11:38pm

These logs just say that your called ended up trying a sip connection to 8881, it apparently was apparently “busy/congested” so it went to voicemail.

ledude · September 25, 2013, 12:50am

Thanks Dicko. So how can it be busy/congested when no one else is using it? Is there anything in the system that can cause it to be treated as busy? Anything I need to watch or reset? I restart the amportal many times already to no avail. Pls advise?

dicko · September 25, 2013, 2:13am

8881 will be considered busy/unavailable for many reasons, if it is not off-hook and has call waiting enabled , then

sip show peers

or more specifically

sip show peer 8881

from the asterisk CLI will help you diagnose.

ledude · September 25, 2013, 4:42am

Thanks dicko.

This is what I gather from sip show peer 8881. Not sure how to decode it. Pls advise? Many thanks in advance again for all of your help?


Name       : 8881
  Description  :
  Secret       : 
  MD5Secret    : 
  Remote Secret: 
  Context      : from-internal
  Record On feature : automon
  Record Off feature : automon
  Subscr.Cont. : 
  Language     :
  Tonezone     : 
  AMA flags    : Unknown
  Transfer mode: open
  CallingPres  : Presentation Allowed, Not Screened
  Callgroup    :
  Pickupgroup  :
  Named Callgr :
  Nam. Pickupgr:
  MOH Suggest  :
  Mailbox      : 8881@default
  VM Extension : *97
  LastMsgsSent : 0/0
  Call limit   : 2147483647
  Max forwards : 0
  Dynamic      : Yes
  Callerid     : 2065551212
  MaxCallBR    : 384 kbps
  Expire       : 1146
  Insecure     : no
  Force rport  : Yes
  Symmetric RTP: Yes
  ACL          : Yes
  DirectMedACL : No
  T.38 support : No
  T.38 EC mode : Unknown
  T.38 MaxDtgrm: -1
  DirectMedia  : No
  PromiscRedir : No
  User=Phone   : No
  Video Support: No
  Text Support : No
  Ign SDP ver  : No
  Trust RPID   : Yes
  Send RPID    : No
  Subscriptions: Yes
  Overlap dial : Yes
  DTMFmode     : rfc2833
  Timer T1     : 500
  Timer B      : 32000
  ToHost       :
  Addr->IP     : 50.47.0.193:5070
  Defaddr->IP  : (null)
  Prim.Transp. : UDP
  Allowed.Trsp : UDP
  Def. Username: 25384617
  SIP Options  : (none)
  Codecs       : (g723|gsm|ulaw|alaw|g726)
  Codec Order  : (ulaw:20,alaw:20,gsm:20,g723:30,g726:20)
  Auto-Framing :  No
  Status       : Unmonitored
  Useragent    : Grandstream HT286 1.0.6.7
  Reg. Contact : sip:[email protected]:5070
  Qualify Freq : 30000 ms
  Keepalive    : 0 ms
  Sess-Timers  : Accept
  Sess-Refresh : uas
  Sess-Expires : 1800 secs
  Min-Sess     : 90 secs
  RTP Engine   : asterisk
  Parkinglot   :
  Use Reason   : No
  Encryption   : No

ledude · September 26, 2013, 1:19am

It’s still happening. all of sudden it works once, then after that, none. Phone never ring, straight to VM. Sounds like something get stuck once a phone call comes in, picked up and hung up. But the status never reset to available. Is there anyway I can check? Please help?

dicko · September 26, 2013, 2:02am

I notice that your endpoint is using SIP registration over 5070, is your server in agreement on that extension?

ledude · September 26, 2013, 2:18am

Yes it does. I open up port 5070 on the server and my ATA end. If firewall is the issue, doesn’t explain why sometime it works sometime it doesn’t though. Thanks dicko.

dicko · September 26, 2013, 2:23am

Do you have any form of “sip helper” on your firewall, rarely are the helpful

ledude · September 26, 2013, 3:12am

Not that I know of dicko. Just a standard iptables that comes with centos 6.4 64bit. Out of curiosity.
Also, I just noticed this a minute ago. I have my ata and softphone connected to the 8881 extension. I have my softphone ringing just now but not my ata. Is it possible that freepbx might get confused and it only rang one or the others? [size= 15px; line-height: 1.5em] Is there a way to make it so that an extension can accept as many share connection as possible if it’s not already built that way? Many thanks again dicko…[/size]

alan · September 26, 2013, 3:19am

Are you saying you have both the soft phone and the ATA registered as the same extension? You can’t have two devices registered to the same extension like that.

dicko · September 26, 2013, 3:20am

There is your problem, you can’t do that, read the wiki and pay attention to ring groups.

ledude · September 26, 2013, 5:01am

Thanks alan_mousty and dicko. I’ve forgotten about my softphone connected to that extension. Thus I was banging my head wondering why. Until my softphone ring and home phone didn’t I just realized that that phone is connected. So is there a way in freepbx configuration to lock the login to just one device so that accidental like this won’t happen again? Just curious. Many thanks again.