SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Raise/discuss any potential issues with MailEnable for consideration in project issue register.
Post Reply
cjard
Posts: 35
Joined: Wed Jan 04, 2012 5:55 pm

SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by cjard »

ME Pro 7.6

I've seen another thread with a similar error message (the error number was different: 80090331)

I've a problem using TLS. The client (i'm using OpenSSL's built in test client to start a tls session) has the following dialog with the SMTP connector:

Client> EHLO openssl.client.net
Server> (ehlo response, cites STARTTLS available among other things)
Client> STARTTLS
Server> 220 Ready to start TLS
Client> (some binary data)
Server> 454 TLS not available due to temporary reason

The services run as LocalSystem. I'm applying the MEInstaller "Apply strict" option now, to see if it helps (it's taking loooooong), as well as verifying permissions on the registry keys and configuring things as per http://www.mailenable.com/kb/content/ar ... D=ME020479

Is this likely to be a permissions issue, the same as 80090331?

MailEnable-Ian
Site Admin
Posts: 9738
Joined: Mon Mar 22, 2004 4:44 am
Location: Melbourne, Victoria, Australia

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by MailEnable-Ian »

Hi,

Try and telnet to the SMTP service locally on the MailEnable server. I.e: telnet localhost 25

Once connected issue the EHLO command then STARTTLS command to see if you get the same 454 error. Just trying to eliminate any proxies/firewalls causing the problem.
Regards,

Ian Margarone
MailEnable Support

cjard
Posts: 35
Joined: Wed Jan 04, 2012 5:55 pm

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by cjard »

Hi Ian

