[Dovecot] Exim and Dovecot2 SASL: 435 Unable to authenticate at present

Sergey Urushkin urushkin at telros.ru
Tue Jun 28 20:38:24 EEST 2011


Hi. I had working Exim 4.71 and Dovecot 1.2.9 SASL configuration on 
Ubuntu Lucid, but needed some features from dovecot2, so I installed 
2.0.13 from 
https://launchpad.net/~carsten-uppenbrink-net/+archive/dovecot2 . Now I 
get Subj error while trying to authenticate via dovecot auth-client 
socket. However IMAP auth works fine with 2.0.13 and smtp auth worked 
fine until upgrade, so I think there is something wrong with dovecot2.

Dovecot logs stay empty even with auth_debug*, just one string "auth: 
Debug: Loading modules from bla...". But here is another information 
that may help. And if it's needed I can build dovecot myself to ensure 
that ppa-build isn't guilty. Or debug some another way.

Thanks.

dovecot -n:
# 2.0.13: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.32-31-server x86_64 Ubuntu 10.04.2 LTS
auth_debug = yes
auth_debug_passwords = yes
auth_mechanisms = plain login apop
auth_verbose = yes
disable_plaintext_auth = no
first_valid_gid = 8
first_valid_uid = 8
hostname = mail.domain.lan
last_valid_gid = 8
last_valid_uid = 8
lda_mailbox_autocreate = yes
lda_mailbox_autosubscribe = yes
listen = *
mail_gid = mail
mail_location = maildir:~/
mail_plugins = " quota trash"
mail_privileged_group = mail
mail_uid = mail
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope 
encoded-character vacation subaddress comparator-i;ascii-numeric 
relational regex imap4flags copy include variables body enotify 
environment mailbox date
passdb {
   args = scheme=CRAM-MD5 username_format=%n 
/etc/dovecot/passwd.d/%d.passwd
   driver = passwd-file
}
plugin {
   autocreate = Trash
   autocreate2 = Junk
   autocreate3 = Drafts
   autocreate4 = Templates
   autocreate5 = Sent
   autosubscribe = Trash
   autosubscribe2 = Junk
   autosubscribe3 = Drafts
   autosubscribe4 = Templates
   autosubscribe5 = Sent
   quota = maildir:user quota
   quota_rule = *:storage=200M
   sieve = ~/dovecot.sieve
   sieve_dir = ~/sieve
   trash = /etc/dovecot/dovecot-trash.conf.ext
}
postmaster_address = postmaster at domain.lan
protocols = " imap sieve pop3 sieve"
service auth {
   unix_listener auth-client {
     mode = 0600
     user = Debian-exim
   }
   unix_listener auth-userdb {
     mode = 0600
     user = mail
   }
}
service managesieve-login {
   inet_listener sieve_deprecated {
     port = 2000
   }
}
ssl_cert = </etc/ssl/certs/dovecot.pem
ssl_key = </etc/ssl/private/dovecot.pem
userdb {
   args = username_format=%n /etc/dovecot/passwd.d/%d.passwd
   driver = passwd-file
}
protocol lda {
   mail_plugins = " quota trash sieve"
}
protocol imap {
   imap_client_workarounds = delay-newmail tb-extra-mailbox-sep 
tb-lsub-flags
   mail_plugins = " quota trash imap_quota"
}
protocol pop3 {
   pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
}


##################
swaks --to test at domain.lan --from=test at domain.lan --auth 
--auth-user=test at domain.lan --auth-password=111111 --server 127.0.0.1 
-tlsc: (the same without tls, apop)
=== Trying 127.0.0.1:465...
=== Connected to 127.0.0.1.
=== TLS started w/ cipher DHE-RSA-AES256-SHA
<~  220 mail.domain.lan, ESMTP ready
  ~> EHLO mail.domain.lan
<~  250-mail.domain.lan Hello mail.domain.lan [127.0.0.1]
<~  250-SIZE 26214400
<~  250-PIPELINING
<~  250-AUTH PLAIN LOGIN
<~  250 HELP
  ~> AUTH LOGIN
<~* 435 Unable to authenticate at present
  ~> AUTH PLAIN AHRlc3RAZG9tYWluLmxhbgAxMTExMTE=
<~* 435 Unable to authenticate at present
*** No authentication type succeeded
  ~> QUIT
<~  221 mail.domain.lan closing connection
=== Connection closed with remote host.


