No voicemail picks up -- Keeps ringing forever

I’ve noticed that despite having voicemail enabled on an extension the phone itself just rings and rings and rings, with voicemail never picking up. I can, from the device itself, press the voicemail key and setup my mailbox greeting, etc. But no matter what the call is never handed off to voicemail.

Anyone have any pointers on where to start with this problem? Voicemail is turned on for that extension. Ring time is set to 15 seconds. Password is set and works fine for checking voicemail. But alas, I cannot ever get the device to stop ringing so I can leave a voicemail.

@uberamd What do the call logs say when you make the call? Do they show it attempting to pick up at all or just continuous ringing? You don’t have FollowMe or any Call Forwarding rules on the extension?

Here are the logs, extension 100 calling 103, both are chan_sip Cisco 7960 devices:

[2015-12-11 20:48:13] NOTICE[2089] chan_sip.c: Peer '103' is now Reachable. (213ms / 2000ms)
[2015-12-11 20:48:23] VERBOSE[2089][C-0000000b] netsock2.c: == Using SIP RTP TOS bits 184
[2015-12-11 20:48:23] VERBOSE[2089][C-0000000b] netsock2.c: == Using SIP RTP CoS mark 5
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [103@from-internal:1] GotoIf("SIP/100-0000000b", "1?ext-local,103,1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (ext-local,103,1)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [103@ext-local:1] Set("SIP/100-0000000b", "__RINGTIMER=15") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [103@ext-local:2] Macro("SIP/100-0000000b", "exten-vm,novm,103,0,0,0") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/100-0000000b", "user-callerid,") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/100-0000000b", "TOUCH_MONITOR=1449888503.11") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/100-0000000b", "AMPUSER=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/100-0000000b", "0?report") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/100-0000000b", "1?Set(REALCALLERIDNUM=100)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/100-0000000b", "AMPUSER=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/100-0000000b", "0?limit") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/100-0000000b", "AMPUSERCIDNAME=Steve M") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/100-0000000b", "0?report") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/100-0000000b", "AMPUSERCID=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/100-0000000b", "__DIAL_OPTIONS=Ttr") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/100-0000000b", "CALLERID(all)="Steve M" <100>") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/100-0000000b", "0?limit") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/100-0000000b", "0?Set(GROUP(concurrency_limit)=100)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:14] ExecIf("SIP/100-0000000b", "0?Set(CHANNEL(language)=)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/100-0000000b", "0?continue") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:16] ExecIf("SIP/100-0000000b", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/100-0000000b", "__TTL=64") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("SIP/100-0000000b", "1?continue") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-user-callerid,s,29)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/100-0000000b", "CALLERID(number)=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/100-0000000b", "CALLERID(name)=Steve M") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/100-0000000b", "CDR(cnum)=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/100-0000000b", "CDR(cnam)=Steve M") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/100-0000000b", "CHANNEL(language)=en") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:2] Set("SIP/100-0000000b", "RingGroupMethod=none") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:3] Set("SIP/100-0000000b", "__EXTTOCALL=103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:4] Set("SIP/100-0000000b", "__PICKUPMARK=103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:5] Set("SIP/100-0000000b", "RT=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:6] ExecIf("SIP/100-0000000b", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:7] ExecIf("SIP/100-0000000b", "0?MacroExit()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:8] Gosub("SIP/100-0000000b", "sub-record-check,s,1(exten,103,dontcare)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/100-0000000b", "0?initialized") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:2] Set("SIP/100-0000000b", "__REC_STATUS=INITIALIZED") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:3] Set("SIP/100-0000000b", "NOW=1449888503") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/100-0000000b", "__DAY=11") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:5] Set("SIP/100-0000000b", "__MONTH=12") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/100-0000000b", "__YEAR=2015") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/100-0000000b", "__TIMESTR=20151211-204823") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/100-0000000b", "__FROMEXTEN=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:9] Set("SIP/100-0000000b", "__MON_FMT=wav") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/100-0000000b", "Recordings initialized") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/100-0000000b", "0?Set(ARG3=dontcare)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/100-0000000b", "REC_POLICY_MODE_SAVE=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/100-0000000b", "0?Set(REC_STATUS=NO)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/100-0000000b", "5?checkaction") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (sub-record-check,s,17)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/100-0000000b", "1?sub-record-check,exten,1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (sub-record-check,exten,1)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:1] NoOp("SIP/100-0000000b", "Exten Recording Check between 100 and 103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:2] Set("SIP/100-0000000b", "CALLTYPE=internal") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:3] ExecIf("SIP/100-0000000b", "0?Set(CALLTYPE=)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:4] Set("SIP/100-0000000b", "CALLEE=dontcare") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:5] ExecIf("SIP/100-0000000b", "0?Set(CALLEE=dontcare)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:6] GotoIf("SIP/100-0000000b", "0?callee") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:7] GotoIf("SIP/100-0000000b", "1?caller") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (sub-record-check,exten,13)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:13] Set("SIP/100-0000000b", "RECMODE=dontcare") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:14] ExecIf("SIP/100-0000000b", "0?Set(RECMODE=dontcare)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:15] ExecIf("SIP/100-0000000b", "1?Set(RECMODE=dontcare)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:16] Gosub("SIP/100-0000000b", "recordcheck,1(dontcare,internal,103)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/100-0000000b", "Starting recording check against dontcare") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/100-0000000b", "dontcare") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (sub-record-check,recordcheck,3)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [exten@sub-record-check:17] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:9] GotoIf("SIP/100-0000000b", "1?macrodial") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-exten-vm,s,15)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:15] GosubIf("SIP/100-0000000b", "0?clrheader,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-exten-vm:16] Macro("SIP/100-0000000b", "dial-one,,Ttr,103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/100-0000000b", "DEXTEN=103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/100-0000000b", "DIALSTATUS_CW=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("SIP/100-0000000b", "0?screen,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("SIP/100-0000000b", "0?cf,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("SIP/100-0000000b", "1?skip1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-dial-one,s,8)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("SIP/100-0000000b", "0?nodial") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("SIP/100-0000000b", "0?continue") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:10] Set("SIP/100-0000000b", "EXTHASCW=ENABLED") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/100-0000000b", "0?next1:cwinusebusy") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-dial-one,s,23)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:23] GotoIf("SIP/100-0000000b", "0?next3:continue") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-dial-one,s,25)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/100-0000000b", "0?nodial") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("SIP/100-0000000b", "1?dstring,1():dlocal,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/100-0000000b", "DSTRING=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/100-0000000b", "DEVICES=103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/100-0000000b", "0?Return()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/100-0000000b", "0?Set(DEVICES=03)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/100-0000000b", "LOOPCNT=1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/100-0000000b", "ITER=1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/100-0000000b", "THISDIAL=SIP/103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/100-0000000b", "1?zap2dahdi,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/100-0000000b", "0?Return()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/100-0000000b", "NEWDIAL=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/100-0000000b", "LOOPCNT2=1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/100-0000000b", "ITER2=1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/100-0000000b", "THISPART2=SIP/103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/100-0000000b", "0?Set(THISPART2=DAHDI/103)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/100-0000000b", "NEWDIAL=SIP/103&") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/100-0000000b", "ITER2=2") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/100-0000000b", "0?begin2") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/100-0000000b", "THISDIAL=SIP/103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:9] GotoIf("SIP/100-0000000b", "1?docheck") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-dial-one,dstring,12)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:12] GotoIf("SIP/100-0000000b", "0?skipset") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:13] Set("SIP/100-0000000b", "DSTRING=SIP/103&") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:14] Set("SIP/100-0000000b", "ITER=2") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:15] GotoIf("SIP/100-0000000b", "0?begin") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:16] ExecIf("SIP/100-0000000b", "0?Return()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:17] Set("SIP/100-0000000b", "DSTRING=SIP/103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [dstring@macro-dial-one:18] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/100-0000000b", "0?nodial") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/100-0000000b", "0?skiptrace") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("SIP/100-0000000b", "1?ctset,1():ctclear,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/100-0000000b", "DB(CALLTRACE/103)=100") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/100-0000000b", "D_OPTIONS=Ttr") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:31] GosubIf("SIP/100-0000000b", "0?func-set-sipheader,s,1(Alert-Info,)()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/100-0000000b", "0?Set(CHANNEL(musicclass)=)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:33] GosubIf("SIP/100-0000000b", "0?qwait,1()") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:34] Set("SIP/100-0000000b", "__CWIGNORE=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/100-0000000b", "__KEEPCID=TRUE") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:36] GotoIf("SIP/100-0000000b", "0?usegoto,1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("SIP/100-0000000b", "0?godial") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:38] Gosub("SIP/100-0000000b", "sub-presencestate-display,s,1(103)") in new stack
[2015-12-11 20:48:23] WARNING[13409][C-0000000b] func_presencestate.c: PRESENCE_STATE unknown
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@sub-presencestate-display:1] Goto("SIP/100-0000000b", "state-,1") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (sub-presencestate-display,state-,1)
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [state-@sub-presencestate-display:1] Set("SIP/100-0000000b", "PRESENCESTATE_DISPLAY=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [state-@sub-presencestate-display:2] Return("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:39] Set("SIP/100-0000000b", "CONNECTEDLINE(name,i)=Steve 2") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:40] Set("SIP/100-0000000b", "CONNECTEDLINE(num)=103") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:41] Set("SIP/100-0000000b", "D_OPTIONS=TtrI") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:42] Macro("SIP/100-0000000b", "dialout-one-predial-hook,") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SIP/100-0000000b", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-dial-one:43] Dial("SIP/100-0000000b", "SIP/103,,TtrIb(func-apply-sipheaders^s^1)") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] netsock2.c: == Using SIP RTP TOS bits 184
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] netsock2.c: == Using SIP RTP CoS mark 5
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_stack.c: -- SIP/103-0000000c Internal Gosub(func-apply-sipheaders,s,1) start
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/103-0000000c", "Applying SIP Headers to channel") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@func-apply-sipheaders:2] Set("SIP/103-0000000c", "SIPHEADERKEYS=") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@func-apply-sipheaders:3] While("SIP/103-0000000c", "0") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_while.c: -- Jumping to priority 7
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@func-apply-sipheaders:8] Return("SIP/103-0000000c", "") in new stack
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_stack.c: == Spawn extension (from-internal, 103, 1) exited non-zero on 'SIP/103-0000000c'
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_stack.c: -- SIP/103-0000000c Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_dial.c: -- Called SIP/103
[2015-12-11 20:48:23] VERBOSE[13409][C-0000000b] app_dial.c: -- Connected line update to SIP/100-0000000b prevented.
[2015-12-11 20:48:24] VERBOSE[13409][C-0000000b] app_dial.c: -- SIP/103-0000000c is ringing
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] app_macro.c: == Spawn extension (macro-dial-one, s, 43) exited non-zero on 'SIP/100-0000000b' in macro 'dial-one'
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] app_macro.c: == Spawn extension (macro-exten-vm, s, 16) exited non-zero on 'SIP/100-0000000b' in macro 'exten-vm'
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: == Spawn extension (ext-local, 103, 2) exited non-zero on 'SIP/100-0000000b'
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [h@ext-local:1] Macro("SIP/100-0000000b", "hangupcall,") in new stack
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-hangupcall:1] ExecIf("SIP/100-0000000b", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-hangupcall:2] GotoIf("SIP/100-0000000b", "1?theend") in new stack
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Goto (macro-hangupcall,s,4)
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-hangupcall:4] ExecIf("SIP/100-0000000b", "0?Set(CDR(recordingfile)=)") in new stack
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: -- Executing [s@macro-hangupcall:5] Hangup("SIP/100-0000000b", "") in new stack
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] app_macro.c: == Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'SIP/100-0000000b' in macro 'hangupcall'
[2015-12-11 20:49:57] VERBOSE[13409][C-0000000b] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/100-0000000b'

