After applying a certificate for TLS to encrypt SMTP traffic, your Email Prevent server is failing to deliver mail as expected.
Release : 16.x-25.1
Component : Network Prevent for Email
Certificate configuration is not "rocket science" (OK some parts of rocket science probably do include certificate handshakes these days 😉) - but if the steps are not followed precisely it is easy for TLS handshakes to fail.
Thus, just as per other Certificate configurations in DLP (e.g., for Tomcat cert replacement), certain steps are required:
This is a troubleshooting article with some examples from DLP logs that might assist with further troublehsooint of SMTP certificates in DLP Email Prevent.
First things first: Make sure one's prevent.ks file is in the right location:
To troubleshoot Request Processor logs, first ensure that you have FINEST logging enabled. This can be done in one of two ways:
Note that reading RequestProcessor and SMTP Operational logs requires some practice. Some guidance:
Key for IP addresses listed in below log excerpts:
Per the first issue below, you can see that this portion of the logging was the Request Processor component ("rp"):
com.vontu.mta.rp.level=FINEST
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.log.SmtpLogManager logConnectionAccepted
INFO: (SMTP_CONNECTION.1201) Connection accepted (tid=35 cid=Upstream-2328463c-7b08-442e-a683-3bad1096dc71 local=10.d.l.p:10025 remote=10.a.b.c:2932)
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.RequestProcessorHandler handleLineFromDownstream
FINE: Received line from downstream for processing.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.ESMTPResponse parse
FINEST: Parsing response 450 4.7.0 TLS encryption required
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16349 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 35
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.RequestProcessorHandler handleLineFromUpstream
FINE: Received line from upstream for processing.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16378 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 6
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ForwardConnectionBase connectToServer
FINE: Connected to server :mxb-006bf001.example.com
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.log.SmtpLogManager logForwardConnectionEstablished
INFO: (SMTP_CONNECTION.1203) Forward connection established (tid=35 cid=Downstream-ae269cb6-5b1e-4b78-9756-f93d5f7ab4d2 local=10.d.l.p:59330 remote=205.x.y.z:25)
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.RequestProcessorHandler handleLineFromDownstream
FINE: Received line from downstream for processing.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.ESMTPResponse parse
FINEST: Parsing response 250 2.0.0 Reset state
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16361 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 23
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.ESMTPResponse parse
FINEST: Parsing response 220 mx0a-006bf001.example.com ESMTP mfa-m0279755
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ConnectionsStateManagerAction processBanner
FINE: RPT(35): Banner::
220 mx0a-006bf001.example.com ESMTP mfa-m0279755.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.tls.SecurityStateManager getEmailSecurityType
FINE: getEmailSecurityType NO_TLS
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.EventLoop handlePeerDisconnect
WARNING: RPT(35): Disconnect from sending peer com.vontu.mta.rp.connection.UpstreamConnection@6d83fc11.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer flush
FINEST: RPT(35)[Upstream-2328463c-7b08-442e-a683-3bad1096dc71|S:[/10.d.l.p:10025 -> /10.a.b.c:2932]1 selected for write ops
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16276 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 108
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ConnectionsStateManagerAction cleanUpAfterAbort
WARNING: RPT(35): Message aborted during transfer. Clearing message chain state.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16384 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.log.SmtpLogManager logUpstreamConnectionClosed
INFO: (SMTP_CONNECTION.1205) Service connection closed (tid=35 cid=Upstream-2328463c-7b08-442e-a683-3bad1096dc71 local=10.d.l.p:10025 remote=10.a.b.c:2932 messages=0 time=0.1s)
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer close
FINE: RPT(35)_channel is closed
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send(): r: 16384 q: 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer send
FINEST: send: wrote 0
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.log.SmtpLogManager logDownstreamConnectionClosed
INFO: (SMTP_CONNECTION.1204) Forward connection closed (tid=35 cid=Downstream-ae269cb6-5b1e-4b78-9756-f93d5f7ab4d2 local=10.d.l.p:59330 remote=205.x.y.z:25)
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer close
FINE: RPT(35)_channel is closed
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ConnectionsStateManager messageComplete
FINE: RPT(35): message complete. INITIALIZED -> COMPLETE.
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.log.SmtpLogManager logPeerDisconnected
INFO: (SMTP_CONNECTION.1202) Peer disconnected (tid=35 cid=Upstream-2328463c-7b08-442e-a683-3bad1096dc71 local=<> remote=<>)
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer close
FINEST: Close on disconnected peer
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.tls.SecurityStateManager getEmailSecurityType
FINE: getEmailSecurityType NO_TLS
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer close
FINEST: Close on disconnected peer
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ESMTPPeer close
FINEST: Close on disconnected peer
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.tls.SecurityStateManager getEmailSecurityType
FINE: getEmailSecurityType NO_TLS
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.detection.RemoteDetectionRequestSubmitter <init>
INFO: RPT(35) connected to message chain using local port59337
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.connection.ConnectionsStateManager1G connectToMessageChains
INFO: RPT(35) connected to message chain
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.ESMTPRequestProcessorThread run
INFO: RPT(35): Waiting for new connection
Mar 14, 2022 4:32:14 PM com.vontu.mta.rp.tls.SecurityStateManager reset
FINE: Reset NO_TLS (previous NO_TLS)
Above shows "NO_TLS" is being agreed in the email connection. This could be due to a misplaced "prevent.ks" file (as per KB 208318 link above). At any rate, other errors will also be present.
Errors on the "forward connection" logged as "IO" or "NullPointer" exceptions. Generally, these will occur repeatedly for every attempted message. This was occurring on a gateway MTA server or appliance:
21/Jul/22:12:23:32:726-0500 [INFO] (SMTP_CONNECTION.1201) Connection accepted (tid=31 cid=Upstream-d853829b-f7c7-4055-9904-c9169caa9e04 local=10.d.l.p:10025 remote=10.a.b.c:46120)
21/Jul/22:12:23:32:787-0500 [INFO] (SMTP_CONNECTION.1203) Forward connection established (tid=31 cid=Downstream-a5383e42-ce0d-4372-b145-af4c14892177 local=10.d.l.p:34402 remote=140.x.y.z:587)
21/Jul/22:12:23:33:090-0500 [INFO] (SMTP_CONNECTION.5203) Forward connection error (tid=31 cid=Downstream-a5383e42-ce0d-4372-b145-af4c14892177 mta=<> reason=java.io.IOException: java.lang.NullPointerException)
21/Jul/22:12:23:33:090-0500 [INFO] (SMTP_CONNECTION.1205) Service connection closed (tid=31 cid=Upstream-d853829b-f7c7-4055-9904-c9169caa9e04 local=10.d.l.p:10025 remote=10.a.b.c:46120 messages=0 time=0.36s)
21/Jul/22:12:23:33:091-0500 [INFO] (SMTP_CONNECTION.1202) Peer disconnected (tid=31 cid=Downstream-a5383e42-ce0d-4372-b145-af4c14892177 local=<> remote=<>)
The above exception was occurring because "prevent.ks" keystore was in the incorrect keystore directory (Program Files). Certs had been imported, but no actual TLS conversation really took place because the Prevent server had no certificate to present (the "Null Pointer"). Again, check Which is the correct keystore folder for importing TLS certificates for Network Prevent for Email?
Once the keystore was moved into correct keystore directory (ProgramData), and Detection Server restarted, new errors appeared:
27/Jul/22:11:07:00:421-0500 [INFO] (SMTP_CONNECTION.1201) Connection accepted (tid=28 cid=Upstream-f66c9867-e71f-4637-9521-89ab19138628 local=10.d.l.p:10025 remote=10.a.b.c:50281)
27/Jul/22:11:07:00:482-0500 [INFO] (SMTP_CONNECTION.1203) Forward connection established (tid=28 cid=Downstream-12b46b12-415e-46ae-874e-ec8ef1e80825 local=10.d.l.p:48954 remote=140.x.y.z:587)
27/Jul/22:11:07:01:106-0500 [SEVERE] (SMTP_CONNECTION.5208) TLS handshake failed (tid=28 cid=Upstream-f66c9867-e71f-4637-9521-89ab19138628 local=10.d.l.p:10025 remote=10.a.b.c:50281 reason=Received fatal alert: decode_error)
27/Jul/22:11:07:01:106-0500 [INFO] (SMTP_CONNECTION.5202) Sender connection error (tid=28 cid=Upstream-f66c9867-e71f-4637-9521-89ab19138628 local=10.d.l.p:10025 remote=10.a.b.c:50281 reason=Received fatal alert: decode_error)
27/Jul/22:11:07:01:108-0500 [INFO] (SMTP_CONNECTION.1202) Peer disconnected (tid=28 cid=Upstream-f66c9867-e71f-4637-9521-89ab19138628 local=<> remote=<>)
The above "fatal alert: decode_error" is something covered in RFC5346, and indicates that part of the TLS handshake has gone wrong because "some field was out of the specified range". It turned out in this case that the cipher being presented by the Upstream MTA was one that DLP didn't like (it was an older TLS1.1 cipher). Once the customer removed that from the list of possible ciphers being offered, mail was accepted without issues (e.g., a supported TLS1.2 cipher).
For more details on troubleshooting cipher issues: Selecting Ciphers for DLP.
28/Mar/22:16:03:02:362-0500 [INFO] (SMTP_CONNECTION.1201) Connection accepted (tid=2b cid=Upstream-fea4540f-3852-4b9c-93ae-77564ca87da1 local=10.d.l.p:10025 remote=10.a.b.c:5263)
28/Mar/22:16:03:02:409-0500 [INFO] (SMTP_CONNECTION.1203) Forward connection established (tid=2b cid=Downstream-d715a3c9-0e8d-473d-8e19-f795e95ecfc8 local=10.d.l.p:62801 remote=205.x.y.z:25)
28/Mar/22:16:03:02:690-0500 [INFO] (SMTP_CONNECTION.5209) TLS handshake completed (tid=2b cid=Upstream-fea4540f-3852-4b9c-93ae-77564ca87da1 local=10.d.l.p:10025 remote=10.a.b.c:5263 peer=<unverified> protocol=<TLSv1.2> cipher=<TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384>)
28/Mar/22:16:03:02:784-0500 [SEVERE] (SMTP_CONNECTION.5208) TLS handshake failed (tid=2b cid=Downstream-d715a3c9-0e8d-473d-8e19-f795e95ecfc8 local=10.d.l.p:62801 remote=205.x.y.z:25 reason=General SSLEngine problem)
28/Mar/22:16:03:02:784-0500 [INFO] (SMTP_CONNECTION.5203) Forward connection error (tid=2b cid=Downstream-d715a3c9-0e8d-473d-8e19-f795e95ecfc8 mta=m.t.a:25 reason=General SSLEngine problem)
28/Mar/22:16:03:02:784-0500 [INFO] (SMTP_CONNECTION.1205) Service connection closed (tid=2b cid=Upstream-fea4540f-3852-4b9c-93ae-77564ca87da1 local=10.d.l.p:10025 remote=10.a.b.c:5263 messages=0 time=0.42s)
28/Mar/22:16:03:02:784-0500 [INFO] (SMTP_CONNECTION.1202) Peer disconnected (tid=2b cid=Downstream-d715a3c9-0e8d-473d-8e19-f795e95ecfc8 local=<> remote=<>)
For the above connection failure, a version of the DLP prevent.ks file exists, and has had a cert from the downstream MTA (a hosted or cloud MTA, in this case) imported into that keystore.
The "General SSLEngine problem" in this instance is another result which can happen when the prevent.ks was in the wrong location ("Program Files\..\..\..\Protect\keystore" instead of "ProgramData\..\..\..\keystore").
However, the fact that this TLS failure occurred on the Forward connection, indicates that the certificate chain previously imported into the prevent.ks keystore is likely the source of the problem.
Note that:
So, if either a "General SSL Problem" occurs (or a "PKIX path building failed") - check the certificate chain in the MTA certificates. If we have no way to authenticate it up to a known RootCA – the TLS operation will fail.
Setting up TLS encryption for SMTP Prevent
Once the prevent.ks file was moved to the correct location (“ProgramData” directory, as configured in Protect.properties files on Prevent server), followed by a restart of services, the error changed:
SMTP Operational log:
31/Mar/22:08:03:07:755-0500 [INFO] (SMTP_CONNECTION.1201) Connection accepted (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646)
31/Mar/22:08:03:07:837-0500 [INFO] (SMTP_CONNECTION.1203) Forward connection established (tid=2a cid=Downstream-66ab8086-9d47-40c2-bc5b-cb21f802eb1a local=10.d.l.p:54711 remote=205.x.y.z:25)
31/Mar/22:08:03:08:008-0500 [SEVERE] (SMTP_CONNECTION.5208) TLS handshake failed (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646 reason=no cipher suites in common)
31/Mar/22:08:03:08:008-0500 [INFO] (SMTP_CONNECTION.5202) Sender connection error (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646 reason=no cipher suites in common)
31/Mar/22:08:03:08:008-0500 [INFO] (SMTP_CONNECTION.1202) Peer disconnected (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=<> remote=<>)
RP logs:
Mar 31, 2022 8:03:07 AM com.vontu.mta.rp.log.SmtpLogManager logConnectionAccepted
INFO: (SMTP_CONNECTION.1201) Connection accepted (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646)
Mar 31, 2022 8:03:07 AM com.vontu.mta.rp.log.SmtpLogManager logForwardConnectionEstablished
INFO: (SMTP_CONNECTION.1203) Forward connection established (tid=2a cid=Downstream-66ab8086-9d47-40c2-bc5b-cb21f802eb1a local=10.d.l.p:54711 remote=205.x.y.z:25)
Mar 31, 2022 8:03:07 AM com.vontu.mta.rp.handlers.StartTLSState handleCommand
INFO: Received command "STARTTLS" from com.vontu.mta.rp.connection.UpstreamConnection@399a80c0 relaying to com.vontu.mta.rp.connection.DownstreamConnection@7d403143
Mar 31, 2022 8:03:07 AM com.vontu.mta.rp.handlers.StartTLSState handleResponse
INFO: Received response "220 2.0.0 Ready to start TLS" from com.vontu.mta.rp.connection.DownstreamConnection@7d403143 relaying to com.vontu.mta.rp.connection.UpstreamConnection@399a80c0
Mar 31, 2022 8:03:07 AM com.vontu.mta.rp.connection.ESMTPPeer relinquishChannel
INFO: RPT(2a)_channel is relinquished
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.connection.ESMTPPeer relinquishChannel
INFO: RPT(2a)_channel is relinquished
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.handlers.StartTLSState handleResponse
INFO: STARTTLS Response completed=true
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.tls.SecureESMTPPeer send
SEVERE: (SMTP_CONNECTION.5208) TLS handshake failed (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646 reason=no cipher suites in common)
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.log.SmtpLogManager logSenderConnectionError
INFO: (SMTP_CONNECTION.5202) Sender connection error (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=10.d.l.p:10025 remote=10.a.b.c:58646 reason=no cipher suites in common)
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.log.SmtpLogManager logConnectionError
WARNING: RPT(2a): Handling writing op IOException on com.vontu.mta.rp.connection.UpstreamConnection@399a80c0 with peer com.vontu.mta.rp.connection.DownstreamConnection@7d403143 as disconnect.
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.EventLoop handlePeerDisconnect
WARNING: RPT(2a): Disconnect from sending peer com.vontu.mta.rp.connection.UpstreamConnection@399a80c0.
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.connection.ConnectionsStateManagerAction cleanUpAfterAbort
WARNING: RPT(2a): Message aborted during transfer. Clearing message chain state.
Mar 31, 2022 8:03:08 AM com.vontu.mta.rp.log.SmtpLogManager logPeerDisconnected
INFO: (SMTP_CONNECTION.1202) Peer disconnected (tid=2a cid=Upstream-7e833b98-907a-4a13-8d1b-085190c732fc local=<> remote=<>)
In this case, the TLS handshake failure has to do with the Upstream MTA. Since DLP doesn't require the Upstream Certificate into Email Prevent (we only require the downstream Certs in order to authenticate where we are releasing the message to after inspection) - a TLS connection failure upstream is often related to MTA settings (e..g, on Exchange or the in-house MTA). For example, the sending MTA is where the options for TLS are presented - and they have to be accepted by the receiving MTA (DLP in this instance). If DLP and the upstream MTA can't agree on the handshake parameters, the handshake will fail.
Thus, confirm that cipher suites as configured are expected to work: Selecting Ciphers for DLP.
Landing page for certificate KBs:
Certificates, Keystores, and Keys used in Data Loss Prevention