Possible DTMF / Voicemail Issue?

Hi,

I’m having an issue where an incoming call is going to voicemail and the caller can hear the welcome message. Part of that message is “Press 0 for the operator”, however, when the call presses 0, it continues through the entire voicemail process and never breaks out to the operator.

The operator has been set in the general settings.

Any help would be appreciated.

Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “0?s-NOANSWER|1”) in new stack
Jul 15 13:26:39 DEBUG[27464] pbx.c: Not taking any branch
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '0’
Jul 15 13:26:39 DEBUG[27464] pbx.c: Function result is 'unavail’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Set(“Zap/2-1”, “MODE=unavail”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Set
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '1’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “1?notdirect”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Goto (macro-vm,vmx,5)
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 DEBUG[27464] pbx.c: Function result is 'enabled’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing NoOp(“Zap/2-1”, “Checking if ext 352 is enabled: enabled”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Noop
Jul 15 13:26:39 DEBUG[27464] pbx.c: Function result is 'enabled’
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '0’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “0?s-NOANSWER|1”) in new stack
Jul 15 13:26:39 DEBUG[27464] pbx.c: Not taking any branch
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Macro(“Zap/2-1”, “get-vmcontext|352”) in new stack
Jul 15 13:26:39 DEBUG[27464] pbx.c: Function result is 'default’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Set(“Zap/2-1”, “VMCONTEXT=default”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Set
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '0’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “0?200:300”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Goto (macro-get-vmcontext,s,300)
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing NoOp(“Zap/2-1”, “”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: NoOp
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Macro
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing AGI(“Zap/2-1”, “checksound.agi|/var/spool/asterisk/voicemail/default/352/temp”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/checksound.agi
Jul 15 13:26:39 VERBOSE[27464] logger.c: checksound.agi|/var/spool/asterisk/voicemail/default/352/temp: VmX requires: /var/spool/asterisk/voicemail/default
/352/temp.wav or .WAV exist in order to function
Jul 15 13:26:39 VERBOSE[27464] logger.c: – AGI Script checksound.agi completed, returning 0
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: AGI
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '0’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “0?tmpgreet”) in new stack
Jul 15 13:26:39 DEBUG[27464] pbx.c: Not taking any branch
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing AGI(“Zap/2-1”, “checksound.agi|/var/spool/asterisk/voicemail/default/352/unavail”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/checksound.agi
Jul 15 13:26:39 VERBOSE[27464] logger.c: checksound.agi|/var/spool/asterisk/voicemail/default/352/unavail: VmX requires: /var/spool/asterisk/voicemail/defa
ult/352/unavail.wav or .WAV exist in order to function
Jul 15 13:26:39 VERBOSE[27464] logger.c: – AGI Script checksound.agi completed, returning 0
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: AGI
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '1’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “1?nofile”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Goto (macro-vm,vmx,63)
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing NoOp(“Zap/2-1”, “File for mode: unavail does not exist| SYSTEMSTATUS: APPERROR| going to normal voi
cemail”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Noop
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Goto(“Zap/2-1”, “s-NOANSWER|1”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Goto (macro-vm,s-NOANSWER,1)
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Goto
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Macro(“Zap/2-1”, “get-vmcontext|352”) in new stack
Jul 15 13:26:39 DEBUG[27464] pbx.c: Function result is 'default’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing Set(“Zap/2-1”, “VMCONTEXT=default”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Set
Jul 15 13:26:39 DEBUG[27464] pbx.c: Expression result is '0’
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing GotoIf(“Zap/2-1”, “0?200:300”) in new stack
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Goto (macro-get-vmcontext,s,300)
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: GotoIf
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing NoOp(“Zap/2-1”, “”) in new stack
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: NoOp
Jul 15 13:26:39 DEBUG[27464] app_macro.c: Executed application: Macro
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Executing VoiceMail(“Zap/2-1”, “352@default|u”) in new stack
Jul 15 13:26:39 WARNING[27464] chan_zap.c: Unable to request echo training on channel 2
Jul 15 13:26:39 DEBUG[27464] app_voicemail.c: /var/spool/asterisk/voicemail/default/352/unavail doesn’t exist, doing what we can
Jul 15 13:26:39 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:39 VERBOSE[27464] logger.c: – Playing ‘vm-theperson’ (language ‘en’)
Jul 15 13:26:40 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:41 DEBUG[27464] channel.c: Scheduling timer at 154 sample intervals
Jul 15 13:26:41 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:41 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:41 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:41 VERBOSE[27464] logger.c: – Playing ‘digits/3’ (language ‘en’)
Jul 15 13:26:42 DEBUG[27464] channel.c: Scheduling timer at 130 sample intervals
Jul 15 13:26:42 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:42 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:42 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:42 VERBOSE[27464] logger.c: – Playing ‘digits/5’ (language ‘en’)
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 122 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:43 VERBOSE[27464] logger.c: – Playing ‘digits/2’ (language ‘en’)
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 50 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:43 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:43 VERBOSE[27464] logger.c: – Playing ‘vm-isunavail’ (language ‘en’)
Jul 15 13:26:44 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:45 DEBUG[27464] channel.c: Scheduling timer at 138 sample intervals
Jul 15 13:26:45 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:45 DEBUG[27464] channel.c: Scheduling timer at 0 sample intervals
Jul 15 13:26:45 DEBUG[27464] channel.c: Scheduling timer at 160 sample intervals
Jul 15 13:26:45 VERBOSE[27464] logger.c: – Playing ‘vm-intro’ (language ‘en’)
Jul 15 13:26:48 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:49 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:50 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:52 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:53 DEBUG[27464] chan_zap.c: DTMF digit: 0 on Zap/2-1
Jul 15 13:26:53 DEBUG[27348] channel.c: Didn’t get a frame from channel: SIP/376-084d05b8
Jul 15 13:26:53 DEBUG[27348] channel.c: Bridge stops bridging channels Local/300@from-internal-0bad,2 and SIP/376-084d05b8
Jul 15 13:26:53 DEBUG[27348] chan_sip.c: update_call_counter(376) - decrement call limit counter
Jul 15 13:26:53 DEBUG[27348] app_dial.c: Exiting with DIALSTATUS=ANSWER.