#####################
exim -d+auth output:
Exim version 4.71 uid=0 gid=0 pid=29270 D=fbb95cfd
Berkeley DB: Berkeley DB 4.8.24: (August 14, 2009)
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc GnuTLS 
move_frozen_messages Content_Scanning DKIM Old_Demime
Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz dnsdb 
dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql sqlite
Authenticators: cram_md5 cyrus_sasl dovecot plaintext spa
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram 
redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
Size of off_t: 8
GnuTLS compile-time version: 2.8.5
GnuTLS runtime version: 2.8.5
changed uid/gid: forcing real = effective
   uid=0 gid=0 pid=29270
   auxiliary group list: <none>
seeking password data for user "root": cache not available
getpwnam() succeeded uid=0 gid=0
configuration file is /etc/exim4/exim4.conf
log selectors = 0000cefe 00233821
cwd=/ 4 args: /usr/sbin/exim4 -bd -q30m -d+auth
trusted user
admin user
seeking password data for user "Debian-exim": cache not available
getpwnam() succeeded uid=103 gid=105
seeking password data for user "Debian-exim": using cached result
getpwnam() succeeded uid=103 gid=105
seeking password data for user "mail": cache not available
getpwnam() succeeded uid=8 gid=8
originator: uid=0 gid=0 login=root name=root
29270 LOG: MAIN
29270   IPv6 socket creation failed: Address family not supported by 
protocol
29270 LOG: MAIN
29270   Failed to create IPv6 socket for wildcard listening (Address 
family not supported by protocol): will use IPv4
29270 listening on all interfaces (IPv4) port 25
29270 LOG: MAIN
29270   IPv6 socket creation failed: Address family not supported by 
protocol
29270 LOG: MAIN
29270   Failed to create IPv6 socket for wildcard listening (Address 
family not supported by protocol): will use IPv4
29270 listening on all interfaces (IPv4) port 465
29270 pid written to /var/run/exim4/exim.pid
29270 changed uid/gid: running as a daemon
29270   uid=103 gid=105 pid=29270
29270   auxiliary group list: 105 999
29270 LOG: MAIN
29270   exim 4.71 daemon started: pid=29270, -q30m, listening for SMTP 
on port 25 (IPv4) and for SMTPS on port 465 (IPv4)
29270 set_process_info: 29270 daemon: -q30m, listening for SMTP on port 
25 (IPv4) and for SMTPS on port 465 (IPv4)
29270 daemon running with uid=103 gid=105 euid=103 egid=105
29270 SIGALRM received
29270 1 queue-runner process running
29270 Listening...
29271 Starting queue-runner: pid 29271
29271 exec /usr/sbin/exim4 -q
29270 child 29271 ended: status=0x0
29270 0 queue-runner processes now running
29270 Listening...
29270 Connection request from 127.0.0.1 port 58341
29270 search_tidyup called
29270 1 SMTP accept process running
29270 Listening...
29279 sender_fullhost = [127.0.0.1]
29279 sender_rcvhost = [127.0.0.1]
29279 Process 29279 is handling incoming connection from [127.0.0.1]
29279 host in host_lookup? no (option unset)
29279 set_process_info: 29279 handling incoming connection from 
[127.0.0.1] I=[127.0.0.1]:465
29279 initializing GnuTLS as a server
29279 read D-H parameters from file
29279 initialized D-H parameters
29279 certificate file = /etc/ssl/certs/dovecot.pem
29279 key file = /etc/ssl/private/dovecot.pem
29279 initialized certificate stuff
29279 host in tls_verify_hosts? no (option unset)
29279 host in tls_try_verify_hosts? no (option unset)
29279 initialized GnuTLS session
29279 gnutls_handshake was successful
29279 cipher: TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32
29279 host in host_reject_connection? no (option unset)
29279 duplicate IP address 127.0.0.1 (MX=-1) removed
29279 gethostbyname2 looked up these IP addresses:
29279   name=localhost address=::1
29279   name=localhost address=127.0.0.1
29279 host in sender_unqualified_hosts? yes (matched "localhost")
29279 duplicate IP address 127.0.0.1 (MX=-1) removed
29279 gethostbyname2 looked up these IP addresses:
29279   name=localhost address=::1
29279   name=localhost address=127.0.0.1
29279 host in recipient_unqualified_hosts? yes (matched "localhost")
29279 host in helo_verify_hosts? no (option unset)
29279 host in helo_try_verify_hosts? no (option unset)
29279 host in helo_accept_junk_hosts? no (option unset)
29279 SMTP>> 220 mail.domain.lan, ESMTP ready
29279 tls_do_write(7f10202175a0, 31)
29279 gnutls_record_send(SSL, 7f10202175a0, 31)
29279 outbytes=31
29279 Process 29279 is ready for new message
29279 smtp_setup_msg entered
29279 Calling gnutls_record_recv(7f102023f0c0, 7f1020241e40, 4096)
29279 SMTP<< EHLO mail.domain.lan
29279 mail.domain.lan in helo_lookup_domains? no (end of list)
29279 sender_fullhost = (mail.domain.lan) [127.0.0.1]
29279 sender_rcvhost = [127.0.0.1] (helo=mail.domain.lan)
29279 set_process_info: 29279 handling TLS incoming connection from 
(mail.domain.lan) [127.0.0.1] I=[127.0.0.1]:465
29279 host in pipelining_advertise_hosts? yes (matched "*")
29279 host in auth_advertise_hosts? yes (matched "*")
29279 tls_do_write(7f10202229c8, 119)
29279 gnutls_record_send(SSL, 7f10202229c8, 119)
29279 outbytes=119
29279 SMTP>> 250-mail.domain.lan Hello mail.domain.lan [127.0.0.1]
29279 250-SIZE 26214400
29279 250-PIPELINING
29279 250-AUTH PLAIN LOGIN
29279 250 HELP
29279 Calling gnutls_record_recv(7f102023f0c0, 7f1020241e40, 4096)
29279 SMTP<< AUTH LOGIN
29279 dovecot authentication
29279 received: VERSION	1	1
29279 received: MECH	PLAIN	plaintext
29279 received: MECH	LOGIN	plaintext
29279 received: MECH	APOP	private	dictionary	active
29279 received: SPID	29280
29279 received: CUID	1
29279 received: COOKIE	cf735efce15b21bbb10568c4a762017c
29279 SMTP>> 435 Unable to authenticate at present
29279 tls_do_write(7f10202175a0, 39)
29279 gnutls_record_send(SSL, 7f10202175a0, 39)
29279 outbytes=39
29279 LOG: MAIN REJECT
29279   auth_login authenticator failed for (mail.domain.lan) 
[127.0.0.1] I=[127.0.0.1]:465: 435 Unable to authenticate at present: 
authentication socket protocol error
29279 Calling gnutls_record_recv(7f102023f0c0, 7f1020241e40, 4096)
29279 SMTP<< AUTH PLAIN AHRlc3RAZG9tYWluLmxhbgAxMTExMTE=
29279 host in smtp_accept_max_nonmail_hosts? yes (matched "*")
29279 dovecot authentication
29279 received: VERSION	1	1
29279 received: MECH	PLAIN	plaintext
29279 received: MECH	LOGIN	plaintext
29279 received: MECH	APOP	private	dictionary	active
29279 received: SPID	29280
29279 received: CUID	2
29279 received: COOKIE	06f8b3d9441b40b4069f53cdd0d128a4
29279 SMTP>> 435 Unable to authenticate at present
29279 tls_do_write(7f10202175a0, 39)
29279 gnutls_record_send(SSL, 7f10202175a0, 39)
29279 outbytes=39
29279 LOG: MAIN REJECT
29279   auth_plain authenticator failed for (mail.domain.lan) 
[127.0.0.1] I=[127.0.0.1]:465: 435 Unable to authenticate at present: 
authentication socket protocol error
29279 Calling gnutls_record_recv(7f102023f0c0, 7f1020241e40, 4096)
29279 SMTP<< QUIT
29279 SMTP>> 221 mail.domain.lan closing connection
29279 tls_do_write(7f10202175a0, 37)
29279 gnutls_record_send(SSL, 7f10202175a0, 37)
29279 outbytes=37
29279 tls_close(): shutting down TLS
29279 LOG: smtp_connection MAIN
29279   SMTP connection from (mail.domain.lan) [127.0.0.1] 
I=[127.0.0.1]:465 closed by QUIT
29279 search_tidyup called
29270 child 29279 ended: status=0x0
29270 0 SMTP accept processes now running
29270 Listening...

-- 
Best regards,
Sergey Urushkin


More information about the dovecot mailing list