opensmtpd-5.7.1 - cannot authenticate

Tue Jul 28 19:24:16 UTC 2015

On 2015-Jul-28, 15:24, Herbert J. Skuhra wrote:
> On Mon, Jul 27, 2015 at 08:47:47PM +0200, Pietro Cerutti wrote:
> > Hi,
> > 
> > I tried to upgrade from 5.4.6 to 5.7.1, and suddenly I am unable to
> > authenticate.  This is from the log file:
> > 
> > Jul 27 17:05:03 mail smtpd[12146]: smtp-in: Failed command on session
> > a0516551dc7a4dc4: "AUTH PLAIN (...)" => 501 5.5.2 Syntax error: Syntax
> > error
> > 
> > Relevant config lines area
> > 
> > pki mydomain certificate   "/usr/local/etc/mail-admin/tls/server.crt"
> > pki mydomain key           "/usr/local/etc/mail-admin/tls/server.key"
> > table credentials file:/usr/local/etc/mail-admin/db/auth-smtp.db
> > listen on 192.168.1.1 secure auth-optional <credentials> pki mydomain
> 
> What's the output of 'file /usr/local/etc/mail-admin/db/auth-smtp.db'?
> Maybe you need db: not file:?

it's an ASCII file, as it was with 5.4.6. As I said, no config
(including backend table files) has changed.

> > I am able to switch from the 5.4.6 to the 5.7.1 binary and reproduce
> > that I can send mail with the former and cannot with the latter. No
> > config has changed.
> 
> Have you tried to run 'smtpd -dv' or 'smtpd -dv -T all'?

Here's the output from smtpd -dv -T all.

Thank you!

