Prev: bug in spamassassin date rule may lead to false spam marking
Next: smtpd crashes
From: Patrick Ben Koetter on 2 Jan 2010 13:09
* froinds J <froinds(a)gmail.com>:
> I made the changes you suggested and still can't authenticate.
> Here is the log from maillog. Thanks

You client does not start a TLS session.

p(a)rick



>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: connection established
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: master_notify: status 0
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: name_mask: resource
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: name_mask: software
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: connect from
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_list_match:
> adsl-012-034-567-890.sip.my.isp.net : no match
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_list_match: 12.34.56.78:
> no match
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_list_match:
> adsl-012-034-567-890.sip.my.isp.net : no match
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_list_match: 12.34.56.78:
> no match
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 192.168.1.0/28
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 127.0.0.0/8
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 12.34.56.78
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: >>> START Client host
> RESTRICTIONS <<<
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: generic_checks:
> name=permit_mynetworks
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: permit_mynetworks:
> adsl-012-034-567-890.sip.my.isp.net 12.34.56.78
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 192.168.1.0/28
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 127.0.0.0/8
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 12.34.56.78
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: generic_checks:
> name=permit_mynetworks status=1
>
> Jan 2 10:14:41 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 220 myDomName.com ESMTP
> Postfix
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: <
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: EHLO [192.168.0.105]
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >>> START Helo command
> RESTRICTIONS <<<
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: generic_checks:
> name=reject_invalid_hostname
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: reject_invalid_hostaddr:
> [192.168.0.105]
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: generic_checks:
> name=reject_invalid_hostname status=0
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >>> END Helo command
> RESTRICTIONS <<<
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-myDomName.com
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-PIPELINING
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-SIZE 10240000
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-VRFY
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-ETRN
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_list_match:
> adsl-012-034-567-890.sip.my.isp.net : no match
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_list_match: 12.34.56.78:
> no match
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-STARTTLS
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-ENHANCEDSTATUSCODES
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250-8BITMIME
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: >
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]: 250 DSN
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: smtp_get: EOF
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 192.168.1.0/28
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 192.168.1.0/28
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 127.0.0.0/8
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 127.0.0.0/8
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostname:
> adsl-012-034-567-890.sip.my.isp.net ~? 12.34.56.78
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: match_hostaddr: 12.34.56.78 ~?
> 12.34.56.78
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: lost connection after EHLO from
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: disconnect from
> adsl-012-034-567-890.sip.my.isp.net [12.34.56.78]
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: master_notify: status 1
>
> Jan 2 10:14:42 fedora postfix/smtpd[17435]: connection closed
>
>
>
>
> On Sat, Jan 2, 2010 at 3:50 AM, Patrick Ben Koetter <p(a)state-of-mind.de>wrote:
>
> > * froinds J <froinds(a)gmail.com>:
> > > My problem is: if I allow TLS I cannot authenticate. Without TLS
> > everything
> > > works. Here is the output from saslfinger.
> > > Thanks for your help.
> >
> >
> >
> >
> >
> > >
> > > saslfinger - postfix Cyrus sasl configuration Sat Jan 2 02:12:49 EST
> > 2010
> > > version: 1.0.2
> > > mode: server-side SMTP AUTH
> > >
> > > -- basics --
> > > Postfix: 2.6.5
> > > System: Fedora release 12 (Constantine)
> > >
> > > -- smtpd is linked to --
> > > libsasl2.so.2 => /usr/lib/libsasl2.so.2 (0x00110000)
> > >
> > > -- active SMTP AUTH and TLS parameters for smtpd --
> > > broken_sasl_auth_clients = yes
> > > smtpd_sasl_auth_enable = yes
> > > smtpd_sasl_authenticated_header = yes
> > > smtpd_sasl_local_domain = $myhostname
> > > smtpd_sasl_security_options = noanonymous, noplaintext
> > > smtpd_tls_CAfile = /etc/postfix/ssl/cacert.pem
> > > smtpd_tls_auth_only = yes
> > > smtpd_tls_cert_file = /etc/postfix/ssl/smtpd.crt
> > > smtpd_tls_key_file = /etc/postfix/ssl/smtpd.key
> > > smtpd_tls_loglevel = 3
> > > smtpd_tls_received_header = yes
> > > smtpd_tls_security_level = encrypt
> > > smtpd_tls_session_cache_timeout = 3600s
> > >
> > >
> > > -- listing of /usr/lib/sasl --
> > > total 80
> > > drwxr-xr-x. 2 root root 4096 2009-12-29 12:31 .
> > > dr-xr-xr-x. 150 root root 69632 2010-01-01 16:52 ..
> > > -rw-r--r--. 1 root root 70 2009-09-16 09:38 smtpd.conf
> >
> > Delete /usr/lib/sasl/smtpd.conf. Postfix will not use Cyrus SASL 1.x
> > anymore.
> >
> >
> > > -- listing of /usr/lib/sasl2 --
> > > total 504
> > > drwxr-xr-x. 2 root root 4096 2009-12-29 12:31 .
> > > dr-xr-xr-x. 150 root root 69632 2010-01-01 16:52 ..
> > > -rwxr-xr-x. 1 root root 14912 2009-09-24 06:20 libanonymous.so
> > > -rwxr-xr-x. 1 root root 14912 2009-09-24 06:20 libanonymous.so.2
> > > -rwxr-xr-x. 1 root root 14912 2009-09-24 06:20 libanonymous.so.2.0.23
> > > -rwxr-xr-x. 1 root root 17596 2009-09-24 06:20 libcrammd5.so
> > > -rwxr-xr-x. 1 root root 17596 2009-09-24 06:20 libcrammd5.so.2
> > > -rwxr-xr-x. 1 root root 17596 2009-09-24 06:20 libcrammd5.so.2.0.23
> > > -rwxr-xr-x. 1 root root 48032 2009-09-24 06:20 libdigestmd5.so
> > > -rwxr-xr-x. 1 root root 48032 2009-09-24 06:20 libdigestmd5.so.2
> > > -rwxr-xr-x. 1 root root 48032 2009-09-24 06:20 libdigestmd5.so.2.0.23
> > > -rwxr-xr-x. 1 root root 15356 2009-09-24 06:20 liblogin.so
> > > -rwxr-xr-x. 1 root root 15356 2009-09-24 06:20 liblogin.so.2
> > > -rwxr-xr-x. 1 root root 15356 2009-09-24 06:20 liblogin.so.2.0.23
> > > -rwxr-xr-x. 1 root root 15452 2009-09-24 06:20 libplain.so
> > > -rwxr-xr-x. 1 root root 15452 2009-09-24 06:20 libplain.so.2
> > > -rwxr-xr-x. 1 root root 15452 2009-09-24 06:20 libplain.so.2.0.23
> > > -rwxr-xr-x. 1 root root 20872 2009-09-24 06:20 libsasldb.so
> > > -rwxr-xr-x. 1 root root 20872 2009-09-24 06:20 libsasldb.so.2
> > > -rwxr-xr-x. 1 root root 20872 2009-09-24 06:20 libsasldb.so.2.0.23
> > > -rw-r--r--. 1 root root 25 2009-09-16 14:55 Sendmail.conf
> > > -rw-r--r--. 1 root root 138 2010-01-02 01:22 smtpd.conf
> > >
> > > -- listing of /etc/sasl2 --
> > > total 16
> > > drwxr-xr-x. 2 root root 4096 2009-09-24 06:20 .
> > > drwxr-xr-x. 122 root root 12288 2010-01-01 16:31 ..
> > >
> > >
> > > -- content of /usr/lib/sasl2/smtpd.conf --
> > > pwcheck_method: auxprop
> >
> > Add:
> >
> > auxprop_plugin: sasldb
> >
> > > mech_list: PLAIN LOGIN CRAM-MD5 DIGEST-MD5
> > > log_level: 4
> >
> >
> >
> > > -- active services in /etc/postfix/master.cf --
> > > # service type private unpriv chroot wakeup maxproc command + args
> > > # (yes) (yes) (yes) (never) (100)
> > > 52525 inet n - n - - smtpd -v
> >
> > At a first glance your configuration looks sane. Maybe your problem is not
> > SASL, but TLS. You are running smtpd verbose. What does the log say about
> > errors?
> >
> >
> > > pickup fifo n - n 60 1 pickup
> > > cleanup unix n - n - 0 cleanup
> > > qmgr fifo n - n 300 1 qmgr
> > > tlsmgr unix - - n 1000? 1 tlsmgr
> > > rewrite unix - - n - - trivial-rewrite
> > > bounce unix - - n - 0 bounce
> > > defer unix - - n - 0 bounce
> > > trace unix - - n - 0 bounce
> > > verify unix - - n - 1 verify
> > > flush unix n - n 1000? 0 flush
> > > proxymap unix - - n - - proxymap
> > > proxywrite unix - - n - 1 proxymap
> > > smtp unix - - n - - smtp
> > > relay unix - - n - - smtp
> > > -o smtp_fallback_relay=
> > > showq unix n - n - - showq
> > > error unix - - n - - error
> > > retry unix - - n - - error
> > > discard unix - - n - - discard
> > > local unix - n n - - local
> > > virtual unix - n n - - virtual
> > > lmtp unix - - n - - lmtp
> > > anvil unix - - n - 1 anvil
> > > scache unix - - n - 1 scache
> > >
> > >
> > > -- mechanisms on localhost --
> > >
> > >
> > > -- end of saslfinger output --
> >
> > --
> > 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/>
> >

