Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

  • Congratulations Chriss Miller on being selected by the Tek-Tips community for having the most helpful posts in the forums last week. Way to Go!

Voicemail to email issue

Status
Not open for further replies.

fortage

MIS
Joined
Jun 15, 2000
Messages
329
Location
US
VM Pro 6.1.16
Most email notification are normally successful except 1 or 2 a day fail. A portion of a log for a typical failure is below. I do not notice anything irregular in the Exchange SMTP logs just the typical BDAT, BDAT then nothing then QUIT.
Any Ideas?

16/02/2011 04:56:49.784 - 500 5.5.1 Unrecognized command
16/02/2011 04:56:49.784 - 500 5.5.1 Unrecognized command
16/02/2011 04:56:49.784 - 500 5.5.1 Unrecognized command
16/02/2011 04:56:50.862 - < 500 5.5.1 Unrecognized command
16/02/2011 04:56:50.909 - CSMTPConnection::SendMMAudixMessage: An unexpected end of message response was received.
16/02/2011 04:56:51.018 - ######## START OF CHUNK ######
16/02/2011 04:56:51.143 - > QUIT
16/02/2011 04:56:51.190 - ######## END OF CHUNK ######
16/02/2011 04:57:51.190 - CSMTPConnection::ReadResponse: Timed Out waiting for response from SMTP server.
16/02/2011 04:57:51.237 - <
16/02/2011 04:57:51.284 - CSMTPConnection::Disconnect: An unexpected QUIT response was received.
 
Well since you posted practicaly no details and just a snippet of a trace then perhaps the Unrecognized Command is actually an Autorisation Required message that is unacknowledged which caused the unexpected end of message response.

Or something like that.

 
I didn't realize that the entire log is needed, it's 11,000 lines. I re-posted what I thought was relevant.


