mjhjmtu

I've set up a mail server following https://thomas-leister.de/en/mailserver-debian-stretch/ and when trying to connect a client (Outlook 365) it's unable to connect to the SMTP server. Checking mail.log with full Dovecot verbosity it looks like it's authenticating IMAP then immediately closing the connection.

Here's my mail.log when attempting to connect client just once.

Jun 21 07:53:50 mail dovecot: master: Warning: Killed with signal 15 (by pid=10163 uid=0 code=kill)
Jun 21 07:53:50 mail dovecot: imap(Josh@mysite.ca): Server shutting down. in=152 out=2220
Jun 21 07:53:50 mail dovecot: master: Dovecot v2.2.27 (c0f36b0) starting up for imap, lmtp, sieve (core dumps disabled)
Jun 21 07:53:56 mail postfix[10184]: Postfix is running with backwards-compatible default settings
Jun 21 07:53:56 mail postfix[10184]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jun 21 07:53:56 mail postfix[10184]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Jun 21 07:53:56 mail postfix/postfix-script[10190]: stopping the Postfix mail system
Jun 21 07:53:56 mail postfix/master[5066]: terminating on signal 15
Jun 21 07:53:56 mail postfix[10253]: Postfix is running with backwards-compatible default settings
Jun 21 07:53:56 mail postfix[10253]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jun 21 07:53:56 mail postfix[10253]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Jun 21 07:53:57 mail postfix/postfix-script[10352]: starting the Postfix mail system
Jun 21 07:53:57 mail postfix/master[10354]: daemon started -- version 3.1.8, configuration /etc/postfix
Jun 21 07:54:00 mail dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Jun 21 07:54:00 mail dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Jun 21 07:54:00 mail dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Jun 21 07:54:00 mail dovecot: auth: Debug: auth client connected (pid=10359)
Jun 21 07:54:00 mail dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=g4gzkiVv7OesUygU#011lip=208.146.44.129#011rip=172.83.40.20#011lport=993#011rport=59372#011local_name=imap.mysite.ca#011resp=AEpvc2hAandha2UuY2EAMXBPb3AyVFQ= (previous base64 data may contain sensitive data)
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: sql(josh@mysite.ca,172.83.40.20,<g4gzkiVv7OesUygU>): query: SELECT username AS user, domain, password FROM accounts WHERE username = 'josh' AND domain = 'mysite.ca' and enabled = true;
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: sql(josh@mysite.ca,172.83.40.20,<g4gzkiVv7OesUygU>): username changed josh@mysite.ca -> Josh
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: sql(Josh,172.83.40.20,<g4gzkiVv7OesUygU>): username changed Josh -> Josh@mysite.ca
Jun 21 07:54:00 mail dovecot: auth: Debug: sql(josh@mysite.ca,172.83.40.20,<g4gzkiVv7OesUygU>): username changed josh@mysite.ca -> Josh@mysite.ca
Jun 21 07:54:00 mail dovecot: auth: Debug: sql(Josh@mysite.ca,172.83.40.20,<g4gzkiVv7OesUygU>): username changed Josh@mysite.ca -> Josh
Jun 21 07:54:00 mail dovecot: auth: Debug: sql(Josh,172.83.40.20,<g4gzkiVv7OesUygU>): username changed Josh -> Josh@mysite.ca
Jun 21 07:54:00 mail dovecot: auth: Debug: client passdb out: OK#0111#011user=Josh@mysite.ca
Jun 21 07:54:00 mail dovecot: auth: Debug: master in: REQUEST#0111298792449#01110359#0111#011eea41cbba6c921b40a93a702989eed61#011session_pid=10363#011request_auth_token
Jun 21 07:54:00 mail dovecot: auth-worker(10362): Debug: sql(Josh@mysite.ca,172.83.40.20,<g4gzkiVv7OesUygU>): SELECT concat('*:storage=', quota, 'M') AS quota_rule FROM accounts WHERE username = 'Josh' AND domain = 'mysite.ca' AND sendonly = false;
Jun 21 07:54:00 mail dovecot: auth: Debug: master userdb out: USER#0111298792449#011Josh@mysite.ca#011quota_rule=*:storage=2048M#011auth_token=6716f415ff804ba96add892baeeaecff7f0592cd
Jun 21 07:54:00 mail dovecot: imap-login: Login: user=<Josh@mysite.ca>, method=PLAIN, rip=172.83.40.20, lip=208.146.44.129, mpid=10363, TLS, session=<g4gzkiVv7OesUygU>
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Loading modules from directory: /usr/lib/dovecot/modules
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib90_antispam_plugin.so
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Added userdb setting: plugin/quota_rule=*:storage=2048M
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Effective uid=1001, gid=1001, home=/var/vmail/mailboxes/mysite.ca/Josh
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Quota root: name=User quota backend=maildir args=
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Quota grace: root=User quota bytes=214748364 (10%)
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: fs: root=/var/vmail/mailboxes/mysite.ca/Josh/mail, index=, indexpvt=, control=, inbox=/var/vmail/mailboxes/mysite.ca/Josh/mail, alt=
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag check: STORAGE ret=1 value=0 limit=2097152
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag check: MESSAGE ret=0 value=0 limit=0
Jun 21 07:54:00 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag=0((null)) vs currently overquota=0
Jun 21 07:54:33 mail dovecot: auth: Debug: auth client connected (pid=10381)
Jun 21 07:54:34 mail dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=vIIvlCVv8eesUygU#011lip=208.146.44.129#011rip=172.83.40.20#011lport=143#011rport=59377#011local_name=mail.mysite.ca#011resp=AEpvc2hAandha2UuY2EAMXBPb3AyVFQ= (previous base64 data may contain sensitive data)
Jun 21 07:54:34 mail dovecot: auth-worker(10362): Debug: sql(josh@mysite.ca,172.83.40.20,<vIIvlCVv8eesUygU>): query: SELECT username AS user, domain, password FROM accounts WHERE username = 'josh' AND domain = 'mysite.ca' and enabled = true;
Jun 21 07:54:34 mail dovecot: auth-worker(10362): Debug: sql(josh@mysite.ca,172.83.40.20,<vIIvlCVv8eesUygU>): username changed josh@mysite.ca -> Josh
Jun 21 07:54:34 mail dovecot: auth-worker(10362): Debug: sql(Josh,172.83.40.20,<vIIvlCVv8eesUygU>): username changed Josh -> Josh@mysite.ca
Jun 21 07:54:34 mail dovecot: auth: Debug: sql(josh@mysite.ca,172.83.40.20,<vIIvlCVv8eesUygU>): username changed josh@mysite.ca -> Josh@mysite.ca
Jun 21 07:54:34 mail dovecot: auth: Debug: sql(Josh@mysite.ca,172.83.40.20,<vIIvlCVv8eesUygU>): username changed Josh@mysite.ca -> Josh
Jun 21 07:54:34 mail dovecot: auth: Debug: sql(Josh,172.83.40.20,<vIIvlCVv8eesUygU>): username changed Josh -> Josh@mysite.ca
Jun 21 07:54:34 mail dovecot: auth: Debug: client passdb out: OK#0111#011user=Josh@mysite.ca
Jun 21 07:54:34 mail dovecot: auth: Debug: master in: REQUEST#0111986658305#01110381#0111#0114a81a655e2fd95775a69d67377032381#011session_pid=10382#011request_auth_token
Jun 21 07:54:34 mail dovecot: auth-worker(10362): Debug: sql(Josh@mysite.ca,172.83.40.20,<vIIvlCVv8eesUygU>): SELECT concat('*:storage=', quota, 'M') AS quota_rule FROM accounts WHERE username = 'Josh' AND domain = 'mysite.ca' AND sendonly = false;
Jun 21 07:54:34 mail dovecot: auth: Debug: master userdb out: USER#0111986658305#011Josh@mysite.ca#011quota_rule=*:storage=2048M#011auth_token=345528122fb785f133c083192ec59c03663f0b95
Jun 21 07:54:34 mail dovecot: imap-login: Login: user=<Josh@mysite.ca>, method=PLAIN, rip=172.83.40.20, lip=208.146.44.129, mpid=10382, TLS, session=<vIIvlCVv8eesUygU>
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Loading modules from directory: /usr/lib/dovecot/modules
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Module loaded: /usr/lib/dovecot/modules/lib90_antispam_plugin.so
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Added userdb setting: plugin/quota_rule=*:storage=2048M
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Effective uid=1001, gid=1001, home=/var/vmail/mailboxes/mysite.ca/Josh
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Quota root: name=User quota backend=maildir args=
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Quota grace: root=User quota bytes=214748364 (10%)
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: fs: root=/var/vmail/mailboxes/mysite.ca/Josh/mail, index=, indexpvt=, control=, inbox=/var/vmail/mailboxes/mysite.ca/Josh/mail, alt=
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag check: STORAGE ret=1 value=0 limit=2097152
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag check: MESSAGE ret=0 value=0 limit=0
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Debug: quota: quota_over_flag=0((null)) vs currently overquota=0
Jun 21 07:54:34 mail dovecot: imap(Josh@mysite.ca): Connection closed (IDLE running for 0.001 + waiting input for 0.001 secs, 2 B in + 10+10 B out, state=wait-input) in=11 out=372
Jun 21 07:57:10 mail postfix/postscreen[10463]: CONNECT from [185.234.218.188]:64778 to [208.146.44.129]:25
Jun 21 07:57:10 mail postfix/postscreen[10463]: PREGREET 11 after 0.16 from [185.234.218.188]:64778: EHLO Userrn
Jun 21 07:57:10 mail postfix/postscreen[10463]: DISCONNECT [185.234.218.188]:64778
Jun 21 07:58:51 mail dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Jun 21 07:58:51 mail dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Jun 21 07:58:51 mail dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Jun 21 07:58:51 mail dovecot: auth: Debug: auth client connected (pid=10530)
Jun 21 08:01:52 mail dovecot: imap-login: Disconnected: Inactivity (no auth attempts in 181 secs): user=<>, rip=92.63.193.40, lip=208.146.44.129, TLS, session=<4VNJriVvVWVcP8Eo>

