[RESOLVED] Voicemail messages undeleted immediately

Running a clean Asterisk 1.6.2.0-rc1 on a newly-installed Ubuntu Server 9.04. No GUIs, doing everything by hand one step at a time as I find my way. Having the time of my life, I might add.

Several roadblocks already cleared thanks to Google (which often points back here), extensions can talk to each other, voicemail takes messages, and I even got MWI working on the Grandstream BT-100 on first attempt.

Several hurdles still to overcome, but here’s the current one: when I connect to voicemail from an extension and listen to a message then delete it, I hear “message undeleted”. With lots of debug verbosity, I can see: [quote] – <SIP/6000-028a93e8> Playing ‘vm-deleted.gsm’ (language ‘en’)
– <SIP/6000-028a93e8> Playing ‘vm-undeleted.gsm’ (language ‘en’)[/quote]in the log, so it did delete the message, then changed its mind.

My config files are brutally small and simple at this point.

Google can’t help me this time around… give me a clue, gang?

in case it makes any difference, it’s not just a glitch with the undelete prompt being played at me - the message itself persists, so it looks like it really did get undeleted.

argh

gets more interesting! Have just added another phone into the mix, a UTStarcom F1000G (great little units, BTW). This one doesn’t suffer the same problem, messages get deleted just fine.

So apparently it’s a problem with the BT-100. ANybody come across this before?

You can debug DTMFs - it could be possible - the first phone to send 2 DTMFs

DTMF debugging switched on. Sample voicemail session:

[quote] – Executing [121@my-phones:1] VoiceMailMain(“SIP/6000-00c47cd8”, “6000,s”) in new stack
– <SIP/6000-00c47cd8> Playing ‘vm-youhave.gsm’ (language ‘en’)
– <SIP/6000-00c47cd8> Playing ‘digits/3.gsm’ (language ‘en’)
– <SIP/6000-00c47cd8> Playing ‘vm-Old.gsm’ (language ‘en’)
– <SIP/6000-00c47cd8> Playing ‘vm-messages.gsm’ (language ‘en’)
– <SIP/6000-00c47cd8> Playing ‘vm-onefor.gsm’ (language ‘en’)
[Sep 20 21:49:26] DTMF[5364]: channel.c:2832 __ast_read: DTMF begin ‘1’ received on SIP/6000-00c47cd8
[Sep 20 21:49:26] DTMF[5364]: channel.c:2836 __ast_read: DTMF begin ignored ‘1’ on SIP/6000-00c47cd8
[Sep 20 21:49:27] DTMF[5364]: channel.c:2760 __ast_read: DTMF end ‘1’ received on SIP/6000-00c47cd8, duration 35 ms
[Sep 20 21:49:27] DTMF[5364]: channel.c:2816 __ast_read: DTMF end passthrough ‘1’ on SIP/6000-00c47cd8
– <SIP/6000-00c47cd8> Playing ‘vm-first.gsm’ (language ‘en’)
[Sep 20 21:49:27] DTMF[5364]: channel.c:2760 __ast_read: DTMF end ‘1’ received on SIP/6000-00c47cd8, duration 280 ms
[Sep 20 21:49:27] DTMF[5364]: channel.c:2816 __ast_read: DTMF end passthrough ‘1’ on SIP/6000-00c47cd8
== Parsing ‘/var/spool/asterisk/voicemail/default/6000/Old/msg0000.txt’: == Found
– <SIP/6000-00c47cd8> Playing ‘/var/spool/asterisk/voicemail/default/6000/Old/msg0000.slin’ (language ‘en’)
[Sep 20 21:49:30] DTMF[5364]: channel.c:2832 __ast_read: DTMF begin ‘7’ received on SIP/6000-00c47cd8
[Sep 20 21:49:30] DTMF[5364]: channel.c:2836 __ast_read: DTMF begin ignored ‘7’ on SIP/6000-00c47cd8
[Sep 20 21:49:30] DTMF[5364]: channel.c:2760 __ast_read: DTMF end ‘7’ received on SIP/6000-00c47cd8, duration 35 ms
[Sep 20 21:49:30] DTMF[5364]: channel.c:2816 __ast_read: DTMF end passthrough ‘7’ on SIP/6000-00c47cd8
[color=darkred]-- <SIP/6000-00c47cd8> Playing ‘vm-deleted.gsm’ (language ‘en’)[/color]
[Sep 20 21:49:30] DTMF[5364]: channel.c:2760 __ast_read: DTMF end ‘7’ received on SIP/6000-00c47cd8, duration 280 ms
[Sep 20 21:49:30] DTMF[5364]: channel.c:2816 __ast_read: DTMF end passthrough ‘7’ on SIP/6000-00c47cd8
[color=darkred]-- <SIP/6000-00c47cd8> Playing ‘vm-undeleted.gsm’ (language ‘en’)[/color]
– <SIP/6000-00c47cd8> Playing ‘vm-advopts.gsm’ (language ‘en’)
== Spawn extension (my-phones, 121, 1) exited non-zero on ‘SIP/6000-00c47cd8’
[/quote]
If I had any idea what that it was supposed to look like, I might know what to make of it. Extension 6000 was used, and VM resides on ext 121.

