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 [s@macro-dial-one:52] ExecIf("SIP/1002-0000000f", "0?MacroExit()") in new stack
-- Executing [s@macro-dial-one:53] ExecIf("SIP/1002-0000000f", "0?Set(DIALSTATUS=)") in new stack
-- Executing [s@macro-dial-one:54] GosubIf("SIP/1002-0000000f", "0?s-BUSY,1()") in new stack
-- Executing [s@macro-dial-one:55] MacroExit("SIP/1002-0000000f", "") in new stack
-- Executing [s@macro-exten-vm:17] Set("SIP/1002-0000000f", "SV_DIALSTATUS=BUSY") in new stack
-- Executing [s@macro-exten-vm:18] GosubIf("SIP/1002-0000000f", "0?docfu,1()") in new stack
-- Executing [s@macro-exten-vm:19] GosubIf("SIP/1002-0000000f", "0?docfb,1()") in new stack
-- Executing [s@macro-exten-vm:20] Set("SIP/1002-0000000f", "DIALSTATUS=BUSY") in new stack
-- Executing [s@macro-exten-vm:21] ExecIf("SIP/1002-0000000f", "0?MacroExit()") in new stack
-- Executing [s@macro-exten-vm:22] GotoIf("SIP/1002-0000000f", "0?s-BUSY,1") in new stack
-- Executing [s@macro-exten-vm:23] Macro("SIP/1002-0000000f", "vm,2000,BUSY,") in new stack
-- Executing [s@macro-vm:1] Macro("SIP/1002-0000000f", "user-callerid,SKIPTTL") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/1002-0000000f", "TOUCH_MONITOR=1484612424.15") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/1002-0000000f", "AMPUSER=1002") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/1002-0000000f", "14?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [s@macro-user-callerid:15] GotoIf("SIP/1002-0000000f", "1?continue") in new stack
-- Goto (macro-user-callerid,s,29)
-- Executing [s@macro-user-callerid:29] Set("SIP/1002-0000000f", "CALLERID(number)=1002") in new stack
-- Executing [s@macro-user-callerid:30] Set("SIP/1002-0000000f", "CALLERID(name)=Test Softphone") in new stack
-- Executing [s@macro-user-callerid:31] GotoIf("SIP/1002-0000000f", "0?cnum") in new stack
-- Executing [s@macro-user-callerid:32] Set("SIP/1002-0000000f", "CDR(cnam)=Test Softphone") in new stack
-- Executing [s@macro-user-callerid:33] Set("SIP/1002-0000000f", "CDR(cnum)=1002") in new stack
-- Executing [s@macro-user-callerid:34] Set("SIP/1002-0000000f", "CHANNEL(language)=en") in new stack
-- Executing [s@macro-vm:2] Set("SIP/1002-0000000f", "VMGAIN=") in new stack
-- Executing [s@macro-vm:3] Macro("SIP/1002-0000000f", "blkvm-check,") in new stack
-- Executing [s@macro-blkvm-check:1] Set("SIP/1002-0000000f", "GOSUB_RETVAL=") in new stack
-- Executing [s@macro-blkvm-check:2] ExecIf("SIP/1002-0000000f", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
-- Executing [s@macro-blkvm-check:3] MacroExit("SIP/1002-0000000f", "") in new stack
-- Executing [s@macro-vm:4] GotoIf("SIP/1002-0000000f", "1?vmx,1") in new stack
-- Goto (macro-vm,vmx,1)
-- Executing [vmx@macro-vm:1] Set("SIP/1002-0000000f", "MEXTEN=2000") in new stack
-- Executing [vmx@macro-vm:2] Set("SIP/1002-0000000f", "MMODE=BUSY") in new stack
-- Executing [vmx@macro-vm:3] Set("SIP/1002-0000000f", "RETVM=") in new stack
-- Executing [vmx@macro-vm:4] Set("SIP/1002-0000000f", "MODE=busy") in new stack
-- Executing [vmx@macro-vm:5] Macro("SIP/1002-0000000f", "get-vmcontext,2000") in new stack
-- Executing [s@macro-get-vmcontext:1] Set("SIP/1002-0000000f", "VMCONTEXT=default") in new stack
-- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/1002-0000000f", "0?200:300") in new stack
-- Goto (macro-get-vmcontext,s,300)
-- Executing [s@macro-get-vmcontext:300] NoOp("SIP/1002-0000000f", "") in new stack
-- Executing [vmx@macro-vm:6] Set("SIP/1002-0000000f", "MODE=busy") in new stack
-- Executing [vmx@macro-vm:7] NoOp("SIP/1002-0000000f", "MODE IS: busy") in new stack
-- Executing [vmx@macro-vm:8] GotoIf("SIP/1002-0000000f", "1?chknomsg") in new stack
-- Goto (macro-vm,vmx,10)
-- Executing [vmx@macro-vm:10] GotoIf("SIP/1002-0000000f", "0?s-BUSY,1") in new stack
-- Executing [vmx@macro-vm:11] GotoIf("SIP/1002-0000000f", "1?notdirect") in new stack
-- Goto (macro-vm,vmx,13)
-- Executing [vmx@macro-vm:13] NoOp("SIP/1002-0000000f", "Checking if ext 2000 is enabled: ") in new stack
-- Executing [vmx@macro-vm:14] GotoIf("SIP/1002-0000000f", "1?s-BUSY,1") in new stack
-- Goto (macro-vm,s-BUSY,1)
-- Executing [s-BUSY@macro-vm:1] NoOp("SIP/1002-0000000f", "BUSY voicemail") in new stack
-- Executing [s-BUSY@macro-vm:2] Macro("SIP/1002-0000000f", "get-vmcontext,2000") in new stack
-- Executing [s@macro-get-vmcontext:1] Set("SIP/1002-0000000f", "VMCONTEXT=default") in new stack
-- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/1002-0000000f", "0?200:300") in new stack
-- Goto (macro-get-vmcontext,s,300)
-- Executing [s@macro-get-vmcontext:300] NoOp("SIP/1002-0000000f", "") in new stack
-- Executing [s-BUSY@macro-vm:3] VoiceMail("SIP/1002-0000000f", "2000@default,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 [h@ext-local:1] Macro("SIP/1002-0000000f", "hangupcall,") in new stack
-- Executing [s@macro-hangupcall:1] GotoIf("SIP/1002-0000000f", "1?theend") in new stack
-- Goto (macro-hangupcall,s,3)
-- Executing [s@macro-hangupcall:3] ExecIf("SIP/1002-0000000f", "0?Set(CDR(recordingfile)=)") in new stack
-- Executing [s@macro-hangupcall: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 [6666666666@from-trunk:1] Set("SIP/voipms-00000013", "__DIRECTION=INBOUND") in new stack
-- Executing [6666666666@from-trunk:2] Gosub("SIP/voipms-00000013", "sub-record-check,s,1(in,6666666666,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/voipms-00000013", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/voipms-00000013", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/voipms-00000013", "NOW=1484613029") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/voipms-00000013", "__DAY=16") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/voipms-00000013", "__MONTH=01") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/voipms-00000013", "__YEAR=2017") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/voipms-00000013", "__TIMESTR=20170116-193029") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/voipms-00000013", "__FROMEXTEN=unknown") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/voipms-00000013", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/voipms-00000013", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/voipms-00000013", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/voipms-00000013", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/voipms-00000013", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/voipms-00000013", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/voipms-00000013", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [in@sub-record-check:1] NoOp("SIP/voipms-00000013", "Inbound Recording Check to 6666666666") in new stack
-- Executing [in@sub-record-check:2] Set("SIP/voipms-00000013", "FROMEXTEN=unknown") in new stack
-- Executing [in@sub-record-check:3] ExecIf("SIP/voipms-00000013", "10?Set(FROMEXTEN=5555555555)") in new stack
-- Executing [in@sub-record-check:4] Gosub("SIP/voipms-00000013", "recordcheck,1(dontcare,in,6666666666)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/voipms-00000013", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/voipms-00000013", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/voipms-00000013", "") in new stack
-- Executing [in@sub-record-check:5] Return("SIP/voipms-00000013", "") in new stack
-- Executing [6666666666@from-trunk:3] Gosub("SIP/voipms-00000013", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/voipms-00000013", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/voipms-00000013", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/voipms-00000013", "") in new stack
-- Executing [6666666666@from-trunk:4] Set("SIP/voipms-00000013", "__FROM_DID=6666666666") in new stack
-- Executing [6666666666@from-trunk:5] Set("SIP/voipms-00000013", "CDR(did)=6666666666") in new stack
-- Executing [6666666666@from-trunk:6] ExecIf("SIP/voipms-00000013", "0 ?Set(CALLERID(name)=5555555555)") in new stack
-- Executing [6666666666@from-trunk:7] Set("SIP/voipms-00000013", "__MOHCLASS=") in new stack
-- Executing [6666666666@from-trunk:8] Set("SIP/voipms-00000013", "__REVERSAL_REJECT=FALSE") in new stack
-- Executing [6666666666@from-trunk:9] GotoIf("SIP/voipms-00000013", "1?post-reverse-charge") in new stack
-- Goto (from-trunk,6666666666,11)
-- Executing [6666666666@from-trunk:11] NoOp("SIP/voipms-00000013", "") in new stack
-- Executing [6666666666@from-trunk:12] Set("SIP/voipms-00000013", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
-- Executing [6666666666@from-trunk:13] Set("SIP/voipms-00000013", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
-- Executing [6666666666@from-trunk:14] Set("SIP/voipms-00000013", "CALLERID(name-pres)=allowed_not_screened") in new stack
-- Executing [6666666666@from-trunk:15] Set("SIP/voipms-00000013", "CALLERID(num-pres)=allowed_not_screened") in new stack
-- Executing [6666666666@from-trunk:16] NoOp("SIP/voipms-00000013", "CallerID Entry Point") in new stack
-- Executing [6666666666@from-trunk:17] Goto("SIP/voipms-00000013", "ext-trunk,3,1") in new stack
-- Goto (ext-trunk,3,1)
-- Executing [3@ext-trunk:1] Set("SIP/voipms-00000013", "TDIAL_STRING=SIP/cucm") in new stack
-- Executing [3@ext-trunk:2] Set("SIP/voipms-00000013", "DIAL_TRUNK=3") in new stack
-- Executing [3@ext-trunk:3] Goto("SIP/voipms-00000013", "ext-trunk,tdial,1") in new stack
-- Goto (ext-trunk,tdial,1)
-- Executing [tdial@ext-trunk:1] Set("SIP/voipms-00000013", "OUTBOUND_GROUP=OUT_3") in new stack
-- Executing [tdial@ext-trunk:2] GotoIf("SIP/voipms-00000013", "1?nomax") in new stack
-- Goto (ext-trunk,tdial,4)
-- Executing [tdial@ext-trunk:4] ExecIf("SIP/voipms-00000013", "1?Set(CALLERPRES(name-pres)=allowed_not_screened)") in new stack
-- Executing [tdial@ext-trunk:5] ExecIf("SIP/voipms-00000013", "1?Set(CALLERPRES(num-pres)=allowed_not_screened)") in new stack
-- Executing [tdial@ext-trunk:6] Set("SIP/voipms-00000013", "DIAL_NUMBER=6666666666") in new stack
-- Executing [tdial@ext-trunk:7] GosubIf("SIP/voipms-00000013", "0?sub-flp-3,s,1()") in new stack
-- Executing [tdial@ext-trunk:8] Set("SIP/voipms-00000013", "OUTNUM=6666666666") in new stack
-- Executing [tdial@ext-trunk:9] Set("SIP/voipms-00000013", "DIAL_TRUNK_OPTIONS=T") in new stack
-- Executing [tdial@ext-trunk: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 [5800@from-internal:1] Macro("SIP/172.16.2.48-00000015", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/172.16.2.48-00000015", "TOUCH_MONITOR=1484613029.21") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/172.16.2.48-00000015", "AMPUSER=5555555555") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/172.16.2.48-00000015", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("SIP/172.16.2.48-00000015", "1?Set(REALCALLERIDNUM=5555555555)") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/172.16.2.48-00000015", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/172.16.2.48-00000015", "0?limit") in new stack
-- Executing [s@macro-user-callerid:7] Set("SIP/172.16.2.48-00000015", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:8] GotoIf("SIP/172.16.2.48-00000015", "1?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [s@macro-user-callerid:15] GotoIf("SIP/172.16.2.48-00000015", "0?continue") in new stack
-- Executing [s@macro-user-callerid:16] ExecIf("SIP/172.16.2.48-00000015", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
-- Executing [s@macro-user-callerid:17] Set("SIP/172.16.2.48-00000015", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:18] GotoIf("SIP/172.16.2.48-00000015", "1?continue") in new stack
-- Goto (macro-user-callerid,s,29)
-- Executing [s@macro-user-callerid:29] Set("SIP/172.16.2.48-00000015", "CALLERID(number)=5555555555") in new stack
-- Executing [s@macro-user-callerid:30] Set("SIP/172.16.2.48-00000015", "CALLERID(name)=5555555555") in new stack
-- Executing [s@macro-user-callerid:31] GotoIf("SIP/172.16.2.48-00000015", "0?cnum") in new stack
-- Executing [s@macro-user-callerid:32] Set("SIP/172.16.2.48-00000015", "CDR(cnam)=5555555555") in new stack
-- Executing [s@macro-user-callerid:33] Set("SIP/172.16.2.48-00000015", "CDR(cnum)=5555555555") in new stack
-- Executing [s@macro-user-callerid:34] Set("SIP/172.16.2.48-00000015", "CHANNEL(language)=en") in new stack
-- Executing [5800@from-internal:2] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(name-charset,i)=utf8") in new stack
-- Executing [5800@from-internal:3] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(name,i)=My Voicemail") in new stack
-- Executing [5800@from-internal:4] Set("SIP/172.16.2.48-00000015", "CONNECTEDLINE(num,i)=") in new stack
-- Executing [5800@from-internal:5] Answer("SIP/172.16.2.48-00000015", "") in new stack
-- SIP/cucm-00000014 answered SIP/voipms-00000013
-- Executing [5800@from-internal: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 [5800@from-internal:7] Macro("SIP/172.16.2.48-00000015", "get-vmcontext,") in new stack
-- Executing [s@macro-get-vmcontext:1] Set("SIP/172.16.2.48-00000015", "VMCONTEXT=") in new stack
-- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/172.16.2.48-00000015", "1?200:300") in new stack
-- Goto (macro-get-vmcontext,s,200)
-- Executing [s@macro-get-vmcontext: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 [5800@from-internal:8] Set("SIP/172.16.2.48-00000015", "VMBOXEXISTSSTATUS=") in new stack
-- Executing [5800@from-internal:9] GotoIf("SIP/172.16.2.48-00000015", "0?mbexist") in new stack
-- Executing [5800@from-internal: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 [h@from-internal:1] Macro("SIP/172.16.2.48-00000015", "hangupcall") in new stack
-- Executing [s@macro-hangupcall:1] GotoIf("SIP/172.16.2.48-00000015", "1?theend") in new stack
-- Goto (macro-hangupcall,s,3)
-- Executing [s@macro-hangupcall:3] ExecIf("SIP/172.16.2.48-00000015", "0?Set(CDR(recordingfile)=)") in new stack
-- Executing [s@macro-hangupcall: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.