I run a Dovecot/Postfix mailserver using virtual users based on a directory structure rather than a MySQL database as I only have a few users.

Recently for some reason I could no longer send emails which I had setup to use SSL/TLS. I could receive emails fine so my current configuration for encrypted IMAP was good.

In /var/log/dovecot.info:

2014-09-10 21:40:48 imap-login: Info: Login: user=<xxxxxxx@rejected.io>, method=CRAM-MD5, rip=xxx.xxx.xxx.xxx, lip=xxx.xxx.xxx.xxx, mpid=4620, TLS, session=<1rMrEbwCeQBWFkEN>

Interestingly setting up an IMAP account from new from work failed so I’m confused! Sending from wherever was a no go, in the log when I’ve been trying to send I see:

2014-09-10 21:25:51 auth: Info: passwd-file(xxx,xxx.xxx.xxx.xxx,<9Miu27sChQDBPsL2>): unknown user
2014-09-10 21:25:53 imap-login: Info: Disconnected (auth failed, 1 attempts in 2 secs): user=<xxx>, method=CRAM-MD5, rip=xxx.xxx.xxx.xxx, lip=xxx.xxx.xxx.xxx, TLS, session=<9Miu27sChQDBPsL2>

I really have no idea what changed!  I found this thread which seemed similar so because of the format of my user and passwd files I changed my /etc/dovecot/dovecot.conf from:

passdb {
args = /etc/dovecot/passwd
driver = passwd-file
}
userdb {
args = /etc/dovecot/users
driver = passwd-file
}

To:

passdb {
args = /etc/dovecot/passwd.%d
driver = passwd-file
}
userdb {
args = /etc/dovecot/users.%d
driver = passwd-file
}

I also tried:

args = /etc/dovecot/passwd.%0.d
args = /etc/dovecot/users.%0.d

Neither worked. I changed the password for my virtual user accounts and that didn’t work and I’ve now messed around with it so much I can’t get email! :O

I’ve turned on the following debugging options in /etc/dovecot/dovecot.conf to get a better idea of the problem:

auth_verbose = yes
auth_debug = yes
auth_debug_passwords = yes
verbose_ssl = yes

You can run the following command to get a readout of the current running config encase you get lost in all the changes you do; back up the originals before starting, if only I’d eat my own medicine!

sudo doveconf -n

Making troubleshooting harder was my Fail2ban config on dovecot and SASL which kept banning me for a while as my phone and my work computer kept trying to connect with the old wrong password! Thankfully it’s only 20 mins but it felt like ages.

After turning up all the dovecot debugging the SSL connections and handshakes from my computer and phone looked good though I still need to verify my postfix and dovecot certificates haven’t expired.

From my phone software, MailDroid I was seeing an error of :

Protocol:  smtp
Error: No authentication mechanisms supported by both server and client

The IMAP connection now looked ok:

2014-09-11 10:39:34 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [xxx.xxx.xxx.xxx] 2014-09-11 10:39:34 auth: Debug: client in: AUTH 1 CRAM-MD5 service=imap secured session=OBQ/8sYC/ADBPs3B lip=xxx.xxx.xxx.xxx rip= xxx.xxx.xxx.xxx lport=993 rport=54780
2014-09-11 10:39:34 auth: Debug: client passdb out: CONT 1 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
2014-09-11 10:39:34 auth: Debug: client in: CONT 1 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx= (previous base64 data may contain sensitive data)
2014-09-11 10:39:34 auth: Debug: passwd-file(xxx@xxxx.org.uk,xxx.xxx.xxx.xxx,<OBQ/8sYC/ADBPs3B>): lookup: user=xxx@xxxx.org.uk file=/etc/dovecot/passwd
2014-09-11 10:39:34 auth: Debug: password(xxx@xxxx.org.uk,xxx.xxx.xxx.xxx,<OBQ/8sYC/ADBPs3B>): Credentials: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
2014-09-11 10:39:34 auth: Debug: client passdb out: OK 1 user=xxx@xxxx.org.uk
2014-09-11 10:39:34 auth: Debug: master in: REQUEST  xxxxxxxxxxxxxxxxxxxxxxxx session_pid=5527 request_auth_token
2014-09-11 10:39:34 auth: Debug: passwd-file(xxx@xxxx.org.uk,xxx.xxx.xxx.xxx,<OBQ/8sYC/ADBPs3B>): lookup: user=xxx@xxxx.org.uk file=/etc/dovecot/users
2014-09-11 10:39:34 auth: Debug: master userdb out: USER 1215168513 xxx@xxxx.org.uk uid=5000 gid=5000 home=/home/vmail/xxxx.org.uk/xxx/ auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
2014-09-11 10:39:34 imap-login: Info: Login: user=<xxx@xxxx.org.uk>, method=CRAM-MD5, rip= xxx.xxx.xxx.xxx, lip= xxx.xxx.xxx.xxx, mpid=5527, TLS, session=<OBQ/8sYC/ADBPs3B>
2014-09-11 10:39:34 imap(xxx@xxxx.org.uk): Info: Disconnected: Logged out in=9 out=397
2014-09-11 10:39:34 imap-login: Debug: SSL alert: close notify [xxx.xxx.xxx.xxx]

So I’m back to successfully connecting via IMAPS. My current Thunderbird settings are:

IMAP:
Port = 993
Connection Security = SSL/TLS
Authentication method = Encrypted Password
SMTP:
Port: 587
Connection Security = STARTTLS
Authentication method = Encrypted Password

OK but I still cannot send. Thunderbird thinks the password is wrong when I know it isn’t and my phone thinks there’s no authentication mechanisms.

It’s now a definite Postfix to Dovecot SMTP authentication issue as I’ve set up SASL authentication:

Sep 11 10:49:01 vert postfix/submission/smtpd[5561]: connect from xxxxx.xxx.xx.uk[xxx.xxx.xxx.xxx] Sep 11 10:49:01 vert postfix/submission/smtpd[5561]: warning:xxxxx.xxx.xx.uk[xxx.xxx.xxx.xxx] : SASL CRAM-MD5 authentication failed: authentication failure

Using the Postfix SASL page again I started by looking through the /etc/dovecot/conf.d/10-master.conf file I noticed a syntax error which can’t be right, I missed commenting out a single ‘}’. Corrected that, restarted both services without success.

I then went through /etc/postfix/main.cf and changed the following settings from:

smtpd_sasl_auth_enable = no
smtpd_sasl_type = cyrus
smtpd_sasl_path = smtpd
smtpd_sasl_security_options = noanonymous
smtpd_tls_auth_only = no

To:

smtpd_sasl_auth_enable = yes
smtpd_sasl_type = dovecot
smtpd_sasl_path = private/dovecot-auth
smtpd_sasl_security_options = noanonymous, noplaintext
smtpd_sasl_tls_security_options = noanonymous
smtpd_tls_auth_only = yes

Then ran:

sudo postfix reload

I CAN NOW SEND!!!!!!  I validated that I’m not restricting valid incoming email which is great and I think I’m now a little more secure than before.

So it seems at some point the postfix config must have been changed to almost default, certainly the setting smtpd_sasl_type = cyrus seems to hint at that some of my postfix config got reset, however some customisations, specifically the virtual mailbox setup were left alone. Very confusing.