ssl/tls and starttls [50%]

drsox · Post by **drsox** » 2014-06-02 15:33

I also need outbound to be able to relay via Office365

(Sadly the only allowed smtp on the firewall).

prisma · Post by **prisma** » 2014-06-02 15:40

Bills experimental build supports STARTTLS for incoming SMTP. Still nothing more. But works very well for me.

I'm waiting also for further enhancements regarding STARTTLS for outgoing SMTP. Some people in this forum need it e.g. for ISPs smarthosts. As far as I know they use "stunnel" for workaround...

Feel free to vote here what you need next:
http://www.hmailserver.com/forum/viewtopic.php?t=26118
http://www.hmailserver.com/forum/viewtopic.php?t=25966

Bill48105 · Post by **Bill48105** » 2014-06-02 15:41

A few weeks ago I added outbound STARTTLS to a test build here just for routes but does not work. Always gives handshake errors. I suspect it's an openssl related issue but been unable to debug it. I'll share the build if someone wants to test but realize it'd require advanced low-level testing. Like wireshark or such and significant knowledge of SSL/TLS to help figure out why handshake is failing before it'd be useful.
Bill

prisma · Post by **prisma** » 2014-06-02 15:44

Bill48105 wrote:A few weeks ago I added outbound STARTTLS to a test build here just for routes but does not work. Always gives handshake errors. I suspect it's an openssl related issue but been unable to debug it. I'll share the build if someone wants to test but realize it'd require advanced low-level testing. Like wireshark or such and significant knowledge of SSL/TLS to help figure out why handshake is failing before it'd be useful.
Bill

Oh, didn't recognize this, share it with me!

Bill48105 · Post by **Bill48105** » 2014-06-02 15:53

prisma wrote:
Bill48105 wrote:A few weeks ago I added outbound STARTTLS to a test build here just for routes but does not work. Always gives handshake errors. I suspect it's an openssl related issue but been unable to debug it. I'll share the build if someone wants to test but realize it'd require advanced low-level testing. Like wireshark or such and significant knowledge of SSL/TLS to help figure out why handshake is failing before it'd be useful.
Bill
Oh, didn't recognize this, share it with me!

Yeah I mentioned it in another post but didn't post up since it didn't work. It's possible it just requires tweeking ciphers (glad I added the INI) or something trivial I'm overlooking. I'll send you PM
thx
Bill

drsox · Post by **drsox** » 2014-06-02 16:05

I am happy to do some testing too.. send me the info

drsox · Post by **drsox** » 2014-06-02 16:45

I can't send you a pm directly Bill as I've not posted enough yet.

As far as I can see the test build sends STARTTLS and then further "in the clear" data... compared to Outlook.

Bill48105 · Post by **Bill48105** » 2014-06-02 17:06

drsox wrote:I can't send you a pm directly Bill as I've not posted enough yet.

As far as I can see the test build sends STARTTLS and then further "in the clear" data... compared to Outlook.

Thx drsox. I'll need to check if the build I shared. If you set hmailserver.ini [Settings] LogLevel=99 you will get more low level info including that hmail attempts the handshake & the errors when it does. That snippet you posted makes it look like it ever tries but that can't be the case based on what i've seen here.
Something like this when sending to gmail:

Code: Select all