16/02/2011 04:56:25.752 - Attempting to connect to host mydomain.com on port 25, local bound address is (null)
16/02/2011 04:56:46.768 - CSMTPConnection::Connect: Could not connect to the SMTP server mydomain.com on port 25. Error 10060 [0x274c] (A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.)
16/02/2011 04:56:46.862 - Attempting to connect to host 2.2.2.2 on port 25, local bound address is (null)
16/02/2011 04:56:46.971 - Successfully connected to host 2.2.2.2 on port 25
16/02/2011 04:56:47.018 - < 220 mailserver.domain.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.4675 ready at Wed, 16 Feb 2011 04:56:43 -0500
16/02/2011 04:56:47.081 - ######## START OF CHUNK ######
16/02/2011 04:56:47.127 - > EHLO phone01
16/02/2011 04:56:47.127 - ######## END OF CHUNK ######
16/02/2011 04:56:47.127 - < 250-exchfr102.domain.com Hello [1.1.1.1]
16/02/2011 04:56:47.127 - 250-TURN
16/02/2011 04:56:47.127 - 250-SIZE 61440000
16/02/2011 04:56:47.127 - 250-ETRN
16/02/2011 04:56:47.127 - 250-PIPELINING
16/02/2011 04:56:47.127 - 250-DSN
16/02/2011 04:56:47.127 - 250-ENHANCEDSTATUSCODES
16/02/2011 04:56:47.127 - 250-8bitmime
16/02/2011 04:56:47.127 - 250-BINARYMIME
16/02/2011 04:56:47.127 - 250-CHUNKING
16/02/2011 04:56:47.127 - 250-VRFY
16/02/2011 04:56:47.127 - 250-X-EXPS GSSAPI NTLM
16/02/2011 04:56:47.127 - 250-AUTH GSSAPI NTLM
16/02/2011 04:56:47.127 - 250-X-LINK2STATE
16/02/2011 04:56:47.127 - 250-XEXCH50
16/02/2011 04:56:47.127 - 250 OK
16/02/2011 04:56:47.190 - ######## START OF CHUNK ######
16/02/2011 04:56:47.237 - > MAIL FROM:<voicemail@mydomain.com> BODY=BINARYMIME
16/02/2011 04:56:47.237 - ######## END OF CHUNK ######
16/02/2011 04:56:47.237 - < 250 2.1.0 voicemail@mydomain.com....Sender OK
16/02/2011 04:56:47.299 - ######## START OF CHUNK ######
16/02/2011 04:56:47.346 - > RCPT TO:<support@mydomain.com>
16/02/2011 04:56:47.346 - ######## END OF CHUNK ######
16/02/2011 04:56:47.362 - < 250 2.1.5 support@mydomain.com
16/02/2011 04:56:47.409 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > BDAT 672
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > From: IP Office Voicemail Pro Server <voicemail@mydomain.com>
16/02/2011 04:56:47.456 - To: <support@mydomain.com>
16/02/2011 04:56:47.456 - Subject: Voicemail Message (1231231 > SupportGroup) From:12334232
16/02/2011 04:56:47.456 - Date: Wed, 16 Feb 2011 04:56:47 -0500
16/02/2011 04:56:47.456 - X-Mailer: Voicemail Pro Server
16/02/2011 04:56:47.456 - MIME-Version: 1.0
16/02/2011 04:56:47.456 - Content-Type: multipart/mixed;
16/02/2011 04:56:47.456 - boundary="{0145d2e9-713b-4ef7-8223-7844d2520624}"
16/02/2011 04:56:47.456 - Content-Transfer-Encoding: binary
16/02/2011 04:56:47.456 - X-Priority: 3
16/02/2011 04:56:47.456 - X-MSMail-Priority: Normal
16/02/2011 04:56:47.456 - Priority: Normal
16/02/2011 04:56:47.456 - Importance: Normal
16/02/2011 04:56:47.456 - Sensitivity: Normal
16/02/2011 04:56:47.456 - Content-Class: voice
16/02/2011 04:56:47.456 - X-CallingTelephoneNumber: 12334232
16/02/2011 04:56:47.456 - X-VoiceMessageDuration: 27
16/02/2011 04:56:47.456 - X-VoiceMessageSenderName:
16/02/2011 04:56:47.456 - X-AttachmentOrder: ;MSG00094.WAV
16/02/2011 04:56:47.456 - X-MS-Has-Attach: yes
16/02/2011 04:56:47.456 -
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > BDAT 46
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > This is a multi-part message in MIME format.
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > BDAT 142
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - >
16/02/2011 04:56:47.456 - --{0145d2e9-713b-4ef7-8223-7844d2520624}
16/02/2011 04:56:47.456 - Content-Type: text/plain;
16/02/2011 04:56:47.456 - charset=iso-8859-1
16/02/2011 04:56:47.456 - Content-Transfer-Encoding: quoted-printable
16/02/2011 04:56:47.456 -
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > BDAT 38
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > IP Office Voicemail redirected message
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - > BDAT 197
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.456 - ######## START OF CHUNK ######
16/02/2011 04:56:47.456 - >
16/02/2011 04:56:47.456 -
16/02/2011 04:56:47.456 - --{0145d2e9-713b-4ef7-8223-7844d2520624}
16/02/2011 04:56:47.456 - Content-Type: audio/wav;
16/02/2011 04:56:47.456 - name="MSG00094.WAV"
16/02/2011 04:56:47.456 - Content-Transfer-Encoding: base64
16/02/2011 04:56:47.456 - Content-Disposition: attachment;
16/02/2011 04:56:47.456 - filename="MSG00094.WAV"
16/02/2011 04:56:47.456 -
16/02/2011 04:56:47.456 - ######## END OF CHUNK ######
16/02/2011 04:56:47.581 - ######## START OF CHUNK ######
16/02/2011 04:56:47.581 - > BDAT 591688
16/02/2011 04:56:47.581 - ######## END OF CHUNK ######
16/02/2011 04:56:47.581 - ######## START OF CHUNK ######
16/02/2011 04:56:49.596 - ######## END OF CHUNK ######
16/02/2011 04:56:49.596 - ######## START OF CHUNK ######
16/02/2011 04:56:49.596 - > AAAAAAAAA
16/02/2011 04:56:49.721 - AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
16/02/2011 04:56:49.721 - AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=
16/02/2011 04:56:49.721 - ######## END OF CHUNK ######
16/02/2011 04:56:49.721 - ######## START OF CHUNK ######
16/02/2011 04:56:49.721 - > BDAT 44
16/02/2011 04:56:49.784 - ######## END OF CHUNK ######
16/02/2011 04:56:49.784 - ######## START OF CHUNK ######
16/02/2011 04:56:49.784 - >
16/02/2011 04:56:49.784 - --{0145d2e9-713b-4ef7-8223-7844d2520624}--
16/02/2011 04:56:49.784 - ######## END OF CHUNK ######
16/02/2011 04:56:49.784 - ######## START OF CHUNK ######
16/02/2011 04:56:49.784 - > BDAT 2 LAST
16/02/2011 04:56:49.784 - ######## END OF CHUNK ######
16/02/2011 04:56:49.784 - ######## START OF CHUNK ######
16/02/2011 04:56:49.784 - >
16/02/2011 04:56:49.784 - ######## END OF CHUNK ######
16/02/2011 04:56:49.784 - < 250 2.6.0 CHUNK received OK, 672 Octets
16/02/2011 04:56:49.784 - 250 2.6.0 CHUNK received OK, 46 Octets
16/02/2011 04:56:49.784 - 250 2.6.0 CHUNK received OK, 142 Octets
16/02/2011 04:56:49.784 - 250 2.6.0 CHUNK received OK, 38 Octets
16/02/2011 04:56:49.784 - 250 2.6.0 CHUNK received OK, 197 Octets
16/02/2011 04:56:49.784 - 500 5.5.1 Unrecognized command
16/02/2011 04:56:50.862 - < 500 5.5.1 Unrecognized command
16/02/2011 04:56:50.909 - CSMTPConnection::SendMMAudixMessage: An unexpected end of message response was received.
16/02/2011 04:56:51.018 - ######## START OF CHUNK ######
16/02/2011 04:56:51.143 - > QUIT
16/02/2011 04:56:51.190 - ######## END OF CHUNK ######
16/02/2011 04:57:51.190 - CSMTPConnection::ReadResponse: Timed Out waiting for response from SMTP server.
16/02/2011 04:57:51.237 - <
16/02/2011 04:57:51.284 - CSMTPConnection::Disconnect: An unexpected QUIT response was received.
 
