Calling voicemail goes to pilot instead of greeting

Hello,

I have FreePBX 10 (asterisk 13) setup with an external SIP trunk service, and an internal SIP trunk to a CUCM 8.6 server. Phones are registered to CUCM, and voicemail is setup on FreePBX. On the CUCM side, I create extension 2000 for the voicemail pilot, and on the FreePBX side I set 2000 as the voicemail feature code. The phones can access their voicemail by hitting the voicemail button, or dialing the pilot 2000. My problem is that whenever someone dials another extension, instead of getting the voicemail greeting, they get “Comedian mail, extension”. I have tried everything to no avail. I am in the process of reinstalling FreePBX to start from scratch. The first error message I could receive is:

app_voicemail.c: VM_INFO requires an argument ([@],attribute[,folder])

Unfortunately the internet didn’t provide much assistance. I have disabled PJSIP and only using Chan_Sip on udp 5060. If you need any further error messages I will provide them once I get it fully up and running. Any ideas how I can get the voicemail greeting when calling an extension and not the voicemail pilot? I appreciate any assistance.

You need to configure the Cisco system to add the extension number to the SIP header, and then you need custom code on the FreePBX system to extract it on an inbound call, then route the call as appropriate. I have done it once before but I can’t recall specific details. We can do this in support for you if you have budget (click the support link above).

Thank you for your reply! Unfortunately, this is for a home lab environment, so I don’t have a budget. I also forgot to mention that every extension in CUCM I also create a “custom extension” that matches in FreePBX, with voicemail enabled. I am working on getting everything setup, and will post the debug when I have it. Not sure if still need the custom code to be extracted since the extensions match within both systems.

Okay, I have everything installed as it was before. I have a “voip.ms” account that is trunked to my FreePBX. On the Cisco phones registered through my CUCM box, I am able to dial out using the voip.ms trunk. For troubleshooting, I created SIP extension “2000” on FreePBX. I use a softphone for testing. Extension 1002 is created on CUCM. Below is the output when I call from CUCM extension 1002 to FreePBX extension 2000 when it goes to voicemail. As expected, I reach the voicemail greeting.