I’ll admit I’m relatively new to this software, but I don’t see anything obvious there. FollowMe is turned off, most settings are default.

Logs seem to indicate I let the device ring for 33 seconds before I hung up. Thanks!

@uberamd This is stating that you do not have VM enabled for this extension. “novm” means No Voice Mail. Can you provide the extension settings from sip_additional.conf for this extension?

And did you apply the config after enabling VM for this extension?

Absolutely, here it is:

[103]
deny=0.0.0.0/0.0.0.0
secret=Cisco1234
dtmfmode=rfc2833
canreinvite=no
context=from-internal
host=dynamic
trustrpid=yes
sendrpid=no
type=friend
nat=no
port=5060
qualify=yes
qualifyfreq=60
transport=udp,tcp,tls
avpf=no
force_avp=no
icesupport=no
encryption=no
callgroup=
pickupgroup=
dial=SIP/103
mailbox=103@device
permit=0.0.0.0/0.0.0.0
callerid=Steve 2 <103>
callcounter=yes
faxdetect=no
cc_monitor_policy=generic

UI: http://i.imgur.com/zqpc6WE.png

OK, that looks good. Can you now do the extensions_additional.conf? Looking for a line that looks like this:

If it it looks like this, VM is enabled:
exten => 103,n,Macro(exten-vm,103,103,0,0,0)

