mailcow / mailcow-dockerized

mailcow: dockerized - 🐮 + 🐋 = 💕
https://mailcow.email
GNU General Public License v3.0
9.09k stars 1.19k forks source link

Dovecot auth: Fatal: master: service(auth) #3211

Closed Pitastic closed 4 years ago

Pitastic commented 4 years ago

Please try to answer all questions. If you cannot, don't just delete it. If you completely ignore or remove the whole template, your issue is either closed or ignored, too. :( This is (not only) because we are evil. Many awesome mailcow supporters don't bother to reply to an issue, when crucial information is missing. Especially when it could have been answered by using this issue template. We need as much information as possible. Please post all logs, do not copy that one line you think may be interesting. Copy the whole bunch and remove sensible information. :) Thank you!

Prior to placing the issue, please check following: (fill out each checkbox with a X once done)


Description of the bug: What kind of issue have you exactly come across? Postfix is closing connections because it is unable for a smtp handshake. I figured out that the dovecot auth service failed or timed out.

Reproduction of said bug: How exactly do you reproduce the bug?

I ran into the problem after an update but I reproduced it with a fresh mailcow install:

  1. stop old running mailcow containers and docker volume prune
  2. clone mailcow from git
  3. generateConfig.sh and change the DBPASS, the ports and the domain
  4. docker-compose up -d
  5. Stop after everything is pulled and build docker-compose down
  6. Copy my SSL certs as described here in the docs
  7. Bring it up docker-compose up -d

System information

I used to run mailcow behind a Proxy but I am now running it without a Proxy to keep it simple. I crashed my old installation by running a chmod/chown -R accidently in the mailcow folder :hankey: - now I try to get a fresh install running (first without my backups...). The Postfix-Logline: fatal: no SASL authentication mechanisms led me to a auth failure from dovecot.

Question Answer
My operating system ubuntu 16.04 server (v-server)
Is Apparmor, SELinux or similar active? no
Virtualization technlogy (KVM, VMware, Xen, etc) kvm
Server/VM specifications (Memory, CPU Cores) 4GB RAM, 4cores
Docker Version (docker version) 19.03.5
Docker-Compose Version (docker-compose version) 1.22.0, build f46880fe
Reverse proxy (custom solution) yes - but I do it without, I use my own ssl-certs

Further notes:

I switched off my iptable rules with iptables -P INPUT ALLOW and iptables -P OUTPUT ALLOW

iptables -L -vn : pastebin

ip6tables -L -vn : pastebin

iptables -L -vn -t nat : pastebin

ip6tables -L -vn -t nat : pastebin

General logs:

1. mailcow.conf

# ------------------------------
# mailcow web ui configuration
# ------------------------------
# example.org is _not_ a valid hostname, use a fqdn here.
# Default admin user is "admin"
# Default password is "moohoo"

MAILCOW_HOSTNAME=my.domain.de

# ------------------------------
# SQL database configuration
# ------------------------------

DBNAME=mailcow
DBUSER=mailcow

# Please use long, random alphanumeric strings (A-Za-z0-9)

DBPASS=----MYPASS---
DBROOT=----MYPASS---

# ------------------------------
# HTTP/S Bindings
# ------------------------------

# You should use HTTPS, but in case of SSL offloaded reverse proxies:
# Might be important: This will also change the binding within the container.
# If you use a proxy within Docker, point it to the ports you set below.

HTTP_PORT=80
HTTP_BIND=0.0.0.0

HTTPS_PORT=443
HTTPS_BIND=0.0.0.0

# ------------------------------
# Other bindings
# ------------------------------
# You should leave that alone
# Format: 11.22.33.44:25 or 0.0.0.0:465 etc.
# Do _not_ use IP:PORT in HTTP(S)_BIND or HTTP(S)_PORT

SMTP_PORT=25
SMTPS_PORT=465
SUBMISSION_PORT=587
IMAP_PORT=143
IMAPS_PORT=993
POP_PORT=110
POPS_PORT=995
SIEVE_PORT=4190
DOVEADM_PORT=127.0.0.1:19991
SQL_PORT=127.0.0.1:13306
SOLR_PORT=127.0.0.1:18983

# Your timezone

TZ=Europe/Berlin

# Fixed project name

COMPOSE_PROJECT_NAME=mailcowdockerized