Every now and again when inactive I will get

Jun 21 08:17:12 mail dovecot: auth: Debug: sql(Josh@mysite.ca,92.63.193.40,<KGX85CVv3MlcP8Eo>): username changed Josh@mysite.ca -> Josh
Jun 21 08:17:12 mail dovecot: auth: Debug: sql(Josh,92.63.193.40,<KGX85CVv3MlcP8Eo>): username changed Josh -> Josh@mysite.ca
Jun 21 08:17:14 mail dovecot: auth: Debug: client passdb out: FAIL#0111#011user=Josh@mysite.ca#011original_user=josh@mysite.ca
Jun 21 08:17:14 mail dovecot: imap-login: Debug: Ignoring unknown passdb extra field: original_user
Jun 21 08:17:25 mail dovecot: imap-login: Disconnected (auth failed, 1 attempts in 16 secs): user=<Josh@mysite.ca>, method=PLAIN, rip=92.63.193.40, lip=208.146.44.129, TLS, session=<KGX85CVv3MlcP8Eo>

Right now I'm not sure where to go from here. Let me know if more logs or configs are required.

Server settings in Outlook:

Incoming: mail.mysite.ca port 143 STARTTLS
Outgoing: mail.mysite.ca port 587 STARTTLS

EDIT1:

I noticed when postfix shows in the log it's trying to connect on port 25 I think? It rarely appears in the log. Trying port 25 on outlook doesn't work.