If it looks like this is is not
exten => 103,n,Macro(exten-vm,novm,103,1,1,1)

Really you’re looking to so the the next value after “exten-vm” is the extension number or novm

Interesting, sure enough it’s set to this:

exten => 103,1,Set(__RINGTIMER=${IF($["${DB(AMPUSER/103/ringtimer)}" > "0"]?${DB(AMPUSER/103/ringtimer)}:${RINGTIMER_DEFAULT})})
exten => 103,n,Macro(exten-vm,novm,103,0,0,0)

I’m assuming I don’t want to be modifying these files by hand as they’ll get stomped out by FreePBX when it rebuilds configs?

Hmm, so I turned voicemail off in the UI for extension 103 and the extensions_additional.conf file updated to this:

exten => 103,n,Macro(exten-vm,103,103,0,0,0)

Then I called 103 from 100 and it rang for 15 seconds and it sounded like voicemail was going to pick up, but instead it was just a voice that said “I’m sorry” and disconnected the call.

Based on the logs it appears voicemail isn’t setup, which makes sense as I turned it off, but why would it update the extensions_additional file to indicate it should go to VM AFTER I turn it off, but not when I turn it on? This is bizarre (to me anyway :slight_smile: )

[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] app_dial.c: -- Nobody picked up in 15000 ms
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-dial-one:44] ExecIf("SIP/100-0000000d", "0?MacroExit()") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-dial-one:45] ExecIf("SIP/100-0000000d", "0?Set(DIALSTATUS=)") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-dial-one:46] GosubIf("SIP/100-0000000d", "0?s-NOANSWER,1()") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-dial-one:47] MacroExit("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:17] Set("SIP/100-0000000d", "SV_DIALSTATUS=NOANSWER") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:18] GosubIf("SIP/100-0000000d", "0?docfu,1()") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:19] GosubIf("SIP/100-0000000d", "0?docfb,1()") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:20] Set("SIP/100-0000000d", "DIALSTATUS=NOANSWER") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:21] ExecIf("SIP/100-0000000d", "0?MacroExit()") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:22] GotoIf("SIP/100-0000000d", "0?s-NOANSWER,1") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-exten-vm:23] Macro("SIP/100-0000000d", "vm,103,NOANSWER,") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-vm:1] Macro("SIP/100-0000000d", "user-callerid,SKIPTTL") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/100-0000000d", "TOUCH_MONITOR=1449891023.13") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/100-0000000d", "AMPUSER=100") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/100-0000000d", "7?report") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-user-callerid,s,15)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/100-0000000d", "1?continue") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-user-callerid,s,29)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/100-0000000d", "CALLERID(number)=100") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/100-0000000d", "CALLERID(name)=Steve M") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/100-0000000d", "CDR(cnum)=100") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/100-0000000d", "CDR(cnam)=Steve M") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/100-0000000d", "CHANNEL(language)=en") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-vm:2] Set("SIP/100-0000000d", "VMGAIN=") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-vm:3] Macro("SIP/100-0000000d", "blkvm-check,") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-blkvm-check:1] Set("SIP/100-0000000d", "GOSUB_RETVAL=") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-blkvm-check:2] ExecIf("SIP/100-0000000d", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-blkvm-check:3] MacroExit("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-vm:4] GotoIf("SIP/100-0000000d", "1?vmx,1") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-vm,vmx,1)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:1] Set("SIP/100-0000000d", "MEXTEN=103") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:2] Set("SIP/100-0000000d", "MMODE=NOANSWER") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:3] Set("SIP/100-0000000d", "RETVM=") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:4] Set("SIP/100-0000000d", "MODE=unavail") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:5] Macro("SIP/100-0000000d", "get-vmcontext,103") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/100-0000000d", "VMCONTEXT=default") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/100-0000000d", "0?200:300") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-get-vmcontext,s,300)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:6] Set("SIP/100-0000000d", "MODE=unavail") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:7] NoOp("SIP/100-0000000d", "MODE IS: unavail") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:8] GotoIf("SIP/100-0000000d", "1?chknomsg") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-vm,vmx,10)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:10] GotoIf("SIP/100-0000000d", "0?s-NOANSWER,1") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:11] GotoIf("SIP/100-0000000d", "1?notdirect") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-vm,vmx,13)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:13] NoOp("SIP/100-0000000d", "Checking if ext 103 is enabled: ") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [vmx@macro-vm:14] GotoIf("SIP/100-0000000d", "1?s-NOANSWER,1") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-vm,s-NOANSWER,1)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/100-0000000d", "get-vmcontext,103") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/100-0000000d", "VMCONTEXT=default") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/100-0000000d", "0?200:300") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-get-vmcontext,s,300)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/100-0000000d", "103@default,u") in new stack
[2015-12-11 21:30:38] WARNING[15991][C-0000000c] app_voicemail.c: No entry in voicemail config file for '103'
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s-NOANSWER@macro-vm:3] Goto("SIP/100-0000000d", "exit-FAILED,1") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-vm,exit-FAILED,1)
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [exit-FAILED@macro-vm:1] Playback("SIP/100-0000000d", "im-sorry&an-error-has-occured") in new stack
[2015-12-11 21:30:38] VERBOSE[15991][C-0000000c] file.c: -- <SIP/100-0000000d> Playing 'im-sorry.ulaw' (language 'en')
[2015-12-11 21:30:39] WARNING[15991][C-0000000c] file.c: File an-error-has-occured does not exist in any format
[2015-12-11 21:30:39] WARNING[15991][C-0000000c] file.c: Unable to open an-error-has-occured (format (ulaw)): No such file or directory
[2015-12-11 21:30:39] WARNING[15991][C-0000000c] app_playback.c: ast_streamfile failed on SIP/100-0000000d for im-sorry&an-error-has-occured
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [exit-FAILED@macro-vm:2] GotoIf("SIP/100-0000000d", "0?exit-RETURN,1") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [exit-FAILED@macro-vm:3] Hangup("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] app_macro.c: == Spawn extension (macro-vm, exit-FAILED, 3) exited non-zero on 'SIP/100-0000000d' in macro 'vm'
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] app_macro.c: == Spawn extension (macro-exten-vm, s, 23) exited non-zero on 'SIP/100-0000000d' in macro 'exten-vm'
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: == Spawn extension (ext-local, 103, 2) exited non-zero on 'SIP/100-0000000d'
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [h@ext-local:1] Macro("SIP/100-0000000d", "hangupcall,") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-hangupcall:1] ExecIf("SIP/100-0000000d", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-hangupcall:2] GotoIf("SIP/100-0000000d", "1?theend") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Goto (macro-hangupcall,s,4)
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-hangupcall:4] ExecIf("SIP/100-0000000d", "0?Set(CDR(recordingfile)=)") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: -- Executing [s@macro-hangupcall:5] Hangup("SIP/100-0000000d", "") in new stack
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] app_macro.c: == Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'SIP/100-0000000d' in macro 'hangupcall'
[2015-12-11 21:30:39] VERBOSE[15991][C-0000000c] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/100-0000000d'

