Dovecot Immediate Connection Closed

The name of the pictureThe name of the pictureThe name of the pictureClash Royale CLAN TAG#URR8PPP











up vote
1
down vote

favorite












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



debian email postfix dovecot




share|improve this question





















  • Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
    – roaima
    Jun 21 at 23:07










  • @roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
    – JoshQuake
    Jun 22 at 5:02










  • Added output to OP.
    – JoshQuake
    Jun 22 at 6:06














up vote
1
down vote

favorite












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



debian email postfix dovecot




share|improve this question





















  • Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
    – roaima
    Jun 21 at 23:07










  • @roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
    – JoshQuake
    Jun 22 at 5:02










  • Added output to OP.
    – JoshQuake
    Jun 22 at 6:06












up vote
1
down vote

favorite









up vote
1
down vote

favorite











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



debian email postfix dovecot




share|improve this question













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




debian email postfix dovecot





share|improve this question












share|improve this question




share|improve this question








edited Jun 22 at 6:06
























asked Jun 21 at 12:42









JoshQuake

286




286











  • Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
    – roaima
    Jun 21 at 23:07










  • @roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
    – JoshQuake
    Jun 22 at 5:02










  • Added output to OP.
    – JoshQuake
    Jun 22 at 6:06
















  • Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
    – roaima
    Jun 21 at 23:07










  • @roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
    – JoshQuake
    Jun 22 at 5:02










  • Added output to OP.
    – JoshQuake
    Jun 22 at 6:06















Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
– roaima
Jun 21 at 23:07




Dovecot doesn't serve SMTP. Have you actually got anything listening for SMTP?
– roaima
Jun 21 at 23:07












@roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
– JoshQuake
Jun 22 at 5:02




@roaima postfix is supposed to be listening for smtp, right? It's running, but I'm not getting any responses in the logs except for when I restart postfix. No errors.
– JoshQuake
Jun 22 at 5:02












Added output to OP.
– JoshQuake
Jun 22 at 6:06




Added output to OP.
– JoshQuake
Jun 22 at 6:06










2 Answers
2






active

oldest

votes

















up vote
1
down vote



accepted










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.






share|improve this answer





















  • I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
    – JoshQuake
    Jun 22 at 6:09










  • Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
    – roaima
    Jun 22 at 8:05










  • Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
    – JoshQuake
    Jun 22 at 11:33






  • 1




    Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
    – JoshQuake
    Jun 22 at 12:44

















up vote
0
down vote













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






share|improve this answer





















  • Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
    – JoshQuake
    Jun 21 at 21:04










Your Answer







StackExchange.ready(function()
var channelOptions =
tags: "".split(" "),
id: "106"
;
initTagRenderer("".split(" "), "".split(" "), channelOptions);

StackExchange.using("externalEditor", function()
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled)
StackExchange.using("snippets", function()
createEditor();
);

else
createEditor();

);

function createEditor()
StackExchange.prepareEditor(
heartbeatType: 'answer',
convertImagesToLinks: false,
noModals: false,
showLowRepImageUploadWarning: true,
reputationToPostImages: null,
bindNavPrevention: true,
postfix: "",
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
);



);








 

draft saved


draft discarded


















StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2funix.stackexchange.com%2fquestions%2f451091%2fdovecot-immediate-connection-closed%23new-answer', 'question_page');

);

Post as a guest

















2 Answers
2






active

oldest

votes








2 Answers
2






active

oldest

votes









active

oldest

votes






active

oldest

votes








up vote
1
down vote



accepted










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.






share|improve this answer





















  • I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
    – JoshQuake
    Jun 22 at 6:09










  • Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
    – roaima
    Jun 22 at 8:05










  • Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
    – JoshQuake
    Jun 22 at 11:33






  • 1




    Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
    – JoshQuake
    Jun 22 at 12:44














up vote
1
down vote



accepted










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.






share|improve this answer





















  • I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
    – JoshQuake
    Jun 22 at 6:09










  • Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
    – roaima
    Jun 22 at 8:05










  • Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
    – JoshQuake
    Jun 22 at 11:33






  • 1




    Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
    – JoshQuake
    Jun 22 at 12:44












up vote
1
down vote



accepted







up vote
1
down vote



accepted






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.






share|improve this answer













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.







share|improve this answer













share|improve this answer



share|improve this answer











answered Jun 22 at 6:01









roaima

39.2k544105




39.2k544105











  • I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
    – JoshQuake
    Jun 22 at 6:09










  • Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
    – roaima
    Jun 22 at 8:05










  • Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
    – JoshQuake
    Jun 22 at 11:33






  • 1




    Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
    – JoshQuake
    Jun 22 at 12:44
















  • I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
    – JoshQuake
    Jun 22 at 6:09










  • Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
    – roaima
    Jun 22 at 8:05










  • Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
    – JoshQuake
    Jun 22 at 11:33






  • 1




    Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
    – JoshQuake
    Jun 22 at 12:44















