Incoming Calls get Dial Tone (and can call extensions)

TrevorP · December 29, 2015, 2:15pm

I am testing FreePBX 10.13.66, and having a problem with incoming calls. When the call is rejected (by the extension) the caller hears dialtone, and can call internal numbers. The setup and log is below.

What I would expect is the call is ended.

The default no answer/busy rules in the extension are “Unavail Voicemail if Enabled” etc, the same thing happens if I choose “Terminate Call / Hang Up” etc.

Is this behaviour expected?

I set up a fresh install for this test, set up as follows:

FreePBX-64bit-10.13.66.iso
No Raid Install (running in a virtual machine on a raid array)
enable ipv4 - DHCP (static lease assigned)
enable ipv6 - Automatic, DHCP only
UTC Clock, Australia/Sydney

Web GUI:
set “admin” username/password and email
FreePBX Admin
Activate
Enter email address, and password
Activate with existing deployment ID (created for the same machine earlier today)
Complete
Firewall Continue, Next,
Yes, trust client (10.0.3.39/32)
Yes, Trust network (10.0.3.0/24) (network is actually a /22)
Yes, Enable responsive firewall
Yes Auto configure IP Settings
SIPStation, Not Now

Admin > System Admin > DNS, add 127.0.0.1 to top of list (seems to fix pjsip reliabilty problem)
Connectivity > Trunks
Add PJSIP, Name: NodePhone2, Outbound Caller ID: , pjsip username, pjsip secret, pjsip sip server
Applications > Extensions
Add Extension, PJSIP, User Extension: 200, Display Name: Test, secret: shortened to 8 chars for testing
Connectivity > Inbound Routes
Add, Description: Default, Destination: Extension: 200

Apply Config

Register phone (CSipSimple Android Client)
Check registration: NodePhone2/sip:sip.internode.on.net:5060 NodePhone2 Registered

run asterisk -rvvvvv

make incoming call from mobile phone