"APPLICATION"	3504	"2014-05-21 22:58:27.661"	"SMTPDeliverer - Message 1596: Relaying to host smtp.gmail.com."
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"SD::_InitiateExternalConnection"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - SSLOptionList Option: default_workarounds,no_sslv2"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - SSLCipherList Option not set, skipping."
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - Found SSL Option: default_workarounds"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - SSL Option SET: default_workarounds"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - Found SSL Option: no_sslv2"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::PrepareSSLContext - SSL Option SET: no_sslv2"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::Start"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"Creating session 5"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::Try"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::usessl"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPCconnection::GetSocket(): next_layer()"
"DEBUG"	3504	"2014-05-21 22:58:27.661"	"TCPConnection::SocketisNOTopen"
"TCPIP"	3504	"2014-05-21 22:58:27.661"	"Connecting to smtp.gmail.com..."
"SMTPD"	1448	4	"2014-05-21 22:58:27.661"	"192.168.3.20"	"RECEIVED: QUIT"
"SMTPD"	1448	4	"2014-05-21 22:58:27.661"	"192.168.3.20"	"SENT: 221 goodbye"
"DEBUG"	1448	"2014-05-21 22:58:27.661"	"TCPConnection::Write non ssl"
"DEBUG"	3200	"2014-05-21 22:58:27.661"	"Closing TCP/IP socket"
"DEBUG"	3200	"2014-05-21 22:58:27.661"	"Ending session 4"
"DEBUG"	3200	"2014-05-21 22:58:27.739"	"TCPCconnection::GetSocket(): next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.770"	"TCPConnection::~TCPConnection 4USESSL & TLS1"
"DEBUG"	3200	"2014-05-21 22:58:27.770"	"TCPConnection::Read next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.801"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3200	"2014-05-21 22:58:27.801"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.801"	"74.125.193.109"	"RECEIVED: 220 mx.google.com ESMTP v8sm9936510igk.16 - gsmtp"
"DEBUG"	3200	"2014-05-21 22:58:27.801"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.801"	"74.125.193.109"	"SENT: EHLO WIN7-20"
"DEBUG"	3200	"2014-05-21 22:58:27.801"	"TCPConnection::Write next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.801"	"SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG"	1448	"2014-05-21 22:58:27.801"	"TCPConnection::Read next_layer()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3428	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250-mx.google.com at your service, [*.*.*.*]"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPConnection::Read next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250-SIZE 35882577"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPConnection::Read next_layer()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3428	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250-8BITMIME"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPConnection::Read next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250-STARTTLS"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPConnection::Read next_layer()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3428	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250-ENHANCEDSTATUSCODES"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	3428	"2014-05-21 22:58:27.926"	"TCPConnection::Read next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"RECEIVED: 250 CHUNKING"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:27.926"	"74.125.193.109"	"SENT: STARTTLS"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPConnection::Write next_layer()"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPConnection::STARTTLS_Handshake handshake1"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"TCPConnection::STARTTLS_Handshake handshake3"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"STARTTLS true"
"DEBUG"	3200	"2014-05-21 22:58:27.926"	"sleeping 2 sec"
"DEBUG"	964	"2014-05-21 22:58:27.957"	"TCPCconnection::GetSocket(): next_layer()"
"TCPIP"	964	"2014-05-21 22:58:27.957"	"TCPConnection - SSL handshake with client failed. Error code: 336031996, Message: unknown protocol, Remote IP: 74.125.193.109"
"DEBUG"	3200	"2014-05-21 22:58:29.939"	"_stateSTARTTLS = 3"
"DEBUG"	3200	"2014-05-21 22:58:29.939"	"StartTLSState3() true"
"DEBUG"	3200	"2014-05-21 22:58:29.939"	"TCPCconnection::GetSocket(): lowest_layer()"
"SMTPC"	3200	5	"2014-05-21 22:58:29.939"	"74.125.193.109"	"SENT: EHLO WIN7-20"
"DEBUG"	3428	"2014-05-21 22:58:29.939"	"TCPConnection::Write ssl"
"DEBUG"	3200	"2014-05-21 22:58:29.939"	"TCPCconnection::GetSocket(): lowest_layer()"
"DEBUG"	3200	"2014-05-21 22:58:29.939"	"The write operation failed. Remote IP: 74.125.193.109, Session: 5, Code: 336031996, Message: unknown protocol"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"SD::~_InitiateExternalConnection-5"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Ending session 5"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"SD::~_DeliverToExternalAccounts-2"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Collect delivery result"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Collect delivery result - Done"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"SD::_RescheduleDelivery"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Retrieving retry options."
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Starting rescheduling."
"APPLICATION"	3504	"2014-05-21 22:58:29.939"	"SMTPDeliverer - Message 1596: Message could not be delivered. Scheduling it for later delivery in 60 minutes."
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"PersistentMessage::SetNextTryTime()"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"PersistentMessage::~SetNextTryTime()"
"DEBUG"	3504	"2014-05-21 22:58:29.939"	"Message rescheduled for later delivery."
"APPLICATION"	3504	"2014-05-21 22:58:29.939"	"SMTPDeliverer - Message 1596: Message delivery thread completed."
"DEBUG"	3416	"2014-05-21 22:58:57.551"	"Deleting message"
"DEBUG"	3416	"2014-05-21 22:58:57.551"	"Deleting message file."

Things to note from hmail's logging. next_layer means "plain text" on sslsocket. lowest_layer means encryption level. Also note the read/write switch from "non ssl" to "ssl" after the handshake starts which as far as I know should be the case. It could very well be a timing issue of WHEN the switchover to lowest_layer/ssl starts during the handshake process. I've yet to see anywhere state that but I assume as soon as starttls is issued & remote responds OK switch should happen. And that appears to be what happens for incoming starttls.

And PS. the 2nd EHLO is being sent blindly for now. Obviously it should be based on results of the handshake but at this point was just trying to get past the handshake.

drsox · Post by **drsox** » 2014-06-02 22:45

From my transaction: (Might contain the end of my smtp local delivery session too)

Code: Select all