-- Got SIP response 486 "Busy Here" back from 172.16.4.20:59377 -- SIP/2000-00000010 is busy == Everyone is busy/congested at this time (1:1/0/0) -- Executing [[email protected]:52] ExecIf("SIP/1002-0000000f", "0?MacroExit()") in new stack -- Executing [[email protected]:53] ExecIf("SIP/1002-0000000f", "0?Set(DIALSTATUS=)") in new stack -- Executing [[email protected]:54] GosubIf("SIP/1002-0000000f", "0?s-BUSY,1()") in new stack -- Executing [[email protected]:55] MacroExit("SIP/1002-0000000f", "") in new stack -- Executing [[email protected]:17] Set("SIP/1002-0000000f", "SV_DIALSTATUS=BUSY") in new stack -- Executing [[email protected]:18] GosubIf("SIP/1002-0000000f", "0?docfu,1()") in new stack -- Executing [[email protected]:19] GosubIf("SIP/1002-0000000f", "0?docfb,1()") in new stack -- Executing [[email protected]:20] Set("SIP/1002-0000000f", "DIALSTATUS=BUSY") in new stack -- Executing [[email protected]:21] ExecIf("SIP/1002-0000000f", "0?MacroExit()") in new stack -- Executing [[email protected]:22] GotoIf("SIP/1002-0000000f", "0?s-BUSY,1") in new stack -- Executing [[email protected]:23] Macro("SIP/1002-0000000f", "vm,2000,BUSY,") in new stack -- Executing [[email protected]:1] Macro("SIP/1002-0000000f", "user-callerid,SKIPTTL") in new stack -- Executing [[email protected]:1] Set("SIP/1002-0000000f", "TOUCH_MONITOR=1484612424.15") in new stack -- Executing [[email protected]:2] Set("SIP/1002-0000000f", "AMPUSER=1002") in new stack -- Executing [[email protected]:3] GotoIf("SIP/1002-0000000f", "14?report") in new stack -- Goto (macro-user-callerid,s,15) -- Executing [[email protected]:15] GotoIf("SIP/1002-0000000f", "1?continue") in new stack -- Goto (macro-user-callerid,s,29) -- Executing [[email protected]:29] Set("SIP/1002-0000000f", "CALLERID(number)=1002") in new stack -- Executing [[email protected]:30] Set("SIP/1002-0000000f", "CALLERID(name)=Test Softphone") in new stack -- Executing [[email protected]:31] GotoIf("SIP/1002-0000000f", "0?cnum") in new stack -- Executing [[email protected]:32] Set("SIP/1002-0000000f", "CDR(cnam)=Test Softphone") in new stack -- Executing [[email protected]:33] Set("SIP/1002-0000000f", "CDR(cnum)=1002") in new stack -- Executing [[email protected]:34] Set("SIP/1002-0000000f", "CHANNEL(language)=en") in new stack -- Executing [[email protected]:2] Set("SIP/1002-0000000f", "VMGAIN=") in new stack -- Executing [[email protected]:3] Macro("SIP/1002-0000000f", "blkvm-check,") in new stack -- Executing [[email protected]:1] Set("SIP/1002-0000000f", "GOSUB_RETVAL=") in new stack -- Executing [[email protected]:2] ExecIf("SIP/1002-0000000f", "0?Set(GOSUB_RETVAL=TRUE)") in new stack -- Executing [[email protected]:3] MacroExit("SIP/1002-0000000f", "") in new stack -- Executing [[email protected]:4] GotoIf("SIP/1002-0000000f", "1?vmx,1") in new stack -- Goto (macro-vm,vmx,1) -- Executing [[email protected]:1] Set("SIP/1002-0000000f", "MEXTEN=2000") in new stack -- Executing [[email protected]:2] Set("SIP/1002-0000000f", "MMODE=BUSY") in new stack -- Executing [[email protected]:3] Set("SIP/1002-0000000f", "RETVM=") in new stack -- Executing [[email protected]:4] Set("SIP/1002-0000000f", "MODE=busy") in new stack -- Executing [[email protected]:5] Macro("SIP/1002-0000000f", "get-vmcontext,2000") in new stack -- Executing [[email protected]:1] Set("SIP/1002-0000000f", "VMCONTEXT=default") in new stack -- Executing [[email protected]:2] GotoIf("SIP/1002-0000000f", "0?200:300") in new stack -- Goto (macro-get-vmcontext,s,300) -- Executing [[email protected]:300] NoOp("SIP/1002-0000000f", "") in new stack -- Executing [[email protected]:6] Set("SIP/1002-0000000f", "MODE=busy") in new stack -- Executing [[email protected]:7] NoOp("SIP/1002-0000000f", "MODE IS: busy") in new stack -- Executing [[email protected]:8] GotoIf("SIP/1002-0000000f", "1?chknomsg") in new stack -- Goto (macro-vm,vmx,10) -- Executing [[email protected]:10] GotoIf("SIP/1002-0000000f", "0?s-BUSY,1") in new stack -- Executing [[email protected]:11] GotoIf("SIP/1002-0000000f", "1?notdirect") in new stack -- Goto (macro-vm,vmx,13) -- Executing [[email protected]:13] NoOp("SIP/1002-0000000f", "Checking if ext 2000 is enabled: ") in new stack -- Executing [[email protected]:14] GotoIf("SIP/1002-0000000f", "1?s-BUSY,1") in new stack -- Goto (macro-vm,s-BUSY,1) -- Executing [[email protected]:1] NoOp("SIP/1002-0000000f", "BUSY voicemail") in new stack -- Executing [[email protected]:2] Macro("SIP/1002-0000000f", "get-vmcontext,2000") in new stack -- Executing [[email protected]:1] Set("SIP/1002-0000000f", "VMCONTEXT=default") in new stack -- Executing [[email protected]:2] GotoIf("SIP/1002-0000000f", "0?200:300") in new stack -- Goto (macro-get-vmcontext,s,300) -- Executing [[email protected]:300] NoOp("SIP/1002-0000000f", "") in new stack -- Executing [[email protected]:3] VoiceMail("SIP/1002-0000000f", "[email protected],b") in new stack -- <SIP/1002-0000000f> Playing 'vm-theperson.ulaw' (language 'en') -- <SIP/1002-0000000f> Playing 'digits/2.ulaw' (language 'en') -- <SIP/1002-0000000f> Playing 'digits/0.ulaw' (language 'en') -- <SIP/1002-0000000f> Playing 'digits/0.ulaw' (language 'en') -- <SIP/1002-0000000f> Playing 'digits/0.ulaw' (language 'en') == Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'SIP/1002-0000000f' in macro 'vm' == Spawn extension (macro-exten-vm, s, 23) exited non-zero on 'SIP/1002-0000000f' in macro 'exten-vm' == Spawn extension (ext-local, 2000, 2) exited non-zero on 'SIP/1002-0000000f' -- Executing [[email protected]:1] Macro("SIP/1002-0000000f", "hangupcall,") in new stack -- Executing [[email protected]:1] GotoIf("SIP/1002-0000000f", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) -- Executing [[email protected]:3] ExecIf("SIP/1002-0000000f", "0?Set(CDR(recordingfile)=)") in new stack -- Executing [[email protected]:4] Hangup("SIP/1002-0000000f", "") in new stack == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/1002-0000000f' in macro 'hangupcall' == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/1002-0000000f'

