Calls between extensions failing imemdiately

euan · July 10, 2025, 8:32am

I’ve got a FreePBX 17.0.19.28 install running on top of Debian 12 (bookworm), installed using the install script. This system has been running for a while.

I’ve got several PJSIP extensions configured, and am only using the system for internal calls between extensions.

All was working fine until I recently installed system updates (apt-get update && apt-get upgrade -y) and module updates (via the web GUI). Since then, all calls between extensions fail immediately with a busy dial tone.

I’ve tried monitoring the logs while making a call (asterisk -cvvvvvr), and got the following output:

Connected to Asterisk 22.4.1 currently running on freepbx (pid = 106580)
  == Using SIP RTP Audio TOS bits 184
  == Using SIP RTP Audio TOS bits 184 in TCLASS field.
  == Using SIP RTP Audio CoS mark 5
    -- Executing [9540@from-internal:1] GotoIf("PJSIP/9653-00000001", "1?ext-local,9540,1:followme-check,9540,1") in new stack
    -- Goto (ext-local,9540,1)
    -- Executing [9540@ext-local:1] Set("PJSIP/9653-00000001", "__RINGTIMER=15") in new stack
    -- Executing [9540@ext-local:2] ExecIf("PJSIP/9653-00000001", "0?Set(__CWIGNORE=)") in new stack
    -- Executing [9540@ext-local:3] Gosub("PJSIP/9653-00000001", "macro-exten-vm,s,1(novm,9540,0,0,0)") in new stack
    -- Executing [s@macro-exten-vm:1] Gosub("PJSIP/9653-00000001", "macro-user-callerid,s,1(novm,9540,,,,macro-exten-vm)") in new stack
    -- Executing [s@macro-user-callerid:1] Set("PJSIP/9653-00000001", "TOUCH_MONITOR=1752134909.1") in new stack
    -- Executing [s@macro-user-callerid:2] Set("PJSIP/9653-00000001", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:3] Set("PJSIP/9653-00000001", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:4] Set("PJSIP/9653-00000001", "CHANEXTENCONTEXT=9653-00000001") in new stack
    -- Executing [s@macro-user-callerid:5] Set("PJSIP/9653-00000001", "CHANEXTEN=9653-00000001") in new stack
    -- Executing [s@macro-user-callerid:6] Set("PJSIP/9653-00000001", "CALLERID(number)=9653") in new stack
    -- Executing [s@macro-user-callerid:7] Set("PJSIP/9653-00000001", "AMPUSER=9653") in new stack
    -- Executing [s@macro-user-callerid:8] Set("PJSIP/9653-00000001", "HOTDESCKCHAN=9653-00000001") in new stack
    -- Executing [s@macro-user-callerid:9] Set("PJSIP/9653-00000001", "HOTDESKEXTEN=9653") in new stack
    -- Executing [s@macro-user-callerid:10] Set("PJSIP/9653-00000001", "HOTDESKCALL=0") in new stack
    -- Executing [s@macro-user-callerid:11] ExecIf("PJSIP/9653-00000001", "0?Set(HOTDESKCALL=1)") in new stack
    -- Executing [s@macro-user-callerid:12] ExecIf("PJSIP/9653-00000001", "0?Set(CALLERID(name)=)") in new stack
    -- Executing [s@macro-user-callerid:13] GotoIf("PJSIP/9653-00000001", "0?report") in new stack
    -- Executing [s@macro-user-callerid:14] ExecIf("PJSIP/9653-00000001", "1?Set(REALCALLERIDNUM=9653)") in new stack
    -- Executing [s@macro-user-callerid:15] Set("PJSIP/9653-00000001", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("PJSIP/9653-00000001", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:17] Set("PJSIP/9653-00000001", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:18] ExecIf("PJSIP/9653-00000001", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
    -- Executing [s@macro-user-callerid:19] GotoIf("PJSIP/9653-00000001", "1?report") in new stack
    -- Goto (macro-user-callerid,s,28)
    -- Executing [s@macro-user-callerid:28] NoOp("PJSIP/9653-00000001", "Macro depricated!! To keep the same line numbers") in new stack
    -- Executing [s@macro-user-callerid:29] NoOp("PJSIP/9653-00000001", "Macro depricated !!  To keep the same line numbers") in new stack
    -- Executing [s@macro-user-callerid:30] GotoIf("PJSIP/9653-00000001", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:31] ExecIf("PJSIP/9653-00000001", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [s@macro-user-callerid:32] Set("PJSIP/9653-00000001", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:33] GotoIf("PJSIP/9653-00000001", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,49)
    -- Executing [s@macro-user-callerid:49] Set("PJSIP/9653-00000001", "CALLERID(number)=9653") in new stack
    -- Executing [s@macro-user-callerid:50] Set("PJSIP/9653-00000001", "CALLERID(name)=Spectralink 9653") in new stack
    -- Executing [s@macro-user-callerid:51] GotoIf("PJSIP/9653-00000001", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:52] Set("PJSIP/9653-00000001", "__MCNUM=9653") in new stack
    -- Executing [s@macro-user-callerid:53] Set("PJSIP/9653-00000001", "__MCNAME=Spectralink 9653") in new stack
    -- Executing [s@macro-user-callerid:54] Set("PJSIP/9653-00000001", "__MCEXTEN=") in new stack
    -- Executing [s@macro-user-callerid:55] Set("PJSIP/9653-00000001", "__MCORGCHAN=PJSIP/9653-00000001") in new stack
    -- Executing [s@macro-user-callerid:56] Set("PJSIP/9653-00000001", "CDR(cnam)=Spectralink 9653") in new stack
    -- Executing [s@macro-user-callerid:57] Set("PJSIP/9653-00000001", "CDR(cnum)=9653") in new stack
    -- Executing [s@macro-user-callerid:58] Return("PJSIP/9653-00000001", "") in new stack
    -- Executing [s@macro-exten-vm:2] Set("PJSIP/9653-00000001", "RingGroupMethod=none") in new stack
    -- Executing [s@macro-exten-vm:3] Set("PJSIP/9653-00000001", "__EXTTOCALL=9540") in new stack
    -- Executing [s@macro-exten-vm:4] Set("PJSIP/9653-00000001", "__PICKUPMARK=9540") in new stack
    -- Executing [s@macro-exten-vm:5] Set("PJSIP/9653-00000001", "RT=") in new stack
    -- Executing [s@macro-exten-vm:6] GotoIf("PJSIP/9653-00000001", "1?startcheck:exitcheck") in new stack
    -- Goto (macro-exten-vm,s,7)
    -- Executing [s@macro-exten-vm:7] GotoIf("PJSIP/9653-00000001", "0?featureSIP:featurePJSIP") in new stack
    -- Goto (macro-exten-vm,s,11)
    -- Executing [s@macro-exten-vm:11] ExecIf("PJSIP/9653-00000001", "0?Gosub(macro-vm,novm,DIRECTDIAL,)") in new stack
    -- Executing [s@macro-exten-vm:12] ExecIf("PJSIP/9653-00000001", "0?Return()") in new stack
    -- Executing [s@macro-exten-vm:13] GotoIf("PJSIP/9653-00000001", "1?featuremoniPJSIP:featuremoniSIP") in new stack
    -- Goto (macro-exten-vm,s,14)
    -- Executing [s@macro-exten-vm:14] ExecIf("PJSIP/9653-00000001", "0?ChanSpy(,q)") in new stack
    -- Executing [s@macro-exten-vm:15] ExecIf("PJSIP/9653-00000001", "0?Return()") in new stack
    -- Executing [s@macro-exten-vm:16] GotoIf("PJSIP/9653-00000001", "1?check-ext-intercom:featuremoniSIP") in new stack
    -- Goto (macro-exten-vm,s,19)
    -- Executing [s@macro-exten-vm:19] GotoIf("PJSIP/9653-00000001", "0?ext-intercomSIP:ext-intercomPJSIP") in new stack
    -- Goto (macro-exten-vm,s,20)
    -- Executing [s@macro-exten-vm:20] ExecIf("PJSIP/9653-00000001", "0?Gosub(ext-intercom,*809540,1())") in new stack
    -- Executing [s@macro-exten-vm:21] ExecIf("PJSIP/9653-00000001", "0?Return()") in new stack
    -- Executing [s@macro-exten-vm:22] GotoIf("PJSIP/9653-00000001", "1?exitcheck:ext-intercomSIP") in new stack
    -- Goto (macro-exten-vm,s,25)
    -- Executing [s@macro-exten-vm:25] NoOp("PJSIP/9653-00000001", "Exiting Checks") in new stack
    -- Executing [s@macro-exten-vm:26] Gosub("PJSIP/9653-00000001", "sub-record-check,s,1(exten,9540,dontcare)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("PJSIP/9653-00000001", "0?initialized") in new stack
    -- Executing [s@sub-record-check:2] Set("PJSIP/9653-00000001", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:3] Set("PJSIP/9653-00000001", "NOW=1752134909") in new stack
    -- Executing [s@sub-record-check:4] Set("PJSIP/9653-00000001", "__DAY=10") in new stack
    -- Executing [s@sub-record-check:5] Set("PJSIP/9653-00000001", "__MONTH=07") in new stack
    -- Executing [s@sub-record-check:6] Set("PJSIP/9653-00000001", "__YEAR=2025") in new stack
    -- Executing [s@sub-record-check:7] Set("PJSIP/9653-00000001", "__TIMESTR=20250710-090829") in new stack
    -- Executing [s@sub-record-check:8] Set("PJSIP/9653-00000001", "__FROMEXTEN=9653") in new stack
    -- Executing [s@sub-record-check:9] Set("PJSIP/9653-00000001", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:10] NoOp("PJSIP/9653-00000001", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("PJSIP/9653-00000001", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("PJSIP/9653-00000001", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("PJSIP/9653-00000001", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("PJSIP/9653-00000001", "5?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("PJSIP/9653-00000001", "1?sub-record-check,exten,1") in new stack
    -- Goto (sub-record-check,exten,1)
    -- Executing [exten@sub-record-check:1] NoOp("PJSIP/9653-00000001", "Exten Recording Check between 9653 and 9540") in new stack
    -- Executing [exten@sub-record-check:2] Set("PJSIP/9653-00000001", "CALLTYPE=internal") in new stack
    -- Executing [exten@sub-record-check:3] ExecIf("PJSIP/9653-00000001", "0?Set(CALLTYPE=)") in new stack
    -- Executing [exten@sub-record-check:4] Set("PJSIP/9653-00000001", "CALLEE=") in new stack
    -- Executing [exten@sub-record-check:5] ExecIf("PJSIP/9653-00000001", "1?Set(CALLEE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:6] GotoIf("PJSIP/9653-00000001", "0?callee") in new stack
    -- Executing [exten@sub-record-check:7] GotoIf("PJSIP/9653-00000001", "1?caller") in new stack
    -- Goto (sub-record-check,exten,13)
    -- Executing [exten@sub-record-check:13] Set("PJSIP/9653-00000001", "RECMODE=") in new stack
    -- Executing [exten@sub-record-check:14] Set("PJSIP/9653-00000001", "CALLERRECMODE=") in new stack
    -- Executing [exten@sub-record-check:15] Set("PJSIP/9653-00000001", "CALEERECMODE=") in new stack
    -- Executing [exten@sub-record-check:16] GotoIf("PJSIP/9653-00000001", "1?processnormal") in new stack
    -- Goto (sub-record-check,exten,21)
    -- Executing [exten@sub-record-check:21] ExecIf("PJSIP/9653-00000001", "1?Set(RECMODE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:22] ExecIf("PJSIP/9653-00000001", "1?Set(RECMODE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:23] Gosub("PJSIP/9653-00000001", "recordcheck,1(dontcare,internal,9540)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/9653-00000001", "Starting recording check against dontcare") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/9653-00000001", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [recordcheck@sub-record-check:3] Return("PJSIP/9653-00000001", "") in new stack
    -- Executing [exten@sub-record-check:24] Return("PJSIP/9653-00000001", "") in new stack
    -- Executing [s@macro-exten-vm:27] GotoIf("PJSIP/9653-00000001", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,33)
    -- Executing [s@macro-exten-vm:33] GosubIf("PJSIP/9653-00000001", "0?clrheader,1()") in new stack
    -- Executing [s@macro-exten-vm:34] Gosub("PJSIP/9653-00000001", "macro-dial-one,s,1(,HhTtr,9540)") in new stack
    -- Executing [s@macro-dial-one:1] Set("PJSIP/9653-00000001", "DEXTEN=9540") in new stack
    -- Executing [s@macro-dial-one:2] Set("PJSIP/9653-00000001", "__CRM_SOURCE=9653") in new stack
    -- Executing [s@macro-dial-one:3] Set("PJSIP/9653-00000001", "__MCEXTTOCALL=9540") in new stack
    -- Executing [s@macro-dial-one:4] Set("PJSIP/9653-00000001", "__MCMULTI=eaa2957e3eb89b4210d3196433e9da75") in new stack
    -- Executing [s@macro-dial-one:5] ExecIf("PJSIP/9653-00000001", "0?Set(__EXTTOCALL=9540)") in new stack
    -- Executing [s@macro-dial-one:6] Set("PJSIP/9653-00000001", "DIALSTATUS_CW=") in new stack
    -- Executing [s@macro-dial-one:7] GosubIf("PJSIP/9653-00000001", "0?screen,1()") in new stack
    -- Executing [s@macro-dial-one:8] GosubIf("PJSIP/9653-00000001", "0?cf,1()") in new stack
    -- Executing [s@macro-dial-one:9] GotoIf("PJSIP/9653-00000001", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,12)
    -- Executing [s@macro-dial-one:12] GotoIf("PJSIP/9653-00000001", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:13] GotoIf("PJSIP/9653-00000001", "0?continue") in new stack
    -- Executing [s@macro-dial-one:14] Set("PJSIP/9653-00000001", "EXTHASCW=") in new stack
    -- Executing [s@macro-dial-one:15] GotoIf("PJSIP/9653-00000001", "1?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,16)
    -- Executing [s@macro-dial-one:16] GotoIf("PJSIP/9653-00000001", "0?docfu:skip3") in new stack
    -- Goto (macro-dial-one,s,20)
    -- Executing [s@macro-dial-one:20] GotoIf("PJSIP/9653-00000001", "1?next2:continue") in new stack
    -- Goto (macro-dial-one,s,21)
    -- Executing [s@macro-dial-one:21] GotoIf("PJSIP/9653-00000001", "1?continue") in new stack
    -- Goto (macro-dial-one,s,29)
    -- Executing [s@macro-dial-one:29] GotoIf("PJSIP/9653-00000001", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:30] GosubIf("PJSIP/9653-00000001", "1?dstring,1():dlocal,1()") in new stack
    -- Executing [dstring@macro-dial-one:1] Set("PJSIP/9653-00000001", "DSTRING=") in new stack
    -- Executing [dstring@macro-dial-one:2] Set("PJSIP/9653-00000001", "DEVICES=") in new stack
    -- Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/9653-00000001", "1?Return()") in new stack
    -- Executing [s@macro-dial-one:31] GotoIf("PJSIP/9653-00000001", "1?nodial") in new stack
    -- Goto (macro-dial-one,s,64)
    -- Executing [s@macro-dial-one:64] NoOp("PJSIP/9653-00000001", "") in new stack
    -- Executing [s@macro-dial-one:65] ExecIf("PJSIP/9653-00000001", "1?Set(DIALSTATUS=NOANSWER)") in new stack
    -- Executing [s@macro-dial-one:66] NoOp("PJSIP/9653-00000001", "Returned from dial-one with nothing to call and DIALSTATUS: NOANSWER") in new stack
    -- Executing [s@macro-dial-one:67] Return("PJSIP/9653-00000001", "") in new stack
    -- Executing [s@macro-exten-vm:35] Set("PJSIP/9653-00000001", "SV_DIALSTATUS=NOANSWER") in new stack
    -- Executing [s@macro-exten-vm:36] GosubIf("PJSIP/9653-00000001", "0?docfu,1()") in new stack
    -- Executing [s@macro-exten-vm:37] GosubIf("PJSIP/9653-00000001", "0?docfb,1()") in new stack
    -- Executing [s@macro-exten-vm:38] Set("PJSIP/9653-00000001", "DIALSTATUS=NOANSWER") in new stack
    -- Executing [s@macro-exten-vm:39] ExecIf("PJSIP/9653-00000001", "0?Return()") in new stack
    -- Executing [s@macro-exten-vm:40] GotoIf("PJSIP/9653-00000001", "1?s-NOANSWER,1") in new stack
    -- Goto (macro-exten-vm,s-NOANSWER,1)
    -- Executing [s-NOANSWER@macro-exten-vm:1] GotoIf("PJSIP/9653-00000001", "0?exit,1") in new stack
    -- Executing [s-NOANSWER@macro-exten-vm:2] PlayTones("PJSIP/9653-00000001", "congestion") in new stack
    -- Executing [s-NOANSWER@macro-exten-vm:3] Congestion("PJSIP/9653-00000001", "10") in new stack
  == Spawn extension (macro-exten-vm, s-NOANSWER, 3) exited non-zero on 'PJSIP/9653-00000001'

To me, this looks like something called macro-exten-vm is failing for some reason. I took a guess that vm was something to do with voicemail, but I’ve checked and voicemail is disabled for all extensions.

If I check the call report, it shows the call lasting 0 seconds and again mentions macro-exten-vm:

Any ideas what to check next?

euan · July 10, 2025, 8:45am

Out of interest, I just enabled Voicemail for the called party, and as soon as I did so, calls to that extension started working perfectly.

I’d be interested to know why enabling voicemail for the extension fixes it, but at least I can get calls working again now.

system · August 10, 2025, 8:46am

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.