IP500 V2 intermittent Vmail to Email fails with embedded. 1

[Kargo]

here is a closed thread for reference, but I did not see a solution.

http://www.tek-tips.com/viewthread.cfm?qid=1575091&page=2

I am having the exact same issue. Further testing shows that the Alarms work (like when you unplug a phone it emails the alert, even thou the vmail to email messages stop.)

And I found the one message that started it all but it was last week in my traces. Traces are as follows.
61362626mS LVM(email): SMTPServer woken up...
61362626mS LVM(email): SMTPServer: waiting for all buffers to be sent
61362626mS LVM(email): SMTPServer snoozing...
61362634mS LVM(email): SMTPServer::BufferSent msg_size(0) buffer_count(103) in use(2)
61362637mS LVM(email): SMTPServer woken up...
61362637mS LVM(email): SMTPServer: waiting for all buffers to be sent
61362638mS LVM(email): SMTPServer snoozing...
61362733mS LVM(email): SMTPServer::BufferSent msg_size(0) buffer_count(103) in use(1)
61362733mS LVM(email): SMTPServer::BufferSent msg_size(0) buffer_count(103) in use(0)
61362736mS LVM(email): SMTPServer woken up...
61362736mS LVM(email): SMTPServer: send terminator
61362841mS ERR: SMTP error: " Message refused.
" 61362842mS LVM(email): SMTPServer: RSET sent ok
61362843mS LVM(email): SMTPServer::ScheduleRetry qsize=1
61363043mS ERR: SMTP error: " Recipient accepted.
" 61363043mS LVM(email): SMTPServer: RSET sent ok
61363047mS LVM(email): SMTPServer: something wrong sending email
61363047mS LVM(email): SMTPServer::ScheduleRetry qsize=1
61363047mS LVM(email): SMTPServer snoozing...


Any thoughts would be greatly appreciated. thanks.

 

[tlpeter]

Or do you use the same username for the sender as a user has for notification

BAZINGA!

I'm not insane, my mother had me tested!

 

[DrDrayAvaya]

looks like Exchange Server is my problem. I've changed the SMTP server address to be the corresponding external ISP SMTP address and hey presto a whole heap of system alerts are in the inbox post reboot.
not sure why exchange would be grumpy about relaying to an internal address? i've used a known internal user address (who is still employed and valid) and the internal exchange IP address.

So i know more than i needed to know about SMTP error messages...
in your trace it shows ERR: SMTP error: "Message refused.
which looks to be something security related to do with spam filtering from what ive read, but looks like just plain differences in tolerance to certain conditions from the smtp server.
exchange looks to be running a fairly tight ship.

cheers,

Chris

Blatant Spam Blocking:

•571 message refused - psmtp

 

[DrDrayAvaya]

this is successful trace of email alert for user mailbox set to alert fyi and at bottom successful short message that didn't end up as a long enough message and hence no email, but shows the SD card deleting the message.

have put ******** where my mobile number showed up, and To (test) is the username "test" that I created.
Not the most riveting reading, but someone may find it useful in future maybe? Google leads me to tek-tips all the time for Avaya IP Office info. very handy and huge time saver!