--
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/>

From: froinds J on 2 Jan 2010 13:59
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.
Thanks.

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]

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

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]

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
From: Patrick Ben Koetter on 2 Jan 2010 16:02
* froinds J <froinds(a)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/>

From: froinds J on 2 Jan 2010 17:32
Ah you so were right.
I set up postfix to use the certs that cyrus-imapd creates by default and
everything works now.
What's weird is that cyrus-imapd was using the same certs postfix was using
and it didn't complain. I was able to receive email when I turned off TSL
for postfix.
So I guess the problem is that I'm not creating good self-signed
certificates. I've done this more than 20 times following every source on
the internet including the guides in postfix.org. My certs have always
worked with cyrus-imapd and apache, but I always run into trouble with
postfix.

Can you provide a set of instructions to follow?

Thanks so much.



On Sat, Jan 2, 2010 at 4:02 PM, Patrick Ben Koetter <p(a)state-of-mind.de>wrote:

> * froinds J <froinds(a)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.
>
>
From: Patrick Ben Koetter on 2 Jan 2010 18:04
* froinds J <froinds(a)gmail.com>:
> Ah you so were right.
> I set up postfix to use the certs that cyrus-imapd creates by default and
> everything works now.
> What's weird is that cyrus-imapd was using the same certs postfix was using
> and it didn't complain. I was able to receive email when I turned off TSL
> for postfix.
> So I guess the problem is that I'm not creating good self-signed
> certificates. I've done this more than 20 times following every source on
> the internet including the guides in postfix.org. My certs have always
> worked with cyrus-imapd and apache, but I always run into trouble with
> postfix.
>
> Can you provide a set of instructions to follow?

You can use TinyCA <http://tinyca.sm-zone.net/> to setup a CA and the required
certificates. Then configure Postfix. When your done, send "postconf -n" output and we will have a look at the config.

p(a)rick




>
> Thanks so much.
>
>
>
> On Sat, Jan 2, 2010 at 4:02 PM, Patrick Ben Koetter <p(a)state-of-mind.de>wrote:
>
> > * froinds J <froinds(a)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.
> >
> >

--
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/>

First  |  Prev  |  Next  |  Last
Pages: 1 2 3
Prev: bug in spamassassin date rule may lead to false spam marking
Next: smtpd crashes