VMail login issues -- just us?

General Help
1

Hi,

I jumped from 1.814.210.58-2 to 1.817.210.58-1 and everything went smoothly. One thing has crept up though since then. Periodically users are unable to access voicemail via *97 as their PIN is never accepted. I expect that this is an asterisk, not FreePBX, issue but I’m wondering if there’s a way around this.

Thoughts?

Thanks!

2

Is this the FreePBX distro?

Are you able to tail your log?

tail -f /var/log/asterisk/full

and watch the DTMF output to see if the machine is even seeing the input? You have to turn DTMF on in your logger file.

3

[yeah, distro = freepbxdistro]

The logging keeps from DTMF appearing in full but I’ve now started the DTMF log and verified that it logs the RFC2833 events. So now I wait for the next report.

Thanks for the tip about the DTMF log. <-- what I learned today

4

I stitched together the dtmf and full logs for a call which had the issues.

In this guy’s situation his user is 4337 (device is Aastra 43i/3.2.0), is vm password is 7150 and dialed *97 to get to voicemail. In the first password collection sequence it only gets the ‘7’, doesn’t get any digits in the second pass but then works in the third pass. The device is configured with DTMF mode RFC2833.

What’s the next level of logging, if anything, I can do to trace this issue. I wish it weren’t sporadic so I could get a legit trace. What’s it mean with the digits are showing up in the DTMF log? The devices are on the same lan as the PBX and in some cases only feet away/same switch.

Ideas for where to look next?