4297457mS LVM(email): LvmEmailManager woken up...
4297457mS LVM(email): LvmEmailManager ProcessNewMessage: From(0***********) To(test) Mode(3)
4297458mS LVM(email): Send SMTP message
4297458mS LVM(email): SMTPServer New Email...
4297458mS LVM(email): LvmEmailManager ProcessNewMessage: Message start(4192f1) 1st read(0) end read(0) audio(4192f2) end(4192f2) duration(1) audio size(0)
4297458mS LVM(email): LvmEmailManager snoozing...
4297458mS LVM(email): SMTPServer woken up... Session 00000000 Client 00000000 State 0 Q Size 1 current_message 00000000
4297458mS LVM(email): SMTPServer Initialise Session...
4297459mS LVM(email): SMTPServer Connecting... Session f5381c3c Client f535b1c4
4297459mS LVM(email): SMTPServer snoozing...
4297490mS LVM(email): SMTPServer Rx in Connecting State...
4297490mS LVM(email): SMTPServer Connected...
4297497mS LVM(email): SMTPServer woken up... Session f5381c3c Client f535b1c4 State 7 Q Size 1 current_message 00000000
4297497mS LVM(email): SMTPServer: Initiate msg send
4297529mS PRN: Sending body size=329
4297529mS LVM(email): Sending packet 329 (1)
4297529mS LVM(email): SMTPServer snoozing...
4297571mS LVM(email): SMTPServer woken up... Session f5381c3c Client f535b1c4 State 8 Q Size 1 current_message f53866c4
4297571mS LVM(email): SMTPServer: send terminator
4297673mS LVM(email): SMTPServer: Message accepted
4297673mS LVM(email): LvmEmailManager::MsgSent
4297673mS LVM(email): SMTPServer snoozing...
4297686mS CMMap: a=9.9 b=0.0 B0
4298061mS CMMap: a=9.9 b=0.0 B1
4298436mS CMMap: a=9.9 b=0.0 B0
4298811mS CMMap: a=9.9 b=0.0 B1
4299186mS CMMap: a=9.9 b=0.0 B0
4299561mS CMMap: a=9.9 b=0.0 B1
4299936mS CMMap: a=9.9 b=0.0 B0
4300311mS CMMap: a=9.9 b=0.0 B1
4300686mS CMMap: a=9.9 b=0.0 B0
4301061mS CMMap: a=9.9 b=0.0 B1
4301436mS CMMap: a=9.9 b=0.0 B0
4301811mS CMMap: a=9.9 b=0.0 B1
4302186mS CMMap: a=9.9 b=0.0 B0
4302561mS CMMap: a=9.9 b=0.0 B1
4302674mS LVM(email): SMTPServer woken up... Session f5381c3c Client f535b1c4 State 8 Q Size 0 current_message 00000000
4302675mS LVM(email): SMTPServer Closing Connection...
4302675mS LVM(email): SMTPSender ~SMTPTCPSession... Session f5381c3c Client f535b1c4
4302675mS LVM(email): SMTPServer Connection Closed... Session f5381c3c Client 00000000
4302675mS LVM(email): SMTPServer snoozing...
4302936mS CMMap: a=9.9 b=0.0 B0
4302942mS RES: Thu 2/6/2011 23:46:35 FreeMem=66070176(1) CMMsg=3 (3) Buff=200 958 184 7407 3 Links=21478
4302943mS RES2: IP 500 V2 7.0(5) Tasks=46 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=64 Poll=0 Ready=1 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
4303311mS CMMap: a=9.9 b=0.0 B1



and the short message...

