Problems after upgrade from 2.0 to 2.2

Frank Rust frust at iti.cs.tu-bs.de
Thu Nov 12 07:03:17 UTC 2015


Hi all,
after upgrade from some 2.0 version to 2.2.19 (debian) i face map login problems:

# doveconf -n
# 2.2.19 (ca91d540fd87): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.9
# OS: Linux 2.6.32-5-amd64 x86_64 Debian 8.2 ext4
auth_debug = yes
auth_debug_passwords = yes
auth_verbose = yes
auth_verbose_passwords = plain
debug_log_path = /var/log/dovecot-debug.log
hostname = test.my.domain.de
info_log_path = /var/log/dovecot.log
mail_access_groups = smmta
mail_debug = yes
mail_location = mbox:/extra/mail/mbox.dir/%u/mailboxes:DIRNAME=mBoX-MeSsAgEs:INDEX=/extra/mail/mbox.dir/%u/index:CONTROL=/extra/mail/mbox.dir/%u/control:INBOX=/extra/mail/%u
mail_plugins = quota
mail_privileged_group = smmta
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 index ihave duplicate
namespace inbox {
  location = 
  mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix = 
}
passdb {
  driver = pam
}
plugin {
  mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename flag_change append
  quota = fs:User quota
  quota_rule = *:storage=1G
  quota_rule2 = Trash:storage=+100M
  quota_warning = storage=95%% quota-warning 95 %u
  quota_warning2 = storage=80%% quota-warning 80 %u
  sieve = file:~/sieve;active=~/.dovecot.sieve
}
postmaster_address = postmaster at my.domain.de
protocols = " imap sieve pop3"
quota_full_tempfail = yes
ssl = required
ssl_cert = </etc/ssl/StartCom/test.my.domain.pem
ssl_cipher_list = EECDH+ECDSA+AESGCM:EECDH+aRSA+AESGCM:EECDH+ECDSA+SHA256:EECDH+aRSA+RC4:EDH+aRSA EECDH RC4:!aNULL:!eNULL:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS
ssl_key = </etc/ssl/StartCom/test.my.domain.key
ssl_prefer_server_ciphers = yes
ssl_protocols = !SSLv2 !SSLv3
userdb {
  driver = passwd
}
verbose_ssl = yes
protocol lda {
  mail_plugins = 
}


When I try to log in with openssl:

$ openssl s_client -connect test.familie-rust.de:993
CONNECTED(00000003)
depth=1 C = IL, O = StartCom Ltd., OU = Secure Digital Certificate Signing, CN = StartCom Class 1 Primary Intermediate Server CA
verify error:num=20:unable to get local issuer certificate
---
Certificate chain
 0 s:/C=DE/CN=test.my.domain.de/emailAddress=postmaster at my.domain.de
   i:/C=IL/O=StartCom Ltd./OU=Secure Digital Certificate Signing/CN=StartCom Class 1 Primary Intermediate Server CA
 1 s:/C=IL/O=StartCom Ltd./OU=Secure Digital Certificate Signing/CN=StartCom Class 1 Primary Intermediate Server CA
   i:/C=IL/O=StartCom Ltd./OU=Secure Digital Certificate Signing/CN=StartCom Certification Authority
---
Server certificate
-----BEGIN CERTIFICATE——
(…)
-----END CERTIFICATE-----
subject=/C=DE/CN=test.my.domain.de/emailAddress=postmaster at my.domain.de
issuer=/C=IL/O=StartCom Ltd./OU=Secure Digital Certificate Signing/CN=StartCom Class 1 Primary Intermediate Server CA
---
No client certificate CA names sent
Peer signing digest: SHA512
Server Temp Key: ECDH, P-384, 384 bits
---
SSL handshake has read 4328 bytes and written 506 bytes
---
New, TLSv1/SSLv3, Cipher is ECDHE-RSA-AES256-GCM-SHA384
Server public key is 4096 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES256-GCM-SHA384
    Session-ID: B0...5B
    Session-ID-ctx: 
    Master-Key: 59D...EC0
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    TLS session ticket lifetime hint: 300 (seconds)
    TLS session ticket:
    0000 - 35 47 73 57 22 45 21 7d-fe ea a4 36 f1 35 76 3a   5GsW"E!}…6.5v:
    (…)
    Start Time: 1447309592
    Timeout   : 300 (sec)
    Verify return code: 20 (unable to get local issuer certificate)