All external calls are routed to CUCM, and use a translation pattern to hit extension 1002. When I call my external DID, 1002 rings. I let it ring, and go to voicemail. Where the voicemail greeting for 1002 should pop up, I get the voicemail pilot. Here is the output:

== Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 -- Executing [[email protected]:1] Set("SIP/voipms-00000013", "__DIRECTION=INBOUND") in new stack -- Executing [[email protected]:2] Gosub("SIP/voipms-00000013", "sub-record-check,s,1(in,6666666666,dontcare)") in new stack -- Executing [[email protected]:1] GotoIf("SIP/voipms-00000013", "0?initialized") in new stack -- Executing [[email protected]:2] Set("SIP/voipms-00000013", "__REC_STATUS=INITIALIZED") in new stack -- Executing [[email protected]:3] Set("SIP/voipms-00000013", "NOW=1484613029") in new stack -- Executing [[email protected]:4] Set("SIP/voipms-00000013", "__DAY=16") in new stack -- Executing [[email protected]:5] Set("SIP/voipms-00000013", "__MONTH=01") in new stack -- Executing [[email protected]:6] Set("SIP/voipms-00000013", "__YEAR=2017") in new stack -- Executing [[email protected]:7] Set("SIP/voipms-00000013", "__TIMESTR=20170116-193029") in new stack -- Executing [[email protected]:8] Set("SIP/voipms-00000013", "__FROMEXTEN=unknown") in new stack -- Executing [[email protected]:9] Set("SIP/voipms-00000013", "__MON_FMT=wav") in new stack -- Executing [[email protected]:10] NoOp("SIP/voipms-00000013", "Recordings initialized") in new stack -- Executing [[email protected]:11] ExecIf("SIP/voipms-00000013", "0?Set(ARG3=dontcare)") in new stack -- Executing [[email protected]:12] Set("SIP/voipms-00000013", "REC_POLICY_MODE_SAVE=") in new stack -- Executing [[email protected]:13] ExecIf("SIP/voipms-00000013", "0?Set(REC_STATUS=NO)") in new stack -- Executing [[email protected]:14] GotoIf("SIP/voipms-00000013", "2?checkaction") in new stack -- Goto (sub-record-check,s,17) -- Executing [[email protected]:17] GotoIf("SIP/voipms-00000013", "1?sub-record-check,in,1") in new stack -- Goto (sub-record-check,in,1) -- Executing [[email protected]:1] NoOp("SIP/voipms-00000013", "Inbound Recording Check to 6666666666") in new stack -- Executing [[email protected]:2] Set("SIP/voipms-00000013", "FROMEXTEN=unknown") in new stack -- Executing [[email protected]:3] ExecIf("SIP/voipms-00000013", "10?Set(FROMEXTEN=5555555555)") in new stack -- Executing [[email protected]:4] Gosub("SIP/voipms-00000013", "recordcheck,1(dontcare,in,6666666666)") in new stack -- Executing [[email protected]:1] NoOp("SIP/voipms-00000013", "Starting recording check against dontcare") in new stack -- Executing [[email protected]:2] Goto("SIP/voipms-00000013", "dontcare") in new stack -- Goto (sub-record-check,recordcheck,3) -- Executing [[email protected]:3] Return("SIP/voipms-00000013", "") in new stack -- Executing [[email protected]:5] Return("SIP/voipms-00000013", "") in new stack -- Executing [[email protected]:3] Gosub("SIP/voipms-00000013", "app-blacklist-check,s,1()") in new stack -- Executing [[email protected]:1] GotoIf("SIP/voipms-00000013", "0?blacklisted") in new stack -- Executing [[email protected]:2] Set("SIP/voipms-00000013", "CALLED_BLACKLIST=1") in new stack -- Executing [[email protected]:3] Return("SIP/voipms-00000013", "") in new stack -- Executing [[email protected]:4] Set("SIP/voipms-00000013", "__FROM_DID=6666666666") in new stack -- Executing [[email protected]:5] Set("SIP/voipms-00000013", "CDR(did)=6666666666") in new stack -- Executing [[email protected]:6] ExecIf("SIP/voipms-00000013", "0 ?Set(CALLERID(name)=5555555555)") in new stack -- Executing [[email protected]:7] Set("SIP/voipms-00000013", "__MOHCLASS=") in new stack -- Executing [[email protected]:8] Set("SIP/voipms-00000013", "__REVERSAL_REJECT=FALSE") in new stack -- Executing [[email protected]:9] GotoIf("SIP/voipms-00000013", "1?post-reverse-charge") in new stack -- Goto (from-trunk,6666666666,11) -- Executing [[email protected]:11] NoOp("SIP/voipms-00000013", "") in new stack -- Executing [[email protected]:12] Set("SIP/voipms-00000013", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack -- Executing [[email protected]:13] Set("SIP/voipms-00000013", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack -- Executing [[email protected]:14] Set("SIP/voipms-00000013", "CALLERID(name-pres)=allowed_not_screened") in new stack -- Executing [[email protected]:15] Set("SIP/voipms-00000013", "CALLERID(num-pres)=allowed_not_screened") in new stack -- Executing [[email protected]:16] NoOp("SIP/voipms-00000013", "CallerID Entry Point") in new stack -- Executing [[email protected]:17] Goto("SIP/voipms-00000013", "ext-trunk,3,1") in new stack -- Goto (ext-trunk,3,1) -- Executing [[email protected]:1] Set("SIP/voipms-00000013", "TDIAL_STRING=SIP/cucm") in new stack -- Executing [[email protected]:2] Set("SIP/voipms-00000013", "DIAL_TRUNK=3") in new stack -- Executing [[email protected]:3] Goto("SIP/voipms-00000013", "ext-trunk,tdial,1") in new stack -- Goto (ext-trunk,tdial,1) -- Executing [[email protected]:1] Set("SIP/voipms-00000013", "OUTBOUND_GROUP=OUT_3") in new stack -- Executing [[email protected]:2] GotoIf("SIP/voipms-00000013", "1?nomax") in new stack -- Goto (ext-trunk,tdial,4) -- Executing [[email protected]:4] ExecIf("SIP/voipms-00000013", "1?Set(CALLERPRES(name-pres)=allowed_not_screened)") in new stack -- Executing [[email protected]:5] ExecIf("SIP/voipms-00000013", "1?Set(CALLERPRES(num-pres)=allowed_not_screened)") in new stack -- Executing [[email protected]:6] Set("SIP/voipms-00000013", "DIAL_NUMBER=6666666666") in new stack -- Executing [[email protected]:7] GosubIf("SIP/voipms-00000013", "0?sub-flp-3,s,1()") in new stack -- Executing [[email protected]:8] Set("SIP/voipms-00000013", "OUTNUM=6666666666") in new stack -- Executing [[email protected]:9] Set("SIP/voipms-00000013", "DIAL_TRUNK_OPTIONS=T") in new stack -- Executing [[email protected]:10] Dial("SIP/voipms-00000013", "SIP/cucm/6666666666,300,T") in new stack == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 -- Called SIP/cucm/6666666666 == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 -- Executing [[email protected]:1] Macro("SIP/172.16.2.48-00000015", "user-callerid,") in new stack -- Executing [[email protected]:1] Set("SIP/172.16.2.48-00000015", "TOUCH_MONITOR=1484613029.21") in new stack -- Executing [[email protected]:2] Set("SIP/172.16.2.48-00000015", "AMPUSER=5555555555") in new stack -- Executing [[email protected]:3] GotoIf("SIP/172.16.2.48-00000015", "0?report") in new stack -- Executing [[email protected]:4] ExecIf("SIP/172.16.2.48-00000015", "1?Set(REALCALLERIDNUM=5555555555)") in new stack -- Executing [[email protected]:5] Set("SIP/172.16.2.48-00000015", "AMPUSER=") in new stack -- Executing [[email protected]:6] GotoIf("SIP/172.16.2.48-00000015", "0?limit") in new stack -- Executing [[email protected]:7] Set("SIP/172.16.2.48-00000015", "AMPUSERCIDNAME=") in new stack -- Executing [[email protected]:8] GotoIf("SIP/172.16.2.48-00000015", "1?report") in new stack -- Goto (macro-user-callerid,s,15) -- Executing [[email protected]:15] GotoIf("SIP/172.16.2.48-00000015", "0?continue") in new stack -- Executing [[email protected]:16] ExecIf("SIP/172.16.2.48-00000015", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack -- Executing [[email protected]:17] Set("SIP/172.16.2.48-00000015", "__TTL=64") in new stack -- Executing [[email protected]:18] GotoIf("SIP/172.16.2.48-00000015", "1?continue") in new stack -- Goto (macro-user-callerid,s,29) -- Executing [[email protected]:29] Set("SIP/172.16.2.48-00000015", "CALLERID(number)=5555555555") in new stack -- Executing [[email protected]:30] Set("SIP/172.16.2.48-00000015", "CALLERID(name)=5555555555") in new stack -- Executing [[email protected]:31] GotoIf("SIP/172.16.2.48-00000015", "0?cnum") in new stack -- Executing [[email protected]:32] Set("SIP/172.16.2.48-00000015", "CDR(cnam)=5555555555") in new stack -- Executing [[email protected]:33] Set("SIP/172.16.2.48-00000015", "CDR(cnum)=5555555555") in new stack -- Executing [[email protected]:34] Set("SIP/172.16.2.48-00000015", "CHANNEL(language)=en") in new stack -- Executing [[email protected]:2] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(name-charset,i)=utf8") in new stack -- Executing [[email protected]:3] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(name,i)=My Voicemail") in new stack -- Executing [[email protected]:4] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(num,i)=") in new stack -- Executing [[email protected]:5] Answer("SIP/172.16.2.48-00000015", "") in new stack -- SIP/cucm-00000014 answered SIP/voipms-00000013 -- Executing [[email protected]:6] Wait("SIP/172.16.2.48-00000015", "1") in new stack -- Channel SIP/cucm-00000014 joined 'simple_bridge' basic-bridge <8094e570-b59f-4445-890e-b940cab3e0a0> -- Channel SIP/voipms-00000013 joined 'simple_bridge' basic-bridge <8094e570-b59f-4445-890e-b940cab3e0a0> -- Executing [[email protected]:7] Macro("SIP/172.16.2.48-00000015", "get-vmcontext,") in new stack -- Executing [[email protected]:1] Set("SIP/172.16.2.48-00000015", "VMCONTEXT=") in new stack -- Executing [[email protected]:2] GotoIf("SIP/172.16.2.48-00000015", "1?200:300") in new stack -- Goto (macro-get-vmcontext,s,200) -- Executing [[email protected]:200] Set("SIP/172.16.2.48-00000015", "VMCONTEXT=default") in new stack [2017-01-16 19:30:31] ERROR[6947][C-00000012]: app_voicemail.c:12511 acf_vm_info: VM_INFO requires an argument (<mailbox>[@<context>],attribute[,folder]) [2017-01-16 19:30:31] WARNING[6947][C-00000012]: func_logic.c:192 acf_if: Syntax IF(<expr>?[<true>][:<false>]) (expr must be non-null, and either <true> or <false> must be non-null) [2017-01-16 19:30:31] WARNING[6947][C-00000012]: func_logic.c:193 acf_if: In this case, <expr>='', <true>='SUCCESS', and <false>='FAILED' -- Executing [[email protected]:8] Set("SIP/172.16.2.48-00000015", "VMBOXEXISTSSTATUS=") in new stack -- Executing [[email protected]:9] GotoIf("SIP/172.16.2.48-00000015", "0?mbexist") in new stack -- Executing [[email protected]:10] VoiceMailMain("SIP/172.16.2.48-00000015", "") in new stack -- <SIP/172.16.2.48-00000015> Playing 'vm-login.ulaw' (language 'en') -- Channel SIP/voipms-00000013 left 'simple_bridge' basic-bridge <8094e570-b59f-4445-890e-b940cab3e0a0> == Spawn extension (ext-trunk, tdial, 10) exited non-zero on 'SIP/voipms-00000013' -- Channel SIP/cucm-00000014 left 'simple_bridge' basic-bridge <8094e570-b59f-4445-890e-b940cab3e0a0> [2017-01-16 19:30:35] WARNING[6947][C-00000012]: app_voicemail.c:10999 vm_authenticate: Couldn't read username -- Executing [[email protected]:1] Macro("SIP/172.16.2.48-00000015", "hangupcall") in new stack -- Executing [[email protected]:1] GotoIf("SIP/172.16.2.48-00000015", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) -- Executing [[email protected]:3] ExecIf("SIP/172.16.2.48-00000015", "0?Set(CDR(recordingfile)=)") in new stack -- Executing [[email protected]:4] Hangup("SIP/172.16.2.48-00000015", "") in new stack == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/172.16.2.48-00000015' in macro 'hangupcall' == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/172.16.2.48-00000015'

For reference, I masked the dialed phone number coming into FreePBX as “5555555555” and masked my DID as “6666666666”. I apologize for the lengthy post, but wanted to provide the output as I see.

You want to check inbound voicemail calls to FreePBX for the channel variable ${CALLERID(rdnis)}. If this var is populated, then it is a caller who wants to leave a message. If not, then it is a user who wan’t to check their voicemail.

Still not getting this to work properly. Unfortunately most articles on the internet date back to older versions of Asterisk. I created this within extensions_custom.conf:

[ciscovm-custom] exten => 5800,1,GotoIf($["${CALLERID(rdnis)}" = ""]?400) exten => 5800,2,MailboxExists(${CALLERID(rdnis)}@default) exten => 5800,3,Congestion exten => 5800,103,103,Voicemail(su${CALLERID(rdnis)}) exten => 5800,104,Playback(vm-goodbye) exten => 5800,105,Hangup exten => 5800,400,VoicemailMain

5800 is my voicemail pilot. I tried putting the “ciscovm-custom” as the context for the trunk, for the extension, and the “vm context” for the extension, but no go. I either end up getting a fast busy, or best case scenario the “comedian mail” when dialed from another extension. I can clearly see that caller ID is being passed so I don’t understand why it’s not working. Can you suggest anything else?