348849mS CD: CALL: 9.2.1 Deleted
348849mS CMCallEvt: 9.2.1 -1 Q931 Trunk:9 CHAN=13: StateChange: END=X CMCSCompleted->CMCSDelete
348849mS CMExtnEvt: RAS: CALL LOST (CMCauseNormal)
348849mS CMCallEvt: 0.1011.0 -1 RAS.0: StateChange: END=X CMCSConnected->CMCSCompleted
348850mS CMExtnEvt: v=1011 State, new=PortRecoverDelay old=Connected,0,0,RAS
348850mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[#test] Type=Voicemail (102) Reason=107 Calling[0275835261] Type=National Plan=ISDN Pres=Allowed (0)
BChan: slot=21 chan=42
Cause=16, Normal call clearing
348850mS LVMail: Client2: ProcessMsg: CMReleaseComp Call: lid = 0, id = 1011
348850mS LVMail: Client2: ProcessMsg: CLOSE (CMReleaseComp) end: True pause: False
348850mS LVMail: Client2: Open: opentype: 2
348850mS LVMail: Client2: ProcessMsg: CLOSE - listening packet count 221
348851mS LVMail: Client2: Complete: called
348851mS LVMail: Client2: AssertSpeechMonitor: Off
348851mS LVMail: Client2: StopRASPort: called
348851mS LVM(recorder): LVM Recorder 2: Close called - t_bodylen 17707
348851mS LVM(recorder): LVM Recorder 2: EndPacketGroup: called - n_pkt: 5
348851mS LVM(recorder): LVM Recorder 2: Close: Clipping 401 bytes from test
348851mS LVM(recorder): LVM Recorder 2: Close: Discarding short message test
348851mS LVMail: ~Client2: destructor called
348852mS LVMail: Ticker: UnRegisterLVMClient: 2 List size = 0
348852mS LVMail: ~MailBox2: destructor called
348852mS LVMail: Notify: New: 0 Old: 0 Saved: 0
348852mS LVM(audio): ~Audio2: destructor called
348852mS LVMail: ~AutoBox2: destructor called
348852mS LVMail: ~MailBox2: destructor called
348853mS LVMail: Notify: test New: 4 Old: 0 Saved: 0
348853mS LVM(recorder): ~LVM Recorder 2: destructor called
348853mS CMMap: a=21.42 b=0.0 T0
348854mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 1011->0 )
348854mS CMCallEvt: 0.1011.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
348854mS CMExtnEvt: v=1011 State, new=Idle old=PortRecoverDelay,0,0,RAS
348854mS CMCallEvt: 0.1011.0 -1 BaseEP: DELETE CMEndpoint f5367cbc TOTAL NOW=2 CALL_LIST=0
348855mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
BChan: slot=21 chan=42
Cause=16, Normal call clearing
348855mS CMCallEvt: END CALL:4 (f5b1fd3c)
348856mS CD2: CALL 9.2.1,0.1010.0,4,,,,,,,,,,,,,,,,0,0,,0,,3,0,0,0,0,0,0,1,618,1
348856mS CMCallEvt: 9.2.1 -1 BaseEP: DELETE CMEndpoint f536cc48 TOTAL NOW=1 CALL_LIST=0
348856mS CMCallPkt: v=0
CMVoiceMailStatus
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
UUI type=Local [...] [0x00 0x00 0x00 ]
348857mS CMCallPkt: v=0
CMVoiceMailStatus
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
Called[test] Type=Default (100) Reason=CMDRdirect
UUI type=Local [...] [0x00 0x04 0x00 ]
348858mS CMMap: a=5.14 b=21.42 CheckSpeechPathMonitor (pcp[32]b1r0) unregister
348858mS PRN: Confer DSP: disabled DTMF detector 0
348858mS PRN: Confer DSP channel 0: freed DTMF detector 0, 24 free
348859mS CMMap: PCG::UnmapBChan pcp[32]b1r0 cp_b f5945550 other_cp_b f58f27f8
348859mS CMMap: a=5.14 b=21.42 M0
348859mS CMMap: PCG::UnmapBChan pcp[97]b1r0 cp_b f58f27f8 other_cp_b 0
348860mS LVM(flash): FlashA: AppendFlashItem: File: 31238 nBodyLen: 7452 file: 31238
348878mS CMMap: a=9.9 b=0.0 B1
348893mS LVM(flash): FlashA: AppendFlashItem: exitting after 33 ms
348894mS LVM(flash): FlashA: DiscardFlashItem: File: 31238
348960mS LVM(flash): FlashMan: ServiceAppendQueue: No List Entry for Discarded File 31238

 

[nlasch]

The trace should show 1500 byte packets being sent if there is a WAV attachment.

Hopefully I am wrong but I think it is bug regression. We have multiple sites having issues with different setups. (Most with our provider's mail server, one with the customer's mail server and one with IIS relay using the ISP mail server as a smarthost.)

I had a case raised on 5.0.x that had fixed it but with the rapid development in the past year, I doubt the fixed got applied to all the major releases. It never listed it in any official release notes either I don't think.

I haven't raised a case yet because last time they required WireShark traces between the internet and the IPO which is quite time consuming to setup. There was a lot of back and forth on it last time and I doubt this will be any different. Funny how Avaya can charge their time but we can't charge ours back to them for the logs, traces, etc.