"DEBUG"	2708	"2014-06-02 21:43:21.092"	"Performing local delivery"
"DEBUG"	2708	"2014-06-02 21:43:21.095"	"Local delivery completed"
"DEBUG"	2708	"2014-06-02 21:43:21.097"	"Performing external delivery"
"APPLICATION"	2708	"2014-06-02 21:43:21.100"	"SMTPDeliverer - Message 3: Relaying to host outlook.office365.com."
"DEBUG"	2708	"2014-06-02 21:43:21.101"	"SD::_InitiateExternalConnection"
"DEBUG"	2708	"2014-06-02 21:43:21.102"	"TCPConnection::Start"
"DEBUG"	2708	"2014-06-02 21:43:21.103"	"Creating session 3"
"DEBUG"	2708	"2014-06-02 21:43:21.104"	"TCPConnection::Try"
"DEBUG"	10564	"2014-06-02 21:43:21.277"	"TCPConnection::~TCPConnection 6!USESSL & !TLS"
"DEBUG"	10564	"2014-06-02 21:43:21.278"	"TCPConnection::Read non ssl"
"DEBUG"	7768	"2014-06-02 21:43:21.418"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	7768	3	"2014-06-02 21:43:21.418"	"132.245.81.178"	"RECEIVED: 220 BY2PR06CA042.outlook.office365.com Microsoft ESMTP MAIL Service ready at Mon, 2 Jun 2014 20:43:24 +0000"
"SMTPC"	7768	3	"2014-06-02 21:43:21.419"	"132.245.81.178"	"SENT: EHLO HORSE"
"DEBUG"	7768	"2014-06-02 21:43:21.419"	"TCPConnection::Write non ssl"
"DEBUG"	7768	"2014-06-02 21:43:21.420"	"SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG"	6764	"2014-06-02 21:43:21.421"	"TCPConnection::Read non ssl"
"DEBUG"	19348	"2014-06-02 21:43:21.569"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	19348	3	"2014-06-02 21:43:21.570"	"132.245.81.178"	"RECEIVED: 250-BY2PR06CA042.outlook.office365.com Hello [86.130.98.117]"
"DEBUG"	19348	"2014-06-02 21:43:21.571"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	19348	"2014-06-02 21:43:21.571"	"TCPConnection::Read non ssl"
"DEBUG"	17040	"2014-06-02 21:43:21.572"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	17040	3	"2014-06-02 21:43:21.573"	"132.245.81.178"	"RECEIVED: 250-SIZE 78643200"
"DEBUG"	17040	"2014-06-02 21:43:21.573"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	17040	"2014-06-02 21:43:21.574"	"TCPConnection::Read non ssl"
"DEBUG"	19348	"2014-06-02 21:43:21.574"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	19348	3	"2014-06-02 21:43:21.575"	"132.245.81.178"	"RECEIVED: 250-PIPELINING"
"DEBUG"	19348	"2014-06-02 21:43:21.575"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	19348	"2014-06-02 21:43:21.576"	"TCPConnection::Read non ssl"
"DEBUG"	6764	"2014-06-02 21:43:21.577"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	6764	3	"2014-06-02 21:43:21.577"	"132.245.81.178"	"RECEIVED: 250-DSN"
"DEBUG"	6764	"2014-06-02 21:43:21.578"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	6764	"2014-06-02 21:43:21.578"	"TCPConnection::Read non ssl"
"DEBUG"	19348	"2014-06-02 21:43:21.579"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	19348	3	"2014-06-02 21:43:21.580"	"132.245.81.178"	"RECEIVED: 250-ENHANCEDSTATUSCODES"
"DEBUG"	19348	"2014-06-02 21:43:21.580"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	19348	"2014-06-02 21:43:21.581"	"TCPConnection::Read non ssl"
"DEBUG"	17040	"2014-06-02 21:43:21.582"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	17040	3	"2014-06-02 21:43:21.583"	"132.245.81.178"	"RECEIVED: 250-STARTTLS"
"DEBUG"	17040	"2014-06-02 21:43:21.584"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	17040	"2014-06-02 21:43:21.585"	"TCPConnection::Read non ssl"
"DEBUG"	19348	"2014-06-02 21:43:21.586"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	19348	3	"2014-06-02 21:43:21.586"	"132.245.81.178"	"RECEIVED: 250-8BITMIME"
"DEBUG"	19348	"2014-06-02 21:43:21.587"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	19348	"2014-06-02 21:43:21.588"	"TCPConnection::Read non ssl"
"DEBUG"	17040	"2014-06-02 21:43:21.588"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	17040	3	"2014-06-02 21:43:21.589"	"132.245.81.178"	"RECEIVED: 250-BINARYMIME"
"DEBUG"	17040	"2014-06-02 21:43:21.589"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	17040	"2014-06-02 21:43:21.590"	"TCPConnection::Read non ssl"
"DEBUG"	9088	"2014-06-02 21:43:21.591"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	9088	3	"2014-06-02 21:43:21.591"	"132.245.81.178"	"RECEIVED: 250 CHUNKING"
"SMTPC"	9088	3	"2014-06-02 21:43:21.592"	"132.245.81.178"	"SENT: STARTTLS"
"DEBUG"	9088	"2014-06-02 21:43:21.592"	"TCPConnection::Write non ssl"
"DEBUG"	9088	"2014-06-02 21:43:21.593"	"TCPConnection::STARTTLS_Handshake handshake1"
"DEBUG"	9088	"2014-06-02 21:43:21.594"	"TCPConnection::STARTTLS_Handshake handshake3"
"DEBUG"	9088	"2014-06-02 21:43:21.594"	"STARTTLS true"
"DEBUG"	9088	"2014-06-02 21:43:21.595"	"sleeping 2 sec"
"DEBUG"	15280	"2014-06-02 21:43:21.908"	"TCPConnection::Read non ssl"
"DEBUG"	6764	"2014-06-02 21:43:22.593"	"TCPConnection::Write non ssl"
"DEBUG"	7768	"2014-06-02 21:43:22.594"	"Closing TCP/IP socket"
"DEBUG"	7768	"2014-06-02 21:43:22.596"	"Ending session 2"
"DEBUG"	9088	"2014-06-02 21:43:23.596"	"_stateSTARTTLS = 3"
"DEBUG"	9088	"2014-06-02 21:43:23.596"	"StartTLSState3() true"
"SMTPC"	9088	3	"2014-06-02 21:43:23.597"	"132.245.81.178"	"SENT: EHLO HORSE"
"DEBUG"	17040	"2014-06-02 21:43:23.598"	"TCPConnection::Write non ssl"
"DEBUG"	9088	"2014-06-02 21:43:23.599"	"TCPConnection::Read non ssl"
"DEBUG"	7768	"2014-06-02 21:43:23.600"	"SMTPClientConnection::_ParseASCII()"
"SMTPC"	7768	3	"2014-06-02 21:43:23.600"	"132.245.81.178"	"RECEIVED: 220 2.0.0 SMTP server ready"
"SMTPC"	7768	3	"2014-06-02 21:43:23.601"	"132.245.81.178"	"SENT: MAIL FROM:<testsender@heh.info>"
"DEBUG"	7768	"2014-06-02 21:43:23.602"	"TCPConnection::Write non ssl"
"DEBUG"	7768	"2014-06-02 21:43:23.604"	"SMTPClientConnection::~_ParseASCII() - 4"
"DEBUG"	9088	"2014-06-02 21:43:23.605"	"TCPConnection::Read non ssl"