The only bit I'd struggle with, in terms of the telnet route, is right after I say "STARTTLS" and the server says "OK, go ahead", the server is expecting some binary from the client, and I wouldnt be able to form it. However, here's how I test (from https://scottlinux.com/2014/06/05/check ... h-openssl/):

Downloaded OpenSSL, it has the ability to pretend to be a mail client and issue a starttls, with the following command line:

Code: Select all

openssl s_client -starttls smtp -crlf -connect HOST:PORT
To observe the traffic I use a utility called PortTunnel - it opens a listening socket on e.g. 2525, pipes anything sent to it, to a declared host:port (in my case localhost:25 as MailEnable and portTunnel are on the same machine) and pipes anything received back, back to the connecting in client. I'm sure you're familiar with the form of TCP redirection. PortTunnel also has a facility enabled to dump the bytes passed back and forth, to disk, and that's how I'm observing the conversation

Conversation has essentially been a repeat from localhost as it was externally.

Here's the output from OpenSSL's diag

Code: Select all

E:\openssl>openssl s_client -starttls smtp -crlf -connect localhost:2525
WARNING: can't open config file: /usr/local/ssl/openssl.cnf
CONNECTED(00000740)
6508:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:.\ssl\s
23_clnt.c:825:
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 271 bytes and written 342 bytes
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : 0000
    Session-ID:
    Session-ID-ctx:
    Master-Key:
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1511867268
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
---

And here's the relevant SMTP-DEBUG log entry:

Code: Select all

11/28/17 11:52:44	[1140] Initializing SSL Conversation
11/28/17 11:52:44	Accept Security Context Failed with error code 80090308
11/28/17 11:52:44	[1140] SSL_Handshake negotiation failed
11/28/17 11:52:44	ME-I0070: (recv) socket [1140] was gracefully closed during [STARTTLS] command by the remote client 127.0.0.1.
11/28/17 11:52:44	ME-I0074: [1140] (Debug) End of conversation
Here's the chat between client and server:

220 mail.myhost.com ESMTP MailEnable Service, Version: 7.60-7.60- ready at 11/28/17 11:07:48
EHLO openssl.client.net
250-myhost.com [127.0.0.1], this server offers 5 extensions
250-AUTH LOGIN
250-SIZE 16384000
250-HELP
250-AUTH=LOGIN
250 STARTTLS
STARTTLS
220 Ready to start TLS
BINARY BYTES ISSUED BY OPENSSL HAVE BEEN BASE64 ENCODED:
FgMBAS4BAAEqAwMX381PfCdsaXjlsVO/M/tb3MEv+QdS3+AKTAdAQggcLwAArMAwwCzAKMAkwBTA
CgClAKMAoQCfAGsAagBpAGgAOQA4ADcANgCIAIcAhgCFwDLALsAqwCbAD8AFAJ0APQA1AITAL8Ar
wCfAI8ATwAkApACiAKAAngBnAEAAPwA+ADMAMgAxADAAmgCZAJgAlwBFAEQAQwBCwDHALcApwCXA
DsAEAJwAPAAvAJYAQQAHwBHAB8AMwAIABQAEwBLACAAWABMAEAANwA3AAwAKAP8BAABVAAsABAMA
AQIACgAcABoAFwAZABwAGwAYABoAFgAOAA0ACwAMAAkACgAjAAAADQAgAB4GAQYCBgMFAQUCBQME
AQQCBAMDAQMCAwMCAQICAgMADwABAQ==
454 TLS not available due to temporary reason


The ME SMTP connector also has an additional port that is SSL/TLS immediately (no starttls; it expects the client to go straight to encrypted mode), and that one looks like this when I test it with OpenSSL:

Code: Select all

E:\openssl>openssl s_client -crlf -connect localhost:7372
WARNING: can't open config file: /usr/local/ssl/openssl.cnf
CONNECTED(00000740)
4852:error:140790E5:SSL routines:ssl23_write:ssl handshake failure:.\ssl\s23_lib
.c:177:
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 0 bytes and written 307 bytes
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : 0000
    Session-ID:
    Session-ID-ctx:
    Master-Key:
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1511867741
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
And here's the relevant SMTP-DEBUG log entry:

Code: Select all

11/28/17 11:53:13	[1132] Initializing SSL Conversation
11/28/17 11:53:13	Accept Security Context Failed with error code 80090308
11/28/17 11:53:13	[1132] SSL_Handshake negotiation failed
11/28/17 11:53:13	ME-E0xxx: [1132] SSL Handshake failed. Closing connection.
I've altered the service so that it Logs On using my admin credentials. It was logging on as LocalSystem, trying to get it logging on as IME_SYSTEM gave "Access denied". I'm not entirely sure if the MEInstaller finished its "Apply strict security policy" because i left it going overnight and it was gone in the morning, but launching MEInstaller again re-states the "apply" option not "remove" - though it did at least seemed to have created the IME_SYSTEM user (as it wasnt present on the machine before. When configuring the SMTP conenctor to log on using my admin credentials I also ensured that administrators can access the cert the server uses:

Code: Select all

C:\Documents and Settings\cjard>winhttpcertcfg -l -c LOCAL_MACHINE\My -s "*.myhost.com"
Microsoft (R) WinHTTP Certificate Configuration Tool
Copyright (C) Microsoft Corporation 2001.

Matching certificate:
CN=*.myhost.com
OU=Domain Control Validated

Additional accounts and groups with access to the private key include:
    BUILTIN\Administrators
    NT AUTHORITY\SYSTEM
    SERVER\IME_SYSTEM
So, I'm still thinking it's not a permissions issue..

The only possibly relevant reference I've seen to 80090308 is here:

https://blogs.technet.microsoft.com/pet ... not-valid/

Any thoughts would be welcome..

MailEnable-Ian
Site Admin
Posts: 9738
Joined: Mon Mar 22, 2004 4:44 am
Location: Melbourne, Victoria, Australia

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by MailEnable-Ian »

Hi,

Try and create a self-signed certificate in IIS and then set that as the SSL certificate to be used in MailEnable. Then try the OpenSSL tests.
Regards,

Ian Margarone
MailEnable Support

cjard
Posts: 35
Joined: Wed Jan 04, 2012 5:55 pm

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by cjard »

Hi Ian

I created a self signed cert using the IIS resource kit 6 tools, SelfSSL utility. The following command line was used:

Code: Select all

C:\Program Files\IIS Resources\SelfSSL>selfssl /T /N:CN=mail.myhost.com /K:1024 /V:3650 /S:1 /P:443
This created an SSC and added it to the machine cert store. Took a look at the cert; looks good, subject name there as the name ME thinks the mail server has. I opened MailEnable Admin, got properties on localhost server, SSL tab, and set the cert to NONE, apply, then set to the new list entry mail.myhost.com (the other is a wildcard cert *.myhost.com, so they can be distinguished) and apply again (just in case..)

Stopped SMTP, deleted the DEBUG and ACT logs, started SMTP. Logs look good:

Code: Select all

[11/29/17 16:59:11]****************** LOG FILE STARTED *******************
11/29/17 16:59:11	ME-I0143: Service Loading Configuration Providers
11/29/17 16:59:11	ME-IXXXX: Loaded Address Map Provider
11/29/17 16:59:11	ME-IXXXX: Loaded Authentication Provider
11/29/17 16:59:11	ME-IXXXX: Loaded MEAISM Configuration Provider
11/29/17 16:59:11	ME-IXXXX: Loaded MEAIDP Directory Provider
11/29/17 16:59:11	ME-IXXXX: Loaded MEAILS Configuration Provider
11/29/17 16:59:11	ME-IXXXX: Loaded Postoffice Configuration Provider
11/29/17 16:59:11	ME-I0073: MEW2KDNS Initialized to use DNS Servers (8.8.8.8 8.8.4.4 127.0.0.1 1.2.3.41)
11/29/17 16:59:11	ME-IXXXX: No plug-in DLL configured
11/29/17 16:59:11	ME-I0141: Service Starting
11/29/17 16:59:11	ME-I0139: Outbound Mail Agent Initialised
11/29/17 16:59:11	ME-I0139: Initializing DomainKeys Extension
11/29/17 16:59:11	ME-I0140: Standard Inbound Mail Agent Initialised
11/29/17 16:59:11	ME-I0065: [SYSTEM] Initalised Send Message Master Thread
11/29/17 16:59:11	ME-I0065: [SYSTEM] Resetting queued messages
11/29/17 16:59:11	ME-I0066: [SYSTEM] No outgoing message files in queue.
11/29/17 16:59:11	ME-I0077: Server Address IP Address:1.2.3.41
11/29/17 16:59:11	ME-I0077: Server Address IP Address:1.2.3.42
11/29/17 16:59:11	ME-I0077: Server Address IP Address:1.2.3.43
11/29/17 16:59:11	ME-I0077: Server Address IP Address:1.2.3.44
11/29/17 16:59:11	ME-I0077: Server Address IP Address:1.2.3.45
11/29/17 16:59:11	ME-I0077: Server Address IP Address:127.0.0.1
11/29/17 16:59:11	ME-I0079: Completed enumerating IP Interfaces
11/29/17 16:59:11	ME-I0082: Service binding to all addresses on port (25) for IPv4 family (2). Requires authentication 0
11/29/17 16:59:11	ME-IXXXX: Initalised Recv Message Master Thread
11/29/17 16:59:11	ME-I0085: Service (Alternate) binding to all IPv4 addresses on port (587). Requires authentication 1
11/29/17 16:59:11	ME-IXXXX: Initalised Recv Message Master Thread
11/29/17 16:59:11	ME-I0085: Service (Alternate) binding to all IPv4 addresses on port (7371). Requires authentication 1
11/29/17 16:59:11	ME-I0085: Service (Alternate) binding to all IPv4 addresses on port (7372). Requires authentication 1
11/29/17 16:59:11	ME-IXXXX: Initalised Recv Message Master Thread
11/29/17 16:59:11	ME-F0081: socket() failed
11/29/17 16:59:11	ME-WXXXX: BindAddresses_All: closesocket on socket (-1) returned error: 10038.
11/29/17 16:59:11	ME-I0144: Service Completed Loading Agents
11/29/17 16:59:11	ME-IXXXX: Initalised Recv Message Master Thread
11/29/17 16:59:11	ME-I0076: Listening for connections
11/29/17 16:59:11	ME-I0076: Listening for connections
11/29/17 16:59:11	ME-I0076: Listening for connections
11/29/17 16:59:11	Service bound to certificate with name: "mail.myhost.com".
11/29/17 16:59:11	ME-I0076: Listening for connections
Ran an OpenSSL test, and darnit - same broken result:

Code: Select all

E:\openssl>openssl s_client -starttls smtp -crlf -connect localhost:2525
WARNING: can't open config file: /usr/local/ssl/openssl.cnf
CONNECTED(00000740)
4360:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:.\ssl\s
23_clnt.c:825:
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 271 bytes and written 342 bytes
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : 0000
    Session-ID:
    Session-ID-ctx:
    Master-Key:
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1511976375
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
---
Try the straight-to-ssl socket; it's still broken too:

Code: Select all

E:\openssl>openssl s_client -crlf -connect localhost:7372
WARNING: can't open config file: /usr/local/ssl/openssl.cnf
CONNECTED(00000740)
8004:error:140790E5:SSL routines:ssl23_write:ssl handshake failure:.\ssl\s23_lib
.c:177:
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 0 bytes and written 307 bytes
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : 0000
    Session-ID:
    Session-ID-ctx:
    Master-Key:
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1511976407
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
---
The SMTP chatter still runs the same pattern (client says STARTTLS, server says OK, client sends bytes, server says 454/temporary unavail)

MailEnable-Ian
Site Admin
Posts: 9738
Joined: Mon Mar 22, 2004 4:44 am
Location: Melbourne, Victoria, Australia

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by MailEnable-Ian »

Hi,

Perhaps PM me with login details to the server and ill take a quick look.
Regards,

Ian Margarone
MailEnable Support

bigreddastud
Posts: 46
Joined: Tue Apr 19, 2005 7:30 pm

Re: SMTP debug log contains "Accept Security Context Failed with error code 80090308 "

Post by bigreddastud »

Was there ever any resolution to this issue? I've got the same error (for IMAP server) showing in my ME log files. However, I know that SSL works at least for some clients. One person complained their device was intermittently failing to connect, so I'm trying to dig into why. My device works just fine. No changes to hardware/software of late. Running version 9.72
04/13/18 18:00:13 Couldn't decrypt, error 80090330
04/13/18 18:00:13 Accept Security Context Failed with error code 80090331
04/13/18 18:00:13 [2756] SSL_Handshake negotiation failed
However, SSL can connect when testing with OpenSSL client, but complains about "verify error:num=20:unable to get local issuer certificate"

Note: these commands were run on the same server that Mailenable is setup on:

Code: Select all

C:\Users\Administrator>openssl s_client -showcerts -connect 192.168.1.200:993
Loading 'screen' into random state - done
CONNECTED(00000134)
depth=1 C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
verify error:num=20:unable to get local issuer certificate
verify return:0
---
Certificate chain
 0 s:/CN=mydomain.com
   i:/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
-----BEGIN CERTIFICATE-----
[[REDACTED]]
-----END CERTIFICATE-----
 1 s:/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
   i:/O=Digital Signature Trust Co./CN=DST Root CA X3
-----BEGIN CERTIFICATE-----
[[REDACTED]]
-----END CERTIFICATE-----
---
Server certificate
subject=/CN=mydomain.com
issuer=/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
---
No client certificate CA names sent
---
SSL handshake has read 3568 bytes and written 489 bytes
---
New, TLSv1/SSLv3, Cipher is ECDHE-RSA-AES256-SHA384
Server public key is 4096 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES256-SHA384
    Session-ID: [[REDACTED]]

    Session-ID-ctx:
    Master-Key: [[REDACTED]]
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1523660544
    Timeout   : 300 (sec)
    Verify return code: 20 (unable to get local issuer certificate)
---
* OK IMAP4rev1 server ready at 04/13/18 18:02:24
* BYE Session terminated by server because idle timeout was exceeded

Post Reply