# Set this to "allow" to enable the anyone pseudo user. Disabled by default.
# When enabled, ACL can be created, that apply to "All authenticated users"
# This should probably only be activated on mail hosts, that are used exclusivly by one organisation.
# Otherwise a user might share data with too many other users.
ACL_ANYONE=disallow

# Garbage collector cleanup
# Deleted domains and mailboxes are moved to /var/vmail/_garbage/timestamp_sanitizedstring
# How long should objects remain in the garbage until they are being deleted? (value in minutes)
# Check interval is hourly

MAILDIR_GC_TIME=1440

# Additional SAN for the certificate
#
# You can use wildcard records to create specific names for every domain you add to mailcow.
# Example: Add domains "example.com" and "example.net" to mailcow, change ADDITIONAL_SAN to a value like:
#ADDITIONAL_SAN=imap.*,smtp.*
# This will expand the certificate to "imap.example.com", "smtp.example.com", "imap.example.net", "imap.example.net"
# plus every domain you add in the future.
#
# You can also just add static names...
#ADDITIONAL_SAN=srv1.example.net
# ...or combine wildcard and static names:
#ADDITIONAL_SAN=imap.*,srv1.example.com
#

ADDITIONAL_SAN=

# Skip running ACME (acme-mailcow, Let's Encrypt certs) - y/n

SKIP_LETS_ENCRYPT=n

# Create seperate certificates for all domains - y/n
# this will allow adding more than 100 domains, but some email clients will not be able to connect with alternative hostnames
# see https://wiki.dovecot.org/SSL/SNIClientSupport
ENABLE_SSL_SNI=n

# Skip IPv4 check in ACME container - y/n

SKIP_IP_CHECK=n

# Skip HTTP verification in ACME container - y/n

SKIP_HTTP_VERIFICATION=n

# Skip ClamAV (clamd-mailcow) anti-virus (Rspamd will auto-detect a missing ClamAV container) - y/n

SKIP_CLAMD=n

# Skip Solr on low-memory systems or if you do not want to store a readable index of your mails in solr-vol-1.

SKIP_SOLR=n

# Solr heap size in MB, there is no recommendation, please see Solr docs.
# Solr is a prone to run OOM and should be monitored. Unmonitored Solr setups are not recommended.

SOLR_HEAP=1024

# Enable watchdog (watchdog-mailcow) to restart unhealthy containers (experimental)

USE_WATCHDOG=n

# Allow admins to log into SOGo as email user (without any password)

ALLOW_ADMIN_EMAIL_LOGIN=n

# Send notifications by mail (no DKIM signature, sent from watchdog@MAILCOW_HOSTNAME)
# Can by multiple rcpts, NO quotation marks

#WATCHDOG_NOTIFY_EMAIL=a@example.com,b@example.com,c@example.com
#WATCHDOG_NOTIFY_EMAIL=

# Notify about banned IP (includes whois lookup)
WATCHDOG_NOTIFY_BAN=y

# Max log lines per service to keep in Redis logs

LOG_LINES=9999

# Internal IPv4 /24 subnet, format n.n.n (expands to n.n.n.0/24)

IPV4_NETWORK=172.22.1

# Internal IPv6 subnet in fc00::/7

IPV6_NETWORK=fd4d:6169:6c63:6f77::/64

# Use this IPv4 for outgoing connections (SNAT)

#SNAT_TO_SOURCE=

# Use this IPv6 for outgoing connections (SNAT)

#SNAT6_TO_SOURCE=

# Create or override API key for web ui
# You _must_ define API_ALLOW_FROM, which is a comma separated list of IPs
# API_KEY allowed chars: a-z, A-Z, 0-9, -

#API_KEY=
#API_ALLOW_FROM=172.22.1.1,127.0.0.1

# mail_home is ~/Maildir
MAILDIR_SUB=Maildir

# SOGo session timeout in minutes
SOGO_EXPIRE_SESSION=480

1. Postfix (with a request from mxtoolbox.com)

