ASTERISK-17292: [REGRESSION]: Files based voicemail message re-sequencing still not working as expected.

[Home]

Summary: ASTERISK-17292: [REGRESSION]: Files based voicemail message re-sequencing still not working as expected.

Reporter: David Brillert (aragon) Labels:

Date Opened: 2011-01-26 11:48:38.000-0600 Date Closed: 2011-06-07 14:05:16

Priority: Minor Regression? No

Status: Closed/Complete Components: Applications/app_voicemail

Versions: 1.8.4 Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) mbresq.txt

Description: Files based voicemail message re-sequencing still not working as expected.
Cannot listed to new messages by using the following steps to reproduce.

check new messages and then press 9 to save the message and choose 0 to save it to new messages (which puts it in INBOX again). Changes the file names from 0000 to 0001 assuming there is only one message in the folder.

This problem still occurs after upgrading to revision 303676

****** ADDITIONAL INFORMATION ******

Marked as blocker because this is still a regression.

Comments: By: Paul Belanger (pabelanger) 2011-01-26 18:58:01.000-0600

Downgrading to minor, only release management can set blockers
By: iasgoscouk (iasgoscouk) 2011-01-27 07:52:47.000-0600

I have taken a svn checkout at revision 304421, and cannot make. the following error is displayed:

app_voicemail.c:7784:2: error: expected identifier or â(â before âreturnâ
app_voicemail.c:7785:1: error: expected identifier or â(â before â}â token
app_voicemail.c:6033:12: warning: âresequence_mailboxâ defined but not used
app_voicemail.c: In function âopen_mailboxâ:
app_voicemail.c:7782:2: warning: control reaches end of non-void function
make[1]: *** [app_voicemail.o] Error 1
make: *** [apps] Error 2

My previous svn checkout at 303637 compiles ok.

After checking through the issues list I cafound this issue, and am assuming that the compile issue may be relating to this change.

I use ODBC stored voicemail selected via menuopts, and was wondering whether the 'not used in' error might be related to this issue being for file based voicemail and therefore not required for ODBC stored voicemail, and the code not accounting for it.
By: Michael L. Young (elguero) 2011-01-27 16:56:27.000-0600

aragon: I just tested this with latest trunk and 1.8. I did what you outlined. I pushed 9 to save the message and selected 0. Upon hanging up and calling back into voicemail, the cli displayed a warning that the mailbox was being resequenced and I confirmed that it happened by looking at the directory. Is there something else we can try in order to reproduce it?

iasgoscouk: Check out issue ASTERISK-17299. The compile error is related to the change that was merged in.
By: David Brillert (aragon) 2011-01-27 17:32:24.000-0600

I'm not using trunk.
Using 1.4

I think my description in steps to reproduce was poor...
I retraced my steps to try and reproduce the error to provide better report.

During my first report I believe the message was saved in the old messages folder and was numbered msg0003.txt msg003.WAV and failed to move to INBOX folder.

To reproduce the error I listened to msg0000.txt msg0000.WAV which normally moved to old folder. Then in old folder I renamed to msg0003.txt msg0003.WAV
Then I logged into the mailbox again and pressed 1 for old message and could not play back msg0003.txt msg0003.WAV then tried button 9 and 0 to save as new.
No audible error. Then checked INBOX but message had not been moved.(EDIT): msg0003.txt msg0003.WAV remained unchanged in old folder.

[2011-01-27 18:20:56] WARNING[31522]: app_voicemail.c:6026 play_message: No message attribute file?!! (/var/spool/asterisk/voicemail/tenant/200/Old/msg0000.txt)

By: Leif Madsen (lmadsen) 2011-01-31 13:57:57.000-0600

I'm confused. You're renaming the message manually?

Please explain, clearly, how you're reproducing the issue, along with the console output with debug level logging enabled.
By: Michael L. Young (elguero) 2011-01-31 16:25:54.000-0600

aragon: I tested this out on 1.4 svn, and I didn't quite understand either, but I tried renaming the message manually just in case, and it is working from what I can tell.

The only thing that caught my eye was that the file mode was different for new messages versus saved messages. But, that didn't affect anything since root user still had rw on files.
By: David Brillert (aragon) 2011-02-01 14:28:30.000-0600

I was able to reproduce this again without renaming any files.
-I left 3 new messages in mailbox 6010.
-I logged into mailbox 6010
-listened to message msg000 and pressed 7 to delete
-pressed 6 to listen to message 0001 and pressed 7 to delete
-pressed 6 to listen to message 0002 and pressed 9 to save and 0 to save to new folder

I checked the mailbox directory and message 0002 was saved into new folder as msg0003.txt msg0003.WAV.
-hung up after saving message
-logged into mailbox 6010 to listen to new messages (msg0003)
-pressed 1 to listen but playback failed because the saved message was filed as msg0003 instead of 0000

CLI attached to report.
By: Michael L. Young (elguero) 2011-02-01 16:08:27.000-0600

What version are you running? 1.4 SVN? Latest?

This line caught my eye when you first login to listen to the vm:

[2011-02-01 15:17:08] NOTICE[24009]: app_voicemail.c:6112 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/6010/INBOX, expected 100 but found 3 message(s) in box with max threshold of 100.

For some reason the last message index and the count of messages is off. Is INBOX clean? Are there any other files found under that directory?

Just throwing out ideas and trying to get as much info as possible to help out.
By: David Brillert (aragon) 2011-02-01 20:10:04.000-0600

version is 1.4 SVN r303676
There was nothing in /var/spool/voicemail/default/6010/INBOX or /var/spool/voicemail/default/6010/old prior to running my test.
I left 3 test messages prior to login so the CLI NOTICE is correct.

By: David Brillert (aragon) 2011-02-01 20:17:34.000-0600

My take on this is simple enough.
I leave 3 messages and during login listen to all 3 but only delete the first 2 messages. I save the third message (which is actually message msg0002 since message numbering starts at msg0000). Asterisk saves this (msg0002)as message msg0003. IMHO Asterisk should have saved this as message msg0000 since msg0000 was deleted. But I presume that does not work because message msg0000 is not permanently deleted until I exit the mailbox, therefore Asterisk saves msg0002 as msg0003 and does not re-sequence the saved msg0003 as msg0000.

Also since msg0003 can not be played back the only way to delete it is via command line.

By: godillon (godillon) 2011-02-02 21:16:46.000-0600

I have the same problem with Asterisk version 1.8.2.2 or Asterisk 1.8.3-rc2.

Sometime, the voicemail message re-sequencing is not working correctly.

So , the message filename in a mailbox is msg0001 or msg0002....
So the users can't listen his message.

I can reproduce this problem with this method :

-I left 3 new messages in mailbox XXXX.
-I logged into mailbox XXXX
-listened to message msg000 and pressed 7 to delete
-pressed 6 to listen to message 0001 and pressed 7 to delete
-pressed 6 to listen to message 0002 and pressed 9 to save and 0 to save to new folder

I checked the mailbox directory and message 0002 was saved into new folder as msg0003.txt msg0003.WAV.
-hung up after saving message
-logged into mailbox XXXX to listen to new messages (msg0003)
-pressed 1 to listen but playback failed because the saved message was filed as msg0003 instead of 0000

By: David Brillert (aragon) 2011-02-08 10:00:11.000-0600

A simple test to reproduce the problem and show results in mailbox directory.
*980 is my express messaging feature code to leave message in mailbox.

[2011-02-08 10:55:51] -- Executing [*9806010@default-super:1] Dial("SIP/6010-00000000", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 10:55:51] -- Called 6010@default-local-voicemail
[2011-02-08 10:55:51] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-5cbd,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 10:55:51] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-5cbd,2", "6010@default|b") in new stack
[2011-02-08 10:55:51] -- Local/6010@default-local-voicemail-5cbd,1 answered SIP/6010-00000000
[2011-02-08 10:55:51] -- <Local/6010@default-local-voicemail-5cbd,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 10:55:53] -- <Local/6010@default-local-voicemail-5cbd,2> Playing 'beep' (language 'en')
[2011-02-08 10:55:54] -- Recording the message
[2011-02-08 10:55:54] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/h2lIPU format: wav49, 0xb5f14130
[2011-02-08 10:56:01] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-00000000'
[2011-02-08 10:56:01] -- User hung up
[2011-02-08 10:56:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 10:56:01] Found
[2011-02-08 10:56:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 10:56:01] Found
[2011-02-08 10:56:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 10:56:01] Found
[2011-02-08 10:56:01] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-5cbd,2'
[2011-02-08 10:56:03] == Parsing '/etc/asterisk/manager.conf': [2011-02-08 10:56:03] Found
[2011-02-08 10:56:05] -- Executing [*9806010@default-super:1] Dial("SIP/6010-00000001", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 10:56:05] -- Called 6010@default-local-voicemail
[2011-02-08 10:56:05] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-481c,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 10:56:05] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-481c,2", "6010@default|b") in new stack
[2011-02-08 10:56:05] -- Local/6010@default-local-voicemail-481c,1 answered SIP/6010-00000001
[2011-02-08 10:56:05] -- <Local/6010@default-local-voicemail-481c,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 10:56:07] -- <Local/6010@default-local-voicemail-481c,2> Playing 'beep' (language 'en')
[2011-02-08 10:56:07] -- Recording the message
[2011-02-08 10:56:07] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/uZApad format: wav49, 0xb5f171c0
[2011-02-08 10:56:14] -- User hung up
[2011-02-08 10:56:14] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-00000001'
[2011-02-08 10:56:14] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 10:56:14] Found
[2011-02-08 10:56:14] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 10:56:14] Found
[2011-02-08 10:56:14] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 10:56:14] Found
[2011-02-08 10:56:14] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-481c,2'
[2011-02-08 10:56:18] -- Executing [*9806010@default-super:1] Dial("SIP/6010-00000002", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 10:56:18] -- Called 6010@default-local-voicemail
[2011-02-08 10:56:18] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-9ea3,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 10:56:18] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-9ea3,2", "6010@default|b") in new stack
[2011-02-08 10:56:18] -- Local/6010@default-local-voicemail-9ea3,1 answered SIP/6010-00000002
[2011-02-08 10:56:18] -- <Local/6010@default-local-voicemail-9ea3,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 10:56:19] -- <Local/6010@default-local-voicemail-9ea3,2> Playing 'beep' (language 'en')
[2011-02-08 10:56:20] -- Recording the message
[2011-02-08 10:56:20] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/qQPOLn format: wav49, 0x9ce97b8
[2011-02-08 10:56:28] -- User hung up
[2011-02-08 10:56:28] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-00000002'
[2011-02-08 10:56:28] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 10:56:28] Found
[2011-02-08 10:56:28] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 10:56:28] Found
[2011-02-08 10:56:28] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 10:56:28] Found
[2011-02-08 10:56:28] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-9ea3,2'
[2011-02-08 10:56:32] -- Executing [*981@default-super:1] Goto("SIP/6010-00000003", "default-app-voicemail-main|s|1") in new stack
[2011-02-08 10:56:32] -- Goto (default-app-voicemail-main,s,1)
[2011-02-08 10:56:32] -- Executing [s@default-app-voicemail-main:1] NoOp("SIP/6010-00000003", "Voicemail Main") in new stack
[2011-02-08 10:56:32] -- Executing [s@default-app-voicemail-main:2] Answer("SIP/6010-00000003", "") in new stack
[2011-02-08 10:56:32] -- Executing [s@default-app-voicemail-main:3] AGI("SIP/6010-00000003", "agi://127.0.0.1:4573/extension") in new stack
[2011-02-08 10:56:32] agi://127.0.0.1:4573/extension: Variable 'PHONE_EXTEN_HD' result is not defined!!!
[2011-02-08 10:56:32] agi://127.0.0.1:4573/extension: Variable 'CHECK_HOTDESK' result is not defined!!!
[2011-02-08 10:56:32] -- AGI Script agi://127.0.0.1:4573/extension completed, returning 0
[2011-02-08 10:56:32] -- Executing [s@default-app-voicemail-main:4] Wait("SIP/6010-00000003", "1") in new stack
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:5] Set("SIP/6010-00000003", "GROUP(OUTGOING)=6010") in new stack
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:6] Set("SIP/6010-00000003", "TIMEOUT(absolute)=1200") in new stack
[2011-02-08 10:56:33] -- Channel will hangup at 2011-02-08 16:16:33 UTC.
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:7] Set("SIP/6010-00000003", "TIMEOUT(digit)=5") in new stack
[2011-02-08 10:56:33] -- Digit timeout set to 5
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:8] Set("SIP/6010-00000003", "TIMEOUT(response)=10") in new stack
[2011-02-08 10:56:33] -- Response timeout set to 10
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:9] Set("SIP/6010-00000003", "DBKEY=/Voicemail/default/6010") in new stack
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:10] GotoIf("SIP/6010-00000003", "0?11:14") in new stack
[2011-02-08 10:56:33] -- Goto (default-app-voicemail-main,s,14)
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:14] Set("SIP/6010-00000003", "SCOPSERV_DBDEL(/Voicemail/default/6010)=") in new stack
[2011-02-08 10:56:33] -- Executing [s@default-app-voicemail-main:15] VoiceMailMain("SIP/6010-00000003", "6010@default") in new stack
[2011-02-08 10:56:33] -- <SIP/6010-00000003> Playing 'vm-password' (language 'en')
[2011-02-08 10:56:37] NOTICE[13756]: app_voicemail.c:6114 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/6010/INBOX, expected 100 but found 3 message(s) in box with max threshold of 100.
[2011-02-08 10:56:37] -- <SIP/6010-00000003> Playing 'vm-youhave' (language 'en')
[2011-02-08 10:56:38] -- <SIP/6010-00000003> Playing 'digits/3' (language 'en')
[2011-02-08 10:56:38] -- <SIP/6010-00000003> Playing 'vm-INBOX' (language 'en')
[2011-02-08 10:56:39] -- <SIP/6010-00000003> Playing 'vm-messages' (language 'en')
[2011-02-08 10:56:40] -- <SIP/6010-00000003> Playing 'vm-onefor' (language 'en')
[2011-02-08 10:56:41] -- <SIP/6010-00000003> Playing 'vm-INBOX' (language 'en')
[2011-02-08 10:56:42] -- <SIP/6010-00000003> Playing 'vm-messages' (language 'en')
[2011-02-08 10:56:43] -- <SIP/6010-00000003> Playing 'vm-opts' (language 'en')
[2011-02-08 10:56:43] -- <SIP/6010-00000003> Playing 'vm-first' (language 'en')
[2011-02-08 10:56:44] -- <SIP/6010-00000003> Playing 'vm-message' (language 'en')
[2011-02-08 10:56:45] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 10:56:45] Found
[2011-02-08 10:56:45] -- <SIP/6010-00000003> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000' (language 'en')
[2011-02-08 10:56:47] -- <SIP/6010-00000003> Playing 'vm-deleted' (language 'en')
[2011-02-08 10:56:48] -- <SIP/6010-00000003> Playing 'vm-advopts' (language 'en')
[2011-02-08 10:56:50] -- <SIP/6010-00000003> Playing 'vm-repeat' (language 'en')
[2011-02-08 10:56:50] -- <SIP/6010-00000003> Playing 'vm-message' (language 'en')
[2011-02-08 10:56:51] -- <SIP/6010-00000003> Playing 'digits/2' (language 'en')
[2011-02-08 10:56:52] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 10:56:52] Found
[2011-02-08 10:56:52] -- <SIP/6010-00000003> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001' (language 'en')
[2011-02-08 10:56:55] -- <SIP/6010-00000003> Playing 'vm-deleted' (language 'en')
[2011-02-08 10:56:56] -- <SIP/6010-00000003> Playing 'vm-prev' (language 'en')
[2011-02-08 10:56:59] -- <SIP/6010-00000003> Playing 'vm-advopts' (language 'en')
[2011-02-08 10:56:59] -- <SIP/6010-00000003> Playing 'vm-last' (language 'en')
[2011-02-08 10:56:59] -- <SIP/6010-00000003> Playing 'vm-message' (language 'en')
[2011-02-08 10:57:00] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 10:57:00] Found
[2011-02-08 10:57:00] -- <SIP/6010-00000003> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002' (language 'en')
[2011-02-08 10:57:03] == Parsing '/etc/asterisk/manager.conf': [2011-02-08 10:57:03] Found
[2011-02-08 10:57:04] -- <SIP/6010-00000003> Playing 'vm-savefolder' (language 'en')
[2011-02-08 10:57:05] -- <SIP/6010-00000003> Playing 'vm-message' (language 'en')
[2011-02-08 10:57:06] -- <SIP/6010-00000003> Playing 'digits/3' (language 'en')
[2011-02-08 10:57:07] -- <SIP/6010-00000003> Playing 'vm-savedto' (language 'en')
[2011-02-08 10:57:08] -- <SIP/6010-00000003> Playing 'vm-INBOX' (language 'en')
[2011-02-08 10:57:08] -- <SIP/6010-00000003> Playing 'vm-messages' (language 'en')
[2011-02-08 10:57:09] -- <SIP/6010-00000003> Playing 'vm-prev' (language 'en')
[2011-02-08 10:57:11] == Spawn extension (default-app-voicemail-main, s, 15) exited non-zero on 'SIP/6010-00000003'
[2011-02-08 10:57:11] -- Executing [h@default-app-voicemail-main:1] ResetCDR("SIP/6010-00000003", "w") in new stack
[2011-02-08 10:57:11] -- Executing [h@default-app-voicemail-main:2] NoCDR("SIP/6010-00000003", "") in new stack
[2011-02-08 10:57:11] -- Executing [h@default-app-voicemail-main:3] DeadAGI("SIP/6010-00000003", "agi://127.0.0.1:4573/cdr?arg1=1297180592.18&arg2=dst&arg3=*981") in new stack
[2011-02-08 10:57:11] -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1297180592.18&arg2=dst&arg3=*981 completed, returning 0
[2011-02-08 10:57:16] -- Executing [*981@default-super:1] Goto("SIP/6010-00000004", "default-app-voicemail-main|s|1") in new stack
[2011-02-08 10:57:16] -- Goto (default-app-voicemail-main,s,1)
[2011-02-08 10:57:16] -- Executing [s@default-app-voicemail-main:1] NoOp("SIP/6010-00000004", "Voicemail Main") in new stack
[2011-02-08 10:57:16] -- Executing [s@default-app-voicemail-main:2] Answer("SIP/6010-00000004", "") in new stack
[2011-02-08 10:57:16] -- Executing [s@default-app-voicemail-main:3] AGI("SIP/6010-00000004", "agi://127.0.0.1:4573/extension") in new stack
[2011-02-08 10:57:16] agi://127.0.0.1:4573/extension: Variable 'PHONE_EXTEN_HD' result is not defined!!!
[2011-02-08 10:57:16] agi://127.0.0.1:4573/extension: Variable 'CHECK_HOTDESK' result is not defined!!!
[2011-02-08 10:57:16] -- AGI Script agi://127.0.0.1:4573/extension completed, returning 0
[2011-02-08 10:57:16] -- Executing [s@default-app-voicemail-main:4] Wait("SIP/6010-00000004", "1") in new stack
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:5] Set("SIP/6010-00000004", "GROUP(OUTGOING)=6010") in new stack
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:6] Set("SIP/6010-00000004", "TIMEOUT(absolute)=1200") in new stack
[2011-02-08 10:57:17] -- Channel will hangup at 2011-02-08 16:17:17 UTC.
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:7] Set("SIP/6010-00000004", "TIMEOUT(digit)=5") in new stack
[2011-02-08 10:57:17] -- Digit timeout set to 5
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:8] Set("SIP/6010-00000004", "TIMEOUT(response)=10") in new stack
[2011-02-08 10:57:17] -- Response timeout set to 10
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:9] Set("SIP/6010-00000004", "DBKEY=/Voicemail/default/6010") in new stack
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:10] GotoIf("SIP/6010-00000004", "0?11:14") in new stack
[2011-02-08 10:57:17] -- Goto (default-app-voicemail-main,s,14)
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:14] Set("SIP/6010-00000004", "SCOPSERV_DBDEL(/Voicemail/default/6010)=") in new stack
[2011-02-08 10:57:17] -- Executing [s@default-app-voicemail-main:15] VoiceMailMain("SIP/6010-00000004", "6010@default") in new stack
[2011-02-08 10:57:17] -- <SIP/6010-00000004> Playing 'vm-password' (language 'en')
[2011-02-08 10:57:21] -- <SIP/6010-00000004> Playing 'vm-youhave' (language 'en')
[2011-02-08 10:57:22] -- <SIP/6010-00000004> Playing 'digits/1' (language 'en')
[2011-02-08 10:57:22] -- <SIP/6010-00000004> Playing 'vm-INBOX' (language 'en')
[2011-02-08 10:57:23] -- <SIP/6010-00000004> Playing 'vm-message' (language 'en')
[2011-02-08 10:57:24] -- <SIP/6010-00000004> Playing 'vm-onefor' (language 'en')
[2011-02-08 10:57:25] -- <SIP/6010-00000004> Playing 'vm-INBOX' (language 'en')
[2011-02-08 10:57:25] -- <SIP/6010-00000004> Playing 'vm-first' (language 'en')
[2011-02-08 10:57:26] -- <SIP/6010-00000004> Playing 'vm-message' (language 'en')
[2011-02-08 10:57:27] WARNING[14335]: app_voicemail.c:6026 play_message: No message attribute file?!! (/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt)
[2011-02-08 10:57:27] -- <SIP/6010-00000004> Playing 'vm-advopts' (language 'en')
[2011-02-08 10:57:29] -- <SIP/6010-00000004> Playing 'vm-repeat' (language 'en')
[2011-02-08 10:57:31] == Spawn extension (default-app-voicemail-main, s, 15) exited non-zero on 'SIP/6010-00000004'
[2011-02-08 10:57:31] -- Executing [h@default-app-voicemail-main:1] ResetCDR("SIP/6010-00000004", "w") in new stack
[2011-02-08 10:57:31] -- Executing [h@default-app-voicemail-main:2] NoCDR("SIP/6010-00000004", "") in new stack
[2011-02-08 10:57:31] -- Executing [h@default-app-voicemail-main:3] DeadAGI("SIP/6010-00000004", "agi://127.0.0.1:4573/cdr?arg1=1297180636.19&arg2=dst&arg3=*981") in new stack
[2011-02-08 10:57:31] -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1297180636.19&arg2=dst&arg3=*981 completed, returning 0
lab*CLI>
Disconnected from Asterisk server
[Feb 8 10:57:32] Executing last minute cleanups
Asterisk ending (0).
[root@lab ~]# cd /var/spool/asterisk/voicemail/default/6010
[root@lab 6010]# cd INBOX
[root@lab INBOX]# dir
msg0003.txt msg0003.WAV