[2012-11-08 16:25:20] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:1] Answer("SIP/4337-00007b91", "") in new stack [2012-11-08 16:25:20] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:2] Wait("SIP/4337-00007b91", "1") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:3] Macro("SIP/4337-00007b91", "user-callerid,") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/4337-00007b91", "AMPUSER=4337") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/4337-00007b91", "0?report") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/4337-00007b91", "1?Set(REALCALLERIDNUM=4337)") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/4337-00007b91", "AMPUSER=4337") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/4337-00007b91", "AMPUSERCIDNAME=Guys Name") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/4337-00007b91", "0?report") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/4337-00007b91", "AMPUSERCID=4337") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/4337-00007b91", "CALLERID(all)="Guys Name" <4337>") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/4337-00007b91", "0?limit") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/4337-00007b91", "0?Set(GROUP(concurrency_limit)=4337)") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/4337-00007b91", "0?sub-ccss,s,1(from-internal,*97)") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/4337-00007b91", "0?continue") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:13] Set("SIP/4337-00007b91", "__TTL=64") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:14] GotoIf("SIP/4337-00007b91", "1?continue") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:25] Set("SIP/4337-00007b91", "CALLERID(number)=4337") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/4337-00007b91", "CALLERID(name)=Guys Name") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/4337-00007b91", "CHANNEL(language)=en") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:4] Macro("SIP/4337-00007b91", "get-vmcontext,4337") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/4337-00007b91", "VMCONTEXT=default") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/4337-00007b91", "0?200:300") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/4337-00007b91", "") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:5] Set("SIP/4337-00007b91", "VMBOXEXISTSSTATUS=SUCCESS") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:6] GotoIf("SIP/4337-00007b91", "1?mbexist") in new stack [2012-11-08 16:25:21] VERBOSE[7411] pbx.c: -- Executing [*97@from-internal:106] VoiceMailMain("SIP/4337-00007b91", "4337@default") in new stack [2012-11-08 16:25:22] DTMF[7411] channel.c: DTMF end '7' received on SIP/4337-00007b91, duration 140 ms [2012-11-08 16:25:22] DTMF[7411] channel.c: DTMF end passthrough '7' on SIP/4337-00007b91 [2012-11-08 16:25:21] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-password.ulaw' (language 'en') [2012-11-08 16:25:24] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-incorrect.ulaw' (language 'en') [2012-11-08 16:25:26] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-password.ulaw' (language 'en') [2012-11-08 16:25:37] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-incorrect.ulaw' (language 'en') [2012-11-08 16:25:39] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-password.ulaw' (language 'en') [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF begin '7' received on SIP/4337-00007b91 [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF begin ignored '7' on SIP/4337-00007b91 [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF end '7' received on SIP/4337-00007b91, duration 240 ms [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF end passthrough '7' on SIP/4337-00007b91 [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF begin '1' received on SIP/4337-00007b91 [2012-11-08 16:25:40] DTMF[7411] channel.c: DTMF begin ignored '1' on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF end '1' received on SIP/4337-00007b91, duration 220 ms [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF end passthrough '1' on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF begin '5' received on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF begin ignored '5' on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF end '5' received on SIP/4337-00007b91, duration 220 ms [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF end passthrough '5' on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF begin '0' received on SIP/4337-00007b91 [2012-11-08 16:25:41] DTMF[7411] channel.c: DTMF begin ignored '0' on SIP/4337-00007b91 [2012-11-08 16:25:42] DTMF[7411] channel.c: DTMF end '0' received on SIP/4337-00007b91, duration 240 ms [2012-11-08 16:25:42] DTMF[7411] channel.c: DTMF end passthrough '0' on SIP/4337-00007b91 [2012-11-08 16:25:44] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-youhave.ulaw' (language 'en') [2012-11-08 16:25:45] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:25:45] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-INBOX.ulaw' (language 'en') [2012-11-08 16:25:46] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-and.ulaw' (language 'en') [2012-11-08 16:25:46] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/3.ulaw' (language 'en') [2012-11-08 16:25:47] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-Old.ulaw' (language 'en') [2012-11-08 16:25:48] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-messages.ulaw' (language 'en') [2012-11-08 16:25:49] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-onefor.ulaw' (language 'en') [2012-11-08 16:25:50] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-INBOX.ulaw' (language 'en') [2012-11-08 16:25:50] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-messages.ulaw' (language 'en') [2012-11-08 16:25:51] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-opts.ulaw' (language 'en') [2012-11-08 16:25:53] DTMF[7411] channel.c: DTMF begin '1' received on SIP/4337-00007b91 [2012-11-08 16:25:53] DTMF[7411] channel.c: DTMF begin ignored '1' on SIP/4337-00007b91 [2012-11-08 16:25:54] DTMF[7411] channel.c: DTMF end '1' received on SIP/4337-00007b91, duration 220 ms [2012-11-08 16:25:54] DTMF[7411] channel.c: DTMF end passthrough '1' on SIP/4337-00007b91 [2012-11-08 16:25:54] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-first.ulaw' (language 'en') [2012-11-08 16:25:54] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-message.ulaw' (language 'en') [2012-11-08 16:25:55] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-received.ulaw' (language 'en') [2012-11-08 16:25:56] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/at.ulaw' (language 'en') [2012-11-08 16:25:57] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/4.ulaw' (language 'en') [2012-11-08 16:25:57] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/20.ulaw' (language 'en') [2012-11-08 16:25:58] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/3.ulaw' (language 'en') [2012-11-08 16:25:59] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/p-m.ulaw' (language 'en') [2012-11-08 16:25:59] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-from-phonenumber.ulaw' (language 'en') [2012-11-08 16:26:01] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:02] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:02] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:03] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:04] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:04] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:05] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:06] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:06] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:07] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'digits/1.ulaw' (language 'en') [2012-11-08 16:26:08] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing '/var/spool/asterisk/voicemail/default/4337/INBOX/msg0000.slin' (language 'en') [2012-11-08 16:27:25] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-advopts.ulaw' (language 'en') [2012-11-08 16:27:27] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-repeat.ulaw' (language 'en') [2012-11-08 16:27:30] DTMF[7411] channel.c: DTMF begin '7' received on SIP/4337-00007b91 [2012-11-08 16:27:30] DTMF[7411] channel.c: DTMF begin ignored '7' on SIP/4337-00007b91 [2012-11-08 16:27:30] DTMF[7411] channel.c: DTMF end '7' received on SIP/4337-00007b91, duration 160 ms [2012-11-08 16:27:30] DTMF[7411] channel.c: DTMF end passthrough '7' on SIP/4337-00007b91 [2012-11-08 16:27:30] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-delete.ulaw' (language 'en') [2012-11-08 16:27:30] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-deleted.ulaw' (language 'en') [2012-11-08 16:27:31] VERBOSE[7411] file.c: -- <SIP/4337-00007b91> Playing 'vm-nomore.ulaw' (language 'en') [2012-11-08 16:27:31] VERBOSE[7411] pbx.c: == Spawn extension (from-internal, *97, 106) exited non-zero on 'SIP/4337-00007b91' [2012-11-08 16:27:31] VERBOSE[7411] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/4337-00007b91", "") in new stack [2012-11-08 16:27:31] VERBOSE[7411] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/4337-00007b91'