Bill48105 · Post by **Bill48105** » 2014-06-02 23:04

Very strange drsox. Not only do your logs never show "ssl" vs "non ssl" they don't show the handshake failing or completing either. And I don't see any of the next_layer first_layer lines either. Maybe your LogLevel setting is too low. I'll need to do some more testing here maybe try a relay to office365.
thx
Bill

Bill48105 · Post by **Bill48105** » 2014-06-02 23:05

Oh.. Let me guess. Do you have SSL checked on the route page? That has to be checked.

drsox · Post by **drsox** » 2014-06-02 23:14

Oh, :\ sorry.. I assumed the SSL tick box would have enabled full socket SSL rather than TLS (are those the correct terms?).

Will tick the option and re-test

Sorry!

drsox · Post by **drsox** » 2014-06-02 23:20

Wireshark attached below. Looks like the server says hi and then hmailserver ends the connection?

Code: Select all

"DEBUG"	6224	"2014-06-02 22:15:30.408"	"PersistentMessage::SetNextTryTime()"
"DEBUG"	6224	"2014-06-02 22:15:30.410"	"PersistentMessage::~SetNextTryTime()"
"DEBUG"	9768	"2014-06-02 22:15:30.420"	"Delivering message..."
"APPLICATION"	9768	"2014-06-02 22:15:30.421"	"SMTPDeliverer - Message 3: Delivering message from testsender@x.info to testrcpt@x.info. File: C:\Program Files (x86)\hMailServer\Data\{E3A297F9-B7FD-4343-8EA1-879D708C3E6E}.eml"
"DEBUG"	9768	"2014-06-02 22:15:30.421"	"Applying rules"
"DEBUG"	9768	"2014-06-02 22:15:30.422"	"Performing local delivery"
"DEBUG"	9768	"2014-06-02 22:15:30.423"	"Local delivery completed"
"DEBUG"	9768	"2014-06-02 22:15:30.423"	"Performing external delivery"
"APPLICATION"	9768	"2014-06-02 22:15:30.424"	"SMTPDeliverer - Message 3: Relaying to host outlook.office365.com."
"DEBUG"	9768	"2014-06-02 22:15:30.424"	"SD::_InitiateExternalConnection"
"DEBUG"	9768	"2014-06-02 22:15:30.425"	"TCPConnection::PrepareSSLContext - SSLOptionList Option: default_workarounds,no_sslv2"
"DEBUG"	9768	"2014-06-02 22:15:30.426"	"TCPConnection::PrepareSSLContext - SSLCipherList Option not set, skipping."
"DEBUG"	9768	"2014-06-02 22:15:30.427"	"TCPConnection::PrepareSSLContext - Found SSL Option: default_workarounds"
"DEBUG"	9768	"2014-06-02 22:15:30.427"	"TCPConnection::PrepareSSLContext - SSL Option SET: default_workarounds"
"DEBUG"	9768	"2014-06-02 22:15:30.428"	"TCPConnection::PrepareSSLContext - Found SSL Option: no_sslv2"
"DEBUG"	9768	"2014-06-02 22:15:30.428"	"TCPConnection::PrepareSSLContext - SSL Option SET: no_sslv2"
"DEBUG"	9768	"2014-06-02 22:15:30.429"	"TCPConnection::Start"
"DEBUG"	9768	"2014-06-02 22:15:30.430"	"Creating session 5"
"DEBUG"	9768	"2014-06-02 22:15:30.431"	"TCPConnection::Try"
"DEBUG"	9768	"2014-06-02 22:15:30.431"	"TCPConnection::usessl"
"DEBUG"	9768	"2014-06-02 22:15:30.432"	"TCPCconnection::GetSocket(): next_layer()"
"DEBUG"	9768	"2014-06-02 22:15:30.432"	"TCPConnection::SocketisNOTopen"
"DEBUG"	9088	"2014-06-02 22:15:30.436"	"TCPCconnection::GetSocket(): next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.469"	"TCPConnection::~TCPConnection 4USESSL & TLS1"
"DEBUG"	9088	"2014-06-02 22:15:30.469"	"TCPConnection::Read next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.480"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	9088	"2014-06-02 22:15:30.481"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.482"	"132.245.225.98"	"RECEIVED: 220 DB4PR02CA0035.outlook.office365.com Microsoft ESMTP MAIL Service ready at Mon, 2 Jun 2014 21:15:32 +0000"
"DEBUG"	9088	"2014-06-02 22:15:30.482"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.483"	"132.245.225.98"	"SENT: EHLO HORSE"
"DEBUG"	9088	"2014-06-02 22:15:30.483"	"TCPConnection::Write next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.484"	"SMTPClientConnection::~_ParseASCII() - 2"
"DEBUG"	5836	"2014-06-02 22:15:30.485"	"TCPConnection::Read next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.505"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	5836	"2014-06-02 22:15:30.506"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.506"	"132.245.225.98"	"RECEIVED: 250-DB4PR02CA0035.outlook.office365.com Hello [86.130.98.117]"
"DEBUG"	5836	"2014-06-02 22:15:30.507"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	5836	"2014-06-02 22:15:30.507"	"TCPConnection::Read next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.508"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	9088	"2014-06-02 22:15:30.508"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.509"	"132.245.225.98"	"RECEIVED: 250-SIZE 78643200"
"DEBUG"	9088	"2014-06-02 22:15:30.509"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	9088	"2014-06-02 22:15:30.510"	"TCPConnection::Read next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.510"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	5836	"2014-06-02 22:15:30.511"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.512"	"132.245.225.98"	"RECEIVED: 250-PIPELINING"
"DEBUG"	5836	"2014-06-02 22:15:30.512"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	5836	"2014-06-02 22:15:30.513"	"TCPConnection::Read next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.513"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	9088	"2014-06-02 22:15:30.514"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.515"	"132.245.225.98"	"RECEIVED: 250-DSN"
"DEBUG"	9088	"2014-06-02 22:15:30.515"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	9088	"2014-06-02 22:15:30.516"	"TCPConnection::Read next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.517"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	5836	"2014-06-02 22:15:30.518"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.518"	"132.245.225.98"	"RECEIVED: 250-ENHANCEDSTATUSCODES"
"DEBUG"	5836	"2014-06-02 22:15:30.519"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	5836	"2014-06-02 22:15:30.520"	"TCPConnection::Read next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.520"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	9088	"2014-06-02 22:15:30.521"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.521"	"132.245.225.98"	"RECEIVED: 250-STARTTLS"
"DEBUG"	9088	"2014-06-02 22:15:30.522"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	9088	"2014-06-02 22:15:30.522"	"TCPConnection::Read next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.523"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	5836	"2014-06-02 22:15:30.524"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.524"	"132.245.225.98"	"RECEIVED: 250-8BITMIME"
"DEBUG"	5836	"2014-06-02 22:15:30.525"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	5836	"2014-06-02 22:15:30.525"	"TCPConnection::Read next_layer()"
"DEBUG"	9088	"2014-06-02 22:15:30.526"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	9088	"2014-06-02 22:15:30.526"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	9088	5	"2014-06-02 22:15:30.527"	"132.245.225.98"	"RECEIVED: 250-BINARYMIME"
"DEBUG"	9088	"2014-06-02 22:15:30.528"	"SMTPClientConnection::~_ParseASCII() - 1"
"DEBUG"	9088	"2014-06-02 22:15:30.528"	"TCPConnection::Read next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.529"	"SMTPClientConnection::_ParseASCII()"
"DEBUG"	5836	"2014-06-02 22:15:30.529"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.530"	"132.245.225.98"	"RECEIVED: 250 CHUNKING"
"DEBUG"	5836	"2014-06-02 22:15:30.530"	"TCPCconnection::GetSocket(): next_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:30.531"	"132.245.225.98"	"SENT: STARTTLS"
"DEBUG"	5836	"2014-06-02 22:15:30.531"	"TCPConnection::Write next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:30.532"	"TCPConnection::STARTTLS_Handshake handshake1"
"DEBUG"	5836	"2014-06-02 22:15:30.533"	"TCPConnection::STARTTLS_Handshake handshake3"
"DEBUG"	5836	"2014-06-02 22:15:30.533"	"STARTTLS true"
"DEBUG"	5836	"2014-06-02 22:15:30.534"	"sleeping 2 sec"
"DEBUG"	8900	"2014-06-02 22:15:30.552"	"TCPCconnection::GetSocket(): next_layer()"
"DEBUG"	5836	"2014-06-02 22:15:32.535"	"_stateSTARTTLS = 3"
"DEBUG"	5836	"2014-06-02 22:15:32.535"	"StartTLSState3() true"
"DEBUG"	5836	"2014-06-02 22:15:32.536"	"TCPCconnection::GetSocket(): lowest_layer()"
"SMTPC"	5836	5	"2014-06-02 22:15:32.537"	"132.245.225.98"	"SENT: EHLO HORSE"
"DEBUG"	9088	"2014-06-02 22:15:32.537"	"TCPConnection::Write ssl"
"DEBUG"	5836	"2014-06-02 22:15:32.538"	"TCPCconnection::GetSocket(): lowest_layer()"
"DEBUG"	5836	"2014-06-02 22:15:32.538"	"The write operation failed. Remote IP: 132.245.225.98, Session: 5, Code: 336031996, Message: unknown protocol"
"DEBUG"	9768	"2014-06-02 22:15:32.539"	"SD::~_InitiateExternalConnection-5"
"DEBUG"	9768	"2014-06-02 22:15:32.540"	"Ending session 5"
"DEBUG"	9768	"2014-06-02 22:15:32.540"	"SD::~_DeliverToExternalAccounts-2"
"DEBUG"	9768	"2014-06-02 22:15:32.541"	"Collect delivery result"
"DEBUG"	9768	"2014-06-02 22:15:32.541"	"Collect delivery result - Done"
"DEBUG"	9768	"2014-06-02 22:15:32.542"	"SD::_RescheduleDelivery"
"DEBUG"	9768	"2014-06-02 22:15:32.542"	"Retrieving retry options."
"DEBUG"	9768	"2014-06-02 22:15:32.544"	"Starting rescheduling."
"APPLICATION"	9768	"2014-06-02 22:15:32.544"	"SMTPDeliverer - Message 3: Message could not be delivered. Scheduling it for later delivery in 60 minutes."
"DEBUG"	9768	"2014-06-02 22:15:32.545"	"PersistentMessage::SetNextTryTime()"
"DEBUG"	9768	"2014-06-02 22:15:32.547"	"PersistentMessage::~SetNextTryTime()"
"DEBUG"	9768	"2014-06-02 22:15:32.548"	"Message rescheduled for later delivery."
"APPLICATION"	9768	"2014-06-02 22:15:32.549"	"SMTPDeliverer - Message 3: Message delivery thread completed."