Thank you for the great responses.

I don't think the first error "Error 10060 [0x274c]" means much because it is attempting to make an SMTP connection to, only the domain name part of the email address. The next line in the log connects to the SMTP server by the IP address set in the voicemail pro config.

I can telnet and send mail via command line without issue. This issue only occurs on maybe 1 out of 30 voicemail-email messages delivered.
 
this internal or external mail boxes?]

e.g inside your organisation or to external email addresses?

ACSS - SME
 
16/02/2011 04:56:49.784 - 500 5.5.1 Unrecognized command

16/02/2011 04:56:50.862 - < 500 5.5.1 Unrecognized command
16/02/2011 04:56:50.909 - CSMTPConnection::SendMMAudixMessage: An unexpected end of message response was received.

This is your issue.

looks to me like your SMTP server can't cope with the attachment. It certainly reads like the SMTP server gets upset with something in that portion of the conversation

i.e BDAT 197 - says to server expect this chunk to be 197 octets
then
BDAT 591688 - says to server expect this chunk to be 591688 octets

Then some time passes

250 2.6.0 CHUNK received OK, 197 Octets
then immediately
500 5.5.1 Unrecognized command - suggests that something in the chunk of 591688 isn't right....

Are you sure that the VM mailbox that this comes from is *excatly* the same as the others? Maybe set to forward rather than alert?



Take Care

Matt
I have always wished that my computer would be as easy to use as my telephone.
My wish has come true. I no longer know how to use my telephone.
 
In response to the last to posts. The recipient's email address is that of a group with both internal and external users/addresses.
 
>this internal or external mail boxes?

>In response to the last to posts. The recipient's email address is that of a group with both internal and external users/addresses.

I reckon this is not relevant. I doubt exchange will begin to route the email onwards until it has been fully received by the server. If the mail were failing the onwards routing, there woudl be some log in exchange - and I bet there isn't!

What version exchange is this?



Take Care

Matt
I have always wished that my computer would be as easy to use as my telephone.
My wish has come true. I no longer know how to use my telephone.
 
Could it be related to this?

CQ120602
Client does not save 2nd SMTP sender entry


BAZINGA!

I'm not insane, my mother had me tested!
 
MattKnight - using exchange 2003. I'm not certain about the way Exchange processes incoming messages either.

tlpeter - I saw that CQ number in the latest Admin maintenance release but haven't been able to find out what it means.
 
Look deeper into your sysmon traps to see if you see something like "message size exceeded" If so the look to see if your smtp server has relay mail size capped at a specific size.

 
review this link


and see if anything is set. I reckon the attachment in this log is about 5Mb.

Take Care

Matt
I have always wished that my computer would be as easy to use as my telephone.
My wish has come true. I no longer know how to use my telephone.
 
You really have to find the start of the problem in sysmon traps. To do this reboot the IPO which will reset everything and clear out smtp issues caused but max message size. Run sysmon and when the issue recurs search your archived sysmon traps for this search phrase 500 5.5.1

I set my traps to create a new file evry hour. When you can no longer find 500 5.5.1 in the file then you issue begins in the next hour-file. It is in that file that you will find the origin of your issue.

 
Regarding the sysmon traps. Which options should be enabled to record the smtp events? The only ones I could find were "Voicemail events" and "Email" on the Call tab.

Our message size restrictions are set to 40MB which shouldn't be the problem.
 
Did you try running Microsoft Network Monitor on the Exchange server and I mentioned in my guide (see above)? It will typically tell you exactly what went wrong.

Kyle Holladay
ACSS & APSS SME Communications
MCP/MCTS Exchange 2007
Adtran ATSA, Aruba ACMA

"Thinking is the hardest work there is, which is the probable reason why so few engage in it." - Henry Ford
 
Status
Not open for further replies.

Part and Inventory Search

Sponsor

Back
Top