Solved Dovecot broken after update

My postfix+dovecot2 installation has been running smoothly for over a year but recently I updated dovecot to 2.2.29.1 (from 2.2.27_4) and after that authentication is broken. I have tried reinstalling and also downgrading back to 2.2.27_4.

The configuration has been the same for quite some time and has been working perfectly. Any help would be much appreciated, otherwise I guess the easiest option is to start over completely...

Code:
2017-05-09T09:08:46.026118+02:00 thenas dovecot: auth: Error: auth: environment corrupt; missing value for DOVECOT_
2017-05-09T09:08:46.026160+02:00 thenas dovecot: auth: Fatal: unsetenv(RESTRICT_SETUID) failed: Bad address

doveconf -n
Code:
# 2.2.29.1 (e0b76e3): /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 10.3-RELEASE-p11 amd64
auth_mechanisms = plain login
first_valid_uid = 5000
passdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocols = imap pop3
service auth {
  unix_listener /critical/mail/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
}
ssl = required
ssl_cert = </usr/local/etc/letsencrypt/live/domain.se/fullchain.pem
ssl_cipher_list = EECDH+ECDSA+AESGCM:EECDH+aRSA+AESGCM:EECDH+ECDSA+SHA384:EECDH+ECDSA+SHA256:EECDH+aRSA+SHA384:EECDH+aRSA+SHA256:EECDH+aRSA+RC4:EECDH:EDH+aRSA:!aNULL:!eNULL:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS:!RC4
ssl_key =  # hidden, use -P to show it
ssl_prefer_server_ciphers = yes
ssl_protocols = !SSLv2 !SSLv3
userdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}

postconf -n
Code:
command_directory = /usr/local/sbin
compatibility_level = 2
daemon_directory = /usr/local/libexec/postfix
data_directory = /var/db/postfix
debug_peer_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5
html_directory = no
inet_protocols = ipv4
mail_owner = postfix
mailq_path = /usr/local/bin/mailq
manpage_directory = /usr/local/man
meta_directory = /usr/local/libexec/postfix
milter_default_action = accept
milter_protocol = 2
mydestination = localhost.$mydomain, localhost,
mydomain = domain.se
myhostname = domain.se
mynetworks_style = subnet
myorigin = $mydomain
newaliases_path = /usr/local/bin/newaliases
non_smtpd_milters = inet:localhost:12301
queue_directory = /var/spool/postfix
readme_directory = no
relayhost = [127.0.0.1]:11125
sample_directory = /usr/local/etc/postfix
sendmail_path = /usr/local/sbin/sendmail
setgid_group = maildrop
shlib_directory = /usr/local/lib/postfix
smtp_sasl_auth_enable = yes
smtp_sasl_password_maps = hash:/critical/mail/private/smtp_auth
smtp_sasl_security_options =
smtpd_banner = $myhostname ESMTP $mail_name ($mail_version)
smtpd_milters = inet:localhost:12301
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = /critical/mail/private/auth
smtpd_sasl_type = dovecot
smtpd_tls_CAfile = /usr/local/etc/letsencrypt/live/domain.se/chain.pem
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /usr/local/etc/letsencrypt/live/domain.se/cert.pem
smtpd_tls_ciphers = high
smtpd_tls_eecdh_grade = strong
smtpd_tls_exclude_ciphers = aNULL, MD5 , DES, ADH, RC4, PSD, SRP, 3DES, eNULL
smtpd_tls_key_file = /usr/local/etc/letsencrypt/live/domain.se/privkey.pem
smtpd_tls_mandatory_protocols = !SSLv2, !SSLv3
smtpd_tls_protocols = !SSLv2, !SSLv3
smtpd_tls_security_level = may
smtputf8_enable = yes
tls_preempt_cipherlist = yes
unknown_local_recipient_reject_code = 550
virtual_alias_maps = mysql:/usr/local/etc/postfix/valias.cf
virtual_gid_maps = static:125
virtual_mailbox_base = /critical/mail
virtual_mailbox_domains = mysql:/usr/local/etc/postfix/vdomains.cf
virtual_mailbox_maps = mysql:/usr/local/etc/postfix/vmailbox.cf
virtual_minimum_uid = 5000
virtual_uid_maps = mysql:/usr/local/etc/postfix/vuidmap.cf
 
You may have to take the included sample configuration and carefully rewrite your production configuration, and check all items. Things have changed in Dovecot.
 