localhost*CLI> 
    -- Executing [s@from-pstn:1] ExecIf("PJSIP/NodePhone2-00000000", "1?Set(__FROM_DID=s)") in new stack
    -- Executing [s@from-pstn:2] Gosub("PJSIP/NodePhone2-00000000", "app-blacklist-check,s,1()") in new stack
    -- Executing [s@app-blacklist-check:1] GotoIf("PJSIP/NodePhone2-00000000", "0?blacklisted") in new stack
    -- Executing [s@app-blacklist-check:2] Set("PJSIP/NodePhone2-00000000", "CALLED_BLACKLIST=1") in new stack
    -- Executing [s@app-blacklist-check:3] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@from-pstn:3] Set("PJSIP/NodePhone2-00000000", "CDR(did)=s") in new stack
    -- Executing [s@from-pstn:4] ExecIf("PJSIP/NodePhone2-00000000", "0 ?Set(CALLERID(name)=04XXXXXXXX)") in new stack
    -- Executing [s@from-pstn:5] Set("PJSIP/NodePhone2-00000000", "CHANNEL(musicclass)=default") in new stack
    -- Executing [s@from-pstn:6] Set("PJSIP/NodePhone2-00000000", "__MOHCLASS=default") in new stack
    -- Executing [s@from-pstn:7] Set("PJSIP/NodePhone2-00000000", "__REVERSAL_REJECT=FALSE") in new stack
    -- Executing [s@from-pstn:8] GotoIf("PJSIP/NodePhone2-00000000", "1?post-reverse-charge") in new stack
    -- Goto (from-pstn,s,10)
    -- Executing [s@from-pstn:10] NoOp("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@from-pstn:11] Set("PJSIP/NodePhone2-00000000", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
    -- Executing [s@from-pstn:12] Set("PJSIP/NodePhone2-00000000", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
    -- Executing [s@from-pstn:13] Set("PJSIP/NodePhone2-00000000", "CALLERID(name-pres)=allowed_not_screened") in new stack
    -- Executing [s@from-pstn:14] Set("PJSIP/NodePhone2-00000000", "CALLERID(num-pres)=allowed_not_screened") in new stack
    -- Executing [s@from-pstn:15] NoOp("PJSIP/NodePhone2-00000000", "CallerID Entry Point") in new stack
    -- Executing [s@from-pstn:16] Goto("PJSIP/NodePhone2-00000000", "from-did-direct,200,1") in new stack
    -- Goto (from-did-direct,200,1)
    -- Executing [200@from-did-direct:1] GotoIf("PJSIP/NodePhone2-00000000", "1?ext-local,200,1") in new stack
    -- Goto (ext-local,200,1)
    -- Executing [200@ext-local:1] Set("PJSIP/NodePhone2-00000000", "__RINGTIMER=15") in new stack
    -- Executing [200@ext-local:2] Macro("PJSIP/NodePhone2-00000000", "exten-vm,novm,200,0,0,0") in new stack
    -- Executing [s@macro-exten-vm:1] Macro("PJSIP/NodePhone2-00000000", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("PJSIP/NodePhone2-00000000", "TOUCH_MONITOR=1451392410.0") in new stack
    -- Executing [s@macro-user-callerid:2] Set("PJSIP/NodePhone2-00000000", "AMPUSER=04XXXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("PJSIP/NodePhone2-00000000", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("PJSIP/NodePhone2-00000000", "1?Set(REALCALLERIDNUM=04XXXXXXXX)") in new stack
    -- Executing [s@macro-user-callerid:5] Set("PJSIP/NodePhone2-00000000", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:6] GotoIf("PJSIP/NodePhone2-00000000", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:7] Set("PJSIP/NodePhone2-00000000", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("PJSIP/NodePhone2-00000000", "1?report") in new stack
    -- Goto (macro-user-callerid,s,15)
    -- Executing [s@macro-user-callerid:15] GotoIf("PJSIP/NodePhone2-00000000", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:16] ExecIf("PJSIP/NodePhone2-00000000", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [s@macro-user-callerid:17] Set("PJSIP/NodePhone2-00000000", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:18] GotoIf("PJSIP/NodePhone2-00000000", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("PJSIP/NodePhone2-00000000", "CALLERID(number)=04XXXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:30] Set("PJSIP/NodePhone2-00000000", "CALLERID(name)=04XXXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:31] Set("PJSIP/NodePhone2-00000000", "CDR(cnum)=04XXXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:32] Set("PJSIP/NodePhone2-00000000", "CDR(cnam)=04XXXXXXXX") in new stack
    -- Executing [s@macro-user-callerid:33] Set("PJSIP/NodePhone2-00000000", "CHANNEL(language)=en") in new stack
    -- Executing [s@macro-exten-vm:2] Set("PJSIP/NodePhone2-00000000", "RingGroupMethod=none") in new stack
    -- Executing [s@macro-exten-vm:3] Set("PJSIP/NodePhone2-00000000", "__EXTTOCALL=200") in new stack
    -- Executing [s@macro-exten-vm:4] Set("PJSIP/NodePhone2-00000000", "__PICKUPMARK=200") in new stack
    -- Executing [s@macro-exten-vm:5] Set("PJSIP/NodePhone2-00000000", "RT=") in new stack
[2015-12-29 23:33:30] WARNING[28432][C-00000000]: chan_sip.c:22323 func_header_read: This function can only be used on SIP channels.
    -- Executing [s@macro-exten-vm:6] ExecIf("PJSIP/NodePhone2-00000000", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
[2015-12-29 23:33:30] WARNING[28432][C-00000000]: chan_sip.c:22323 func_header_read: This function can only be used on SIP channels.
[2015-12-29 23:33:30] WARNING[28432][C-00000000]: chan_sip.c:22323 func_header_read: This function can only be used on SIP channels.
    -- Executing [s@macro-exten-vm:7] ExecIf("PJSIP/NodePhone2-00000000", "0?MacroExit()") in new stack
[2015-12-29 23:33:30] WARNING[28432][C-00000000]: chan_sip.c:22323 func_header_read: This function can only be used on SIP channels.
    -- Executing [s@macro-exten-vm:8] Gosub("PJSIP/NodePhone2-00000000", "sub-record-check,s,1(exten,200,dontcare)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("PJSIP/NodePhone2-00000000", "0?initialized") in new stack
    -- Executing [s@sub-record-check:2] Set("PJSIP/NodePhone2-00000000", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:3] Set("PJSIP/NodePhone2-00000000", "NOW=1451392410") in new stack
    -- Executing [s@sub-record-check:4] Set("PJSIP/NodePhone2-00000000", "__DAY=29") in new stack
    -- Executing [s@sub-record-check:5] Set("PJSIP/NodePhone2-00000000", "__MONTH=12") in new stack
    -- Executing [s@sub-record-check:6] Set("PJSIP/NodePhone2-00000000", "__YEAR=2015") in new stack
    -- Executing [s@sub-record-check:7] Set("PJSIP/NodePhone2-00000000", "__TIMESTR=20151229-233330") in new stack
    -- Executing [s@sub-record-check:8] Set("PJSIP/NodePhone2-00000000", "__FROMEXTEN=04XXXXXXXX") in new stack
    -- Executing [s@sub-record-check:9] Set("PJSIP/NodePhone2-00000000", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:10] NoOp("PJSIP/NodePhone2-00000000", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("PJSIP/NodePhone2-00000000", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("PJSIP/NodePhone2-00000000", "5?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("PJSIP/NodePhone2-00000000", "1?sub-record-check,exten,1") in new stack
    -- Goto (sub-record-check,exten,1)
    -- Executing [exten@sub-record-check:1] NoOp("PJSIP/NodePhone2-00000000", "Exten Recording Check between 04XXXXXXXX and 200") in new stack
    -- Executing [exten@sub-record-check:2] Set("PJSIP/NodePhone2-00000000", "CALLTYPE=external") in new stack
    -- Executing [exten@sub-record-check:3] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(CALLTYPE=)") in new stack
    -- Executing [exten@sub-record-check:4] Set("PJSIP/NodePhone2-00000000", "CALLEE=dontcare") in new stack
    -- Executing [exten@sub-record-check:5] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(CALLEE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:6] GotoIf("PJSIP/NodePhone2-00000000", "1?callee") in new stack
    -- Goto (sub-record-check,exten,11)
    -- Executing [exten@sub-record-check:11] Gosub("PJSIP/NodePhone2-00000000", "recordcheck,1(dontcare,external,200)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/NodePhone2-00000000", "Starting recording check against dontcare") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/NodePhone2-00000000", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [recordcheck@sub-record-check:3] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [exten@sub-record-check:12] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@macro-exten-vm:9] GotoIf("PJSIP/NodePhone2-00000000", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,15)
    -- Executing [s@macro-exten-vm:15] GosubIf("PJSIP/NodePhone2-00000000", "0?clrheader,1()") in new stack
    -- Executing [s@macro-exten-vm:16] Macro("PJSIP/NodePhone2-00000000", "dial-one,,Ttr,200") in new stack
    -- Executing [s@macro-dial-one:1] Set("PJSIP/NodePhone2-00000000", "DEXTEN=200") in new stack
    -- Executing [s@macro-dial-one:2] Set("PJSIP/NodePhone2-00000000", "DIALSTATUS_CW=") in new stack
    -- Executing [s@macro-dial-one:3] GosubIf("PJSIP/NodePhone2-00000000", "0?screen,1()") in new stack
    -- Executing [s@macro-dial-one:4] GosubIf("PJSIP/NodePhone2-00000000", "0?cf,1()") in new stack
    -- Executing [s@macro-dial-one:5] GotoIf("PJSIP/NodePhone2-00000000", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,8)
    -- Executing [s@macro-dial-one:8] GotoIf("PJSIP/NodePhone2-00000000", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:9] GotoIf("PJSIP/NodePhone2-00000000", "0?continue") in new stack
    -- Executing [s@macro-dial-one:10] Set("PJSIP/NodePhone2-00000000", "EXTHASCW=ENABLED") in new stack
    -- Executing [s@macro-dial-one:11] GotoIf("PJSIP/NodePhone2-00000000", "0?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,23)
    -- Executing [s@macro-dial-one:23] GotoIf("PJSIP/NodePhone2-00000000", "0?next3:continue") in new stack
    -- Goto (macro-dial-one,s,25)
    -- Executing [s@macro-dial-one:25] GotoIf("PJSIP/NodePhone2-00000000", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:26] GosubIf("PJSIP/NodePhone2-00000000", "1?dstring,1():dlocal,1()") in new stack
    -- Executing [dstring@macro-dial-one:1] Set("PJSIP/NodePhone2-00000000", "DSTRING=") in new stack
    -- Executing [dstring@macro-dial-one:2] Set("PJSIP/NodePhone2-00000000", "DEVICES=200") in new stack
    -- Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/NodePhone2-00000000", "0?Return()") in new stack
    -- Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(DEVICES=00)") in new stack
    -- Executing [dstring@macro-dial-one:5] Set("PJSIP/NodePhone2-00000000", "LOOPCNT=1") in new stack
    -- Executing [dstring@macro-dial-one:6] Set("PJSIP/NodePhone2-00000000", "ITER=1") in new stack
    -- Executing [dstring@macro-dial-one:7] Set("PJSIP/NodePhone2-00000000", "THISDIAL=PJSIP/200") in new stack
    -- Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/NodePhone2-00000000", "1?zap2dahdi,1()") in new stack
    -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/NodePhone2-00000000", "0?Return()") in new stack
    -- Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/NodePhone2-00000000", "NEWDIAL=") in new stack
    -- Executing [zap2dahdi@macro-dial-one:3] Set("PJSIP/NodePhone2-00000000", "LOOPCNT2=1") in new stack
    -- Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/NodePhone2-00000000", "ITER2=1") in new stack
    -- Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/NodePhone2-00000000", "THISPART2=PJSIP/200") in new stack
    -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(THISPART2=DAHDIIP/200)") in new stack
    -- Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/NodePhone2-00000000", "NEWDIAL=PJSIP/200&") in new stack
    -- Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/NodePhone2-00000000", "ITER2=2") in new stack
    -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/NodePhone2-00000000", "0?begin2") in new stack
    -- Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/NodePhone2-00000000", "THISDIAL=PJSIP/200") in new stack
    -- Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/NodePhone2-00000000", "0?docheck") in new stack
    -- Executing [dstring@macro-dial-one:10] NoOp("PJSIP/NodePhone2-00000000", "Debug: Found PJSIP Destination PJSIP/200, updating with PJSIP_DIAL_CONTACTS") in new stack
    -- Executing [dstring@macro-dial-one:11] Set("PJSIP/NodePhone2-00000000", "THISDIAL=PJSIP/200/sip:[email protected]:52996;ob") in new stack
    -- Executing [dstring@macro-dial-one:12] GotoIf("PJSIP/NodePhone2-00000000", "0?skipset") in new stack
    -- Executing [dstring@macro-dial-one:13] Set("PJSIP/NodePhone2-00000000", "DSTRING=PJSIP/200/sip:[email protected]:52996;ob&") in new stack
    -- Executing [dstring@macro-dial-one:14] Set("PJSIP/NodePhone2-00000000", "ITER=2") in new stack
    -- Executing [dstring@macro-dial-one:15] GotoIf("PJSIP/NodePhone2-00000000", "0?begin") in new stack
    -- Executing [dstring@macro-dial-one:16] ExecIf("PJSIP/NodePhone2-00000000", "0?Return()") in new stack
    -- Executing [dstring@macro-dial-one:17] Set("PJSIP/NodePhone2-00000000", "DSTRING=PJSIP/200/sip:[email protected]:52996;ob") in new stack
    -- Executing [dstring@macro-dial-one:18] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@macro-dial-one:27] GotoIf("PJSIP/NodePhone2-00000000", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:28] GotoIf("PJSIP/NodePhone2-00000000", "0?skiptrace") in new stack
    -- Executing [s@macro-dial-one:29] GosubIf("PJSIP/NodePhone2-00000000", "1?ctset,1():ctclear,1()") in new stack
    -- Executing [ctset@macro-dial-one:1] Set("PJSIP/NodePhone2-00000000", "DB(CALLTRACE/200)=04XXXXXXXX") in new stack
    -- Executing [ctset@macro-dial-one:2] Return("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@macro-dial-one:30] Set("PJSIP/NodePhone2-00000000", "D_OPTIONS=Ttr") in new stack
    -- Executing [s@macro-dial-one:31] GosubIf("PJSIP/NodePhone2-00000000", "0?func-set-sipheader,s,1(Alert-Info,)()") in new stack
    -- Executing [s@macro-dial-one:32] ExecIf("PJSIP/NodePhone2-00000000", "1?Set(CHANNEL(musicclass)=default)") in new stack
    -- Executing [s@macro-dial-one:33] GosubIf("PJSIP/NodePhone2-00000000", "0?qwait,1()") in new stack
    -- Executing [s@macro-dial-one:34] Set("PJSIP/NodePhone2-00000000", "__CWIGNORE=") in new stack
    -- Executing [s@macro-dial-one:35] Set("PJSIP/NodePhone2-00000000", "__KEEPCID=TRUE") in new stack
    -- Executing [s@macro-dial-one:36] GotoIf("PJSIP/NodePhone2-00000000", "0?usegoto,1") in new stack
    -- Executing [s@macro-dial-one:37] GotoIf("PJSIP/NodePhone2-00000000", "1?godial") in new stack
    -- Goto (macro-dial-one,s,42)
    -- Executing [s@macro-dial-one:42] Macro("PJSIP/NodePhone2-00000000", "dialout-one-predial-hook,") in new stack
    -- Executing [s@macro-dialout-one-predial-hook:1] MacroExit("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@macro-dial-one:43] Dial("PJSIP/NodePhone2-00000000", "PJSIP/200/sip:[email protected]:52996;ob,,Ttrb(func-apply-sipheaders^s^1)") in new stack
    -- PJSIP/200-00000001 Internal Gosub(func-apply-sipheaders,s,1) start
    -- Executing [s@func-apply-sipheaders:1] NoOp("PJSIP/200-00000001", "Applying SIP Headers to channel") in new stack
    -- Executing [s@func-apply-sipheaders:2] Set("PJSIP/200-00000001", "SIPHEADERKEYS=") in new stack
    -- Executing [s@func-apply-sipheaders:3] While("PJSIP/200-00000001", "0") in new stack
    -- Jumping to priority 7
    -- Executing [s@func-apply-sipheaders:8] Return("PJSIP/200-00000001", "") in new stack
  == Spawn extension (from-internal, 200, 1) exited non-zero on 'PJSIP/200-00000001'
    -- PJSIP/200-00000001 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
    -- Called PJSIP/200/sip:[email protected]:52996;ob
    -- PJSIP/200-00000001 is ringing
localhost*CLI>

I decline the call from the extension

localhost*CLI> 
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Executing [s@macro-dial-one:44] ExecIf("PJSIP/NodePhone2-00000000", "0?MacroExit()") in new stack
    -- Executing [s@macro-dial-one:45] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(DIALSTATUS=)") in new stack
    -- Executing [s@macro-dial-one:46] GosubIf("PJSIP/NodePhone2-00000000", "0?s-BUSY,1()") in new stack
    -- Executing [s@macro-dial-one:47] MacroExit("PJSIP/NodePhone2-00000000", "") in new stack
    -- Executing [s@macro-exten-vm:17] Set("PJSIP/NodePhone2-00000000", "SV_DIALSTATUS=BUSY") in new stack
    -- Executing [s@macro-exten-vm:18] GosubIf("PJSIP/NodePhone2-00000000", "0?docfu,1()") in new stack
    -- Executing [s@macro-exten-vm:19] GosubIf("PJSIP/NodePhone2-00000000", "0?docfb,1()") in new stack
    -- Executing [s@macro-exten-vm:20] Set("PJSIP/NodePhone2-00000000", "DIALSTATUS=BUSY") in new stack
    -- Executing [s@macro-exten-vm:21] ExecIf("PJSIP/NodePhone2-00000000", "0?MacroExit()") in new stack
    -- Executing [s@macro-exten-vm:22] GotoIf("PJSIP/NodePhone2-00000000", "1?s-BUSY,1") in new stack
    -- Goto (macro-exten-vm,s-BUSY,1)
    -- Executing [s-BUSY@macro-exten-vm:1] GotoIf("PJSIP/NodePhone2-00000000", "0?exit,1") in new stack
    -- Executing [s-BUSY@macro-exten-vm:2] PlayTones("PJSIP/NodePhone2-00000000", "busy") in new stack
    -- Executing [s-BUSY@macro-exten-vm:3] Busy("PJSIP/NodePhone2-00000000", "20") in new stack
  == Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on 'PJSIP/NodePhone2-00000000' in macro 'exten-vm'
  == Spawn extension (ext-local, 200, 2) exited non-zero on 'PJSIP/NodePhone2-00000000'
    -- Executing [h@ext-local:1] Macro("PJSIP/NodePhone2-00000000", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/NodePhone2-00000000", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/NodePhone2-00000000", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("PJSIP/NodePhone2-00000000", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/NodePhone2-00000000' in macro 'hangupcall'
  == Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/NodePhone2-00000000'
localhost*CLI>

From the calling mobile I now get dialtone and can call the extension (200) again, or for eg call *43

When I do the same test again, this time calling from skypeout (comes in as an anonymous call), it seems busy is returned to my sip provider, causing them to divert the call to our second line, according to settings I’ve configured on their end.

The only way I have replicated the desired behaviour is by setting the inbound route to “Terminate/Hangup”, though obviously, you can never answer calls that way. (though curiously an anonymous call seems to “ring out”, CEL shows “Anonymous hung up”)

i9techsupport · June 24, 2021, 5:31pm

I am also having this issue. I have yet to figure it out. I’m surprised nobody else has replied within the last six years.

cynjut · June 24, 2021, 7:20pm

I’m surprised you’d believe that his error and your could possibly be related since we are 5 major versions and at least two operating system major updates from there.

The call log from /var/log/asterisk/full (follow a single call by PID) posted to pastebin.freepbx.org will go a long way to helping us help you with this.

Without more information, I’m going to say that someone has set up your system to go to DISA if their phone is busy, and if that’s the case, I’d start looking at your logs to see how long your system has been hacked.

lgaetz · June 24, 2021, 7:48pm

Terminating an inbound channel from a sip provider that has not been answered can give unpredictable results. You can force an answer on the inbound route or you can be more friendly and send the call to VM which will answer the channel for you when the announcement starts.

david55 · June 24, 2021, 11:19pm

Maybe there are a lot of broken ITSPs, but there is no good reason why this should be true of SIP, although it is a problem with analogue FXO lines. SIP has good and unambiguous disconnect supervision.

lgaetz · June 25, 2021, 1:19pm

Not sure I would consider behavior broken. By unpredictable I mean that I have witnessed a few providers that resend an invite over and over if the channel gets a hangup without answer first. In one case the subsequent INVITE would show up from a different source IP. In another case I vaguely recall that there were minor changes in the headers on the INVITE that followed.