Correct, you don’t want to do that. You’ll want to SSH into the system and if you are running FreePBX 13 you’ll want to do: fwconsole restart or if it’s version 12 you’ll want to do: amportal restart

Once you restart FreePBX/Asterisk check extensions_additional.conf again and see if it changed.

You’ll want to turn VM back on again.

Same story. Something seems out of sync. When I enable voicemail for an extension in the GUI it shows as novm in the extensions config. When I disable it it’ll start showing up properly in extensions_additional.conf but play the “I’m sorry” message.

Just created a new extension, before even saving it I set VM to be on, same story. exten-vm,novm. Turn VM off and it sets up the config properly but obviously disables the rest of the needed VM config elsewhere.

I think something is broken with my install. I might spin up a new FreePBX VM and see if I can re-create the issue on a fresh install. As they say, 50th times a charm :smile:

Thanks for the help!

So after you turned it back on and did the restart, you are still having the same issue?

What version of FreePBX/Asterisk and what OS is this on?

Indeed, it keeps the config files in that funky state where they’re opposite of what the UI indicates they should be. Earlier today I actually had to power-cycle the VMware host this is living on so it’s been bounced twice now today, issue refuses to correct itself.

Check it (/etc/asterisk/voicemail.conf) also check that file for bizarre lines.