You may have to take the included sample configuration and carefully rewrite your production configuration, and check all items. Things have changed in Dovecot.
If I had stayed at 2.2.29.1 I'd agree, but downgrading back to the version that I know worked, feels like there's something else there. But I'll definitely give that a go.
 
I've tried looking through the examples to see if there's anything I need to change in my very minimal config but can't seem to find anything. I also tried disabling ssl and also a static passdb + userdb, still the same issue. Doing this I basically started over and still didn't solve the problem so I'm not sure how to move forward.

My Dovecot config
Code:
protocols = imap pop3

auth_mechanisms = plain login

ssl = yes
ssl_cert = </usr/local/etc/letsencrypt/live/domain.se/fullchain.pem
ssl_key = </usr/local/etc/letsencrypt/live/domain.se/privkey.pem
ssl_cipher_list = EECDH+ECDSA+AESGCM:EECDH+aRSA+AESGCM:EECDH+ECDSA+SHA384:EECDH+ECDSA+SHA256:EECDH+aRSA+SHA384:EECDH+aRSA+SHA256:EECDH+aRSA+RC4:EECDH:EDH+aRSA:!aNULL:!eNULL:!LOW:!3DES:!MD5:!EXP:!PSK:!SRP:!DSS:!RC4
ssl_prefer_server_ciphers = yes
ssl_protocols = !SSLv2 !SSLv3

disable_plaintext_auth = yes

first_valid_uid=5000

userdb {
 driver = sql
 args = /usr/local/etc/dovecot/dovecot-sql.conf
}

passdb {
 driver = sql
 args = /usr/local/etc/dovecot/dovecot-sql.conf
}