could somebody else maybe post a similar session-dump for me, so I can compare outputs?

[Sep 20 22:13:22] DTMF[26498]: channel.c:2194 __ast_read: DTMF begin ‘7’ received on IAX2/85.130.97.238:4569-10960
[Sep 20 22:13:22] DTMF[26498]: channel.c:2200 __ast_read: Flags ‘16384’ dtmf_tv ‘1’ tvdiff ‘-1’ on IAX2/85.130.97.238:4569-10960
[Sep 20 22:13:22] DTMF[26498]: channel.c:2204 __ast_read: DTMF begin ignored ‘7’ on IAX2/85.130.97.238:4569-10960
[Sep 20 22:13:22] DTMF[26498]: channel.c:2118 __ast_read: DTMF end ‘7’ received on IAX2/85.130.97.238:4569-10960, duration 0 ms
[Sep 20 22:13:22] DTMF[26498]: channel.c:2171 __ast_read: DTMF end accepted without begin ‘7’ on IAX2/85.130.97.238:4569-10960
[Sep 20 22:13:22] DTMF[26498]: channel.c:2182 __ast_read: DTMF end passthrough ‘7’ on IAX2/85.130.97.238:4569-10960

May be you have to check how DTMFs are sent from phone with problems - and compare of course with other phone.

Good idea!

[quote] – Executing [121@my-phones:1] VoiceMailMain(“SIP/6002-015cd650”, “6002|s”) in new stack
– <SIP/6002-015cd650> Playing ‘vm-youhave’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘digits/1’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-INBOX’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-message’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-onefor’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-INBOX’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-messages’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-opts’ (language ‘en’)
[Sep 20 23:22:27] DTMF[9236]: channel.c:2330 __ast_read: DTMF begin ‘1’ received on SIP/6002-015cd650
[Sep 20 23:22:27] DTMF[9236]: channel.c:2334 __ast_read: DTMF begin ignored ‘1’ on SIP/6002-015cd650
[Sep 20 23:22:27] DTMF[9236]: channel.c:2262 __ast_read: DTMF end ‘1’ received on SIP/6002-015cd650, duration 175 ms
[Sep 20 23:22:27] DTMF[9236]: channel.c:2315 __ast_read: DTMF end passthrough ‘1’ on SIP/6002-015cd650
– <SIP/6002-015cd650> Playing ‘vm-first’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-message’ (language ‘en’)
== Parsing ‘/var/spool/asterisk/voicemail/default/6002/INBOX/msg0000.txt’: Found
– <SIP/6002-015cd650> Playing ‘vm-received’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘digits/at’ (language ‘en’)
[Sep 20 23:22:30] DTMF[9236]: channel.c:2330 __ast_read: DTMF begin ‘7’ received on SIP/6002-015cd650
[Sep 20 23:22:30] DTMF[9236]: channel.c:2334 __ast_read: DTMF begin ignored ‘7’ on SIP/6002-015cd650
[Sep 20 23:22:30] DTMF[9236]: channel.c:2262 __ast_read: DTMF end ‘7’ received on SIP/6002-015cd650, duration 175 ms
[Sep 20 23:22:30] DTMF[9236]: channel.c:2315 __ast_read: DTMF end passthrough ‘7’ on SIP/6002-015cd650
– <SIP/6002-015cd650> Playing ‘vm-deleted’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-advopts’ (language ‘en’)
– <SIP/6002-015cd650> Playing ‘vm-repeat’ (language ‘en’)
== Spawn extension (my-phones, 121, 1) exited non-zero on ‘SIP/6002-015cd650’[/quote]certainly less DTMF 7 activity on this one. Aargh what does that mean? That the BT-100 is buggy?

Just check how DTMFs are set in both phones. Not sure, but I have filling that some times DTMFs could go through sound channel.
Also - you could put some codec with compression - like gsm

Genius! Why did it not occur to me to look at that? The BT-100 was set up (default, I think?) to send DTMF in-audio, via RTP and via SIP INFO. Turned off SIP and in-audio and now it works just fine.

Thanks, mate. Appreciate your help.

Back to fight with FFA now…