Voicemail just records a dial tone

Hi all,

I’ve got a very annoying issue where most of my voicemails get recorded as just a dial tone. I have a feeling there’s something somewhere causing Asterisk to think that the caller hung up as the voicemail picks up, but since I’m pretty new to Asterisk and FreePBX I don’t know where to start looking. It’s not every single call, but it seems like a majority of them. Any time I personally call it always works. A few may be from people hanging up and not leaving a voicemail, but I know for a fact most of them are people really trying to leave voicemails (they usually leave one on my cell or call my cell and tell me they left a message).

I’m using a Digium TDM410P with an FXS and an FXO module. I use a Charter phone line. I’ve got it set up with a DAHDI Trunk. I’m running all this on an old Dell PowerEdge 800 server that I inherited from a client of mine. I’m using FreePBX 2.10.1.9, all my modules are up to date.

Any help would be great. Thanks!

Dialtone indicates the calling party has hung up, set your “far-end disconnect supervision” to whatever is appropriate fo your provider , busydetect if none available to eliminate/reduce those recordings.

Thank you for the reply. They have NOT hung up, that’s the problem. People ask me constantly if I heard their message, but all I heard was dial tone.

Where do I go to enable those? Also, how do I know what the “appropriate” setting is?

Thanks!

Unless you have a very broken system, they have hungup, neither the voicemail app nor the dadhi channel synthesize dialtone, that dialtone must be from your from your telco, they sent it after the caller hungup but your system did not recognize the hangup signal they sent you. You can prove that by by sticking a “butt set” on the line ( an ordinary phone will do at a pinch) when the condition occurs.

Check with your telco as how they provide that “hangup signal”, it varies by provider and country, when you know you , set it up in the dahdi configuration.

That makes sense, thank you. I’ll have to call them and see what they offer for disconnect supervision.

The problem persists. I called Charter and they didn’t seem to know what I was talking about when I asked about hangup detection. The folks at Digium seem to think it’s a dial plan issue. Below is a log of a confirmed call that did leave a message, but all I got was a dial tone.