---
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN] Dovecot ready.
01 login frank myPassword
* BYE Internal error occurred. Refer to server log for more information.
closed

And in the log files I find following information:
dovecot.log
Nov 12 07:47:27 imap-login: Info: Login: user=<frank>, method=PLAIN, rip=134.169.39.105, lip=134.169.39.22, mpid=9475, TLS, session=<...>

dovecot-debug.log:
Nov 12 07:47:27 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Nov 12 07:47:27 auth: Debug: auth client connected (pid=11158)
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2002, ret=-1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2001, ret=1: unknown state [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [134.169.39.105]
Nov 12 07:47:27 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [134.169.39.105]
Nov 12 07:47:27 auth: Debug: client in: AUTH	1	PLAIN	service=imap	secured	session=QkLwUFIkXsCGqSdp	lip=134.169.39.22	rip=134.169.39.105	lport=993	rport=49246	resp=xxxx (previous base64 data removed)
Nov 12 07:47:27 auth-worker(11140): Debug: pam(frank,134.169.39.105): lookup service=dovecot
Nov 12 07:47:27 auth-worker(11140): Debug: pam(frank,134.169.39.105): #1/1 style=1 msg=Password: 
Nov 12 07:47:27 auth: Debug: client passdb out: OK	1	user=frank	
Nov 12 07:47:27 auth: Debug: master in: REQUEST	3038248961	11158	1	4e2362c2872f9288b7c8c3ebd8469620	session_pid=11159	request_auth_token
Nov 12 07:47:27 auth-worker(11140): Debug: pam(frank,134.169.39.105): lookup
Nov 12 07:47:27 auth: Debug: master userdb out: USER	3038248961	frank	system_groups_user=frank	uid=1000	gid=100	home=/home/frank	auth_token=1e04d2c61fb327ec14c1e54ff678d73a325d20bf
Nov 12 07:47:27 imap(frank): Debug: Loading modules from directory: /usr/lib/dovecot/modules
Nov 12 07:47:27 imap(frank): Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Nov 12 07:47:27 imap(frank): Debug: Effective uid=1000, gid=100, home=/home/frank
Nov 12 07:47:27 imap(frank): Debug: Quota root: name=User quota backend=fs args=
Nov 12 07:47:27 imap(frank): Debug: Quota rule: root=User quota mailbox=* bytes=1073741824 messages=0
Nov 12 07:47:27 imap(frank): Debug: Quota rule: root=User quota mailbox=Trash bytes=+104857600 messages=0
Nov 12 07:47:27 imap(frank): Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 frank
Nov 12 07:47:27 imap(frank): Debug: Quota warning: bytes=858993459 (80%) messages=0 reverse=no command=quota-warning 80 frank
Nov 12 07:47:27 imap(frank): Debug: Quota grace: root=User quota bytes=107374182 (10%)
Nov 12 07:47:27 imap(frank): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=no, hidden=no, list=yes, subscriptions=yes location=mbox:/extra/mail/mbox.dir/frank/mailboxes:DIRNAME=mBoX-MeSsAgEs:INDEX=/extra/mail/mbox.dir/frank/index:CONTROL=/extra/mail/mbox.dir/frank/control:INBOX=/extra/mail/frank
Nov 12 07:47:27 imap(frank): Debug: fs: root=/extra/mail/mbox.dir/frank/mailboxes, index=/extra/mail/mbox.dir/frank/index, indexpvt=, control=/extra/mail/mbox.dir/frank/control, inbox=/extra/mail/frank, alt=
Nov 12 07:47:27 imap(frank): Debug: fs quota add mailbox dir = /extra/mail/mbox.dir/frank/mailboxes
Nov 12 07:47:27 imap(frank): Debug: fs quota block device = /dev/mapper/ownCloudVG-ownCloudData
Nov 12 07:47:27 imap(frank): Debug: fs quota mount point = /extra
Nov 12 07:47:27 imap(frank): Debug: fs quota mount type = ext4
Nov 12 07:47:27 imap-login: Debug: SSL alert: close notify [134.169.39.105]

What could cause the problem? 

The problem is not quota related (I enhanced the allowed quota and got the same results)


best regards,
Frank 



More information about the dovecot mailing list