Nevermind looking it up it's normal for pregreet to be on port 25.

EDIT2:

Setting dovecot to performance didn't seem to change anything.

EDIT3:

netstat: Looks like my server is listening on port 25 and 587, right?

Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 0.0.0.0:143 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:53 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:7832 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:25 0.0.0.0:* LISTEN
tcp 0 0 208.146.44.129:25 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:8953 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:4190 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:993 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:11332 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:11333 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:11334 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:3306 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:587 0.0.0.0:* LISTEN
tcp 0 0 208.146.44.129:587 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:6379 0.0.0.0:* LISTEN
tcp6 0 0 :::143 :::* LISTEN
tcp6 0 0 :::80 :::* LISTEN
tcp6 0 0 :::7832 :::* LISTEN
tcp6 0 0 ::1:25 :::* LISTEN
tcp6 0 0 ::1:8953 :::* LISTEN
tcp6 0 0 :::443 :::* LISTEN
tcp6 0 0 :::4190 :::* LISTEN
tcp6 0 0 :::993 :::* LISTEN
tcp6 0 0 ::1:11332 :::* LISTEN
tcp6 0 0 ::1:11333 :::* LISTEN
tcp6 0 0 ::1:11334 :::* LISTEN
tcp6 0 0 ::1:587 :::* LISTEN
udp 0 0 0.0.0.0:21902 0.0.0.0:*
udp 0 0 127.0.0.1:53 0.0.0.0:*
udp 0 0 0.0.0.0:26738 0.0.0.0:*

EDIT4: netstat -nap | awk 'NR<3 || /:25/ || /:587/'

Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 127.0.0.1:25 0.0.0.0:* LISTEN 814/master
tcp 0 0 208.146.44.129:25 0.0.0.0:* LISTEN 814/master
tcp 0 0 127.0.0.1:587 0.0.0.0:* LISTEN 814/master
tcp 0 0 208.146.44.129:587 0.0.0.0:* LISTEN 814/master
tcp6 0 0 ::1:25 :::* LISTEN 814/master
tcp6 0 0 ::1:587 :::* LISTEN 814/master

Here, an SMTP client is speaking before it's been spoken to:

Jun 21 07:57:10 mail postfix/postscreen[10463]: CONNECT from [185.234.218.188]:64778 to [208.146.44.129]:25
Jun 21 07:57:10 mail postfix/postscreen[10463]: PREGREET 11 after 0.16 from [185.234.218.188]:64778: EHLO Userrn
Jun 21 07:57:10 mail postfix/postscreen[10463]: DISCONNECT [185.234.218.188]:64778

This is in violation of the protocol and so the connection is dropped. And possibly even blacklisted for a short while.

Your client should really be talking - with authentication - on 587, not on 25.

Dovecot's imap-login can be configured in two ways: for maximum security and for maximum performance. When configured for security each connection used its own process until disconnection. If limit of possible forked processes reached no new connection will be accepted. When configured for performance all incoming connections are served by single imap-login process that has no limits for the number of simultaneous connections. "Maximum security" does not means that performant setup is insecure but rather secure setup is paranoid. Therefore you can easily configure your dovecot for performance:

service imap-login 
 inet_listener imap 
 port = 143
 
 service_count = 0 ## 0 for performance, 1 for security
 process_min_avail = 1

Further reading can be found here: https://wiki.dovecot.org/LoginProcess