[2014-02-06 14:47:14] VERBOSE[19541] sig_analog.c: – Starting simple switch on ‘DAHDI/1-1’
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:1] ExecIf(“DAHDI/1-1”, “1?Set(__FROM_DID=s)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:2] Gosub(“DAHDI/1-1”, “app-blacklist-check,s,1()”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@app-blacklist-check:1] GotoIf(“DAHDI/1-1”, “0?blacklisted”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@app-blacklist-check:2] Set(“DAHDI/1-1”, “CALLED_BLACKLIST=1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@app-blacklist-check:3] Return(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:3] Set(“DAHDI/1-1”, “CDR(did)=s”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:4] ExecIf(“DAHDI/1-1”, “0 ?Set(CALLERID(name)=7759721077)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:5] Set(“DAHDI/1-1”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:6] Set(“DAHDI/1-1”, “CALLERPRES()=allowed_not_screened”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:7] Set(“DAHDI/1-1”, “__ALERT_INFO=Simple-1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@from-pstn:8] Goto(“DAHDI/1-1”, “ext-group,200,1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (ext-group,200,1)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:1] Macro(“DAHDI/1-1”, “user-callerid,”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:1] Set(“DAHDI/1-1”, “AMPUSER=7759721077”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“DAHDI/1-1”, “0?report”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“DAHDI/1-1”, “1?Set(REALCALLERIDNUM=7759721077)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:4] Set(“DAHDI/1-1”, “AMPUSER=”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:5] Set(“DAHDI/1-1”, “AMPUSERCIDNAME=”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“DAHDI/1-1”, “1?report”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (macro-user-callerid,s,13)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:13] GotoIf(“DAHDI/1-1”, “0?continue”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:14] Set(“DAHDI/1-1”, “__TTL=64”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“DAHDI/1-1”, “1?continue”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (macro-user-callerid,s,26)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:26] Set(“DAHDI/1-1”, “CALLERID(number)=7759721077”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:27] Set(“DAHDI/1-1”, “CALLERID(name)=WISE, NITA”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:28] Set(“DAHDI/1-1”, “CHANNEL(language)=en”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:2] Macro(“DAHDI/1-1”, “blkvm-setifempty,”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-setifempty:1] GotoIf(“DAHDI/1-1”, “1?init”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (macro-blkvm-setifempty,s,4)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-setifempty:4] Set(“DAHDI/1-1”, “__BLKVM_CHANNEL=DAHDI/1-1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-setifempty:5] Set(“DAHDI/1-1”, “SHARED(BLKVM,DAHDI/1-1)=TRUE”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-setifempty:6] Set(“DAHDI/1-1”, “GOSUB_RETVAL=TRUE”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-setifempty:7] MacroExit(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:3] GotoIf(“DAHDI/1-1”, “1?skipov”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (ext-group,200,6)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:6] Set(“DAHDI/1-1”, “RRNODEST=”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:7] Set(“DAHDI/1-1”, “__NODEST=200”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:8] GosubIf(“DAHDI/1-1”, “0?sub-rgsetcid,s,1()”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:9] Gosub(“DAHDI/1-1”, “sub-record-check,s,1(rg,200,always)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:1] GotoIf(“DAHDI/1-1”, “1?check”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (sub-record-check,s,6)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:6] Set(“DAHDI/1-1”, “__MON_FMT=wav”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:7] GotoIf(“DAHDI/1-1”, “1?next”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (sub-record-check,s,10)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:10] ExecIf(“DAHDI/1-1”, “0?Return()”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:11] GotoIf(“DAHDI/1-1”, “0?rg,1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:12] Set(“DAHDI/1-1”, “__REC_STATUS=INITIALIZED”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:13] ExecIf(“DAHDI/1-1”, “1?Set(__REC_POLICY_MODE=always)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:14] Set(“DAHDI/1-1”, “NOW=1391726835”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:15] Set(“DAHDI/1-1”, “__DAY=06”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:16] Set(“DAHDI/1-1”, “__MONTH=02”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:17] Set(“DAHDI/1-1”, “__YEAR=2014”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:18] Set(“DAHDI/1-1”, “__TIMESTR=20140206-144715”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:19] Set(“DAHDI/1-1”, “__FROMEXTEN=7759721077”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:20] Set(“DAHDI/1-1”, “__CALLFILENAME=rg-200-7759721077-20140206-144715-1391726834.57”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@sub-record-check:21] Goto(“DAHDI/1-1”, “rg,1”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (sub-record-check,rg,1)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [rg@sub-record-check:1] GosubIf(“DAHDI/1-1”, “1?record,1(rg,always,7759721077)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [record@sub-record-check:1] Set(“DAHDI/1-1”, “AUDIOHOOK_INHERIT(MixMonitor)=yes”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [record@sub-record-check:2] MixMonitor(“DAHDI/1-1”, “2014/02/06/rg-200-7759721077-20140206-144715-1391726834.57.wav,”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [record@sub-record-check:3] Set(“DAHDI/1-1”, “__REC_STATUS=RECORDING”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [record@sub-record-check:4] Set(“DAHDI/1-1”, “CDR(recordingfile)=rg-200-7759721077-20140206-144715-1391726834.57.wav”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [record@sub-record-check:5] Return(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [rg@sub-record-check:2] Return(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:10] Set(“DAHDI/1-1”, “RingGroupMethod=ringall”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [200@ext-group:11] Macro(“DAHDI/1-1”, “dial,20,tr,100-101-102”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-dial:1] GotoIf(“DAHDI/1-1”, “1?dial”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Goto (macro-dial,s,3)
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-dial:3] AGI(“DAHDI/1-1”, “dialparties.agi”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2014-02-06 14:47:15] VERBOSE[19542] app_mixmonitor.c: == Begin MixMonitor Recording DAHDI/1-1
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: dialparties.agi: Caller ID name is ‘WISE, NITA’ number is ‘7759721077’
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – AGI Script Executing Application: (SIPAddHeader) Options: (Alert-Info:Simple-1)
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: dialparties.agi: Methodology of ring is ‘ringall’
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Added extension 100 to extension map
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Added extension 101 to extension map
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Added extension 102 to extension map
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 100 cf is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 101 cf is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 102 cf is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 100 do not disturb is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 101 do not disturb is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Extension 102 do not disturb is disabled
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: dbset CALLTRACE/100 to 7759721077
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: dbset CALLTRACE/101 to 7759721077
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: dbset CALLTRACE/102 to 7759721077
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – dialparties.agi: Filtered ARG3: 100-101-102
[2014-02-06 14:47:15] VERBOSE[19541] res_agi.c: – <DAHDI/1-1>AGI Script dialparties.agi completed, returning 0
[2014-02-06 14:47:15] VERBOSE[19541] pbx.c: – Executing [s@macro-dial:7] Dial(“DAHDI/1-1”, “DAHDI/3&SIP/101&SIP/102,20,trM(auto-blkvm)”) in new stack
[2014-02-06 14:47:15] VERBOSE[19541] app_dial.c: – Called DAHDI/3
[2014-02-06 14:47:15] WARNING[19541] app_dial.c: Unable to create channel of type ‘SIP’ (cause 20 - Unknown)
[2014-02-06 14:47:15] VERBOSE[19541] netsock2.c: == Using SIP RTP TOS bits 184
[2014-02-06 14:47:15] VERBOSE[19541] netsock2.c: == Using SIP RTP CoS mark 5
[2014-02-06 14:47:15] VERBOSE[19541] app_dial.c: – Called SIP/102
[2014-02-06 14:47:15] VERBOSE[19541] app_dial.c: – DAHDI/3-1 is ringing
[2014-02-06 14:47:15] VERBOSE[19541] app_dial.c: – SIP/102-00000014 connected line has changed. Saving it until answer for DAHDI/1-1
[2014-02-06 14:47:15] VERBOSE[19541] app_dial.c: – SIP/102-00000014 is ringing
[2014-02-06 14:47:17] VERBOSE[19541] app_dial.c: – DAHDI/3-1 is ringing
[2014-02-06 14:47:23] VERBOSE[19541] app_dial.c: – DAHDI/3-1 is ringing
[2014-02-06 14:47:29] VERBOSE[19541] app_dial.c: – DAHDI/3-1 is ringing
[2014-02-06 14:47:35] VERBOSE[19541] app_dial.c: – DAHDI/3-1 is ringing
[2014-02-06 14:47:36] VERBOSE[19541] app_dial.c: – Nobody picked up in 20000 ms
[2014-02-06 14:47:36] VERBOSE[19541] sig_analog.c: – Hanging up on ‘DAHDI/3-1’
[2014-02-06 14:47:36] VERBOSE[19541] chan_dahdi.c: – Hungup ‘DAHDI/3-1’
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-dial:8] Set(“DAHDI/1-1”, “DIALSTATUS=NOANSWER”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-dial:9] GosubIf(“DAHDI/1-1”, “0?NOANSWER,1”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:12] Gosub(“DAHDI/1-1”, “sub-record-cancel,s,1()”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:1] ExecIf(“DAHDI/1-1”, “0?Return()”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:2] StopMixMonitor(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] app_mixmonitor.c: == MixMonitor close filestream
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:3] Set(“DAHDI/1-1”, “__REC_STATUS=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:4] Set(“DAHDI/1-1”, “MON_BASE=/var/spool/asterisk/monitor/2014/02/06/”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:5] Set(“DAHDI/1-1”, “__MON_FMT=wav”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:6] ExecIf(“DAHDI/1-1”, “47?System(rm -f /var/spool/asterisk/monitor/2014/02/06/rg-200-7759721077-20140206-144715-1391726834.57.wav)”) in new sta
ck
[2014-02-06 14:47:36] VERBOSE[19542] app_mixmonitor.c: == End MixMonitor Recording DAHDI/1-1
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:7] Set(“DAHDI/1-1”, “__CALLFILENAME=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:8] Set(“DAHDI/1-1”, “CDR(recordingfile)=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@sub-record-cancel:9] Return(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:13] Set(“DAHDI/1-1”, “RingGroupMethod=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:14] GotoIf(“DAHDI/1-1”, “0?nodest”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:15] Set(“DAHDI/1-1”, “__NODEST=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:16] Macro(“DAHDI/1-1”, “blkvm-clr,”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-clr:1] Set(“DAHDI/1-1”, “SHARED(BLKVM,DAHDI/1-1)=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-clr:2] Set(“DAHDI/1-1”, “GOSUB_RETVAL=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-clr:3] MacroExit(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [200@ext-group:17] Goto(“DAHDI/1-1”, “ext-local,vmu100,1”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (ext-local,vmu100,1)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmu100@ext-local:1] Macro(“DAHDI/1-1”, “vm,100,NOANSWER,”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-vm:1] Macro(“DAHDI/1-1”, “user-callerid,SKIPTTL”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:1] Set(“DAHDI/1-1”, “AMPUSER=7759721077”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“DAHDI/1-1”, “0?report”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“DAHDI/1-1”, “0?Set(REALCALLERIDNUM=7759721077)”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:4] Set(“DAHDI/1-1”, “AMPUSER=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:5] Set(“DAHDI/1-1”, “AMPUSERCIDNAME=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“DAHDI/1-1”, “1?report”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-user-callerid,s,13)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:13] GotoIf(“DAHDI/1-1”, “1?continue”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-user-callerid,s,26)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:26] Set(“DAHDI/1-1”, “CALLERID(number)=7759721077”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:27] Set(“DAHDI/1-1”, “CALLERID(name)=WISE, NITA”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-user-callerid:28] Set(“DAHDI/1-1”, “CHANNEL(language)=en”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-vm:2] Set(“DAHDI/1-1”, “VMGAIN=”"") in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-vm:3] Macro(“DAHDI/1-1”, “blkvm-check,”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-check:1] Set(“DAHDI/1-1”, “GOSUB_RETVAL=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-check:2] ExecIf(“DAHDI/1-1”, “0?Set(GOSUB_RETVAL=TRUE)”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-blkvm-check:3] MacroExit(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-vm:4] GotoIf(“DAHDI/1-1”, “1?vmx,1”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-vm,vmx,1)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:1] Set(“DAHDI/1-1”, “MEXTEN=100”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:2] Set(“DAHDI/1-1”, “MMODE=NOANSWER”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:3] Set(“DAHDI/1-1”, “RETVM=”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:4] Set(“DAHDI/1-1”, “MODE=unavail”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:5] GotoIf(“DAHDI/1-1”, “1?chknomsg”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-vm,vmx,8)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:8] GotoIf(“DAHDI/1-1”, “0?s-NOANSWER,1”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:9] GotoIf(“DAHDI/1-1”, “1?notdirect”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-vm,vmx,11)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:11] NoOp(“DAHDI/1-1”, “Checking if ext 100 is enabled: “) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [vmx@macro-vm:12] GotoIf(“DAHDI/1-1”, “1?s-NOANSWER,1”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-vm,s-NOANSWER,1)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s-NOANSWER@macro-vm:1] Macro(“DAHDI/1-1”, “get-vmcontext,100”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-get-vmcontext:1] Set(“DAHDI/1-1”, “VMCONTEXT=default”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-get-vmcontext:2] GotoIf(“DAHDI/1-1”, “0?200:300”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Goto (macro-get-vmcontext,s,300)
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s@macro-get-vmcontext:300] NoOp(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] pbx.c: – Executing [s-NOANSWER@macro-vm:2] VoiceMail(“DAHDI/1-1”, “100@default,u”””) in new stack
[2014-02-06 14:47:36] VERBOSE[19541] file.c: – <DAHDI/1-1> Playing ‘/var/spool/asterisk/voicemail/default/100/unavail.slin’ (language ‘en’)
[2014-02-06 14:47:44] VERBOSE[19541] file.c: – <DAHDI/1-1> Playing ‘vm-intro.ulaw’ (language ‘en’)
[2014-02-06 14:47:50] VERBOSE[19541] file.c: – <DAHDI/1-1> Playing ‘beep.ulaw’ (language ‘en’)
[2014-02-06 14:47:50] VERBOSE[19541] app_voicemail.c: – Recording the message
[2014-02-06 14:47:50] VERBOSE[19541] app.c: – x=0, open writing: /var/spool/asterisk/voicemail/default/100/tmp/hdSwnQ format: wav, 0xa3102a8
[2014-02-06 14:48:14] VERBOSE[19541] app.c: – User hung up
[2014-02-06 14:48:14] VERBOSE[19541] config.c: == Parsing ‘/var/spool/asterisk/voicemail/default/100/INBOX/msg0000.txt’: [2014-02-06 14:48:14] VERBOSE[19541] config.c: == Found
[2014-02-06 14:48:15] VERBOSE[19541] app_macro.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘DAHDI/1-1’ in macro ‘vm’
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: == Spawn extension (ext-local, vmu100, 1) exited non-zero on ‘DAHDI/1-1’
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: – Executing [h@ext-local:1] Macro(“DAHDI/1-1”, “hangupcall,”) in new stack
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“DAHDI/1-1”, “1?theend”) in new stack
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: – Goto (macro-hangupcall,s,3)
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“DAHDI/1-1”, “0?Set(CDR(recordingfile)=)”) in new stack
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“DAHDI/1-1”, “”) in new stack
[2014-02-06 14:48:15] VERBOSE[19541] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘DAHDI/1-1’ in macro ‘hangupcall’
[2014-02-06 14:48:15] VERBOSE[19541] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on ‘DAHDI/1-1’
[2014-02-06 14:48:15] VERBOSE[19541] sig_analog.c: – Hanging up on ‘DAHDI/1-1’
[2014-02-06 14:48:15] VERBOSE[19541] chan_dahdi.c: – Hungup ‘DAHDI/1-1’

Any ideas please?

I would start off by eliminating initially all possible confounding variables like ring groups follow me and call recordings just test the inbound route straight to an extension then off course to VM.