From: Luc Pardon (lucpskopos.be)
Date: Thu Feb 02 2006 - 04:17:38 CST

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

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.

   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).

    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
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().

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

   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:

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

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

   Note that I don't particularly care about the answers, it's working
for me. I'm asking more because of the remote possibility of a buglet in
the pluggable sasl rewrite.

   I can provide more info if desired, but please don't ask me to
downgrade to 2.2 <g>. Also, this is a live system, so I don't feel like
playing games with it during office hours. For example, I have not yet
tried to remove lmtp_sasl_mechanism_filter again to see what happens.

   Finally, below is a CMNP (cosmetic mini nitpick patch) for
src/xsasl/xsasl_cyrus_client.c.

   Best regards,

    Luc Pardon
    Skopos Consulting
    Belgium

================================
--- xsasl_cyrus_client.c.orig 2006-02-02 10:58:08.000000000 +0100
+++ xsasl_cyrus_client.c 2006-02-02 10:58:25.000000000 +0100
-159,7 +159,7
                                                const char **result,
                                                unsigned *len)
  {
- char *myname = "xsasl_cyrus_get_user";
+ char *myname = "xsasl_cyrus_client_get_user";
      XSASL_CYRUS_CLIENT *client = (XSASL_CYRUS_CLIENT *) context;

      if (msg_verbose)

===========================================

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