Hi,
I have an already working dovecot server on Ubuntu 10.04 with self-created packages version 2.1.13. This setup is working prefect. Now that I do not wish to continue using Ubuntu (to much work for Upgrading), I decided to switch to Gentoo, as I had made best experiences in the past…
I have installed Dovecot on Gentoo and I copied over all my configs and certs and stuff. Also created a user vmail with identical uid/gid and also checked all permissions for the certificate stuff.
Dovecot starts. I also can connect to it. But when trying to login, I get errors:
telnet localhost 143 Trying ::1... Connected to localhost. Escape character is '^]'.
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE STARTTLS AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5 AUTH=DIGEST-MD5 AUTH=NTLM] Dovecot ready. . login croessner <hiddenpw> . NO [UNAVAILABLE] Temporary authentication failure. [mx0:2013-01-13 14:24:02]
In the logs it looks like this:
Jan 13 15:22:30 mx0 dovecot: master: Dovecot v2.1.13 starting up (core dumps disabled) Jan 13 15:23:11 mx0 dovecot: auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth Jan 13 15:23:11 mx0 dovecot: auth: Debug: passwd-file /etc/dovecot/master-users: Read 1 users in 0 secs Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_extended_operation_s Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_extended_operation Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_send_initial_request Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_new_connection 1 1 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_int_open_connection Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_connect_to_host: TCP db.roessner-net.de:389 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_new_socket: 17 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_prepare_socket: 17 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_connect_to_host: Trying 193.239.107.37:389 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_pvt_connect: fd: 17 tm: -1 async: 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_open_defconn: successful Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_send_server_request Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_result ld 0x35d6dd481c0 msgid 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: wait4msg ld 0x35d6dd481c0 msgid 1 (infinite timeout) Jan 13 15:23:11 mx0 dovecot: auth: Error: wait4msg continue ld 0x35d6dd481c0 msgid 1 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Connections: Jan 13 15:23:11 mx0 dovecot: auth: Error: * host: db.roessner-net.de port: 389 (default) Jan 13 15:23:11 mx0 dovecot: auth: Error: refcnt: 2 status: Connected Jan 13 15:23:11 mx0 dovecot: auth: Error: last used: Sun Jan 13 15:23:11 2013 Jan 13 15:23:11 mx0 dovecot: auth: Error: Jan 13 15:23:11 mx0 dovecot: auth: Error: Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Outstanding Requests: Jan 13 15:23:11 mx0 dovecot: auth: Error: * msgid 1, origid 1, status InProgress Jan 13 15:23:11 mx0 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ld 0x35d6dd481c0 request count 1 (abandoned 0) Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Response Queue: Jan 13 15:23:11 mx0 dovecot: auth: Error: Empty Jan 13 15:23:11 mx0 dovecot: auth: Error: ld 0x35d6dd481c0 response count 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_chkResponseList ld 0x35d6dd481c0 msgid 1 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_chkResponseList returns ld 0x35d6dd481c0 NULL Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_int_select Jan 13 15:23:11 mx0 dovecot: auth: Error: read1msg: ld 0x35d6dd481c0 msgid 1 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: read1msg: ld 0x35d6dd481c0 msgid 1 message type extended-result Jan 13 15:23:11 mx0 dovecot: auth: Error: read1msg: ld 0x35d6dd481c0 0 new referrals Jan 13 15:23:11 mx0 dovecot: auth: Error: read1msg: mark request completed, ld 0x35d6dd481c0 msgid 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: request done: ld 0x35d6dd481c0 msgid 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: res_errno: 0, res_error: <>, res_matched: <> Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_free_request (origid 1, msgid 1) Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_parse_extended_result Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_parse_result Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_msgfree
Jan 13 15:23:11 mx0 dovecot: auth: Error: TLS: could not use key file `/etc/ssl/private/mx0.roessner-net.de.key.pem'. Jan 13 15:23:11 mx0 dovecot: auth: Error: TLS: error:0200100D:system library:fopen:Permission denied bss_file.c:398 Jan 13 15:23:11 mx0 dovecot: auth: Error: TLS: error:20074002:BIO routines:FILE_CTRL:system lib bss_file.c:400 Jan 13 15:23:11 mx0 dovecot: auth: Error: TLS: error:140B0002:SSL routines:SSL_CTX_use_PrivateKey_file:system lib ssl_rsa.c:648
Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_err2string Jan 13 15:23:11 mx0 dovecot: auth: Error: LDAP: ldap_start_tls_s() failed: Connect error Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_extended_operation_s Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_extended_operation Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_send_initial_request Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_send_server_request Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_result ld 0x35d6dd481c0 msgid 2 Jan 13 15:23:11 mx0 dovecot: auth: Error: wait4msg ld 0x35d6dd481c0 msgid 2 (infinite timeout) Jan 13 15:23:11 mx0 dovecot: auth: Error: wait4msg continue ld 0x35d6dd481c0 msgid 2 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Connections: Jan 13 15:23:11 mx0 dovecot: auth: Error: * host: db.roessner-net.de port: 389 (default) Jan 13 15:23:11 mx0 dovecot: auth: Error: refcnt: 2 status: Connected Jan 13 15:23:11 mx0 dovecot: auth: Error: last used: Sun Jan 13 15:23:11 2013 Jan 13 15:23:11 mx0 dovecot: auth: Error: Jan 13 15:23:11 mx0 dovecot: auth: Error: Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Outstanding Requests: Jan 13 15:23:11 mx0 dovecot: auth: Error: * msgid 2, origid 2, status InProgress Jan 13 15:23:11 mx0 dovecot: auth: Error: outstanding referrals 0, parent count 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ld 0x35d6dd481c0 request count 1 (abandoned 0) Jan 13 15:23:11 mx0 dovecot: auth: Error: ** ld 0x35d6dd481c0 Response Queue: Jan 13 15:23:11 mx0 dovecot: auth: Error: Empty Jan 13 15:23:11 mx0 dovecot: auth: Error: ld 0x35d6dd481c0 response count 0 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_chkResponseList ld 0x35d6dd481c0 msgid 2 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_chkResponseList returns ld 0x35d6dd481c0 NULL Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_int_select Jan 13 15:23:11 mx0 dovecot: auth: Error: read1msg: ld 0x35d6dd481c0 msgid 2 all 1 Jan 13 15:23:11 mx0 dovecot: auth: Error: ldap_err2string Jan 13 15:23:11 mx0 dovecot: auth: Error: LDAP: ldap_start_tls_s() failed: Can't contact LDAP server Jan 13 15:23:11 mx0 dovecot: auth: Debug: auth client connected (pid=24045) Jan 13 15:24:00 mx0 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=YAanRyzTOAAAAAAAAAAAAAAAAAAAAAAB#011lip=::1#011rip=::1#011lport=143#011rport=59960#011resp=<hidden> Jan 13 15:24:00 mx0 dovecot: auth: Error: ldap_extended_operation_s Jan 13 15:24:00 mx0 dovecot: auth: Error: ldap_extended_operation Jan 13 15:24:00 mx0 dovecot: auth: Error: ldap_send_initial_request Jan 13 15:24:00 mx0 dovecot: auth: Error: ldap_send_server_request Jan 13 15:24:00 mx0 dovecot: auth: Error: ldap_err2string Jan 13 15:24:00 mx0 dovecot: auth: Error: LDAP: ldap_start_tls_s() failed: Can't contact LDAP server Jan 13 15:24:02 mx0 dovecot: auth: Debug: client passdb out: FAIL#0111#011user=croessner#011temp Jan 13 15:26:11 mx0 dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts in 131 secs): user=<croessner>, method=PLAIN, rip=::1, lip=::1, secured, session=<YAanRyzTOAAAAAAAAAAAAAAAAAAAAAAB> Jan 13 15:27:11 mx0 dovecot: auth: Error: ldap_unbind Jan 13 15:27:11 mx0 dovecot: auth: Error: ldap_free_request (origid 2, msgid 2) Jan 13 15:27:11 mx0 dovecot: auth: Error: ldap_free_connection 1 1 Jan 13 15:27:11 mx0 dovecot: auth: Error: ldap_free_connection: actually freed
I checked if Dovecot would even try to access the key:
inotifywait -m -r --format '%:e %f' /etc/ssl Setting up watches. Beware: since -r was given, this may take a while! Watches established. OPEN mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem CLOSE_NOWRITE:CLOSE mail.roessner-net.de.pem OPEN mail.roessner-net.de.key.pem ACCESS mail.roessner-net.de.key.pem CLOSE_NOWRITE:CLOSE mail.roessner-net.de.key.pem OPEN SSL123_CA_Bundle.pem ACCESS SSL123_CA_Bundle.pem CLOSE_NOWRITE:CLOSE SSL123_CA_Bundle.pem OPEN mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem ACCESS mail.roessner-net.de.pem CLOSE_NOWRITE:CLOSE mail.roessner-net.de.pem OPEN mail.roessner-net.de.key.pem ACCESS mail.roessner-net.de.key.pem ACCESS mail.roessner-net.de.key.pem CLOSE_NOWRITE:CLOSE mail.roessner-net.de.key.pem OPEN SSL123_CA_Bundle.pem ACCESS SSL123_CA_Bundle.pem ACCESS SSL123_CA_Bundle.pem ACCESS SSL123_CA_Bundle.pem ACCESS SSL123_CA_Bundle.pem CLOSE_NOWRITE:CLOSE SSL123_CA_Bundle.pem OPEN ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt ACCESS ca-certificates.crt CLOSE_NOWRITE:CLOSE ca-certificates.crt OPEN mx0.roessner-net.de.pem ACCESS mx0.roessner-net.de.pem CLOSE_NOWRITE:CLOSE mx0.roessner-net.de.pem OPEN openssl.cnf ACCESS openssl.cnf ACCESS openssl.cnf ACCESS openssl.cnf CLOSE_NOWRITE:CLOSE openssl.cnf OPEN openssl.cnf ACCESS openssl.cnf ACCESS openssl.cnf ACCESS openssl.cnf CLOSE_NOWRITE:CLOSE openssl.cnf
I can not find any line talking about mx0.roessner-net.de.key.pem. The file exists and has proper permissions:
l /etc/ssl/private/ total 16 drwxr-s---+ 2 root ssl-cert 4096 Jan 12 19:29 ./ drwxr-xr-x 8 root root 4096 Jan 13 15:26 ../ -rw-r--r-- 1 root root 0 Dec 10 18:14 .keep_dev-libs_openssl-0 -r--r----- 1 root ssl-cert 1679 Jan 12 17:23 mail.roessner-net.de.key.pem -r--r-----+ 1 root ssl-cert 887 Jan 12 17:14 mx0.roessner-net.de.key.pem
getfacl /etc/ssl/private/ /etc/ssl/private/mx0.roessner-net.de.key.pem getfacl: Removing leading '/' from absolute path names # file: etc/ssl/private/ # owner: root # group: ssl-cert # flags: -s- user::rwx user:amavis:r-x group::--- mask::r-x other::---
# file: etc/ssl/private/mx0.roessner-net.de.key.pem # owner: root # group: ssl-cert user::r-- user:amavis:r-x #effective:r-- group::r-- mask::r-- other::---
Here is my doveconf -n:
# 2.1.13: /etc/dovecot/dovecot.conf # OS: Linux 3.7.0-hardened x86_64 Gentoo Base System release 2.1 auth_debug = yes auth_master_user_separator = * auth_mechanisms = plain login cram-md5 digest-md5 ntlm auth_verbose = yes hostname = mail.roessner-net.de lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes mail_access_groups = vmail mail_attachment_dir = /var/mail/virtual/copymail/attachments mail_debug = yes mail_gid = vmail mail_location = mdbox:~/mdbox mail_plugins = autocreate quota acl fts fts_solr zlib mail_privileged_group = mail mail_uid = vmail 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 ihave mdbox_rotate_size = 128 M namespace { list = children location = mdbox:%%h/mdbox prefix = shared/%%u/ separator = / subscriptions = no type = shared } namespace inbox { inbox = yes location = mailbox "Deleted Messages" { special_use = \Trash } mailbox Drafts { special_use = \Drafts } mailbox Junk-E-Mail { special_use = \Junk } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } mailbox junkmail { special_use = \Junk } prefix = separator = / type = private } passdb { args = /etc/dovecot/master-users driver = passwd-file master = yes pass = yes } passdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { acl = vfile acl_shared_dict = file:/var/mail/virtual/shared-mailboxes.db autocreate = Trash autocreate2 = Sent autocreate3 = Drafts autocreate4 = junkmail autosubscribe = Trash autosubscribe2 = Sent autosubscribe3 = Drafts autosubscribe4 = junkmail fts = solr fts_solr = break-imap-search url=http://localhost:8080/solr/ quota = dict:User quota::file:%h/mdbox/dovecot-quota quota_rule = *:storage=300M:messages=20000 quota_warning = storage=95%% quota-warning 95 %u quota_warning2 = storage=80%% quota-warning 80 %u sieve = ~/.dovecot.sieve sieve_dir = ~/sieve zlib_save = gz zlib_save_level = 6 } protocols = imap pop3 lmtp sieve service auth-worker { extra_groups = ssl-cert unix_listener auth-worker { mode = 0600 user = vmail } user = vmail } service auth { extra_groups = ssl-cert unix_listener auth-userdb { mode = 0600 user = vmail } user = vmail } service dict { unix_listener dict { mode = 0600 user = vmail } } service lmtp { unix_listener /var/spool/postfix/private/lmtp-dovecot { group = postfix mode = 0666 user = postfix } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = dovecot } ssl_ca =
LDAP looks like this:
uris = ldap://db.roessner-net.de/ ldap://roessner1.roessner-net.de/ sasl_bind = yes sasl_mech = EXTERNAL tls = yes tls_ca_cert_file = /etc/ssl/certs/ca-certificates.crt tls_cert_file = /etc/ssl/certs/mx0.roessner-net.de.pem tls_key_file = /etc/ssl/private/mx0.roessner-net.de.key.pem tls_require_cert = hard debug_level = 7 base = ou=people,ou=it,dc=roessner-net,dc=de user_attrs = rnsMSQuota=quota_rule=*:storage=%$,rnsMSMailboxHome=home user_filter = (&(objectClass=rnsMSDovecotAccount)(|(rnsMSRecipientAddress=%u)(uniqueIdentifier=%u))) pass_attrs = rnsMSDeliverToAddress=user,userPassword=password pass_filter = (&(objectClass=rnsMSDovecotAccount)(|(rnsMSRecipientAddress=%u)(uniqueIdentifier=%u))(rnsMSEnableDovecot=TRUE)) iterate_attrs = rnsMSDovecotUser=user iterate_filter = (objectClass=rnsMSDovecotAccount) default_pass_scheme = PLAIN
Some portage information
[ebuild R ] net-nds/openldap-2.4.30 USE="berkdb crypt ipv6 minimal sasl ssl syslog tcpd -cxx -debug -experimental -gnutls -icu -iodbc -kerberos -odbc -overlays -perl -samba (-selinux) -slp -smbkrb5passwd" 0 kB [ebuild R ] dev-libs/cyrus-sasl-2.1.25-r3:2 USE="berkdb gdbm ldapdb openldap pam ssl urandom -authdaemond -java -kerberos -mysql -postgres -sample -sqlite -srp -static-libs" 0 kB [ebuild R ~] net-mail/dovecot-2.1.13::croessner USE="bzip2 caps imapc ipv6 ldap maildir managesieve mbox mdbox pam pop3c sdbox sieve solr sqlite ssl suid zlib -cydir -doc -kerberos -lucene -mysql -postgres (-selinux) -static-libs -vpopmail" 0 kB
As you can see, I have spent some time on this without luck and currently I have no idea, what the problem is.
Any ideas on that?
Thanks in advance
-Christian Rößner
-- [*] sys4 AG
http://sys4.de, +49 (89) 30 90 46 64 Franziskanerstraße 15, 81669 München
Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263 Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer Aufsichtsratsvorsitzender: Joerg Heidrich