Bill48105 · Post by **Bill48105** » 2014-06-02 23:36

drsox wrote:Wireshark attached below. Looks like the server says hi and then hmailserver ends the connection?

thx but i don't see wireshark attachment
and your logs look like mine now. i assume if connection drops it's because handshake fails but again i've not been able to track it down.

drsox · Post by **drsox** » 2014-06-02 23:43

wireshark log attached, I didn't notice it reject the non-ziped version earlier.

Bill48105 · Post by **Bill48105** » 2014-06-02 23:49

drsox wrote:wireshark log attached, I didn't notice it reject the non-ziped version earlier.

thx but not sure what you sent in that vncpng or some weird extension

drsox · Post by **drsox** » 2014-06-03 00:14

It is just the default format that my wireshark 1.10.7 saves in.

Bill48105 · Post by **Bill48105** » 2014-06-03 00:19

drsox wrote:It is just the default format that my wireshark 1.10.7 saves in.

oh gotcha not used wireshark in forever. fig'd you were posting a screenshot/image of it.
thx
Bill

japi · Post by **japi** » 2014-07-02 00:31

Hi Bill,

thank you for mentioning this experimental build in the other thread, i finally found this one after some searching

(sadly i still have no download link and would be happy to have one!

)

I just did some research on the openssl error code and found something that could be the problem in our case:

