Issue Intermittent Email Connection

[stvnthomas]

Really scratching my head on this and would appreciate any help.

Running CentOS 7.4, Plesk 17.5.3 #42, Postfix + Dovecot.

Our clients have started having intermittent connection errors the last few days; it only seems to be affecting email IMAP/POP/SMTP. Email will work fine then suddenly timeout before rectifying itself a few minutes later. This is happens a dozen times a day with multiple subscriptions across several different networks and internet providers.

Usually the timeout results in the email client reporting the email server isn't responding but I've gotten 'sign-in failed, enter your password' and 'The server returned the error: An SSL error has occurred and a secure connection to the server cannot be made'. Im guessing these all have to do with the connection being dropped while securing the connection or logging in.

The server/mail is secured with a LE certificate. I renewed it just in case but it doesn't seem to have made a difference.

None of the clients are in Fail2Ban (we're experiencing the issue too and we're whitelisted). I checked /var/log/maillog but don't see any unusual activity and I'm not seeing the failed connections. 'plesk repair mail' didn't report any problems.

Probably unrelated and an undocumented change but we're running multiple instances of Plesk and all are missing the "What to do with mail for non-existent users/bounce/forward/reject" section of the domain mail settings.

 

[stvnthomas]

Problem is happening with IMAP, POP and SMTP. I've enabled debugging for postfix and dovecot; first works, second times out. The connection just...stops working.

Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read finished A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: pop3-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [m.y.i.p]
Mar  6 16:58:00 web1 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=pop3#011secured#011session=m/b8DMhmH/JKPhaK#011lip=192.168.100.247#011rip=m.y.i.p#011lport=995#011rport=61983#011local_name=mail.example.com#011resp=<hidden>
Mar  6 16:58:00 web1 dovecot: auth: Debug: plesk(user@example.com,m.y.i.p,<m/b8DMhmH/JKPhaK>): Found mail account for user='user@example.com': scheme='PLAIN' address='user@example.com'
Mar  6 16:58:00 web1 dovecot: auth: Debug: plesk(user@example.com,m.y.i.p,<m/b8DMhmH/JKPhaK>): Valid Maildir found for user='user@example.com' at '/var/qmail/mailnames/example.com/user/Maildir'
Mar  6 16:58:00 web1 dovecot: pop3-login: Login: user=<user@example.com>, method=PLAIN, rip=m.y.i.p, lip=192.168.100.247, mpid=41263, TLS, session=<m/b8DMhmH/JKPhaK>
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Loading modules from directory: /usr/libexec/dovecot/modules
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Module loaded: /usr/libexec/dovecot/modules/lib10_quota_plugin.so
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Effective uid=30, gid=31, home=/var/qmail/mailnames/example.com/user
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Quota root: name=User quota backend=maildir args=
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Quota grace: root=User quota bytes=0
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Namespace inbox: type=private, prefix=INBOX., sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/qmail/mailnames/example.com/user/Maildir
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: maildir++: root=/var/qmail/mailnames/example.com/user/Maildir, index=, indexpvt=, control=, inbox=/var/qmail/mailnames/example.com/user/Maildir, alt=
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: Namespace : type=private, prefix=, sep=, inbox=no, hidden=yes, list=no, subscriptions=no location=fail::LAYOUT=none
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: quota: quota_over_flag check: STORAGE ret=0 value=26844 limit=0
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: quota: quota_over_flag check: MESSAGE ret=0 value=96 limit=0
Mar  6 16:58:00 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Debug: quota: quota_over_flag=0((null)) vs currently overquota=0
Mar  6 16:58:01 web1 dovecot: service=pop3, user=user@example.com, ip=[m.y.i.p]. Disconnected: Logged out rcvd=29, sent=104, top=0/0, retr=0/0, del=0/95, size=27853149

Mar  6 16:58:01 web1 dovecot: pop3-login: Debug: SSL alert: close notify [m.y.i.p]
Mar  6 16:58:54 web1 dovecot: pop3-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [m.y.i.p]
Mar  6 16:58:54 web1 dovecot: pop3-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [m.y.i.p]
Mar  6 16:58:54 web1 dovecot: pop3-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [m.y.i.p]
Mar  6 16:59:54 web1 dovecot: pop3-login: Disconnected (no auth attempts in 60 secs): user=<>, rip=m.y.i.p, lip=192.168.100.247, TLS handshaking: Disconnected, session=<DyvAE8hm4vJKPhaK>