From: Patrick Ben Koetter (pstate-of-mind.de)
Date: Thu Feb 02 2006 - 05:06:36 CST

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

* Luc Pardon <lucpskopos.be>:
> Hello List,
>
> I have a Postfix/Cyrus setup where local mail is delivered to Cyrus
> IMAP via lmtp.
>
> The OS is Redhat Linux and the Cyrus versions are 2.0.16 for imapd
> and 1.5.24 for sasl (and no, this is not a museum's mail system). The
> cyrus-sasl-gssapi module is installed.
>
> Cyrus SASL uses pwcheck_method:sasldb, and postfix has
> lmtp_sasl_password_maps = hash:/etc/postfix/lmtp_sasl_pass in main.cf.

Cyrus SASL doesn't know any pwcheck_method called sasldb. What you experienced
before you upgraded was the fallback behaviour of Cyrus SASL, where it would
fall back to sasldb if the given pwcheck_method would not work.

Set this in smtpd.conf to configure Cyrus-SASL.2.x correctly:

pwcheck_method: auxprop
auxprop_plugin: sasldb

> This setup has been working since at least 2002, i.e. the sasldb and
> lmtp_sasl_pass files have not changed in several years.
>
> Now, I just upgraded Postfix from 2.2-20040829 to 2.3-20060126
> (compiled with -DUSE_CYRUS_SASL etc.).
>
> After the upgrade (and stopping/restarting Postfix), local delivery
> stopped working. Mail got stuck in the queue with the infamous "SASL
> authentication failed; cannot authenticate to server
> smtp.skopos.be[/var/imap/socket/lmtp]: generic failure". Logs coming up
> in a minute.
>
> The SASL_README says that this message happens with plaintext auth,
> but I already had smtp_sasl_security_options = noanonymous (from way
> before the upgrade).

In your case, using the lmtp-client, that would have to be:

lmtp_sasl_security_options = noanonymous

> With -v added to lmtp in master.cf, the logs seemed to indicate that
> the Postfix lmtp client did manage to talk to Cyrus. Cyrus announced
> "250-AUTH GSSAPI LOGIN DIGEST-MD5 CRAM-MD5 PLAIN EXTERNAL" but the
> Postfix lmtpd did not seem to know what to pick. In any case it didn't
          ^^^^^
lmtp-client...

> reply, instead it seemed to wait for something, timed out after 75s,
> gave up and deferred the mail. The relevant (I think) portion of the
> Postfix log is this (with user/pass obfuscated, they were retrieved
> correctly from the hash):
>
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: smtp_connect_unix: trying:
> >/var/imap/socket/lmtp...
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 220 gida.skopos.be LMTP Cyrus
> >v2.0.16 ready
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: >
> >smtp.skopos.be[/var/imap/socket/lmtp]: LHLO smtp.skopos.be
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250-gida.skopos.be
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250-IGNOREQUOTA
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250-8BITMIME
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250-ENHANCEDSTATUSCODES
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250-AUTH GSSAPI LOGIN DIGEST-MD5
> >CRAM-MD5 PLAIN EXTERNAL
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 250 PIPELINING
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: server features: 0x27 size 0
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: Using LMTP PIPELINING, TCP send
> >buffer size is 4096
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: maps_find: smtp_sasl_passwd:
> >hash:/etc/postfix/lmtp_sasl_pass(0,lock|fold_fix): smtp.skopos.be =
> >MYUSER:MYPASSWD
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: smtp_sasl_passwd_lookup: host
> >`smtp.skopos.be' user `MYUSER' pass `MYPASSWD'
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: starting new SASL client
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: name_mask: noanonymous
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: smtp_sasl_authenticate:
> >smtp.skopos.be[/var/imap/socket/lmtp]: SASL mechanisms GSSAPI LOGIN
> >DIGEST-MD5 CRAM-MD5 PLAIN EXTERNAL
> >Feb 2 08:26:02 gida postfix/lmtp[25687]: xsasl_cyrus_get_user: MYUSER
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: connect to subsystem
> >private/defer
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: send attr nrequest = 0
> > <snip snip: some lines with e-mail addresses removed>
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: send attr notify_flags = 0
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: send attr status = 4.7.0
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: send attr diag_type = x-sasl
> >Feb 2 08:27:17 gida postfix/lmtp[25687]: send attr diag_text = generic
> >failure
>
>
> There is nothing special to be seen in the Cyrus logs.
>
> So I tried to set lmtp_sasl_mechanism_filter to various combinations.
> That made it worse: the mail now bounced instead of being deferred. But
> it was a step in the right direction. From the Postfix logs, I could see
> that the LMTP client was now talking back to Cyrus but failed to pass
> authentication.
>
> For example:
>
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: starting new SASL client
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: name_mask: noanonymous
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: smtp_sasl_authenticate:
> >smtp.skopos.be[/var/imap/socket/lmtp]: SASL mechanisms LOGIN DIGEST-MD5
> >CRAM-MD5 PLAIN
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: xsasl_cyrus_get_user: MYUSER
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: xsasl_cyrus_get_user: MYUSER
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: xsasl_cyrus_get_passwd: MYPASSWD
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: >
> >smtp.skopos.be[/var/imap/socket/lmtp]: AUTH LOGIN
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 334 VXNlcm5hbWU6
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: xsasl_cyrus_client_next: decoded
> >challenge: Username:
> > <snip snip lots of auth dialogue and dict lookup stuff>
> >Feb 2 05:40:58 gida postfix/lmtp[23783]: <
> >smtp.skopos.be[/var/imap/socket/lmtp]: 501 5.5.4 authentication failure
>
> The Cyrus logs also show a "badlogin" line to match.
>
> Finally, running sasldblistusers (as per the SASL_README) revealed
> that I had no entries for that "MYSUSER" user with the realm
> smtp.skopos.be, only with the realm gida.skopos.be. The former is
> $myhostname, the latter is gethostbyname().

A classic...

> I also realized that sasldb contains only passwords for PLAIN,
> DIGEST-MD5 and CRAM-MD5.

That's okay. LOGIN is not supported officially.

> Setting "lmtp_sasl_mechanism_filter = plain digest-md5 cram-md5" and
> adding an entry to sasldb for the "$myhostname" realm (with "saslpasswd
> -c -u smtp.skopos.be MYUSER") set mail flowing again. The log shows:
>
> >Feb 2 08:01:00 gida postfix/lmtp[24979]: smtp_sasl_authenticate:
> >smtp.skopos.be[/var/imap/socket/lmtp]: SASL mechanisms DIGEST-MD5 CRAM-MD5
> >PLAIN
> >Feb 2 08:01:00 gida postfix/lmtp[24979]: >
> >smtp.skopos.be[/var/imap/socket/lmtp]: AUTH CRAM-MD5
>
> ... and then it goes on, passes auth and hands the mail over to Cyrus.
>
> It is worth repeating that nothing has changed in this area of the
> config in a long time, and everything was working fine before the upgrade.
>
> The Cyrus side was not touched during the Postfix upgrade (except
> sasldb). Nonetheless its log entries have changed, they show different
> behaviour for a succesful lmtp delivery. Before the upgrade, it reads in
> /var/log/imapd.log:

Cyrus-SASL.2.x would log to the auth facility.

> >Jan 29 04:46:59 gida lmtpd[14422]: accepted connection
> >Jan 29 04:46:59 gida lmtpd[14422]: lmtp connection preauth'd as postman
> >Jan 29 04:46:59 gida master[14431]: about to exec /usr/cyrus/bin/lmtpd
> >Jan 29 04:46:59 gida service-lmtpunix[14431]: executed
> >Jan 29 04:49:40 gida master[11352]: process 14422 exited, status 0
>
> After the Postfix upgrade, the entries show an extra "login"
> statement (again with the actual user id replaced with "MYUSER"):
>
> >Feb 2 09:14:56 gida lmtpd[26135]: accepted connection
> >Feb 2 09:14:56 gida lmtpd[26135]: lmtp connection preauth'd as postman
> >Feb 2 09:14:56 gida lmtpd[26135]: login: [unix socket] MYUSER CRAM-MD5
> >User logged in
> >Feb 2 09:14:56 gida master[26141]: about to exec /usr/cyrus/bin/lmtpd
> >Feb 2 09:14:56 gida service-lmtpunix[26141]: executed
> >Feb 2 09:15:56 gida master[23311]: process 26135 exited, status 0
>
> Except for Postfix's local delivery, there is nothing else talking
> lmtp to Cyrus, so the two snippets are definitely the same process at work.
>
>
> Bottom line:
>
> 1. Could it be that Postfix's 2.3 new smtp/lmtp client is selecting
> the auth mechanism in a different way than 2.2, or even that it does not
> know any mechanisms without the help of lmtp_sasl_mechanism_filter ?

The Cyrus-SASL.2.x libsasl library chooses which mechanism should be used, not
Postfix. Postfix can only filter mechanisms it got offered in order to submit
only a limited subset of offered mechanisms to libsasl - that's how Postfix
keeps libsasl from choosing mechanisms it can't handle e.g. because it wasn't
configured to do so.

> 2. Could it be that 2.3 is using $myhostname whereas 2.2 was using
> gethostbyname for the SASL realm ?

I don't know that.

prick

--
The Book of Postfix
<http://www.postfix-book.com>
saslfinger (debugging SMTP AUTH):
<http://postfix.state-of-mind.de/patrick.koetter/saslfinger/>

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]