Docker-mailserver: dovecot horked on {7.1.0,latest} versions.
Horked is a technical termed for broken :)
Seriously though -- Dovecot configuration works appropriately up to version 7.0.1 and before. Upgrading to the latest or release-v7.1.0 image results in dovecot not starting on docker-mailserver, and consequently rejecting IMAP connections.
Using the same configuration on images up to 7.0.1 works appropriately.
Expectations: A working configuration from 7.0.1 should work in 7.0.1+, unless explicit changes are called out in the Announcements section.
Context
Pretty standard postfix/dovecot setup using imap/ssl w/ letsencrypt, dmarc, dkim, etc.
docker-compose.yml (redacted and paths simplified):
version: "3"
networks:
mail:
driver: bridge
ipam:
config:
- subnet: {MAIL NET}/24
db_db:
external: true
services:
mail:
image: tvial/docker-mailserver:release-v7.0.1
restart: "always"
stop_grace_period: "1m"
networks:
mail:
ipv4_address: {MAIL IP}
ports:
- "25:25/tcp"
- "587:587/tcp"
- "993:993/tcp"
hostname: "mail"
domainname: "{REDACTED}"
container_name: "mail"
environment:
- "DEFAULT_RELAY_HOST=''"
- "DMS_DEBUG=1"
- "DOVECOT_MAILBOX_FORMAT=maildir"
- "ENABLE_CLAMAV=0"
- "ENABLE_ELK_FORWARDER=0"
- "ENABLE_FAIL2BAN=0"
- "ENABLE_FETCHMAIL=0"
- "ENABLE_LDAP=''"
- "ENABLE_MANAGESIEVE=1"
- "ENABLE_POP3=''"
- "ENABLE_POSTFIX_VIRTUAL_TRANSPORT=''"
- "ENABLE_POSTGREY=1"
- "ENABLE_QUOTAS=0"
- "ENABLE_SASLAUTHD=0"
- "ENABLE_SPAMASSASSIN=1"
- "ENABLE_SRS=1"
- "LOGROTATE_INTERVAL=weekly"
- "LOGWATCH_INTERVAL=weekly"
- "ONE_DIR=1"
- "PERMIT_DOCKER=host"
- "PFLOGSUMM_TRIGGER=logrotate"
- "POSTFIX_DAGENT=''"
- "POSTFIX_INET_PROTOCOLS=ipv4"
- "POSTFIX_MAILBOX_SIZE_LIMIT=0"
- "POSTFIX_MESSAGE_SIZE_LIMIT=10480000"
- "POSTGREY_AUTO_WHITELIST_CLIENTS=0"
- "POSTGREY_DELAY=300"
- "POSTGREY_MAX_AGE=35"
- "POSTGREY_TEXT=Delayed by postgrey"
- "POSTMASTER_ADDRESS=postmaster@{REDACTED}"
- "POSTSCREEN_ACTION=enforce"
- "RELAY_HOST=''"
- "SA_KILL=6.31"
- "SA_SPAM_SUBJECT=***SPAM***"
- "SA_TAG2=6.31"
- "SA_TAG=3.0"
- "SASL_PASSWD=''"
- "SASLAUTHD_MECH_OPTIONS=''"
- "SASLAUTHD_MECHANISMS=''"
- "SMTP_ONLY=''"
- "SPOOF_PROTECTION=1"
- "SRS_EXCLUDE_DOMAINS=''"
- "SRS_SENDER_CLASSES=envelope_sender,header_sender"
- "SSL_TYPE=letsencrypt"
- "TLS_LEVEL=modern"
- "TZ=America/Los_Angeles"
- "VIRUSMAILS_DELETE_DELAY=7"
volumes:
- "/d/mail:/var/mail"
- "/d/config:/tmp/docker-mailserver"
- "/d/90-sieve.conf:/etc/dovecot/conf.d/90-sieve.conf"
- "/d/letsencrypt:/etc/letsencrypt:ro"
- "/var/log/docker/mail:/var/log/mail"
- "/etc/localtime:/etc/localtime:ro"
IMAP/SSL works fine, can login without issue (and all versions before this).
$ openssl s_client -starttls imap -connect mail.{REDACTED}:993
CONNECTED(00000005)
Dovecot is running on the server:
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 1 23:05 ? 00:00:00 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
root 8 1 0 23:05 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 457 0 0 23:05 pts/0 00:00:00 /bin/sh
root 525 1 0 23:05 ? 00:00:00 /usr/sbin/cron -f
root 527 1 0 23:05 ? 00:00:00 /usr/sbin/rsyslogd -n
root 533 1 0 23:05 ? 00:00:00 /usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf
dovecot 536 533 0 23:05 ? 00:00:00 dovecot/anvil
root 537 533 0 23:05 ? 00:00:00 dovecot/log
root 538 533 0 23:05 ? 00:00:00 dovecot/config
opendkim 540 1 0 23:05 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 542 540 0 23:05 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 548 1 0 23:05 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/run/opendmarc/opendmarc.pid
postgrey 556 1 1 23:05 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail --delay=300 --max-age=35 --auto-whitelist-clients=0 --g
root 558 1 0 23:05 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
amavis 567 1 16 23:05 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 569 8 0 23:05 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
postsrsd 661 1 0 23:05 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /etc/postsrsd.secret -a = -n 4 -N 4 -u postsrsd -p /var/r
root 1206 1 0 23:05 ? 00:00:00 /usr/lib/postfix/sbin/master
postfix 1208 1206 0 23:05 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_override_options=no_header_body_checks
postfix 1209 1206 0 23:05 ? 00:00:00 qmgr -l -t unix -u
amavis 1210 567 0 23:05 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1211 567 0 23:05 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1214 558 0 23:05 ? 00:00:00 sleep 5
root 1215 457 0 23:05 pts/0 00:00:00 ps -ef
What is affected by this bug?
Upgrading beyond 7.0.1 without any changes causes dovecot not to run, and therefore, IMAP/SSL to fail.
docker-compose.yml (same as above, just version bump):
...
services:
mail:
image: tvial/docker-mailserver:release-v7.1.0
...
IMAP/SSL fails.
$ openssl s_client -starttls imap -connect mail.{REDACTED}:993
140671805964736:error:0200206F:system library:connect:Connection refused:../crypto/bio/b_sock2.c:110:
140671805964736:error:2008A067:BIO routines:BIO_connect:connect error:../crypto/bio/b_sock2.c:111:
connect:errno=111
Dovecot is not running on the server:
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 2 23:03 ? 00:00:00 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
root 8 1 0 23:03 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 552 1 0 23:03 ? 00:00:00 /usr/sbin/cron -f
root 554 1 0 23:03 ? 00:00:00 /usr/sbin/rsyslogd -n
opendkim 558 1 0 23:03 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 560 558 0 23:03 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 566 1 0 23:03 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/run/opendmarc/opendmarc.pid
postgrey 574 1 3 23:03 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail --delay=300 --max-age=35 --auto-whitelist-clients=0 --g
root 576 1 0 23:03 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
amavis 585 1 44 23:03 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 587 8 0 23:03 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
root 596 0 1 23:03 pts/0 00:00:00 /bin/sh
postsrsd 626 1 0 23:03 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /etc/postsrsd.secret -a = -n 4 -N 4 -u postsrsd -p /var/r
amavis 1141 585 0 23:04 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1142 585 0 23:04 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1225 1 0 23:04 ? 00:00:00 /usr/lib/postfix/sbin/master
root 1226 576 0 23:04 ? 00:00:00 sleep 5
postfix 1227 1225 0 23:04 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_override_options=no_header_body_checks
postfix 1228 1225 0 23:04 ? 00:00:00 qmgr -l -t unix -u
root 1229 596 0 23:04 pts/0 00:00:00 ps -ef
roundcube (web UI using IMAP/SSL) is not happy either:
/var/log/syslog:
Oct 12 20:18:47 {SERVER} roundcube[7483]: errors: <eb34b0a6> IMAP Error: Login failed for {USER} against {REDACTED} from {GATEWAY IP}(X-Real-IP:
{CLIENT IP},X-Forwarded-For: {CLIENT IP}). Could not connect to ssl://{REDACTED}:993: Unknown reason in /var/www/html/program/lib/Roundcube/rcube_imap.php on line 200 (POST /?_task=login&_action=login)
When does this occur?
Any version beyond 7.0.1
How do we replicate the issue?
See above for replication. I can provide additional files for postfix conf and dovecot sieve, but that doesn't seem to be the issue.
Actual Behavior
IMAP/SSL logins fail. Dovecot not running on the server.
Expected behavior (i.e. solution)
Expectations: A working configuration from 7.0.1 should work in 7.0.1+, unless explicit changes are called out in the Announcements section.
Your Environment
- Amount of RAM available: 128GB
- Mailserver version used:
- working: release-v7.0.0, release-v7.0.1
- non-working: release-v7.1.0, latest
- Docker version used: Docker version 19.03.13, build 4484c46d9d
- Environment settings relevant to the config: See config.
- Any relevant stack traces ("Full trace" preferred):
r-pufky
All 15 comments
Have you checked these log files?
/var/log/supervisor/supervisord.log/var/log/supervisor/dovecot.log
Alternatively you can run docker logs -f mail during startup.
casperklein
on 13 Oct 2020
7.1.0
Have you checked these log files?
/var/log/supervisor/supervisord.log
Entire contents (7.1.0) -- dovecot not started:
2020-10-13 05:36:32,796 CRIT Supervisor is running as root. Privileges were not dropped because no user is specified in the config file. If you intend to run as root, you can set user=root in the config file to avoid this message.
2020-10-13 05:36:32,796 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2020-10-13 05:36:32,796 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing
2020-10-13 05:36:32,803 INFO RPC interface 'supervisor' initialized
2020-10-13 05:36:32,803 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2020-10-13 05:36:32,803 INFO supervisord started with pid 1
2020-10-13 05:36:33,806 INFO spawned: 'mailserver' with pid 8
2020-10-13 05:36:33,822 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:37,864 INFO spawned: 'postsrsd' with pid 493
2020-10-13 05:36:37,865 INFO success: postsrsd entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:37,963 INFO spawned: 'cron' with pid 507
2020-10-13 05:36:37,963 INFO success: cron entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,063 INFO spawned: 'rsyslog' with pid 509
2020-10-13 05:36:38,063 INFO success: rsyslog entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,163 INFO spawned: 'opendkim' with pid 513
2020-10-13 05:36:38,163 INFO success: opendkim entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,265 INFO spawned: 'opendmarc' with pid 521
2020-10-13 05:36:38,265 INFO success: opendmarc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,366 INFO spawned: 'postgrey' with pid 529
2020-10-13 05:36:38,367 INFO success: postgrey entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,467 INFO spawned: 'postfix' with pid 531
2020-10-13 05:36:38,467 INFO success: postfix entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:38,567 INFO spawned: 'amavis' with pid 540
2020-10-13 05:36:38,567 INFO success: amavis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:36:39,491 INFO exited: postsrsd (exit status 0; expected)
2020-10-13 05:36:39,491 INFO reaped unknown pid 581
/var/log/supervisor/dovecot.log
This logfile does not exist in the 7.1.0,latest containers
7.0.1
/var/log/supervisor/supervisord.log
Entire contents (7.0.1) -- dovecot started:
2020-10-13 05:43:08,489 CRIT Supervisor is running as root. Privileges were not dropped because no user is specified in the config file. If you intend to run as root, you can set user=root in the config file to avoid this message.
2020-10-13 05:43:08,489 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2020-10-13 05:43:08,489 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing
2020-10-13 05:43:08,496 INFO RPC interface 'supervisor' initialized
2020-10-13 05:43:08,496 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2020-10-13 05:43:08,496 INFO supervisord started with pid 1
2020-10-13 05:43:09,498 INFO spawned: 'mailserver' with pid 8
2020-10-13 05:43:09,516 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:13,604 INFO spawned: 'postsrsd' with pid 506
2020-10-13 05:43:13,605 INFO success: postsrsd entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:13,703 INFO spawned: 'cron' with pid 520
2020-10-13 05:43:13,703 INFO success: cron entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:13,799 INFO spawned: 'rsyslog' with pid 522
2020-10-13 05:43:13,799 INFO success: rsyslog entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:13,901 INFO spawned: 'dovecot' with pid 527
2020-10-13 05:43:13,901 INFO success: dovecot entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:14,034 INFO spawned: 'opendkim' with pid 539
2020-10-13 05:43:14,034 INFO success: opendkim entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:14,137 INFO spawned: 'opendmarc' with pid 547
2020-10-13 05:43:14,137 INFO success: opendmarc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:14,238 INFO spawned: 'postgrey' with pid 555
2020-10-13 05:43:14,239 INFO success: postgrey entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:14,340 INFO spawned: 'postfix' with pid 557
2020-10-13 05:43:14,341 INFO success: postfix entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:14,440 INFO spawned: 'amavis' with pid 566
2020-10-13 05:43:14,440 INFO success: amavis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2020-10-13 05:43:15,526 INFO exited: postsrsd (exit status 0; expected)
2020-10-13 05:43:15,526 INFO reaped unknown pid 578
/var/log/supervisor/dovecot.log
Exists but is currently empty
r-pufky
on 13 Oct 2020
What happens, when you run supervisorctl start dovecot?
casperklein
on 13 Oct 2020
Good question.
Manually starting the process will launch it for a few seconds, then it dies.
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 2 12:12 ? 00:00:01 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
root 8 1 0 12:12 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 507 1 0 12:12 ? 00:00:00 /usr/sbin/cron -f
root 509 1 0 12:12 ? 00:00:00 /usr/sbin/rsyslogd -n
opendkim 513 1 0 12:12 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 515 513 0 12:12 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 521 1 0 12:12 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/run/opendmarc/opendmarc.pid
postgrey 529 1 0 12:12 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail --delay=300 --max-age=35 --auto-whitelist-clients=0 --greylist-text=Delayed by postgrey
root 531 1 0 12:12 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
amavis 540 1 4 12:12 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 542 8 0 12:12 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
postsrsd 598 1 0 12:12 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /etc/postsrsd.secret -a = -n 4 -N 4 -u postsrsd -p /var/run/postsrsd.pid -c /var/lib/postsrsd -l 127.0.0.1 -D
root 1178 1 0 12:12 ? 00:00:00 /usr/lib/postfix/sbin/master
postfix 1180 1178 0 12:12 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_override_options=no_header_body_checks
postfix 1181 1178 0 12:12 ? 00:00:00 qmgr -l -t unix -u
amavis 1183 540 0 12:12 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1184 540 0 12:12 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1187 0 0 12:12 pts/0 00:00:00 /bin/sh
root 1601 531 0 12:12 ? 00:00:00 sleep 5
root 1828 1 0 12:12 ? 00:00:00 /usr/bin/doveconf -c /etc/dovecot/dovecot.conf -m master -p -e /usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf
root 1829 1828 0 12:12 ? 00:00:00 /usr/bin/doveconf -c /etc/dovecot/dovecot.conf -m managesieve -e /usr/lib/dovecot/managesieve -k -c /etc/dovecot/dovecot.conf
root 1830 1187 0 12:12 pts/0 00:00:00 ps -ef
~2 seconds later:
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 3 12:12 ? 00:00:02 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
root 8 1 0 12:12 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 507 1 0 12:12 ? 00:00:00 /usr/sbin/cron -f
root 509 1 0 12:12 ? 00:00:00 /usr/sbin/rsyslogd -n
opendkim 513 1 0 12:12 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 515 513 0 12:12 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 521 1 0 12:12 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/run/opendmarc/opendmarc.pid
postgrey 529 1 0 12:12 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail --delay=300 --max-age=35 --auto-whitelist-clients=0 --greylist-text=Delayed by postgrey
root 531 1 0 12:12 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
amavis 540 1 2 12:12 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 542 8 0 12:12 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
postsrsd 598 1 0 12:12 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /etc/postsrsd.secret -a = -n 4 -N 4 -u postsrsd -p /var/run/postsrsd.pid -c /var/lib/postsrsd -l 127.0.0.1 -D
root 1178 1 0 12:12 ? 00:00:00 /usr/lib/postfix/sbin/master
postfix 1180 1178 0 12:12 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_override_options=no_header_body_checks
postfix 1181 1178 0 12:12 ? 00:00:00 qmgr -l -t unix -u
amavis 1183 540 0 12:12 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1184 540 0 12:12 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1187 0 0 12:12 pts/0 00:00:00 /bin/sh
root 3173 531 0 12:13 ? 00:00:00 sleep 5
root 3178 1187 0 12:13 pts/0 00:00:00 ps -ef
This actually generated an error in the dovecot log though:
doveconf: Fatal: Error in configuration file /etc/dovecot/conf.d/10-ssl.conf line 48: ssl_dh: Can't open file /etc/dovecot/dh.pem: No such file or directory
Based on previous information there seems to be two issues here:
- dovecot isn't getting launched by supervisord
- The default location of diffie-hellman PEM certificate has moved (or not setup correctly), or needs to be generated.
FWIW, dovecot config file used only defines ports, so the default config should work.
dovecot.cf
service imap-login {
inet_listener imap {
port = 0
}
inet_listener imaps {
port = 993
ssl = yes
}
}
service pop3-login {
inet_listener pop3 {
port = 0
}
inet_listener pop3s {
port = 0
ssl = yes
}
}
/etc/dovecot/conf.d/10-ssl.conf
...
ssl_dh = </etc/dovecot/dh.pem
...
7.0.1
For this release, the configs are the same, but dh.pem is generated and exists.
/etc/dovecot/conf.d/10-ssl.conf
...
ssl_dh = </etc/dovecot/dh.pem
...
root@mail:/etc/dovecot# ls -al
total 80
drwxr-xr-x 1 root root 4096 Oct 13 12:26 .
drwxr-xr-x 1 root root 4096 Oct 13 12:26 ..
drwxr-xr-x 1 root root 4096 Oct 13 12:26 conf.d
-rw-r--r-- 1 root root 769 Oct 13 12:26 dh.pem
-rw-r----- 1 root dovecot 1507 Jan 23 2019 dovecot-dict-auth.conf.ext
-rw-r----- 1 root dovecot 852 Jan 23 2019 dovecot-dict-sql.conf.ext
-rw-r--r-- 1 root root 578 Aug 12 01:03 dovecot-ldap.conf.ext
-rw-r----- 1 root dovecot 5824 Jan 23 2019 dovecot-sql.conf.ext
-rw-r--r-- 1 root root 4395 Aug 12 01:05 dovecot.conf
-r-------- 1 root root 239 Oct 13 12:26 local.conf
drwx------ 2 root root 4096 Aug 12 01:04 private
drwxr-xr-x 2 root root 4096 Oct 13 12:26 protocols.d
drwxr-xr-x 3 root root 4096 Aug 12 01:05 sieve
drwxr-xr-x 2 root root 4096 Aug 12 01:05 ssl
-rw-r----- 1 dovecot dovecot 374 Oct 13 12:26 userdb
I've looked through the diff for start-mailserver.sh but couldn't actually find anything. Here is the function which set's up the dovecot dh params:
I noticed there is still a bit of misalignment for some of the if-else, my bad.
So essentially what is done is: DHPARAMS_FILE is set to /var/mail-state/lib-shared/dhparams.pem. If this file is not present (could you check that?), we will use /etc/postfix/shared/ffdhe4096.pem (check this too). If DHPARAMS_FILE is present, we will use this. This is done when ONE_DIR=1.
aendeavor
on 14 Oct 2020
7.1.0
Looks like it is mapped to ffdhe4096.pem, but never linked to dh.pem?
# ls -l /var/mail-state/lib-shared/*.pem
ls: cannot access '/var/mail-state/lib-shared/*.pem': No such file or directory
# ls -l /etc/postfix/shared/*.pem
-rw-r--r-- 1 root root 769 Sep 26 04:11 /etc/postfix/shared/ffdhe4096.pem
# diff /etc/postfix/shared/ffdhe4096.pem /etc/postfix/dhparams.pem
# diff /etc/dovecot/dh.pem /etc/postfix/dhparams.pem
diff: /etc/dovecot/dh.pem: No such file or directory
7.0.1
Mapped to ffdhe4096.pem
# ls -l /var/mail-state/lib-shared/*.pem
ls: cannot access '/var/mail-state/lib-shared/*.pem': No such file or directory
# ls -l /etc/postfix/shared/*.pem
-rw-r--r-- 1 root root 769 Aug 12 01:02 /etc/postfix/shared/ffdhe4096.pem
# diff /etc/postfix/shared/ffdhe4096.pem /etc/postfix/dhparams.pem
# diff /etc/dovecot/dh.pem /etc/postfix/dhparams.pem
Can you manually try to copy cp /etc/postfix/shared/ffdhe4096.pem /etc/dovecot/dh.pem and see what鈥檚 happens when you start postfix?
My current guess is that for some reason, there was no /etc/dovecot/dh.pem so the rm exists with a non-zero status code effectively leading to the right side of && not being executed. This should be an easy fix tough, replacing && with ;. But I can't confirm this behaviour of rm right now, I will follow this up soon.
aendeavor
on 14 Oct 2020
7.1.0
Copying dh.pem seems to keep dovecot running. Still not accessible though -- nothing in dovecot logs.
# cp /etc/postfix/shared/ffdhe4096.pem /etc/dovecot/dh.pem
# ls -l /etc/dovecot/dh.pem
-rw-r--r-- 1 root root 769 Oct 14 14:24 dh.pem
# supervisorctl stop postfix
# supervisorctl start postfix
# supervisorctl start dovecot
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 0 14:23 ? 00:00:02 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
root 8 1 0 14:23 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 507 1 0 14:23 ? 00:00:00 /usr/sbin/cron -f
root 509 1 0 14:23 ? 00:00:00 /usr/sbin/rsyslogd -n
opendkim 513 1 0 14:23 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 515 513 0 14:23 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 521 1 0 14:23 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/run/opendmarc/opendmarc.pid
postgrey 529 1 0 14:23 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail --delay=300 --max-age=35 --auto-whitelist-clients=0 --greylist-text=Delayed by postgrey
amavis 540 1 0 14:23 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 542 8 0 14:23 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
postsrsd 572 1 0 14:23 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /etc/postsrsd.secret -a = -n 4 -N 4 -u postsrsd -p /var/run/postsrsd.pid -c /var/lib/postsrsd -l 127.0.0.1 -D
amavis 1046 540 0 14:23 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1047 540 0 14:23 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1205 0 0 14:24 pts/0 00:00:00 /bin/bash
root 1539 1 0 14:33 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
root 2165 1 0 14:33 ? 00:00:00 /usr/lib/postfix/sbin/master
postfix 2167 2165 0 14:33 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_override_options=no_header_body_checks
postfix 2168 2165 0 14:33 ? 00:00:00 qmgr -l -t unix -u
root 2191 1 0 14:34 ? 00:00:00 /usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf
dovecot 2193 2191 0 14:34 ? 00:00:00 dovecot/anvil
root 2194 2191 0 14:34 ? 00:00:00 dovecot/log
root 2195 2191 0 14:34 ? 00:00:00 dovecot/config
root 2199 1539 0 14:34 ? 00:00:00 sleep 5
root 2201 1205 0 14:34 pts/0 00:00:00 ps -ef
Attempting to connect locally or remotely still fails:
# openssl s_client -starttls imap -connect localhost:993
139940836947072:error:0200206F:system library:connect:Connection refused:../crypto/bio/b_sock2.c:110:
139940836947072:error:2008A067:BIO routines:BIO_connect:connect error:../crypto/bio/b_sock2.c:111:
139940836947072:error:0200206F:system library:connect:Connection refused:../crypto/bio/b_sock2.c:110:
139940836947072:error:2008A067:BIO routines:BIO_connect:connect error:../crypto/bio/b_sock2.c:111:
connect:errno=111
```bash
$ openssl s_client -starttls imap -connect mail.{READACTED}:993
139872832475584:error:0200206F:system library:connect:Connection refused:../crypto/bio/b_sock2.c:110:
139872832475584:error:2008A067:BIO routines:BIO_connect:connect error:../crypto/bio/b_sock2.c:111:
connect:errno=111
### Script errors
I tried to restart all services / check-for-changes and ran into a few interesting script issues.
A valid "SMTP_ONLY=''" and "ENABLE_LDAP=''" leads to a check-for-changes.sh script error, and hangs:
```bash
# ./check-for-changes.sh
2020-10-14 14:40:42 Start check-for-changes script.
2020-10-14 14:40:42 Using postmaster address postmaster@(REDACTED}
2020-10-14 14:40:52 Change detected
./check-for-changes.sh: line 99: [[: '': syntax error: operand expected (error token is "''")
* Adding relay mapping for {REDACTED}
* Adding relay mapping for {REDACTED}
postfix: stopped
postfix: started
./check-for-changes.sh: line 232: [[: '': syntax error: operand expected (error token is "''")
This is listed in the documentation ENABLE_SMTP, ENABLE_LDAP as being valid, however the bash comparison looks like it needs to be quoted, or use a 0. SMTP, LDAP lines.
Fully restarting supervisor services results in format string error:
# service supervisor stop
# service supervisor start [2667/2667]
Starting supervisor: Error: Format string '/usr/sbin/saslauthd -d -a mysql -O %(ENV_SASLAUTHD_MECH_OPTIONS)s' for 'program:saslauthd_mysql.command' contains names ('ENV_SASLAUTHD_MECH_OPTIONS') which cannot be expanded. Available names: ENV_LANG, ENV_LANGUAGE, ENV_LC_ADDRESS, ENV_LC_ALL, ENV_LC_COLLATE, ENV_LC_CTYPE, ENV_LC_IDENTIFICATION, ENV_LC_MEASUREMENT, ENV_LC_MESSAGES, ENV_LC_MONETARY, ENV_LC_NAME, ENV_LC_NUMERIC, ENV_LC_PAPER, ENV_LC_TELEPHONE, ENV_LC_TIME, ENV_PATH, ENV_PWD, ENV_TERM, group_name, here, host_node_name, process_num, program_name in section 'program:saslauthd_mysql' (file: '/etc/supervisor/conf.d/saslauth.conf')
This looks like the same bash string comparison error - "SASLAUTHD_MECH_OPTIONS=''" SASLAUTHD_MECH_OPTIONS code; but I haven't looked into this one too much.
r-pufky
on 15 Oct 2020
Alright @r-pufky. I've identified what went wrong in check-for-changes.sh, and the error is most likely in your side, more precisely, in your configuration. You used ENBALE_LDAP='' or EMABLE_LDAP="" which is not what the documentation is actually referring to. _Empty_ is used _literally here_, i.e. you are supposed to use ENBALE_LDAP= :) I must admit, I see your point and understand that this is misleading.
Rationale: The script is using equality checks with -eq and -ne, ... based on numbers, which is the proper way. Therefore, your comparison [[ ${ENABLE_LDAP} -ne 1 ]] expands to [[ "''" -ne 1]] which results in syntax error: operand expected (error token is "''"). I did not think of this when updating the script.
I will make sure to update the docs! In the meantime, please use <PROPERTY>= when you'd like to use the default value. This has worked before because the equality checks were different in 7.0.1. I've also made sure to fix the &&. I will open a branch and PR in a few minutes which contain the fix.
I know this is asked much, but could you build the image from this branch and test it? I would be very grateful:)
aendeavor
on 15 Oct 2020
I will make sure to update the docs! In the meantime, please use
<PROPERTY>=when you'd like to use the default value. This has worked before because the equality checks were different in7.0.1. I've also made sure to fix the&&. I will open a branch and PR in a few minutes which contain the fix.
Awesome - thanks. My only comment here is having a valid default value (0 or '') makes configuration management of the file using explicit options easier. It is still possible with empty values but generally requires some "creative" work for those systems. Shouldn't be an issue though.
Should all the other config options be double checked for similar cases?
I know this is asked much, but could you build the image from this branch and test it? I would be very grateful:)
I can report back on this later tonight. I'll try the current container as well as a fresh local build w/ your 5d91ace patch; both with updated configurations.
r-pufky
on 15 Oct 2020
Should all the other config options be double checked for similar cases?
Probably a good idea. Everywhere I could I implemented the equality checks which now lead to this error. Double-checking is always a good idea.
I can report back on this later tonight. I'll try the current container as well as a fresh local build w/ your 5d91ace patch; both with updated configurations.
That's great.
aendeavor
on 15 Oct 2020
7.1.0
I've replaced all environment variables using empty strings to environment variables that are undefined. Dovecot is now starting correctly on the 7.1.0 release:
$ openssl s_client -starttls imap -connect mail.{REDACTED}:993
CONNECTED(00000005)
# ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 2 15:03 ? 00:00:03 /usr/bin/python2 /usr/bin/supervisord -c /etc/supervisor
root 8 1 0 15:03 ? 00:00:00 /bin/bash /usr/local/bin/start-mailserver.sh
root 494 1 0 15:03 ? 00:00:00 /usr/sbin/cron -f
root 496 1 0 15:03 ? 00:00:00 /usr/sbin/rsyslogd -n
opendkim 508 1 0 15:03 ? 00:00:00 /usr/sbin/opendkim -f
opendkim 510 508 0 15:03 ? 00:00:00 /usr/sbin/opendkim -f
opendma+ 516 1 0 15:03 ? 00:00:00 /usr/sbin/opendmarc -f -p inet:8893@localhost -P /var/ru
postgrey 524 1 0 15:03 ? 00:00:00 postgrey --inet=127.0.0.1:10023 --syslog-facility=mail -
root 535 1 0 15:03 ? 00:00:00 /bin/bash /usr/local/bin/check-for-changes.sh
amavis 540 1 0 15:03 ? 00:00:01 /usr/sbin/amavisd-new (master)
root 542 8 0 15:03 ? 00:00:00 tail -fn 0 /var/log/mail/mail.log
postsrsd 558 1 0 15:03 ? 00:00:00 /usr/sbin/postsrsd -f 10001 -r 10002 -d {REDACTED} -s /et
amavis 1183 540 0 15:03 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
amavis 1184 540 0 15:03 ? 00:00:00 /usr/sbin/amavisd-new (virgin child)
root 1565 1 0 15:03 ? 00:00:00 bash /usr/local/bin/postfix-wrapper.sh
root 2029 1 0 15:03 ? 00:00:00 /usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf
dovecot 2054 2029 0 15:03 ? 00:00:00 dovecot/anvil
root 2055 2029 0 15:03 ? 00:00:00 dovecot/log
root 2058 2029 0 15:03 ? 00:00:00 dovecot/config
root 2199 1 0 15:03 ? 00:00:00 /usr/lib/postfix/sbin/master
postfix 2201 2199 0 15:03 ? 00:00:00 pickup -l -t fifo -u -c -o content_filter= -o receive_ov
postfix 2202 2199 0 15:03 ? 00:00:00 qmgr -l -t unix -u
dovecot 2242 2029 0 15:03 ? 00:00:00 dovecot/stats
dovecot 2243 2029 0 15:03 ? 00:00:00 dovecot/auth
root 2355 0 0 15:04 pts/0 00:00:00 /bin/bash
dovenull 2710 2029 0 15:05 ? 00:00:00 dovecot/imap-login
root 2822 1565 0 15:06 ? 00:00:00 sleep 5
root 2830 535 0 15:06 ? 00:00:00 sleep 1
root 2831 2355 0 15:06 pts/0 00:00:00 ps -ef
Note: setting environment variables to undefined also fixed the dovecot dh.pem creation error.
5d91ace
Built and ran the container -- same results as above. Everything is working appropriately.
Note: there were testing validation failures, but I've ignored those to validate the patch is actually working.
r-pufky
on 16 Oct 2020
Very nice.
What testing validation errors did you encounter?
aendeavor
on 16 Oct 2020
What testing validation errors did you encounter?
Unfortunately I don't have the build/testing log anymore. I pulled the branch and built according to the dev instructions. If I recall correctly it was about 4 failing tests.
git clone https://github.com/tomav/docker-mailserver
git pull origin fix-#1647
git submodule init
git submodule update
sudo make
This resulted in the 4 failing tests.
I built the container for testing using
sudo make build
and ran configuration/dovecot testing against this container (tomav/docker-mailserver:testing)
r-pufky
on 16 Oct 2020
I didn't even know there was a :testing tag. But since the test in TravisCI for #1653 seem to finish successfully, I would lean myself out of the window here and say this is because the tests are flawed right now. The PR, when approved, will be merged and this problem is solved. Thanks for noticing this subtle error and for testing it locally!
aendeavor
on 17 Oct 2020
Related issues
dragonito
路
5Comments
nicklayb
路
4Comments
landergate
路
4Comments
jholster
路
4Comments
Dubbeldrank
路
4Comments
Most helpful comment
Awesome - thanks. My only comment here is having a valid default value (0 or '') makes configuration management of the file using explicit options easier. It is still possible with empty values but generally requires some "creative" work for those systems. Shouldn't be an issue though.
Should all the other config options be double checked for similar cases?
I can report back on this later tonight. I'll try the current container as well as a fresh local build w/ your 5d91ace patch; both with updated configurations.