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 = </etc/ssl/certs/SSL123_CA_Bundle.pem
ssl_cert = </etc/ssl/certs/mail.roessner-net.de.pem
ssl_key = </etc/ssl/private/mail.roessner-net.de.key.pem
userdb {
args = /etc/dovecot/dovecot-ldap.conf.ext
driver = ldap
}
verbose_proctitle = yes
verbose_ssl = yes
protocol lmtp {
mail_plugins = autocreate quota acl fts fts_solr zlib sieve
}
protocol imap {
imap_client_workarounds = tb-extra-mailbox-sep tb-lsub-flags
mail_max_userip_connections = 50
mail_plugins = autocreate quota acl fts fts_solr zlib imap_quota imap_acl
imap_zlib
}
-------------------------------------------------------
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