Voicemail not being recorded on Custom Device

Asterisk Asterisk SIP
1

We recently added several custom devices to act as virtual extensions so that a single phone will ring on two different extensions. For some reason, the voicemail is not working on the new custom device extension. When dialing in (either from an outside line or internally) it goes to the voicemail prompts and allows you to leave a message, but it never gets saved. The log shows that the “User hung up”, even though they did not. Any ideas on a resolution? Portion of the log is below.

[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] app_dial.c: Nobody picked up in 15000 ms
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-dial-one:45] ExecIf("SIP/Vitelity_MKLM-0000035c", "0?MacroExit()") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-dial-one:46] ExecIf("SIP/Vitelity_MKLM-0000035c", "0?Set(DIALSTATUS=)") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-dial-one:47] GosubIf("SIP/Vitelity_MKLM-0000035c", "0?s-NOANSWER,1()") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-dial-one:48] MacroExit("SIP/Vitelity_MKLM-0000035c", "") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-exten-vm:17] Set("SIP/Vitelity_MKLM-0000035c", "SV_DIALSTATUS=NOANSWER") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-exten-vm:18] GosubIf("SIP/Vitelity_MKLM-0000035c", "0?docfu,1()") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-exten-vm:19] GosubIf("SIP/Vitelity_MKLM-0000035c", "0?docfb,1()") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-exten-vm:20] Set("SIP/Vitelity_MKLM-0000035c", "DIALSTATUS=NOANSWER") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-exten-vm:21] ExecIf("SIP/Vitelity_MKLM-0000035c", "1?MacroExit()") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [1100@from-internal:3] Set("SIP/Vitelity_MKLM-0000035c", "__PICKUPMARK=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [1100@from-internal:4] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?ext-local,vmu1100,1") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (ext-local,vmu1100,1)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmu1100@ext-local:1] Macro("SIP/Vitelity_MKLM-0000035c", "vm,1100,NOANSWER,") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-vm:1] Macro("SIP/Vitelity_MKLM-0000035c", "user-callerid,SKIPTTL") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/Vitelity_MKLM-0000035c", "TOUCH_MONITOR=1550007121.1562213") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/Vitelity_MKLM-0000035c", "AMPUSER=9198165636") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/Vitelity_MKLM-0000035c", "0?report") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/Vitelity_MKLM-0000035c", "0?Set(REALCALLERIDNUM=9198165636)") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/Vitelity_MKLM-0000035c", "AMPUSER=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/Vitelity_MKLM-0000035c", "0?limit") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/Vitelity_MKLM-0000035c", "AMPUSERCIDNAME=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?report") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?continue") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-user-callerid,s,28)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:28] Set("SIP/Vitelity_MKLM-0000035c", "CALLERID(number)=9198165636") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/Vitelity_MKLM-0000035c", "CALLERID(name)=MKLM:9198165636") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/Vitelity_MKLM-0000035c", "CDR(cnum)=9198165636") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/Vitelity_MKLM-0000035c", "CDR(cnam)=MKLM:9198165636") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/Vitelity_MKLM-0000035c", "CHANNEL(language)=en") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-vm:2] Set("SIP/Vitelity_MKLM-0000035c", "VMGAIN=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-vm:3] Macro("SIP/Vitelity_MKLM-0000035c", "blkvm-check,") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-blkvm-check:1] Set("SIP/Vitelity_MKLM-0000035c", "GOSUB_RETVAL=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-blkvm-check:2] ExecIf("SIP/Vitelity_MKLM-0000035c", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-blkvm-check:3] MacroExit("SIP/Vitelity_MKLM-0000035c", "") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-vm:4] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?vmx,1") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-vm,vmx,1)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:1] Set("SIP/Vitelity_MKLM-0000035c", "MEXTEN=1100") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:2] Set("SIP/Vitelity_MKLM-0000035c", "MMODE=NOANSWER") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:3] Set("SIP/Vitelity_MKLM-0000035c", "RETVM=") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:4] Set("SIP/Vitelity_MKLM-0000035c", "MODE=unavail") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:5] Macro("SIP/Vitelity_MKLM-0000035c", "get-vmcontext,1100") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/Vitelity_MKLM-0000035c", "VMCONTEXT=default") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Vitelity_MKLM-0000035c", "0?200:300") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("SIP/Vitelity_MKLM-0000035c", "") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:6] Set("SIP/Vitelity_MKLM-0000035c", "MODE=unavail") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:7] NoOp("SIP/Vitelity_MKLM-0000035c", "MODE IS: unavail") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:8] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?chknomsg") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-vm,vmx,10)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:10] GotoIf("SIP/Vitelity_MKLM-0000035c", "0?s-NOANSWER,1") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:11] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?notdirect") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-vm,vmx,13)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:13] NoOp("SIP/Vitelity_MKLM-0000035c", "Checking if ext 1100 is enabled: ") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [vmx@macro-vm:14] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?s-NOANSWER,1") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-vm,s-NOANSWER,1)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s-NOANSWER@macro-vm:1] Macro("SIP/Vitelity_MKLM-0000035c", "get-vmcontext,1100") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/Vitelity_MKLM-0000035c", "VMCONTEXT=default") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Vitelity_MKLM-0000035c", "0?200:300") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("SIP/Vitelity_MKLM-0000035c", "") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] pbx.c: Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/Vitelity_MKLM-0000035c", "1100@default,u") in new stack
[2019-02-12 16:32:23] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'vm-theperson.gsm' (language 'en')
[2019-02-12 16:32:25] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'digits/1.gsm' (language 'en')
[2019-02-12 16:32:26] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'digits/1.gsm' (language 'en')
[2019-02-12 16:32:26] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'digits/0.gsm' (language 'en')
[2019-02-12 16:32:27] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'digits/0.gsm' (language 'en')
[2019-02-12 16:32:28] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'vm-isunavail.gsm' (language 'en')
[2019-02-12 16:32:29] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'vm-intro.gsm' (language 'en')
[2019-02-12 16:32:35] VERBOSE[31089][C-00022a73] file.c: <SIP/Vitelity_MKLM-0000035c> Playing 'beep.gsm' (language 'en')
[2019-02-12 16:32:35] VERBOSE[31089][C-00022a73] app_voicemail.c: Recording the message
[2019-02-12 16:32:35] VERBOSE[31089][C-00022a73] app.c: x=0, open writing: /var/spool/asterisk/voicemail/default/1100/tmp/D1CPgW format: wav, 0xb2aeb8ac
[2019-02-12 16:32:35] VERBOSE[31089][C-00022a73] app.c: x=1, open writing: /var/spool/asterisk/voicemail/default/1100/tmp/D1CPgW format: wav49, 0xb2c1615c
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] app.c: User hung up
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] app_macro.c: Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/Vitelity_MKLM-0000035c' in macro 'vm'
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx.c: Spawn extension (ext-local, vmu1100, 1) exited non-zero on 'SIP/Vitelity_MKLM-0000035c'
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx.c: Executing [h@ext-local:1] Macro("SIP/Vitelity_MKLM-0000035c", "hangupcall,") in new stack
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/Vitelity_MKLM-0000035c", "1?theend") in new stack
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx.c: Executing [s@macro-hangupcall:3] Hangup("SIP/Vitelity_MKLM-0000035c", "") in new stack
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] app_macro.c: Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/Vitelity_MKLM-0000035c' in macro 'hangupcall'
[2019-02-12 16:32:45] VERBOSE[31089][C-00022a73] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/Vitelity_MKLM-0000035c'type or paste code here
2

Asterisk has custom device states, not custom devices, or, at least, that is what Google thinks and used to be true.

The dialplan is complex, and uses macros.

That makes me think this is a FreePBX issue.

Also, given that FreePBX and Asterisk use the word “extension” in different ways, so I can’t work out if you mean:

exten => 1000,1,Dial(SIP/aabbccdd)
exten => 2000,1,Dial(SIP/aabbccdd)

which is basically Asterisk terminology, or

exten => 1000,1,Dial(SIP/aabbccdd&SIP/ffeeddcc)

which would be more in line with FreePBX terminology.

If this is a FreePBX issue, you probably want https://community.freepbx.org/

3

Logs shows voceimail message has been saved, instead of use FreePBX custom extension option, try to create regular sip one and use it for voicemail holder