I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
– JoshQuake
Jun 22 at 6:09




I'm pretty sure that was someone else trying to bruteforce connect. I saw weird login attempts with simple password attempts in previous logs. The port I'm trying to connect to is 587 with and without SPA. I tried port 25 for the hell of it and that didnt work either.
– JoshQuake
Jun 22 at 6:09












Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
– roaima
Jun 22 at 8:05




Then you've got nothing in your log demonstrating an attempt from your client to connect to either 587 or 25.
– roaima
Jun 22 at 8:05












Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
– JoshQuake
Jun 22 at 11:33




Yeah that's my confusion. I've left it running for a day now so I'll pull the logs and dig through see if there's a consistent delay between when I try to connect and when postfix finally pipes up.
– JoshQuake
Jun 22 at 11:33




1




1




Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
– JoshQuake
Jun 22 at 12:44




Jesus... I'm an idiot. My VPN was connected this whole time and it was blocking the outgoing port. Marking this as the answer because you were right, no request was even being sent.
– JoshQuake
Jun 22 at 12:44












up vote
0
down vote













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






share|improve this answer





















  • Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
    – JoshQuake
    Jun 21 at 21:04














up vote
0
down vote













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






share|improve this answer





















  • Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
    – JoshQuake
    Jun 21 at 21:04












up vote
0
down vote










up vote
0
down vote









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






share|improve this answer













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







share|improve this answer













share|improve this answer



share|improve this answer











answered Jun 21 at 12:54









Kondybas

47827




47827











  • Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
    – JoshQuake
    Jun 21 at 21:04
















  • Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
    – JoshQuake
    Jun 21 at 21:04















Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
– JoshQuake
Jun 21 at 21:04




Old comment was irrelevant. Setting Dovecot to performance didn't change anything by the looks of it. Still not attempting to connect to SMTP.
– JoshQuake
Jun 21 at 21:04












 

draft saved


draft discarded


























 


draft saved


draft discarded














StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2funix.stackexchange.com%2fquestions%2f451091%2fdovecot-immediate-connection-closed%23new-answer', 'question_page');

);

Post as a guest
































































-

Popular posts from this blog

How to check contact read email or not when send email to Individual?

Image
Clash Royale CLAN TAG #URR8PPP up vote 1 down vote favorite I'm using WordPress 4.9.8, CiviCRM to 5.5.1, I usually send email to contact by Search> Find contacts View contact details Action> Send email Send email ok, Contact received mail ok like picture But status only Email sent though contact read email or not. So, can CiviCRM can change status to Email read when contact read email? wordpress email share | improve this question asked Sep 26 at 0:12 ToanLuong 49 9 add a comment  |  up vote 1 down vote favorite I'm using WordPress 4.9.8, CiviCRM to 5.5.1, I usually send email to contact by Search> Find contacts View contact details Action> Send email Send email ok, Contact received mail ok like picture But status only Email sent though contact read email or not. So, can CiviCRM can change status to Email read when contact read email? wordpress email share | improve this questi...
Read more

Displaying single band from multi-band raster using QGIS

Image
Clash Royale CLAN TAG #URR8PPP 1 How can I extract a single band from multi-band raster in QGIS? I have an remote sensed image which has 6 bands (including NDVI band), I want to display each band separately, but have no idea how to do. I have seen some questions similar here but none worked for me. The original image (has 6 bands) is: I want to display the band 6 which should be like this: But I tried gdal_translate, and couldn't get the correct result. What I have got is: qgis raster multi-band share | improve this question edited Mar 5 at 0:53 Summer asked Mar 4 at 6:42 Summer Summer 23 6 Is this any help gis.stackexchange.com/questions/220658/… ? if not gis.stackexchange.com/questions/62133/… might help. – Michael Stimson Mar 4 at 6:46 Thanks for answering but when I used gdal_translate, qgis showed that 'Error 4: Kayena.tif: No such file or directory". Would you know how to fi...
Read more

How many registers does an x86_64 CPU actually have?

Image
Clash Royale CLAN TAG #URR8PPP up vote 2 down vote favorite I am currently learning reverse engineering and am studying the flags register. I had in my mind that rflags was just another name for one of the 16 general purpose registers, for example rax or rbx . But it looks like rflags is actually an additional register. So that makes 17 registers in total... how many more could there be? I have spent at least an hour on this and found numerous different answers. The best answer so far is this, which says that there are 40 registers in total. 16 General Purpose Registers 2 Status Registers 6 Code Segment Registers 16 SSE Registers 8 FPU/MMX Registers But if I add that up, I get 48. Could anybody provide an official answer on how many registers an x86_64 CPU has (e.g. an Intel i7). Additionally, I have seen references to 'hardware' and 'architectural' registers. What are those registers and how many are there? register x86-64 share | improve this...
Read more