"TCPIP" 964 "2014-05-21 22:58:27.957" "TCPConnection - SSL handshake with client failed. Error code: 336031996, Message: unknown protocol, Remote IP: 74.125.193.109"

(from https://groups.google.com/a/chromium.or ... RvdnUps37Q )

No ciphers enabled:
336019637 OpenSSL SSL error, reason: 181, name: error:140740B5:SSL
routines:SSL23_CLIENT_HELLO:no ciphers available

No client/server cipher overlap:
336032784 OpenSSL SSL error, reason: 1040, name: error:14077410:SSL
routines:SSL23_GET_SERVER_HELLO:sslv3 alert handshake failure

No protocol version overlap:
336031996 OpenSSL SSL error, reason: 252, name: error:140770FC:SSL
routines:SSL23_GET_SERVER_HELLO:unknown protocol

So, if i am correct, the error means that the gmail servers are not offering any of the SSL/TLS protocol versions, which hMail tries to use (what is enabled in hMailServer? could you please provide the used source/commands/calls with the affected openssl configuration?).

I have just tested gmail and they seem to support any TLS Protocol i know (tested using openssl for windows from http://slproweb.com/products/Win32OpenSSL.html ).
Following tests worked and established an encrypted connection with TLS1, TLS1.1 and TLS1.2:
openssl s_client -starttls smtp -crlf -tls1 -connect 74.125.136.26:25
openssl s_client -starttls smtp -crlf -tls1_1 -connect 74.125.136.26:25
openssl s_client -starttls smtp -crlf -tls1_2 -connect 74.125.136.26:25
(connection can be soft-terminated by entering "QUIT")

Looking forward to solving this problem

Best regards,
Jan

Bill48105 · Post by **Bill48105** » 2014-07-02 00:44

Yeah I gathered the same thing Jan it's like the handshake can't complete because the 2 sides can't come up with compatible options.

I think I had only PM'd this to people who requested it. I can't say this enough:
*** DO NOT USE *** *** DO NOT USE *** DO NOT USE** ** DO NOT USE *** *** DO NOT USE *** DO NOT USE**
THIS DOES NOT WORK - Is it for TESTING of outgoing SMTP STARTTLS handshakes.
To test you setup a route & enable SSL. Any email sent thru that route will attempt STARTTLS handshake
*** SSL IS BROKEN IN THIS BUILD ***
*** DO NOT USE *** *** DO NOT USE *** DO NOT USE** ** DO NOT USE *** *** DO NOT USE *** DO NOT USE**

Bill48105 wrote:Realize this does not work even if you get handshake working it still may not work (tough when I couldn't get past the handshake lol) but yeah if you can test & provide insight into why handshake fails that'll be super helpful.
http://www.mediafire.com/download/j6zpq ... NOT-USE.7z
MD5: 4b33ef43922546815aa60e44e1e5a549 SHA1: 672ae3a01495d516d5c923ec44a552a06c7196b5

There is nothing special to configure (except maybe the new SSL INI's) since this build uses STARTTLS for routes and only routes. No way to turn off. (Not like it matters this is test build and not for real use anyway). So just add a route then send an email & check the logs. I tested to my own hmail & to gmail & both fail after STARTTLS being sent with various handshake errors.
Thx
Bill

*** DO NOT USE *** *** DO NOT USE *** DO NOT USE** ** DO NOT USE *** *** DO NOT USE *** DO NOT USE**
* THIS DOES NOT WORK - Is it for TESTING of outgoing SMTP STARTTLS handshakes.
To test you setup a route & enable SSL. Any email sent thru that route will attempt STARTTLS handshake
*** SSL IS BROKEN IN THIS BUILD **
*** DO NOT USE *** *** DO NOT USE *** DO NOT USE** ** DO NOT USE *** *** DO NOT USE *** DO NOT USE**

japi · Post by **japi** » 2014-07-07 22:09

Hi Bill,

i have not yet found an obvious error in the handshake messages, but i have noticed that one time during my tests TLS was initialized too early by hMailServer.
hMailServer did not wait until the other server replied with "220 Ready to start TLS".

It does not always happen, but is in indication that hMailServer is not waiting correctly before beginning the handshake. Maybe the SMTP Command "220 Ready to start TLS" is then interpreted as handshake reply, which leads to the "unknown protocol" error (trying to start TLS on non-TLS streams is also an common cause for this error).

Probably this only happens if the server sends an zero length [ACK] TCP packet before his SMTP reply.

(Screenshot of the error in wireshark:)

Corresponding log entries:

Code: Select all

"74.125.142.27"	"RECEIVED: 250-mx.google.com at your service, [91.205.173.82]" 
[...]
"74.125.142.27"	"RECEIVED: 250-ENHANCEDSTATUSCODES"
"SMTPClientConnection::~_ParseASCII() - 1"
"TCPConnection::Read next_layer()"
"SMTPClientConnection::_ParseASCII()"
"TCPCconnection::GetSocket(): next_layer()"
"74.125.142.27"	"RECEIVED: 250 CHUNKING"
"TCPCconnection::GetSocket(): next_layer()"
"74.125.142.27"	"SENT: STARTTLS"
"TCPConnection::Write next_layer()"
"TCPConnection::STARTTLS_Handshake handshake1"
"TCPConnection::STARTTLS_Handshake handshake3"
"STARTTLS true"
"sleeping 2 sec"
"TCPCconnection::GetSocket(): next_layer()"
"TCPConnection - SSL handshake with client failed. Error code: 336031996, Message: unknown protocol, Remote IP: 74.125.142.27"

Is your experimental build source code maintained online? I would be happy to take a look at it during testing (it is handy to know which debug messages are followed by which commands)

Kind regards,
Jan

Bill48105 · Post by **Bill48105** » 2014-07-07 22:48

japi wrote:Hi Bill,

i have not yet found an obvious error in the handshake messages, but i have noticed that one time during my tests TLS was initialized too early by hMailServer.
hMailServer did not wait until the other server replied with "220 Ready to start TLS".

It does not always happen, but is in indication that hMailServer is not waiting correctly before beginning the handshake. Maybe the SMTP Command "220 Ready to start TLS" is then interpreted as handshake reply, which leads to the "unknown protocol" error (trying to start TLS on non-TLS streams is also an common cause for this error).

Probably this only happens if the server sends an zero length [ACK] TCP packet before his SMTP reply.

(Screenshot of the error in wireshark:)

Corresponding log entries:
Code: Select all
"74.125.142.27"	"RECEIVED: 250-mx.google.com at your service, [91.205.173.82]" 
[...]
"74.125.142.27"	"RECEIVED: 250-ENHANCEDSTATUSCODES"
"SMTPClientConnection::~_ParseASCII() - 1"
"TCPConnection::Read next_layer()"
"SMTPClientConnection::_ParseASCII()"
"TCPCconnection::GetSocket(): next_layer()"
"74.125.142.27"	"RECEIVED: 250 CHUNKING"
"TCPCconnection::GetSocket(): next_layer()"
"74.125.142.27"	"SENT: STARTTLS"
"TCPConnection::Write next_layer()"
"TCPConnection::STARTTLS_Handshake handshake1"
"TCPConnection::STARTTLS_Handshake handshake3"
"STARTTLS true"
"sleeping 2 sec"
"TCPCconnection::GetSocket(): next_layer()"
"TCPConnection - SSL handshake with client failed. Error code: 336031996, Message: unknown protocol, Remote IP: 74.125.142.27"
Is your experimental build source code maintained online? I would be happy to take a look at it during testing (it is handy to know which debug messages are followed by which commands)

Kind regards,
Jan

Hey Jan,
Hmm ok thanks that could be it. The starttls stuff was just hacked up SSL to get something to test & since that would not be waited for for SSL it wouldn't be there for starttls yet. SO yeah that could be very helpful thanks.

Sorry not yet. hmail was on SVN before & I used tortoise to compare mine to official & commit my changes in batches to make sure the result was buildable. martin moved hmail to github before i had a chance to get my changes in then moved hosting so now SVN is gone & I have no easy way to compare them. I planned to get them as close as possible before posting mine as a fork of the official. I still could post mine but it'd be a nightmare for someone else (martin) to merge them especially since he's made changes to the official since moving to github.
Thanks,
Bill

Post by **martin** » 2014-07-19 21:01

Just FYI, I'm in the middle of adding STARTTLS to hMailServer official builds.

So far I have SMTP Client -> Server and POP3 Client-> Server up and running.

Arius · Post by **Arius** » 2014-08-19 02:54

What is the guessimate on when there will be a hMailServer with starttls? Today I ran into the 'Must issue a STARTTLS command first' on passing a message to gmail port 587.

mattg · Post by **mattg** » 2014-08-19 02:58

Available in current Beta >>https://www.hmailserver.com/download?pa ... loadid=225

Due for release in weeks

Arius · Post by **Arius** » 2014-08-19 03:44

Thank you. I just tested it and it works!

Many thanks for all your effort.

ssl/tls and starttls [50%]

Do you need this feature?

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]

Re: ssl/tls and starttls [50%]