By: David Brillert (aragon) 2011-02-08 11:13:59.000-0600

I ran the same test setup again and noticed that mailbox 6010 is not re-sequenced until a new message is left and user logs into mailbox 6010 again. Therefore it is not possible to listen to any messages in INBOX folder until another message is left in this folder and user logs in again.
I captured the CLI and disconnected from the Asterisk console between testing stages to display status of files in /var/spool/asterisk/voicemail/default/6010/INBOX
I started with a dir command to show that mailbox was empty prior to any tests.

[root@lab INBOX]# dir
[root@lab INBOX]# asterisk -vvvvvvvvvr
== Parsing '/etc/asterisk/asterisk.conf': Found
[Feb 8 11:18:48] Running as group 'scopserv'
[Feb 8 11:18:48] Connected to Asterisk 1.4.40 currently running on lab (pid = 20077)
Verbosity is at least 3
Core debug is at least 3
[2011-02-08 11:18:52] -- Executing [*9806010@default-super:1] Dial("SIP/6010-0000000d", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 11:18:52] -- Called 6010@default-local-voicemail
[2011-02-08 11:18:52] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-f737,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 11:18:52] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-f737,2", "6010@default|b") in new stack
[2011-02-08 11:18:52] -- Local/6010@default-local-voicemail-f737,1 answered SIP/6010-0000000d
[2011-02-08 11:18:52] -- <Local/6010@default-local-voicemail-f737,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 11:18:53] -- <Local/6010@default-local-voicemail-f737,2> Playing 'beep' (language 'en')
[2011-02-08 11:18:54] -- Recording the message
[2011-02-08 11:18:54] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/LMxWWD format: wav49, 0x9496a08
[2011-02-08 11:19:01] -- User hung up
[2011-02-08 11:19:01] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-0000000d'
[2011-02-08 11:19:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:19:01] Found
[2011-02-08 11:19:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:19:01] Found
[2011-02-08 11:19:01] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:19:01] Found
[2011-02-08 11:19:01] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-f737,2'
[2011-02-08 11:19:03] == Parsing '/etc/asterisk/manager.conf': [2011-02-08 11:19:03] Found
[2011-02-08 11:19:07] -- Executing [*9806010@default-super:1] Dial("SIP/6010-0000000e", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 11:19:07] -- Called 6010@default-local-voicemail
[2011-02-08 11:19:07] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-3481,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 11:19:07] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-3481,2", "6010@default|b") in new stack
[2011-02-08 11:19:07] -- Local/6010@default-local-voicemail-3481,1 answered SIP/6010-0000000e
[2011-02-08 11:19:07] -- <Local/6010@default-local-voicemail-3481,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 11:19:11] -- <Local/6010@default-local-voicemail-3481,2> Playing 'beep' (language 'en')
[2011-02-08 11:19:11] -- Recording the message
[2011-02-08 11:19:11] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/0r9X2c format: wav49, 0x9495a28
[2011-02-08 11:19:17] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-0000000e'
[2011-02-08 11:19:17] -- User hung up
[2011-02-08 11:19:17] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 11:19:17] Found
[2011-02-08 11:19:17] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 11:19:17] Found
[2011-02-08 11:19:17] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 11:19:17] Found
[2011-02-08 11:19:17] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-3481,2'
[2011-02-08 11:19:21] -- Executing [*9806010@default-super:1] Dial("SIP/6010-0000000f", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 11:19:21] -- Called 6010@default-local-voicemail
[2011-02-08 11:19:21] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-9230,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 11:19:21] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-9230,2", "6010@default|b") in new stack
[2011-02-08 11:19:21] -- Local/6010@default-local-voicemail-9230,1 answered SIP/6010-0000000f
[2011-02-08 11:19:21] -- <Local/6010@default-local-voicemail-9230,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 11:19:25] -- <Local/6010@default-local-voicemail-9230,2> Playing 'beep' (language 'en')
[2011-02-08 11:19:25] -- Recording the message
[2011-02-08 11:19:25] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/Fd0OuP format: wav49, 0x9496040
[2011-02-08 11:19:32] -- User hung up
[2011-02-08 11:19:32] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6010-0000000f'
[2011-02-08 11:19:32] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 11:19:32] Found
[2011-02-08 11:19:32] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 11:19:32] Found
[2011-02-08 11:19:32] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 11:19:32] Found
[2011-02-08 11:19:32] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-9230,2'
lab*CLI>
Disconnected from Asterisk server
[Feb 8 11:19:40] Executing last minute cleanups
Asterisk ending (0).
[root@lab INBOX]# dir
msg0000.txt msg0000.WAV msg0001.txt msg0001.WAV msg0002.txt msg0002.WAV
[root@lab INBOX]# asterisk -vvvvvvvvvr
== Parsing '/etc/asterisk/asterisk.conf': Found
[Feb 8 11:19:45] Running as group 'scopserv'
[Feb 8 11:19:45] Connected to Asterisk 1.4.40 currently running on lab (pid = 20077)
Verbosity is at least 3
Core debug is at least 3
[2011-02-08 11:19:47] Extension Changed 6010[default-local] new state InUse for Notify User 6001
[2011-02-08 11:19:47] -- Executing [*981@default-super:1] Goto("SIP/6010-00000010", "default-app-voicemail-main|s|1") in new stack
[2011-02-08 11:19:47] -- Goto (default-app-voicemail-main,s,1)
[2011-02-08 11:19:47] -- Executing [s@default-app-voicemail-main:1] NoOp("SIP/6010-00000010", "Voicemail Main") in new stack
[2011-02-08 11:19:47] -- Executing [s@default-app-voicemail-main:2] Answer("SIP/6010-00000010", "") in new stack
[2011-02-08 11:19:47] -- Executing [s@default-app-voicemail-main:3] AGI("SIP/6010-00000010", "agi://127.0.0.1:4573/extension") in new stack
[2011-02-08 11:19:48] agi://127.0.0.1:4573/extension: Variable 'PHONE_EXTEN_HD' result is not defined!!!
[2011-02-08 11:19:48] agi://127.0.0.1:4573/extension: Variable 'CHECK_HOTDESK' result is not defined!!!
[2011-02-08 11:19:48] -- AGI Script agi://127.0.0.1:4573/extension completed, returning 0
[2011-02-08 11:19:48] -- Executing [s@default-app-voicemail-main:4] Wait("SIP/6010-00000010", "1") in new stack
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:5] Set("SIP/6010-00000010", "GROUP(OUTGOING)=6010") in new stack
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:6] Set("SIP/6010-00000010", "TIMEOUT(absolute)=1200") in new stack
[2011-02-08 11:19:49] -- Channel will hangup at 2011-02-08 16:39:49 UTC.
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:7] Set("SIP/6010-00000010", "TIMEOUT(digit)=5") in new stack
[2011-02-08 11:19:49] -- Digit timeout set to 5
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:8] Set("SIP/6010-00000010", "TIMEOUT(response)=10") in new stack
[2011-02-08 11:19:49] -- Response timeout set to 10
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:9] Set("SIP/6010-00000010", "DBKEY=/Voicemail/default/6010") in new stack
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:10] GotoIf("SIP/6010-00000010", "0?11:14") in new stack
[2011-02-08 11:19:49] -- Goto (default-app-voicemail-main,s,14)
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:14] Set("SIP/6010-00000010", "SCOPSERV_DBDEL(/Voicemail/default/6010)=") in new stack
[2011-02-08 11:19:49] -- Executing [s@default-app-voicemail-main:15] VoiceMailMain("SIP/6010-00000010", "6010@default") in new stack
[2011-02-08 11:19:49] -- <SIP/6010-00000010> Playing 'vm-password' (language 'en')
[2011-02-08 11:19:53] NOTICE[30237]: app_voicemail.c:6114 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/6010/INBOX, expected 100 but found 3 message(s) in box with max threshold of 100.
[2011-02-08 11:19:53] -- <SIP/6010-00000010> Playing 'vm-youhave' (language 'en')
[2011-02-08 11:19:53] -- <SIP/6010-00000010> Playing 'digits/3' (language 'en')
[2011-02-08 11:19:54] -- <SIP/6010-00000010> Playing 'vm-INBOX' (language 'en')
[2011-02-08 11:19:54] -- <SIP/6010-00000010> Playing 'vm-first' (language 'en')
[2011-02-08 11:19:55] -- <SIP/6010-00000010> Playing 'vm-message' (language 'en')
[2011-02-08 11:19:56] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:19:56] Found
[2011-02-08 11:19:56] -- <SIP/6010-00000010> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000' (language 'en')
[2011-02-08 11:19:57] -- <SIP/6010-00000010> Playing 'vm-deleted' (language 'en')
[2011-02-08 11:19:59] -- <SIP/6010-00000010> Playing 'vm-advopts' (language 'en')
[2011-02-08 11:20:00] -- <SIP/6010-00000010> Playing 'vm-message' (language 'en')
[2011-02-08 11:20:01] -- <SIP/6010-00000010> Playing 'digits/2' (language 'en')
[2011-02-08 11:20:02] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001.txt': [2011-02-08 11:20:02] Found
[2011-02-08 11:20:02] -- <SIP/6010-00000010> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0001' (language 'en')
[2011-02-08 11:20:03] == Parsing '/etc/asterisk/manager.conf': [2011-02-08 11:20:03] Found
[2011-02-08 11:20:04] -- <SIP/6010-00000010> Playing 'vm-deleted' (language 'en')
[2011-02-08 11:20:05] -- <SIP/6010-00000010> Playing 'vm-prev' (language 'en')
[2011-02-08 11:20:07] -- <SIP/6010-00000010> Playing 'vm-last' (language 'en')
[2011-02-08 11:20:07] -- <SIP/6010-00000010> Playing 'vm-message' (language 'en')
[2011-02-08 11:20:08] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002.txt': [2011-02-08 11:20:08] Found
[2011-02-08 11:20:08] -- <SIP/6010-00000010> Playing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0002' (language 'en')
[2011-02-08 11:20:09] -- <SIP/6010-00000010> Playing 'vm-savefolder' (language 'en')
[2011-02-08 11:20:12] -- <SIP/6010-00000010> Playing 'vm-press' (language 'en')
[2011-02-08 11:20:12] -- <SIP/6010-00000010> Playing 'vm-message' (language 'en')
[2011-02-08 11:20:13] -- <SIP/6010-00000010> Playing 'digits/3' (language 'en')
[2011-02-08 11:20:14] -- <SIP/6010-00000010> Playing 'vm-savedto' (language 'en')
[2011-02-08 11:20:15] -- <SIP/6010-00000010> Playing 'vm-INBOX' (language 'en')
[2011-02-08 11:20:16] -- <SIP/6010-00000010> Playing 'vm-messages' (language 'en')
[2011-02-08 11:20:17] -- <SIP/6010-00000010> Playing 'vm-prev' (language 'en')
[2011-02-08 11:20:18] == Spawn extension (default-app-voicemail-main, s, 15) exited non-zero on 'SIP/6010-00000010'
[2011-02-08 11:20:18] -- Executing [h@default-app-voicemail-main:1] ResetCDR("SIP/6010-00000010", "w") in new stack
[2011-02-08 11:20:18] -- Executing [h@default-app-voicemail-main:2] NoCDR("SIP/6010-00000010", "") in new stack
[2011-02-08 11:20:18] -- Executing [h@default-app-voicemail-main:3] DeadAGI("SIP/6010-00000010", "agi://127.0.0.1:4573/cdr?arg1=1297181987.58&arg2=dst&arg3=*981") in new stack
[2011-02-08 11:20:18] -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1297181987.58&arg2=dst&arg3=*981 completed, returning 0
[2011-02-08 11:20:18] Extension Changed 6010[default-local] new state Idle for Notify User 6001
[2011-02-08 11:20:19] == Refreshing DNS lookups.
lab*CLI>
Disconnected from Asterisk server
[Feb 8 11:20:22] Executing last minute cleanups
Asterisk ending (0).
[root@lab INBOX]# dir
msg0003.txt msg0003.WAV
[root@lab INBOX]# asterisk -vvvvvvvvvr
== Parsing '/etc/asterisk/asterisk.conf': Found
[Feb 8 11:20:26] Running as group 'scopserv'
[Feb 8 11:20:26] Connected to Asterisk 1.4.40 currently running on lab (pid = 20077)
Verbosity is at least 3
Core debug is at least 3
[2011-02-08 11:20:29] -- Executing [*981@default-super:1] Goto("SIP/6010-00000011", "default-app-voicemail-main|s|1") in new stack
[2011-02-08 11:20:29] -- Goto (default-app-voicemail-main,s,1)
[2011-02-08 11:20:29] -- Executing [s@default-app-voicemail-main:1] NoOp("SIP/6010-00000011", "Voicemail Main") in new stack
[2011-02-08 11:20:29] -- Executing [s@default-app-voicemail-main:2] Answer("SIP/6010-00000011", "") in new stack
[2011-02-08 11:20:29] -- Executing [s@default-app-voicemail-main:3] AGI("SIP/6010-00000011", "agi://127.0.0.1:4573/extension") in new stack
[2011-02-08 11:20:29] Extension Changed 6010[default-local] new state InUse for Notify User 6001
[2011-02-08 11:20:29] agi://127.0.0.1:4573/extension: Variable 'PHONE_EXTEN_HD' result is not defined!!!
[2011-02-08 11:20:29] agi://127.0.0.1:4573/extension: Variable 'CHECK_HOTDESK' result is not defined!!!
[2011-02-08 11:20:29] -- AGI Script agi://127.0.0.1:4573/extension completed, returning 0
[2011-02-08 11:20:29] -- Executing [s@default-app-voicemail-main:4] Wait("SIP/6010-00000011", "1") in new stack
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:5] Set("SIP/6010-00000011", "GROUP(OUTGOING)=6010") in new stack
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:6] Set("SIP/6010-00000011", "TIMEOUT(absolute)=1200") in new stack
[2011-02-08 11:20:30] -- Channel will hangup at 2011-02-08 16:40:30 UTC.
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:7] Set("SIP/6010-00000011", "TIMEOUT(digit)=5") in new stack
[2011-02-08 11:20:30] -- Digit timeout set to 5
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:8] Set("SIP/6010-00000011", "TIMEOUT(response)=10") in new stack
[2011-02-08 11:20:30] -- Response timeout set to 10
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:9] Set("SIP/6010-00000011", "DBKEY=/Voicemail/default/6010") in new stack
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:10] GotoIf("SIP/6010-00000011", "0?11:14") in new stack
[2011-02-08 11:20:30] -- Goto (default-app-voicemail-main,s,14)
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:14] Set("SIP/6010-00000011", "SCOPSERV_DBDEL(/Voicemail/default/6010)=") in new stack
[2011-02-08 11:20:30] -- Executing [s@default-app-voicemail-main:15] VoiceMailMain("SIP/6010-00000011", "6010@default") in new stack
[2011-02-08 11:20:30] -- <SIP/6010-00000011> Playing 'vm-password' (language 'en')
[2011-02-08 11:20:33] -- <SIP/6010-00000011> Playing 'vm-youhave' (language 'en')
[2011-02-08 11:20:34] -- <SIP/6010-00000011> Playing 'digits/1' (language 'en')
[2011-02-08 11:20:35] -- <SIP/6010-00000011> Playing 'vm-INBOX' (language 'en')
[2011-02-08 11:20:36] -- <SIP/6010-00000011> Playing 'vm-message' (language 'en')
[2011-02-08 11:20:36] -- <SIP/6010-00000011> Playing 'vm-onefor' (language 'en')
[2011-02-08 11:20:37] -- <SIP/6010-00000011> Playing 'vm-first' (language 'en')
[2011-02-08 11:20:37] -- <SIP/6010-00000011> Playing 'vm-message' (language 'en')
[2011-02-08 11:20:38] WARNING[30815]: app_voicemail.c:6026 play_message: No message attribute file?!! (/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt)
[2011-02-08 11:20:38] -- <SIP/6010-00000011> Playing 'vm-advopts' (language 'en')
[2011-02-08 11:20:40] -- <SIP/6010-00000011> Playing 'vm-repeat' (language 'en')
[2011-02-08 11:20:40] == Spawn extension (default-app-voicemail-main, s, 15) exited non-zero on 'SIP/6010-00000011'
[2011-02-08 11:20:40] -- Executing [h@default-app-voicemail-main:1] ResetCDR("SIP/6010-00000011", "w") in new stack
[2011-02-08 11:20:40] -- Executing [h@default-app-voicemail-main:2] NoCDR("SIP/6010-00000011", "") in new stack
[2011-02-08 11:20:40] -- Executing [h@default-app-voicemail-main:3] DeadAGI("SIP/6010-00000011", "agi://127.0.0.1:4573/cdr?arg1=1297182029.59&arg2=dst&arg3=*981") in new stack
[2011-02-08 11:20:41] -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1297182029.59&arg2=dst&arg3=*981 completed, returning 0
[2011-02-08 11:20:41] Extension Changed 6010[default-local] new state Idle for Notify User 6001
lab*CLI>
Disconnected from Asterisk server
[Feb 8 11:20:50] Executing last minute cleanups
Asterisk ending (0).
[root@lab INBOX]# dir
msg0003.txt msg0003.WAV
[root@lab INBOX]# asterisk -vvvvvvvvvr
== Parsing '/etc/asterisk/asterisk.conf': Found
[Feb 8 11:20:54] Running as group 'scopserv'
[Feb 8 11:20:54] Connected to Asterisk 1.4.40 currently running on lab (pid = 20077)
Verbosity is at least 3
Core debug is at least 3
[2011-02-08 11:21:01] -- Executing [*9806010@default-super:1] Dial("SIP/6002-00000012", "Local/6010@default-local-voicemail") in new stack
[2011-02-08 11:21:01] -- Called 6010@default-local-voicemail
[2011-02-08 11:21:01] Extension Changed 6002[default-local] new state InUse for Notify User 6001
[2011-02-08 11:21:01] -- Executing [6010@default-local-voicemail:1] Set("Local/6010@default-local-voicemail-8b97,2", "VMOPERATOR=Local/s@default-aa-operator-6010") in new stack
[2011-02-08 11:21:01] -- Executing [6010@default-local-voicemail:2] VoiceMail("Local/6010@default-local-voicemail-8b97,2", "6010@default|b") in new stack
[2011-02-08 11:21:01] -- Local/6010@default-local-voicemail-8b97,1 answered SIP/6002-00000012
[2011-02-08 11:21:01] -- <Local/6010@default-local-voicemail-8b97,2> Playing '/var/spool/asterisk/voicemail/default/6010/busy' (language 'en')
[2011-02-08 11:21:02] -- <Local/6010@default-local-voicemail-8b97,2> Playing 'beep' (language 'en')
[2011-02-08 11:21:03] -- Recording the message
[2011-02-08 11:21:03] -- x=0, open writing: /var/spool/asterisk/voicemail/default/6010/tmp/7Yjlup format: wav49, 0x94967b8
[2011-02-08 11:21:03] == Parsing '/etc/asterisk/manager.conf': [2011-02-08 11:21:03] Found
[2011-02-08 11:21:12] == Spawn extension (default-super, *9806010, 1) exited non-zero on 'SIP/6002-00000012'
[2011-02-08 11:21:12] -- User hung up
[2011-02-08 11:21:12] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:21:12] Found
[2011-02-08 11:21:12] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:21:12] Found
[2011-02-08 11:21:12] == Parsing '/var/spool/asterisk/voicemail/default/6010/INBOX/msg0000.txt': [2011-02-08 11:21:12] Found
[2011-02-08 11:21:12] Extension Changed 6002[default-local] new state Idle for Notify User 6002
[2011-02-08 11:21:12] Extension Changed 6002[default-local] new state Idle for Notify User 6001
[2011-02-08 11:21:12] == Spawn extension (default-local-voicemail, 6010, 2) exited non-zero on 'Local/6010@default-local-voicemail-8b97,2'
lab*CLI>
Disconnected from Asterisk server
[Feb 8 11:21:21] Executing last minute cleanups
Asterisk ending (0).
[root@lab INBOX]# dir
msg0000.txt msg0000.WAV msg0003.txt msg0003.WAV
[root@lab INBOX]# asterisk -vvvvvvvvvr
== Parsing '/etc/asterisk/asterisk.conf': Found
[Feb 8 11:21:28] Running as group 'scopserv'
[Feb 8 11:21:28] Connected to Asterisk 1.4.40 currently running on lab (pid = 20077)
Verbosity is at least 3
Core debug is at least 3
[2011-02-08 11:21:29] -- Executing [*981@default-super:1] Goto("SIP/6010-00000013", "default-app-voicemail-main|s|1") in new stack
[2011-02-08 11:21:29] -- Goto (default-app-voicemail-main,s,1)
[2011-02-08 11:21:29] -- Executing [s@default-app-voicemail-main:1] NoOp("SIP/6010-00000013", "Voicemail Main") in new stack
[2011-02-08 11:21:29] -- Executing [s@default-app-voicemail-main:2] Answer("SIP/6010-00000013", "") in new stack
[2011-02-08 11:21:29] -- Executing [s@default-app-voicemail-main:3] AGI("SIP/6010-00000013", "agi://127.0.0.1:4573/extension") in new stack
[2011-02-08 11:21:29] agi://127.0.0.1:4573/extension: Variable 'PHONE_EXTEN_HD' result is not defined!!!
[2011-02-08 11:21:29] agi://127.0.0.1:4573/extension: Variable 'CHECK_HOTDESK' result is not defined!!!
[2011-02-08 11:21:29] -- AGI Script agi://127.0.0.1:4573/extension completed, returning 0
[2011-02-08 11:21:29] -- Executing [s@default-app-voicemail-main:4] Wait("SIP/6010-00000013", "1") in new stack
[2011-02-08 11:21:29] Extension Changed 6010[default-local] new state InUse for Notify User 6010
[2011-02-08 11:21:29] Extension Changed 6010[default-local] new state InUse for Notify User 6002
[2011-02-08 11:21:29] Extension Changed 6010[default-local] new state InUse for Notify User 6001
[2011-02-08 11:21:30] -- Executing [s@default-app-voicemail-main:5] Set("SIP/6010-00000013", "GROUP(OUTGOING)=6010") in new stack
[2011-02-08 11:21:30] -- Executing [s@default-app-voicemail-main:6] Set("SIP/6010-00000013", "TIMEOUT(absolute)=1200") in new stack
[2011-02-08 11:21:30] -- Channel will hangup at 2011-02-08 16:41:30 UTC.
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:7] Set("SIP/6010-00000013", "TIMEOUT(digit)=5") in new stack
[2011-02-08 11:21:31] -- Digit timeout set to 5
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:8] Set("SIP/6010-00000013", "TIMEOUT(response)=10") in new stack
[2011-02-08 11:21:31] -- Response timeout set to 10
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:9] Set("SIP/6010-00000013", "DBKEY=/Voicemail/default/6010") in new stack
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:10] GotoIf("SIP/6010-00000013", "0?11:14") in new stack
[2011-02-08 11:21:31] -- Goto (default-app-voicemail-main,s,14)
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:14] Set("SIP/6010-00000013", "SCOPSERV_DBDEL(/Voicemail/default/6010)=") in new stack
[2011-02-08 11:21:31] -- Executing [s@default-app-voicemail-main:15] VoiceMailMain("SIP/6010-00000013", "6010@default") in new stack
[2011-02-08 11:21:31] -- <SIP/6010-00000013> Playing 'vm-password' (language 'en')
[2011-02-08 11:21:34] NOTICE[31545]: app_voicemail.c:6114 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/6010/INBOX, expected 100 but found 2 message(s) in box with max threshold of 100.
[2011-02-08 11:21:34] -- <SIP/6010-00000013> Playing 'vm-youhave' (language 'en')
[2011-02-08 11:21:35] -- <SIP/6010-00000013> Playing 'digits/2' (language 'en')
[2011-02-08 11:21:36] -- <SIP/6010-00000013> Playing 'vm-INBOX' (language 'en')
[2011-02-08 11:21:36] -- <SIP/6010-00000013> Playing 'vm-messages' (language 'en')
[2011-02-08 11:21:37] -- <SIP/6010-00000013> Playing 'vm-onefor' (language 'en')
[2011-02-08 11:21:39] -- <SIP/6010-00000013> Playing 'vm-INBOX' (language 'en')
[2011-02-08 11:21:39] -- <SIP/6010-00000013> Playing 'vm-messages' (language 'en')
[2011-02-08 11:21:40] == Spawn extension (default-app-voicemail-main, s, 15) exited non-zero on 'SIP/6010-00000013'
[2011-02-08 11:21:40] -- Executing [h@default-app-voicemail-main:1] ResetCDR("SIP/6010-00000013", "w") in new stack
[2011-02-08 11:21:40] -- Executing [h@default-app-voicemail-main:2] NoCDR("SIP/6010-00000013", "") in new stack
[2011-02-08 11:21:40] -- Executing [h@default-app-voicemail-main:3] DeadAGI("SIP/6010-00000013", "agi://127.0.0.1:4573/cdr?arg1=1297182089.66&arg2=dst&arg3=*981") in new stack
[2011-02-08 11:21:40] -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1297182089.66&arg2=dst&arg3=*981 completed, returning 0
[2011-02-08 11:21:40] Extension Changed 6010[default-local] new state Idle for Notify User 6010
[2011-02-08 11:21:40] Extension Changed 6010[default-local] new state Idle for Notify User 6002
[2011-02-08 11:21:40] Extension Changed 6010[default-local] new state Idle for Notify User 6001
lab*CLI>
Disconnected from Asterisk server
[Feb 8 11:21:41] Executing last minute cleanups
Asterisk ending (0).
[root@lab INBOX]# dir
msg0000.txt msg0000.WAV msg0001.txt msg0001.WAV
By: Jeff Peeler (jpeeler) 2011-02-09 13:20:19.000-0600

I am unable to reproduce this using these steps:

-I left 3 new messages in mailbox 6010.
-I logged into mailbox 6010
-listened to message msg000 and pressed 7 to delete
-pressed 6 to listen to message 0001 and pressed 7 to delete
-pressed 6 to listen to message 0002 and pressed 9 to save and 0 to save to new folder

I checked the mailbox directory and message 0002 was saved into new folder as msg0003.txt msg0003.WAV.
-hung up after saving message
-logged into mailbox 6010 to listen to new messages (msg0003)
-pressed 1 to listen but playback failed because the saved message was filed as msg0003 instead of 0000

After pressing 1, the resequencing occurs as expected and msg0003 is renamed to msg0000 and is played successfully.
By: David Brillert (aragon) 2011-02-09 14:30:56.000-0600

jpeeler: I just tested a fresh svn checkout 1.4-r306972 and now I cannot reproduce either.
In fact the notice message even changed during voicemail login to...
NOTICE[10805]: app_voicemail.c:6041 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/6010/INBOX, expected 4 but found 1 message(s) in box with max threshold of 100.

I give up ;)
Go ahead and close out this bug report.
By: Jeff Peeler (jpeeler) 2011-02-09 14:32:04.000-0600

Gladly!