service auth {
 unix_listener /critical/mail/private/auth {
  mode = 0660
  user = postfix
  group = postfix
 }
 
I've tried rolling back to 2.2.27_4 again after double checking when I could last fetch mail and what version I was running then. Cleared the dovecot db and created a bare bone config with static userdb/passdb and without ssl but still get the same error. Are there soft dependencies that might be a reason for this suddenly happening?
 
It should work fine though:
Code:
root@mail:~ # pkg version -vR | grep dovecot
dovecot-pigeonhole-0.4.18_1        =   up-to-date with remote
dovecot2-2.2.29.1_1                =   up-to-date with remote
root@mail:~ # ps -ax | grep dovecot
35008  -  IsJ  0:00.01 /usr/local/sbin/dovecot -c /usr/local/etc/dovecot/dovecot.conf
35009  -  IJ   0:00.00 dovecot/anvil
35010  -  IJ   0:00.01 dovecot/log
35012  -  IJ   0:00.08 dovecot/config
35029  -  IJ   0:00.02 dovecot/auth
35030  -  IJ   0:00.00 dovecot/ssl-params
35031  -  IJ   0:00.02 dovecot/auth -w

Although I don't use Postfix. Perhaps it's due to some option you (de)selected?
Code:
root@mail:~ # pkg info dovecot2
dovecot2-2.2.29.1_1
Name           : dovecot2
Version        : 2.2.29.1_1
Installed on   : Thu May 11 10:58:02 2017 CEST
Origin         : mail/dovecot2
Architecture   : FreeBSD:10:amd64
Prefix         : /usr/local
Categories     : ipv6 mail
Licenses       : MIT, LGPL21
Maintainer     : adamw@FreeBSD.org
WWW            : http://www.dovecot.org/
Comment        : Secure, fast and powerful IMAP and POP3 server
Options        :
	CDB            : off
	DOCS           : on
	EXAMPLES       : on
	GSSAPI_BASE    : off
	GSSAPI_HEIMDAL : off
	GSSAPI_MIT     : off
	GSSAPI_NONE    : on
	ICU            : off
	KQUEUE         : on
	LDAP           : off
	LIBWRAP        : off
	LUCENE         : off
	LZ4            : off
	MYSQL          : on
	PGSQL          : off
	SOLR           : off
	SQLITE         : off
	TEXTCAT        : off
	VPOPMAIL       : off
Shared Libs required:
	libcrypto.so.41
	libssl.so.43
	libmysqlclient.so.18
Shared Libs provided:
	lib99_welcome_plugin.so
	lib20_mailbox_alias_plugin.so
	libauthdb_imap.so
	lib20_virtual_plugin.so
	lib20_replication_plugin.so
	lib95_imap_stats_plugin.so
	lib20_var_expand_crypt.so
	lib02_imap_acl_plugin.so
	lib20_quota_clone_plugin.so
	lib20_listescape_plugin.so
	lib20_expire_plugin.so
	lib10_quota_plugin.so
	lib15_notify_plugin.so
	lib05_snarf_plugin.so
	lib11_imap_quota_plugin.so
	libdovecot-lda.so.0
	libdovecot-login.so.0
	libssl_iostream_openssl.so
	libdovecot-fts.so.0
	lib20_push_notification_plugin.so
	lib21_fts_squat_plugin.so
	libdcrypt_openssl.so
	lib02_lazy_expunge_plugin.so
	libfs_compress.so
	lib05_mail_crypt_acl_plugin.so
	lib20_zlib_plugin.so
	lib10_doveadm_expire_plugin.so
	libdovecot.so.0
	lib10_doveadm_quota_plugin.so
	lib01_acl_plugin.so
	libdovecot-compression.so.0
	libdovecot-dsync.so.0
	libdoveadm_mail_crypt_plugin.so
	lib30_imap_zlib_plugin.so
	libdovecot-storage.so.0
	lib11_trash_plugin.so
	lib20_doveadm_fts_plugin.so
	lib10_mail_crypt_plugin.so
	lib10_doveadm_acl_plugin.so
	libstats_auth.so
	lib10_mail_filter_plugin.so
	lib20_autocreate_plugin.so
	lib20_fts_plugin.so
	libdovecot-sql.so.0
	lib05_pop3_migration_plugin.so
	libfs_crypt.so
	libstats_mail.so
	lib20_auth_var_expand_crypt.so
	lib20_mail_log_plugin.so
	lib10_last_login_plugin.so
	lib90_stats_plugin.so
	libfs_mail_crypt.so
Annotations    :
	cpe            : cpe:2.3:a:dovecot:dovecot:2.2.29.1:::::freebsd10:x64:1
	repo_type      : binary
	repository     : SirDice
Flat size      : 17.2MiB
Description    :
Dovecot is an open source IMAP and POP3 email server for Linux/UNIX-like
systems, written with security primarily in mind. Dovecot is an excellent
choice for both small and large installations. It's fast, simple to set up,
requires no special administration and it uses very little memory.

Dovecot is high-performing, self-optimizing, self-healing, and easily
extensible. It includes IMAP4rev1 and POP3 support. IPv6, SSL and TLS are
supported. It supports multiple commonly used IMAP extensions, including SORT,
THREAD and IDLE.

WWW: http://www.dovecot.org/
 
Thank you for pushing me forward! My options are exactly like yours and nothing there looks of, however a ps -ax | grep dovecot does look suspicious:
Code:
96185  -  Ss       0:00,01 /usr/local/sbin/dovecot -c /usr/local/etc/dovecot/dovecot.conf
96186  -  S        0:00,00 dovecot/anvil
96187  -  S        0:00,01 dovecot/log
96189  -  S        0:00,01 dovecot/config
That SSL isn't there now makes sense since I turned it off but there's no auth-process whatsoever. Are there any logs aside from the mail log I can look in?
 
Have a look in /usr/local/etc/dovecot/conf.d/10-logging.conf. There are some options there to increase the logging. If I recall correctly most of it is turned off by default:
Code:
# Log unsuccessful authentication attempts and the reasons why they failed.
auth_verbose = yes        

# Show protocol level SSL errors.
verbose_ssl = yes
You can also redirect the logging to a different file:
Code:
# Log file to use for error messages. "syslog" logs to syslog,
# /dev/stderr logs to stderr.
#log_path = syslog                                
                                                                 
# Log file to use for informational messages. Defaults to log_path.    
#info_log_path =                                                           
# Log file to use for debug messages. Defaults to info_log_path.               
#debug_log_path =
 
In postfix you have the following settings:

Code:
smtp_sasl_auth_enable = yes
smtp_sasl_password_maps = hash:/critical/mail/private/smtp_auth

Affecting dovecot also:

Code:
service auth {
  unix_listener /critical/mail/private/auth {
    group = postfix
    mode = 0660
    user = postfix

From what I see you are using SQL authentication. So, why not use dovecot for SASL instead?


Code:
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot


Code:
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0666
    user = postfix
  }
 
auth_verbose was already on apparently, it seems the auth-process simply never starts and I can't find any traces. Debuglog only gave
Code:
May 11 12:33:50 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
May 11 12:33:50 auth: Debug: Module loaded: /usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so
May 11 12:33:50 auth: Debug: Wrote new auth token secret to /var/run/dovecot/auth-token-secret.dat

Leaning more and more to just rolling back to a snapshot from when it was working...

From what I see you are using SQL authentication. So, why mix SASL?
That I actually have no idea. When it was set up from the beginning I followed a guide for postfix + dovecot

*edit:
Turns out I do, I.. think
Code:
smtpd_sasl_type=dovecot
 
In the end I ended up rolling back to my weekly snapshot and everything worked (version 2.2.27). A quick look at the state then shows that for example ps -ax looked just the same before, no auth process. I guess I'll have to check after each time I update a port for a little while and hopefully I can pinpoint the problem and avoid it... Thanks to the people that tried to push me forward! I think there's simply a distinct lack of actual knowledge on how it works on my side... Too much following guides!
 
Same here. Fought with it for a few hours by now, no success. Also 2.2.29.1. I have a second server with the old config (FreeBSD 10.3 /
dovecot 2.2.21, = before the upgrade), so it's easy for me to compare things. Ideas?
 
I have a second environment w/ almost same configs (only differing on the ssl certs), which is working fine.

Running on problematic host:
Code:
# doveconf -n
# 2.2.21 (5345f22): /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 10.3-RELEASE-p11 amd64
auth_debug = yes
auth_mechanisms = plain login
passdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocols = imap pop3
service auth {
  unix_listener /srv/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
}
ssl = required
ssl_ca = </usr/local/www/domain1/ssl/chain.pem
ssl_cert = </usr/local/www/domain1/ssl/cert.pem
ssl_key = </usr/local/www/domain1/ssl/privkey.pem
userdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}

Running on host that works:
Code:
# doveconf -n
# 2.2.21 (5345f22): /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 10.3-RELEASE-p11 amd64
auth_mechanisms = plain login
passdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocols = imap pop3
service auth {
  unix_listener /srv/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
}
ssl = required
ssl_ca = </etc/nginx/ssl/chain.pem
ssl_cert = </etc/nginx/ssl/cert.pem
ssl_key = </etc/nginx/ssl/privkey.pem
userdb {
  args = /usr/local/etc/dovecot/dovecot-sql.conf
  driver = sql
}

I ran truss -f dovecot -c <conffile> on the two different hosts to find out what was the difference, and made a diff of the `auth` process (--- is the problematic one). Full diff is attached.

Below is the part that stood out for me, the "process exit", right after getgid, which may be related to OP error (auth: Fatal: unsetenv(RESTRICT_SETUID) failed: Bad address)
Code:
 umask(0x0)                = 63 (0x3f)
 openat(AT_FDCWD,"/var/run/dovecot/auth-token-secret.dat.tmp",O_WRONLY|O_CREAT|O_TRUNC,0600) = 16 (0x10)
 umask(0x3f)                = 0 (0x0)
-write(16,"\M-*>^\M^Ca\M-Z\M^]uA\^]\M-W\M-Q"...,32) = 32 (0x20)
+write(16,"\M^_\M-:%\0\M-Hy\M-di\M-T\M-<\bl"...,32) = 32 (0x20)
 close(16)                = 0 (0x0)
 rename("/var/run/dovecot/auth-token-secret.dat.tmp","/var/run/dovecot/auth-token-secret.dat") = 0 (0x0)
-write(2,"\^A\^A89812 Wrote new auth token"...,78) = 78 (0x4e)
 geteuid()                = 0 (0x0)
 getgid()                    = 0 (0x0)
-process exit, rval = 89
-89805: fork()                    = 89812 (0x15ed4)
+23533: fork()                    = 23539 (0x5bf3)

The "write new token" is because I had deleted the /var/run/dovecot/auth-token-secret.dat, which shouldn't change anything.
 

Attachments

  • truss_diff.txt
    39 KB · Views: 433
Apparenlty, some openssl upgrades can cause environments to corrupt (https://forums.freebsd.org/threads/50959/). Which reminds me of a warning I saw when installing ports:

Code:
$ sudo make
/!\ WARNING /!\

You have security/openssl installed but do not have
DEFAULT_VERSIONS+=ssl=openssl set in your make.conf

Maybe this could be the source of the problem? I'll check and post the results back here.
 
Yep, problem solved.
After running as root:
echo 'DEFAULT_VERSIONS+=ssl=openssl' >> /etc/make.conf

And recompiling / reinstalling openssl, problem solved, dovecot up and running.

TIL: Be careful when ignoring warnings.
 
Good work. Looking back I guess you had a mix of ports depending on the port's OpenSSL and the base OpenSSL. That could indeed lead to some weird results.
 
Back
Top