Attaching to mailcowdockerized_postfix-mailcow_1
postfix-mailcow_1    | 2019-12-11 16:19:01,727 INFO Set uid to user 0 succeeded
postfix-mailcow_1    | 2019-12-11 16:19:01,733 INFO supervisord started with pid 1
postfix-mailcow_1    | 2019-12-11 16:19:02,736 INFO spawned: 'processes' with pid 8
postfix-mailcow_1    | 2019-12-11 16:19:02,740 INFO spawned: 'postfix' with pid 9
postfix-mailcow_1    | 2019-12-11 16:19:02,751 INFO spawned: 'syslog-ng' with pid 10
postfix-mailcow_1    | Uptime: 6  Threads: 8  Questions: 37  Slow queries: 0  Opens: 31  Flush tables: 1  Open tables: 23  Queries per second avg: 6.166
postfix-mailcow_1    | Dec 11 16:19:02 mx syslog-ng[10]: syslog-ng starting up; version='3.19.1'
postfix-mailcow_1    | 2019-12-11 16:19:03,998 INFO success: processes entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | 2019-12-11 16:19:03,998 INFO success: postfix entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | 2019-12-11 16:19:03,998 INFO success: syslog-ng entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | chown: cannot access '/usr/share/man/man1/mailq.1.gz': No such file or directory
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[308]: warning: not owned by root: /opt/postfix/conf/.
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[309]: warning: not owned by root: /opt/postfix/conf/./master.cf
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[310]: warning: not owned by root: /opt/postfix/conf/./main.cf
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[311]: warning: not owned by root: /opt/postfix/conf/./smtp_dsn_filter
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[312]: warning: not owned by root: /opt/postfix/conf/./allow_mailcow_local.regexp
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[313]: warning: not owned by root: /opt/postfix/conf/./postscreen_access.cidr
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[314]: warning: not owned by root: /opt/postfix/conf/./anonymize_headers.pcre
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[315]: warning: not owned by root: /opt/postfix/conf/./local_transport
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[317]: warning: group or other writable: /opt/postfix/conf/.
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[318]: warning: group or other writable: /opt/postfix/conf/./master.cf
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[319]: warning: group or other writable: /opt/postfix/conf/./main.cf
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[320]: warning: group or other writable: /opt/postfix/conf/./smtp_dsn_filter
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[321]: warning: group or other writable: /opt/postfix/conf/./allow_mailcow_local.regexp
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[322]: warning: group or other writable: /opt/postfix/conf/./postscreen_access.cidr
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[323]: warning: group or other writable: /opt/postfix/conf/./anonymize_headers.pcre
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[324]: warning: group or other writable: /opt/postfix/conf/./local_transport
postfix-mailcow_1    | Dec 11 16:19:07 mx postfix/postfix-script[329]: warning: symlink leaves directory: /etc/postfix/./makedefs.out
postfix-mailcow_1    | Dec 11 16:19:08 mx postfix/postfix-script[354]: starting the Postfix mail system
postfix-mailcow_1    | Dec 11 16:19:08 mx postfix/master[356]: daemon started -- version 3.4.7, configuration /opt/postfix/conf
postfix-mailcow_1    | Dec 11 16:21:01 mx postfix/postscreen[363]: cache proxy:btree:/var/lib/postfix/postscreen_cache full cleanup: retained=0 dropped=0 entries
postfix-mailcow_1    | Dec 11 16:21:01 mx postfix/postscreen[363]: CONNECT from [185.234.216.95]:63679 to [172.22.1.9]:25
postfix-mailcow_1    | Dec 11 16:21:10 mx postfix/postscreen[363]: fatal: watchdog timeout
postfix-mailcow_1    | Dec 11 16:21:11 mx postfix/master[356]: warning: process /usr/lib/postfix/sbin/postscreen pid 363 exit status 1
postfix-mailcow_1    | Dec 11 16:21:11 mx postfix/master[356]: warning: /usr/lib/postfix/sbin/postscreen: bad command startup -- throttling
postfix-mailcow_1    | Dec 11 16:22:01 mx whitelist_forwardinghosts: Look up 185.234.216.95 on whitelist, result 200 DUNNO
postfix-mailcow_1    | Dec 11 16:22:11 mx postfix/postscreen[371]: CONNECT from [18.205.72.90]:52877 to [172.22.1.9]:25
postfix-mailcow_1    | Dec 11 16:22:11 mx whitelist_forwardinghosts: Look up 18.205.72.90 on whitelist, result 200 DUNNO
postfix-mailcow_1    | Dec 11 16:22:11 mx postfix/postscreen[371]: HANGUP after 0 from [18.205.72.90]:52877 in tests before SMTP handshake
postfix-mailcow_1    | Dec 11 16:22:11 mx postfix/postscreen[371]: DISCONNECT [18.205.72.90]:52877
postfix-mailcow_1    | Dec 11 16:22:13 mx postfix/dnsblog[389]: addr 18.205.72.90 listed by domain hostkarma.junkemailfilter.com as 127.0.0.1
postfix-mailcow_1    | Dec 11 16:22:13 mx postfix/dnsblog[389]: addr 18.205.72.90 listed by domain hostkarma.junkemailfilter.com as 127.0.1.1
postfix-mailcow_1    | Dec 11 16:22:14 mx postfix/dnsblog[385]: addr 18.205.72.90 listed by domain list.dnswl.org as 127.0.3.1
postfix-mailcow_1    | Dec 11 16:22:24 mx postfix/postscreen[371]: CONNECT from [52.55.244.91]:44369 to [172.22.1.9]:25
postfix-mailcow_1    | Dec 11 16:22:24 mx whitelist_forwardinghosts: Look up 52.55.244.91 on whitelist, result 200 DUNNO
postfix-mailcow_1    | Dec 11 16:22:24 mx postfix/dnsblog[384]: addr 52.55.244.91 listed by domain hostkarma.junkemailfilter.com as 127.0.0.1
postfix-mailcow_1    | Dec 11 16:22:24 mx postfix/dnsblog[384]: addr 52.55.244.91 listed by domain hostkarma.junkemailfilter.com as 127.0.1.1
postfix-mailcow_1    | Dec 11 16:22:25 mx postfix/dnsblog[378]: addr 52.55.244.91 listed by domain list.dnswl.org as 127.0.3.2
postfix-mailcow_1    | Dec 11 16:22:27 mx postfix/postscreen[371]: PASS NEW [52.55.244.91]:44369
postfix-mailcow_1    | Dec 11 16:22:34 mx postfix/smtpd[394]: connect from keeper-us-east-1b.mxtoolbox.com[52.55.244.91]
postfix-mailcow_1    | Dec 11 16:23:04 mx postfix/smtpd[394]: lost connection after CONNECT from keeper-us-east-1b.mxtoolbox.com[52.55.244.91]
postfix-mailcow_1    | Dec 11 16:23:04 mx postfix/smtpd[394]: disconnect from keeper-us-east-1b.mxtoolbox.com[52.55.244.91] commands=0/0
postfix-mailcow_1    | Dec 11 16:23:12 mx postfix/smtps/smtpd[399]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:23:13 mx postfix/smtps/smtpd[399]: Anonymous TLS connection established from unknown[45.82.153.140]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Dec 11 16:23:17 mx postfix/smtps/smtpd[400]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:23:19 mx postfix/smtps/smtpd[400]: Anonymous TLS connection established from unknown[45.82.153.140]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Dec 11 16:23:24 mx postfix/smtps/smtpd[401]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:23:26 mx postfix/smtps/smtpd[401]: Anonymous TLS connection established from unknown[45.82.153.140]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Dec 11 16:23:31 mx postfix/smtps/smtpd[402]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:23:33 mx postfix/smtps/smtpd[399]: fatal: no SASL authentication mechanisms
postfix-mailcow_1    | Dec 11 16:23:34 mx postfix/master[356]: warning: process /usr/lib/postfix/sbin/smtpd pid 399 exit status 1
postfix-mailcow_1    | Dec 11 16:23:34 mx postfix/master[356]: warning: /usr/lib/postfix/sbin/smtpd: bad command startup -- throttling
postfix-mailcow_1    | Dec 11 16:23:34 mx postfix/smtps/smtpd[402]: Anonymous TLS connection established from unknown[45.82.153.140]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Dec 11 16:23:39 mx postfix/smtps/smtpd[400]: fatal: no SASL authentication mechanisms
postfix-mailcow_1    | Dec 11 16:23:40 mx postfix/master[356]: warning: process /usr/lib/postfix/sbin/smtpd pid 400 exit status 1
postfix-mailcow_1    | Dec 11 16:23:46 mx postfix/smtps/smtpd[401]: fatal: no SASL authentication mechanisms
postfix-mailcow_1    | Dec 11 16:23:47 mx postfix/master[356]: warning: process /usr/lib/postfix/sbin/smtpd pid 401 exit status 1
postfix-mailcow_1    | Dec 11 16:23:54 mx postfix/smtps/smtpd[402]: fatal: no SASL authentication mechanisms
postfix-mailcow_1    | Dec 11 16:23:55 mx postfix/master[356]: warning: process /usr/lib/postfix/sbin/smtpd pid 402 exit status 1
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[404]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[406]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[403]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[403]: SSL_accept error from unknown[45.82.153.140]: lost connection
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[403]: lost connection after CONNECT from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[403]: disconnect from unknown[45.82.153.140] commands=0/0
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[407]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[405]: connect from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[407]: SSL_accept error from unknown[45.82.153.140]: lost connection
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[405]: SSL_accept error from unknown[45.82.153.140]: lost connection
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[405]: lost connection after CONNECT from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[405]: disconnect from unknown[45.82.153.140] commands=0/0
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[407]: lost connection after CONNECT from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[407]: disconnect from unknown[45.82.153.140] commands=0/0
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[406]: SSL_accept error from unknown[45.82.153.140]: lost connection
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[406]: lost connection after CONNECT from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[406]: disconnect from unknown[45.82.153.140] commands=0/0
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[404]: SSL_accept error from unknown[45.82.153.140]: lost connection
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[404]: lost connection after CONNECT from unknown[45.82.153.140]
postfix-mailcow_1    | Dec 11 16:24:35 mx postfix/smtps/smtpd[404]: disconnect from unknown[45.82.153.140] commands=0/0

