* froinds J <froi...@gmail.com>:
> Oops! I forgot to check SSL.
> My client now seems to start a TLS session and still nothing. Here is the
> log with the SSL error.
TLS log. My favourite waste of time. Everything is layed out so clear... :/
There are two lines in your log that make me think (think, not know!) that
your client doesn't like the server certificate. Read below.
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: connection established
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: master_notify: status 0
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: name_mask: resource
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: name_mask: software
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: connect from
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match:
> adsl-012-034-567-890.sip.myisp.net: no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match: 12.34.56.78:
> no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match:
> adsl-012-034-567-890.sip.myisp.net: no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match: 12.34.56.78:
> no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 192.168.1.0/28
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 127.0.0.0/8
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 12.34.56.78
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >>> START Client host
> RESTRICTIONS <<<
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: generic_checks:
> name=permit_mynetworks
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: permit_mynetworks:
> adsl-012-034-567-890.sip.myisp.net 12.34.56.78
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 192.168.1.0/28
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 127.0.0.0/8
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 12.34.56.78
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: generic_checks:
> name=permit_mynetworks status=1
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 220 myDomName.com ESMTP
> Postfix
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: <
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: EHLO [192.168.0.105]
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >>> START Helo command
> RESTRICTIONS <<<
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: generic_checks:
> name=reject_invalid_hostname
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: reject_invalid_hostaddr:
> [192.168.0.105]
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: generic_checks:
> name=reject_invalid_hostname status=0
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >>> END Helo command
> RESTRICTIONS <<<
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-myDomName.com
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-PIPELINING
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-SIZE 10240000
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-VRFY
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-ETRN
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match:
> adsl-012-034-567-890.sip.myisp.net: no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: match_list_match: 12.34.56.78:
> no match
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-STARTTLS
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-ENHANCEDSTATUSCODES
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250-8BITMIME
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 250 DSN
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: <
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: STARTTLS
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: >
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: 220 2.0.0 Ready to start TLS
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: setting up TLS connection from
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]
This is where your client requests a TLS session.
> Jan 2 13:02:11 fedora postfix/smtpd[20531]:
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: TLS cipher list
> "ALL:!EXPORT:!LOW:+RC4:@STRENGTH"
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: auto_clnt_open: connected to
> private/tlsmgr
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: send attr request = seed
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: send attr size = 32
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: private/tlsmgr: wanted
> attribute: status
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: input attribute name: status
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: input attribute value: 0
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: private/tlsmgr: wanted
> attribute: seed
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: input attribute name: seed
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: input attribute value:
> 04iDdMchtEcMhHMPlZE1PnA4hFVBivxAgufuUinTYeM=
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: private/tlsmgr: wanted
> attribute: (list terminator)
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: input attribute name: (end)
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:before/accept
> initialization
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: read from 02269768 [0227E418]
> (11 bytes => -1 (0xFFFFFFFF))
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: read from 02269768 [0227E418]
> (11 bytes => 11 (0xB))
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 0000 16 03 01 00 9d 01 00 00|99
> 03 01 ........ ...
> …….
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 0090 19 00 0b 00 02 01
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 0096 - <SPACES/NULLS>
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:SSLv3 read client
> hello B
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:SSLv3 write server
> hello A
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:SSLv3 write
> certificate A
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:SSLv3 write server
> done A
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: write to 02269768 [0227AAB0]
> (756 bytes => 756 (0x2F4))
> ……
>
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 02e0 0f 67 ef 48 36 a9 7b 92|5c
> be b2 16 03 01 00 04 .g.H6.{. \.......
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 02f0 0e
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: 02f1 - <SPACES/NULLS>
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: SSL_accept:SSLv3 flush data
> Jan 2 13:02:11 fedora postfix/smtpd[20531]: read from 02269768 [0227E41B] (5
> bytes => -1 (0xFFFFFFFF))
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: SSL_accept error from
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]: -1
This is where an "SSL_accept error" turns up, but I don't know if its relevant
in your case.
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 192.168.1.0/28
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 127.0.0.0/8
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostname:
> adsl-012-034-567-890.sip.myisp.net ~? 12.34.56.78
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: lost connection after STARTTLS
> from adsl-012-034-567-890.sip.myisp.net[12.34.56.78]
This is where the connection seems to time out.
No SMTP AUTH. The client attempts TLS and then nothing happens.
What do you use as client?
Did you import the server's CA certificate into your client?
Does your client issue any warnings?
Is there any Desktop antivirus firewall intercepting your client?
Could you possibly test a TLS connection to your server using the "openssl
s_client" command from command line?
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: disconnect from
> adsl-012-034-567-890.sip.myisp.net[12.34.56.78]
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: master_notify: status 1
> Jan 2 13:02:12 fedora postfix/smtpd[20531]: connection closed
--
All technical questions asked privately will be automatically answered on the
list and archived for public access unless privacy is explicitely required and
justified.
saslfinger (debugging SMTP AUTH):
<http://postfix.state-of-mind.de/patrick.koetter/saslfinger/>
