I have set up an email server stack with Postfix, Dovecot and SquirrelMail. Everything works except SSL communication with the SMTP server.
When I manually test the communication by following the instructions here: http://qmail.jms1.net/test-auth.shtml
I am able to connect and send email no problem.
My main email client is Mac Mail but I have also briefly tried Thunderbird and it failed as well.
I have been struggling with this issue for days to no avail so any help would be greatly appreciated.
I have attached the verbose server logs as well as the logs from my mac mail client
Server logs:
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: connection established
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: master_notify: status 0
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: name_mask: resource
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: name_mask: software
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: connect from unknown[200.200.200.200]
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: unknown: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: 200.200.200.200: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: unknown: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: 200.200.200.200: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_hostname: unknown ~? 127.0.0.0/8
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_hostaddr: 200.200.200.200 ~? 127.0.0.0/8
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: unknown: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: 200.200.200.200: no match
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: send attr request = connect
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: send attr ident = smtp:200.200.200.200
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: status
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: status
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: 0
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: count
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: count
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: 2
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: rate
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: rate
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: 8
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: (list terminator)
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: (end)
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 220 removed.url.com ESMTP Postfix (Ubuntu)
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: xsasl_cyrus_server_create: SASL service=smtp, realm=(null)
Jan 20 16:17:52 ip-10-170-23-22 postfix/smtpd[3141]: name_mask: noanonymous
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: < unknown[200.200.200.200]: EHLO [200.200.200.200]
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-removed.url.com
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-PIPELINING
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-SIZE 30720000
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-VRFY
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-ETRN
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-STARTTLS
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-AUTH PLAIN LOGIN
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: unknown: no match
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: 200.200.200.200: no match
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-AUTH=PLAIN LOGIN
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-ENHANCEDSTATUSCODES
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250-8BITMIME
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 250 DSN
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: < unknown[200.200.200.200]: STARTTLS
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: > unknown[200.200.200.200]: 220 2.0.0 Ready to start TLS
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: auto_clnt_open: connected to private/tlsmgr
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: send attr request = seed
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: send attr size = 32
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: private/tlsmgr: wanted attribute: status
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: status
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: 0
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: private/tlsmgr: wanted attribute: seed
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: seed
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: Rty6lJEY7yPnGODjh8beH1wJu1nRuUM1R1ydWVNHLLI=
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: private/tlsmgr: wanted attribute: (list terminator)
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: (end)
Jan 20 16:17:53 ip-10-170-23-22 postfix/smtpd[3143]: auto_clnt_close: disconnect private/tlsmgr stream
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: SSL_accept error from unknown[200.200.200.200]: -1
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: match_hostname: unknown ~? 127.0.0.0/8
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: match_hostaddr: 200.200.200.200 ~? 127.0.0.0/8
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: unknown: no match
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: match_list_match: 200.200.200.200: no match
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: send attr request = disconnect
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: send attr ident = smtp:200.200.200.200
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: status
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: status
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: input attribute value: 0
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: private/anvil: wanted attribute: (list terminator)
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: input attribute name: (end)
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: lost connection after STARTTLS from unknown[200.200.200.200]
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: disconnect from unknown[200.200.200.200]
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: master_notify: status 1
Jan 20 16:17:54 ip-10-170-23-22 postfix/smtpd[3141]: connection closed
Here are the debug logs from Mac Mail.app:
2012-01-20 16:26:08.219 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x1820d570 error=(NSStreamSocketSSLErrorDomain,-9812)
2012-01-20 16:26:08.220 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x1820d570 error=(NSStreamSocketSSLErrorDomain,-9812)
CONNECTED Jan 20 16:26:08.239 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
READ Jan 20 16:26:08.415 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
220 removed.url.com ESMTP Postfix (Ubuntu)
WROTE Jan 20 16:26:08.676 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
EHLO [200.200.200.200]
READ Jan 20 16:26:08.935 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
250-removed.url.com
250-PIPELINING
250-SIZE 30720000
250-VRFY
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
WROTE Jan 20 16:26:08.936 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
STARTTLS
2012-01-20 16:26:08.998 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x18714200 error=(NSStreamSocketSSLErrorDomain,-9812)
2012-01-20 16:26:08.999 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x18714200 error=(NSStreamSocketSSLErrorDomain,-9812)
READ Jan 20 16:26:09.205 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18249570 -- thread:0x182aae40
220 2.0.0 Ready to start TLS
2012-01-20 16:26:09.499 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x18249570 error=(NSStreamSocketSSLErrorDomain,-9812)
2012-01-20 16:26:09.500 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x18249570 error=(NSStreamSocketSSLErrorDomain,-9812)
CONNECTED Jan 20 16:26:11.013 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
READ Jan 20 16:26:11.265 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
220 removed.url.com ESMTP Postfix (Ubuntu)
WROTE Jan 20 16:26:11.266 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
EHLO [200.200.200.200]
READ Jan 20 16:26:11.556 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
250-removed.url.com
250-PIPELINING
250-SIZE 30720000
250-VRFY
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
WROTE Jan 20 16:26:11.557 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
STARTTLS
READ Jan 20 16:26:11.816 [kCFStreamSocketSecurityLevelNone] -- host:removed.url.com -- port:25 -- socket:0x18790de0 -- thread:0x182aae40
220 2.0.0 Ready to start TLS
2012-01-20 16:26:12.119 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x18790de0 error=(NSStreamSocketSSLErrorDomain,-9812)
2012-01-20 16:26:12.120 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x18790de0 error=(NSStreamSocketSSLErrorDomain,-9812)
2012-01-20 16:26:12.395 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x152fb600 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:12.396 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x152fb600 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:12.675 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x182a4bb0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:12.676 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x182a4bb0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:12.946 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x182a4bb0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:12.946 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x182a4bb0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:13.226 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x152826e0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:13.226 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x152826e0 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:13.505 Mail[3148:8427] *** _NSSocket.m:248 read() failed; socket=0x18212080 error=(NSPOSIXErrorDomain,61)
2012-01-20 16:26:13.505 Mail[3148:8427] *** _NSSocket.m:248 write() failed; socket=0x18212080 error=(NSPOSIXErrorDomain,61)