2. Dovecot

Attaching to mailcowdockerized_dovecot-mailcow_1
dovecot-mailcow_1    | Uptime: 3  Threads: 8  Questions: 1  Slow queries: 0  Opens: 17  Flush tables: 1  Open tables: 11  Queries per second avg: 0.333
dovecot-mailcow_1    | Adding user `vmail' to group `tty' ...
dovecot-mailcow_1    | Adding user vmail to group tty
dovecot-mailcow_1    | Done.
dovecot-mailcow_1    | doveconf: Error: t_readlink(/var/run/dovecot/dovecot.conf) failed: readlink() failed: No such file or directory
dovecot-mailcow_1    |   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
dovecot-mailcow_1    |                                  Dload  Upload   Total   Spent    Left  Speed
100   98k  100   98k    0     0   554k      0 --:--:-- --:--:-- --:--:--  554k
dovecot-mailcow_1    | 20_blatspammer.cf
dovecot-mailcow_1    | 70_HS_body.cf
dovecot-mailcow_1    | 70_HS_header.cf
dovecot-mailcow_1    | 2019-12-11 16:19:04,454 INFO Set uid to user 0 succeeded
dovecot-mailcow_1    | 2019-12-11 16:19:04,463 INFO supervisord started with pid 1
dovecot-mailcow_1    | 2019-12-11 16:19:05,466 INFO spawned: 'processes' with pid 110
dovecot-mailcow_1    | 2019-12-11 16:19:05,475 INFO spawned: 'cron' with pid 111
dovecot-mailcow_1    | 2019-12-11 16:19:05,489 INFO spawned: 'dovecot' with pid 112
dovecot-mailcow_1    | 2019-12-11 16:19:05,504 INFO spawned: 'syslog-ng' with pid 113
dovecot-mailcow_1    | [2019-12-11T16:19:05.694594] WARNING: With use-dns(no), dns-cache() will be forced to 'no' too!;
dovecot-mailcow_1    | Dec 11 16:19:05 mx syslog-ng[113]: syslog-ng starting up; version='3.19.1'
dovecot-mailcow_1    | Dec 11 16:19:05 mx dovecot: master: Dovecot v2.3.9 (e7f79df99) starting up for imap, sieve, lmtp, pop3
dovecot-mailcow_1    | 2019-12-11 16:19:06,717 INFO success: processes entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-12-11 16:19:06,717 INFO success: cron entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-12-11 16:19:06,717 INFO success: dovecot entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-12-11 16:19:06,718 INFO success: syslog-ng entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | Dec 11 16:19:35 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:19:35 mx dovecot: auth: Fatal: master: service(auth): child 126 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:19:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:19:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:19:43 mx dovecot: imap-login: Warning: Auth process not responding, delayed sending initial response (greeting): user=<>, rip=89.183.109.56, lip=172.22.1.250, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[131]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[134]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[130]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[135]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[132]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[139]: (vmail) CMD (/usr/local/bin/quarantine_notify.py >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[131]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:20:01 mx CRON[130]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:20:03 mx dovecot: imap-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=127, input bytes=0
dovecot-mailcow_1    | Dec 11 16:20:03 mx dovecot: imap-login: Disconnected: Auth process broken (disconnected before auth was ready, waited 30 secs): user=<>, rip=89.183.109.56, lip=172.22.1.250, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Dec 11 16:20:05 mx dovecot: auth: Fatal: master: service(auth): child 129 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:20:05 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:20:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:20:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:20:35 mx dovecot: auth: Fatal: master: service(auth): child 152 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:20:35 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:20:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:20:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:21:01 mx CRON[157]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:21:01 mx CRON[160]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:21:01 mx CRON[156]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:21:01 mx CRON[162]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:21:01 mx CRON[157]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:21:02 mx CRON[156]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:21:05 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:21:05 mx dovecot: auth: Fatal: master: service(auth): child 155 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:21:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:21:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:21:35 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:21:35 mx dovecot: auth: Fatal: master: service(auth): child 175 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:21:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:21:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[180]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[183]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[179]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[184]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[180]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:22:01 mx CRON[179]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:22:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:22:05 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:22:05 mx dovecot: auth: Fatal: master: service(auth): child 177 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:22:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:22:12 mx CRON[132]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:22:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:22:35 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:22:35 mx dovecot: auth: Fatal: master: service(auth): child 198 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:22:35 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[201]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[202]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[206]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[205]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[202]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:23:01 mx CRON[201]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:23:05 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:23:06 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:23:06 mx dovecot: auth: Fatal: master: service(auth): child 200 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:23:06 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:23:36 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:23:36 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:23:36 mx dovecot: auth: Fatal: master: service(auth): child 219 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:23:36 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:24:01 mx CRON[224]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:24:01 mx CRON[223]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:24:01 mx CRON[226]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:24:01 mx CRON[227]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:24:02 mx CRON[224]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:24:02 mx CRON[223]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:24:06 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:24:06 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:24:06 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:24:06 mx dovecot: auth: Fatal: master: service(auth): child 222 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:24:36 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:24:36 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:24:36 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:24:36 mx dovecot: auth: Fatal: master: service(auth): child 242 killed with signal 9
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[247]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[249]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[246]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[250]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[248]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[257]: (vmail) CMD (/usr/local/bin/maildir_gc.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[248]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[247]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Dec 11 16:25:01 mx CRON[246]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Dec 11 16:25:06 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=119, input bytes=0
dovecot-mailcow_1    | Dec 11 16:25:06 mx dovecot: master: Error: service(auth): Initial status notification not received in 30 seconds, killing the process
dovecot-mailcow_1    | Dec 11 16:25:06 mx dovecot: managesieve-login: Error: auth-client: conn unix:login (pid=112,uid=0): Timeout waiting for handshake from auth server. my pid=122, input bytes=0
dovecot-mailcow_1    | Dec 11 16:25:06 mx dovecot: auth: Fatal: master: service(auth): child 245 killed with signal 9

I read that there is a dovecot bug in 2.3.4 (I think) but I haven't found any problems from mailcow users so maybe that have nothing to do with it.

andryyy commented 4 years ago

Hi, Which kernel are you on?

Pitastic commented 4 years ago

Hey !

cat /proc/version => Linux version 4.4.0-154-generic (buildd@lgw01-amd64-049) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.10) ) #181-Ubuntu SMP Tue Jun 25 05:29:03 UTC 2019

andryyy commented 4 years ago

You need to install the HWE kernel. :)

Pitastic commented 4 years ago

....I read about this some where...could you give me a hint? or is apt upgrade enough? The old kernel comes from the old (june 2019) snapshot i use...good point!

andryyy commented 4 years ago

apt-get update apt-get install --install-recommends -y linux-generic-hwe-16.04 reboot

Pitastic commented 4 years ago

In the end of the day I decided to start with a really fresh ubuntu 16, install the HWE kernel, get mailcow running and restore my data from the backup (made with a broken mailcow installation).

It's working again! :smiley: Unfortunatly we will never know if this was just a kernel but I think you were right. I did the HWE update in one of my tries but fail at another problem (mysql password e.g.).

Thanks for your quick reply - you gave me a very nice community support :+1:

andryyy commented 4 years ago

You are welcome