smtp: 0x802523000: >>> 220 mail.example.com ESMTP OpenSMTPD
smtp: 0x802523000: IO_LOWAT <io:0x802523048 fd=4 to=300000 fl=W ib=0 ob=0>
smtp: 0x802523000: IO_DATAIN <io:0x802523048 fd=4 to=300000 fl=R ib=16 ob=0>
smtp: 0x802523000: <<< EHLO example.com
filter: new query QK_QUERY QUERY_HELO
filter: filter_drain_query 1746ec4c96a16e71[QK_QUERY,QUERY_HELO=example.com,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
filter: filter_end_query 1746ec4c96a16e71[QK_QUERY,QUERY_HELO=example.com,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
filter: query 1746ec4c96a16e71 done: status=FILTER_OK code=0 response="(null)"
smtp: 0x802523000: STATE_CONNECTED -> STATE_HELO
smtp: 0x802523000: >>> 250-mail.example.com Hello example.com [192.168.1.1], pleased to meet you
smtp: 0x802523000: >>> 250-8BITMIME
smtp: 0x802523000: >>> 250-ENHANCEDSTATUSCODES
smtp: 0x802523000: >>> 250-SIZE 36700160
smtp: 0x802523000: >>> 250-DSN
smtp: 0x802523000: >>> 250-STARTTLS
smtp: 0x802523000: >>> 250 HELP
smtp: 0x802523000: IO_LOWAT <io:0x802523048 fd=4 to=300000 fl=W ib=0 ob=0>
smtp: 0x802523000: IO_DATAIN <io:0x802523048 fd=4 to=300000 fl=R ib=10 ob=0>
smtp: 0x802523000: <<< STARTTLS
smtp: 0x802523000: >>> 220 2.0.0: Ready to start TLS
smtp: 0x802523000: STATE_HELO -> STATE_TLS
smtp: 0x802523000: IO_LOWAT <io:0x802523048 fd=4 to=300000 fl=W ib=0 ob=0>
mproc: pony -> lka : 272 IMSG_SMTP_TLS_INIT
imsg: lka <- pony: IMSG_SMTP_TLS_INIT (len=272)
debug: lka: looking up pki "example.com"
mproc: lka -> pony : 2176 IMSG_SMTP_TLS_INIT
imsg: pony <- lka: IMSG_SMTP_TLS_INIT (len=2176)
debug: session_start_ssl: switching to SSL
debug: pony: rsae_priv_enc
mproc: pony -> ca: allocating 128
mproc: pony -> ca: realloc 128 -> 256
mproc: pony -> ca : 130 IMSG_CA_PRIVENC (flush)
imsg: ca <- pony: IMSG_CA_PRIVENC (len=130)
mproc: ca -> pony: allocating 128
mproc: ca -> pony: realloc 128 -> 1024
mproc: ca -> pony : 535 IMSG_CA_PRIVENC
imsg: pony <- ca: IMSG_CA_PRIVENC (len=535)
smtp: 0x802523000: IO_TLSREADY <io:0x802523048 fd=4 to=300000 fl=R ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=0 ob=0>
smtp-in: session 1746ec49080e52e3: TLS started version=TLSv1/SSLv3 (TLSv1.2), cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256
mproc: pony -> control : 43 IMSG_STAT_INCREMENT
smtp: 0x802523000: STATE_TLS -> STATE_HELO
ramstat: increment: smtp.tls
ramstat: smtp.tls (0x802418101): 0 -> 1
smtp: 0x802523000: IO_DATAIN <io:0x802523048 fd=4 to=300000 fl=R ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=16 ob=0>
smtp: 0x802523000: <<< EHLO example.com
filter: new query QK_QUERY QUERY_HELO
filter: filter_drain_query 1746ec4d6ecf7513[QK_QUERY,QUERY_HELO=example.com,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
filter: filter_end_query 1746ec4d6ecf7513[QK_QUERY,QUERY_HELO=example.com,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
filter: query 1746ec4d6ecf7513 done: status=FILTER_OK code=0 response="(null)"
smtp: 0x802523000: STATE_HELO -> STATE_HELO
smtp: 0x802523000: >>> 250-mail.example.com Hello example.com [192.168.1.1], pleased to meet you
smtp: 0x802523000: >>> 250-8BITMIME
smtp: 0x802523000: >>> 250-ENHANCEDSTATUSCODES
smtp: 0x802523000: >>> 250-SIZE 36700160
smtp: 0x802523000: >>> 250-DSN
smtp: 0x802523000: >>> 250-AUTH PLAIN LOGIN
smtp: 0x802523000: >>> 250 HELP
smtp: 0x802523000: IO_LOWAT <io:0x802523048 fd=4 to=300000 fl=W ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=0 ob=0>
smtp: 0x802523000: IO_DATAIN <io:0x802523048 fd=4 to=300000 fl=R ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=65 ob=0>
smtp: 0x802523000: <<< AUTH PLAIN Z2FockBnYWhyLmNoAGdhaHJAZ2Foci5jaABQNkNydDcsZ2Focg==
smtp: 0x802523000: STATE_HELO -> STATE_AUTH_INIT
smtp: 0x802523000: >>> 501 5.5.2 Syntax error: Syntax error
smtp-in: Failed command on session 1746ec49080e52e3: "AUTH PLAIN (...)" => 501 5.5.2 Syntax error: Syntax error
smtp: 0x802523000: STATE_AUTH_INIT -> STATE_HELO
smtp: 0x802523000: IO_LOWAT <io:0x802523048 fd=4 to=300000 fl=W ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=0 ob=0>
smtp: 0x802523000: IO_DISCONNECTED <io:0x802523048 fd=4 to=300000 fl=R ssl=TLSv1/SSLv3:ECDHE-RSA-AES256-GCM-SHA384:256 ib=0 ob=0>
smtp-in: session 1746ec49080e52e3: connection from host 192.168.1.1 [192.168.1.1] closed (client disconnected)
debug: smtp: 0x802523000: deleting session: disconnected
filter: new query QK_EVENT EVENT_DISCONNECT
filter: filter_drain_query 1746ec4e1b373188[QK_EVENT,EVENT_DISCONNECT,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
filter: filter_end_query 1746ec4e1b373188[QK_EVENT,EVENT_DISCONNECT,filter_session at 0x8024c7480[datalen=0,eom=0x0,ofile=0x0]]
mproc: pony -> control : 43 IMSG_STAT_DECREMENT
mproc: pony -> control : 47 IMSG_STAT_DECREMENT
ramstat: decrement: smtp.tls
ramstat: smtp.tls (0x802418101): 1 -> 0
ramstat: decrement: smtp.session
ramstat: smtp.session (0x802418101): 1 -> 0

-- 
Pietro Cerutti
The FreeBSD Project
gahr at FreeBSD.org

PGP Public Key:
http://gahr.ch/pgp
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 949 bytes
Desc: not available
URL: <http://lists.freebsd.org/pipermail/freebsd-ports/attachments/20150728/6d4f856d/attachment.bin>