Yeah, that was next. Do that.

Seems clean:

[general]
externnotify=/var/lib/asterisk/agi-bin/vmnotify-newvm.php
emailbody=${VM_NAME},\n\nThere is a new voicemail in mailbox ${VM_MAILBOX}:\n\n\tFrom:\t${VM_CALLERID}\n\tLength:\t${VM_DUR} seconds\n\tDate:\t${VM_DATE}\n\nDial *98 to access your voicemail by phone.\nVisit http://AMPWEBADDRESS/ucp to check your voicemail with a web browser.\n
pollmailboxes=yes
pollfreq=10
forcegreetings=yes
forcename=yes
emailsubject=FreePBX Voicemail Notification
fromstring=FreePBX Phone System

[default]
100 => 1234,Steve M,,,attach=no|saycid=yes|envelope=no|delete=no
103 => 1234,Steve 2,,,attach=no|saycid=no|envelope=no|delete=no
104 => 1234,TestVM,,,attach=no|saycid=no|envelope=no|delete=no

This is with voicemail turned ON in the GUI. When I turn it off in the GUI it removes the applicable extension line from voicemail.conf but also removes the novm from extensions_additional.conf

Also, just did a clean install of FreePBX to a new VM, installed the Device Manager and Google Motif extensions (didn’t config, just installed), went to make a new extension, enabled voicemail on it before creating it, and even on the fresh install it has “novm” in the extensions_additional.conf.

Again, what version of FreePBX/Asterisk and OS are you installing this on?

Using the Easy Install distro:

STABLE – 10.13.66
Release Date: 2015
FreePBX 13 • Linux 6.6 • Asterisk 11 option

What modules have you installed?