Mailqueue getting filled with certain messages. Errors on the Symantec Encryption Management Server.

book

Article ID: 158971

calendar_today

Updated On:

Products

Encryption Management Server Gateway Email Encryption

Issue/Introduction

Mailqueue on Exchange (or another mail gateway) gets filled with specific mails that cannot be transferred.
However, other mails seemingly get transferred after some minutes.

 

pgpproxy: error reading/processing message error=-11969 (not connected) - seemingly this happens after the SMTP-Connection timed out.

 

Cause

Your SMTP-Traffic may have been altered, the connection could have broken off.

 

Resolution

Symantec Encryption Management Server is processing the mails, but seemingly having a problem with a communication partner in your mailflow.
Using a traffic capture tool or the raw-line debug log from the server you can checking how the traffic actually looks like. The interesting part may actually be the mail itself.
In the connection you may see the greetings (EHLO) and mail transfer itself and that it should be ended with a closing <CRLF>, like a newline, a dot, "." and yet another newline.

This is an example for an inbound mail:
2014/02/12 09:39:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: ->S:
2014/02/12 09:39:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: ->S: .
2014/02/12 09:39:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: ProcessMessageProgress Event
2014/02/12 09:39:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Progress: 1%
2014/02/12 09:42:04 +01:00 ERROR pgp/messaging[21456]: SMTP-00003: pgpproxy: unable to send mail transaction data to server error=-11969 (not connected)
2014/02/12 09:42:04 +01:00 ERROR pgp/messaging[21456]: SMTP-00003: error handling SMTP DATA event: not connected
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: exception location:
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: SMTP Data ProtocolEvent returning with error -11969 (not connected)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: C<- : 451 Symantec Encryption Server: Error while processing (SMTP-00003)
2014/02/12 09:42:04 +01:00 ERROR pgp/messaging[21456]: SMTP-00003: pgpproxy: error reading/processing message error=-11969 (not connected)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Total connection duration: 180.564 seconds (100.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent in pgpproxyd: 180.513 seconds (100.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent in proxylib: 0.051 seconds (0.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent in policy engine: 0.003 seconds (0.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent doing network I/O: 180.055 seconds (99.7%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent doing network I/O to client: 0.000 seconds (0.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent doing network I/O to server: 0.000 seconds (0.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent doing network I/O from client: 0.040 seconds (0.0%)
2014/02/12 09:42:04 +01:00 DEBUG pgp/messaging[21456]: SMTP-00003: Time spent doing network I/O from server: 180.014 seconds (99.7%)

This is an inbound mail that has been processed by the Symantec Encryption Management Server and should now get transferred to the next mailhop.
In this example you can see that between the closing "." and the processing message suddenly a timejump for about 180 seconds occured. Here You had an SMTP timeout, even though the message was transferred correctly. It seems so, but you should have actually received a 250 OK from the recipient mail server, but it is missing. Additionally you can see the 451 temporary transfer failure.

Now see another message in the other way round from the same faulty mail hop the Symantec Encryption Management Server now receives a message.

2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> : XXX Thanks and best regards,
2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> : XXX Bob
2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> : XXX <Test-Attachment.doc>
2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> :
2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> :
2014/02/12 09:56:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: C-> : X
2014/02/12 09:59:40 +01:00 ERROR pgp/messaging[21456]: SMTP-00004: pgpproxy: error reading/processing message error=-11969 (not connected)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: ->S: QUIT
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: <-S: 221 2.0.0 Bye
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Total connection duration: 181.562 seconds (100.0%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent in pgpproxyd: 181.318 seconds (99.9%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent in proxylib: 0.244 seconds (0.1%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent in policy engine: 0.052 seconds (0.0%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent doing network I/O: 181.176 seconds (99.8%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent doing network I/O to client: 0.001 seconds (0.0%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent doing network I/O to server: 0.004 seconds (0.0%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent doing network I/O from client: 180.044 seconds (99.2%)
2014/02/12 09:59:40 +01:00 DEBUG pgp/messaging[21456]: SMTP-00004: Time spent doing network I/O from server: 1.127 seconds (0.6%)
2014/02/12 09:59:40 +01:00 INFO pgp/messaging[21456]: SMTP-00004: connection from 172.16.1.88:25067 closed

Again you can see a large timejump of about 180 seconds after the last line of the mail. Here the mail got transferred completely but the "." is missing. The Symantec Encryption Management Server now is actually waiting for that closing "." or for more data.
If you check the mail, you can actually see that the "." was transferred but here it ends up just being the X.
The mail traffic has been altered in a way that the mailclosing "." is removed and thus messages cannot be transferred and connections time out.
You need to find out why that is the case. It is most likely that the other mail server or components that are in the mailflow in between cause this.

About the problem with the filled mailqueue:
You have the problem that other messages take a long time to transfer as well. But this problem is caused by the problem described above.
A mail server accepts a specific amount of connections and mail per connections. If those connections are already used, new messages have to wait.
With the setup above you are now having one mail blocking the connection for 180 seconds. Subsequently messages scheduled for this connection are blocked as well.
Thus you have to wait a random time until your "good" messages can pass through.

See the following link for such an example:
http://www.cisco.com/c/en/us/support/docs/security/ios-firewall/69309-smtp-esmtp-ios-fw.html
This is however, a reaction of something that is wrong in the mailflow. Please correct the cause of such illegal commands.

To work around this, you may disable the described function in the firewall.

 


Applies To

PGP Universal Server or Symantec Encryption Management Server that is processing mails.