IP500 Voicemail to Email Failure (Embedded Voicemail)

[nzschooltech]

Good afternoon,

This is another problem with our IP500 I have spent hours working on.

The email took a lot of work to get working with our mail server (Microsoft Exchange 2007 SP1). Now it is stable except that every so often and for no apparent reason that I can discern, the IP500 stops sending messages. The Exchange Server does not stop working for any other client and does not specifically log any issue that I can tell. However I would not really know how to trace the full communication of a message through the logs that Exchange provides.

We have tried tracing messages through Microsoft NetMonitor or Wireshark. Both of these products have similar problems of being unable to decipher the communications between Exchange and the IP 500 in a way that would help us work out what is going on. Netmon is especially bad, Wireshark will show some of the conversation but not enough of it to be useful.

I really need some way for either Exchange or the IP500 to log the full sequence of commands that are being sent. The best I have is the logs from the IP500 so here goes.

Typically the sequence of what will happen when the email feature stops working goes something like this. These entries are all from the same log file. I can give you more if you need it but I have tried to keep to what appears to be relevant for this post:

Typical sequence of events FOR EMAIL MESSAGE SUCCESSFULLY SENT.
A voicemail message is left.
The log is
LVMail: Message recorded. Email mode(1) Addr(<an email address here> Locale(enz)
21791423mS LVM(email): VM Email request added to queue - size = 1
21791424mS LVM(email): LvmEmailManager woken up...
21791424mS LVM(email): LvmEmailManager ProcessNewMessage: From(<somenumber>) To(<someusername>) Mode(1)
21791439mS LVM(audio): SoundPlay: Restart: setup sound-clip: b_header: 0x00 sect_ix: 214 clip_unu: 233051
21791692mS RES: Fri 16/10/2009 14:01:56 FreeMem=73422468(2) CMMsg=7 (7) Buff=200 959 1000 7454 3 Links=1260
21791692mS RES2: IP 500 5.0(8) Tasks=33 RTEngine=0 CMRTEngine=0 Timer=50 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
21791801mS LVM(audio): SoundPlay: NextByte: clip_unu == 0
21791801mS LVM(audio): SoundPlay: GetNextMailFrag: END-OF-DATA
21791806mS LVM(audio): SoundPlay: Restart: setup sound-clip: b_header: 0x00 sect_ix: 214 clip_unu: 233051
21792370mS LVM(audio): SoundPlay: NextByte: clip_unu == 0
21792370mS LVM(audio): SoundPlay: GetNextMailFrag: END-OF-DATA
21792381mS LVM(email): Send SMTP message
21792399mS LVM(email): LvmEmailManager ProcessNewMessage: Message start(14c82c0) 1st read(14c82ca) end read(14c8439) audio(14c867d) end(14c868f) duration(975) audio size(232960)
21792399mS LVM(email): LvmEmailManager snoozing...
21792399mS LVM(email): SMTPServer woken up...
21793904mS PRN: Sending body size=639212

Then there are a whole heap of messages about sending buffers (can be over a thousand different packets or buffers with usually one, sometimes several log entries for each number).
Then finally

21794770mS LVM(email): SMTPServer woken up...
21794770mS LVM(email): SMTPServer: send terminator
21795419mS LVM(email): LvmEmailManager::MsgSent
21795419mS LVM(email): SMTPServer snoozing...

OK. Typical sequence of events FOR EMAIL MESSAGE UNSUCCESSFUL. Same log file.

22096155mS LVMail: Message recorded. Email mode(1) Addr(<some email address>) Locale(enz)
22096155mS LVM(email): VM Email request added to queue - size = 1
22096156mS LVM(email): LvmEmailManager woken up...
22096156mS LVM(email): LvmEmailManager ProcessNewMessage: From(<somenumber>) To(<someusername>) Mode(1)
<In between, someone made a call>
22100214mS LVM(email): Send SMTP message
22100284mS LVM(email): LvmEmailManager ProcessNewMessage: Message start(151291c) 1st read(1512926) end read(1512f31) audio(15138f6) end(151393c) duration(4128) audio size(956080)
22100285mS LVM(email): LvmEmailManager snoozing...
22100285mS LVM(email): SMTPServer woken up...
22100288mS RES: Fri 16/10/2009 14:07:04 FreeMem=70709080(2) CMMsg=7 (7) Buff=200 959 1000 7453 3 Links=1074
22100288mS RES2: IP 500 5.0(8) Tasks=33 RTEngine=0 CMRTEngine=0 Timer=47 Poll=0 Ready=3 CMReady=1 CMQueue=0 VPNNQueue=0 Monitor=1
22100316mS PRN: QMC RESREC f5e76c98 18 f5e79a78 f7d58fe8 f7d597e8 10 640 2688
22100323mS PRN: QMC RESREC f5e6e900 19 f5e712b0 f7d5a0b0 f7d5a8b0 9 576 2624
22100775mS ERR: SMTP error: " 4.4.1 Connection timed out
" 22100776mS LVM(email): SMTPServer: RSET sent ok
22100777mS LVM(email): SMTPServer snoozing...

There is no stream of logs to show the message packets or buffers being sent and the end user never receives any email.

The next time an email is to be sent this is the entire sequence of log entries:

23531527mS LVMail: Message recorded. Email mode(1) Addr(<some user address>) Locale(enz)
23531528mS LVM(email): VM Email request added to queue - size = 1
23531528mS LVM(email): LvmEmailManager woken up...
23531528mS LVM(email): LvmEmailManager wake up SMTP...
23531528mS LVM(email): LvmEmailManager snoozing...
23531528mS LVM(email): SMTPServer woken up...
23531528mS LVM(email): SMTPServer snoozing...

And after that messages look like this:
The same as above except only two lines:
28623832mS LVMail: Message recorded. Email mode(1) Addr(<some user address>) Locale(enz)
28623832mS LVM(email): VM Email request added to queue - size = 2

And the queue just grows each time after that, the queue size increments.

Now I have no idea what causes the SMTP timeout or why the embedded voice system stops or really any idea except we have just gotten used to rebooting the system to get email working again. Any suggestions? Thanks.

 

[nzschooltech]

Have upgraded Wireshark to a newer (hopefully more stable/reliable) release to see what might be going on and turned on SMTP logging on Exchange's SMTP internal relaying connector we set up for the IP Office to use.

The only funny thing I see happening is after 5 minutes of nothing you get this message sent back from Exchange:

451 4.7.0 Timeout waiting for client input

From the appearance, embedded VM's SMTP server must keep the connection to the mail server open continuously after each message and doesn't bother closing it. It seems to recover OK each time and create a new connection as needed.