[BlueOnyx:21066] Dovecot (IMAP) problems

Thu May 25 11:07:50 -05 2017

Having problems. Dovecot appears to be restarting every couple of 
minutes. I have stopped and restarted IMAP in the GUI, manually killed 
dovecot processes after stopping IMAP in the GUI and completely 
restarted the server by a reboot in the GUI. None of these actions seems 
to help.

While dovecot restarts itself momentary outages and errors like 
"Connection to storage server failed" and "Could not load message from 
server." are causing irritation to Roundcube users.

A section of the mail log when dovecot stops:

> May 25 11:44:55 YYYY dovecot: imap-login: Login: user=<XXXX149>, method=LOGIN, rip=34.208.102.34, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10195, session=<CA0rGltQ9gAi0GYi>
> May 25 11:44:55 YYYY dovecot: imap(XXXX149): Disconnected: Logged out in=198 out=2721
> May 25 11:44:56 YYYY dovecot: imap-login: Login: user=<XXXX210>, method=LOGIN, rip=35.167.5.216, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10196, TLS, session=<D9Y2GltQjAAjpwXY>
> May 25 11:44:56 YYYY dovecot: imap-login: Login: user=<XXXX036>, method=LOGIN, rip=34.208.144.186, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10197, TLS, session=<Fkg2GltQfwAi0JC6>
> May 25 11:44:57 YYYY dovecot: imap-login: Login: user=<XXXX149>, method=LOGIN, rip=34.208.102.34, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10201, session=<lpRRGltQAAAi0GYi>
> May 25 11:44:57 YYYY dovecot: imap-login: Login: user=<XXXX210>, method=LOGIN, rip=35.167.5.216, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10202, TLS, session=<IFZTGltQlQAjpwXY>
> May 25 11:44:57 YYYY dovecot: imap-login: Login: user=<XXXX036>, method=LOGIN, rip=34.208.144.186, lip=ZZ.ZZZ.ZZ.ZZ, mpid=10203, TLS, session=<ZXdUGltQmAAi0JC6>
> May 25 11:44:57 YYYY dovecot: imap(XXXX149): Disconnected: Logged out in=513 out=31486
> May 25 11:44:59 YYYY milter-geoip: Milter-GeoIP disabled. Accepting email  -> .
> May 25 11:44:59 YYYY milter-geoip: Email-Allowance-Check: ACCEPT
> May 25 11:44:59 YYYY sendmail[10206]: v4PFixxr010206: from=<azikiwe at clouded.friendly-viewing-28.club>, size=15202, class=0, nrcpts=1, msgid=<jugging.201705251131.977054 at friendly-viewing-28.club> , proto=ESMTP, daemon=MTA, relay=mail.clickical.win [104.255.99.79]
> May 25 11:44:59 YYYY sendmail[10206]: v4PFixxr010206: Milter add: header: X-Virus-Scanned: clamav-milter 0.99 at YYYY.XXXX.org
> May 25 11:44:59 YYYY sendmail[10206]: v4PFixxr010206: Milter add: header: X-Virus-Status: Clean
> May 25 11:44:59 YYYY spamd[2850]: spamd: got connection over /var/run/spamd.sock
> May 25 11:44:59 YYYY spamd[2850]: spamd: setuid to XXXX036 succeeded
> May 25 11:44:59 YYYY spamd[2850]: spamd: processing message <jugging.201705251131.977054 at friendly-viewing-28.club> for XXXX036:536
> May 25 11:45:00 YYYY spamd[10213]: util: failed to spawn a process "/usr/bin/dccproc, -C, -x, 0, -a, 104.255.99.79, -w, whiteclnt": oops: fileno(STDIN) [12] != 0 at /usr/share/perl5/vendor_perl/Mail/SpamAssassin/Util.pm line 1569, <GEN248> line 345. at /usr/share/perl5/vendor_perl/Mail/SpamAssassin/Util.pm line 1507, <GEN248> line 345.
> May 25 11:45:00 YYYY spamd[2850]: dcc: [10213] finished: exit 6
> May 25 11:45:00 YYYY spamd[2850]: dcc: dccproc failed: failed to read X-DCC header from dccproc
> May 25 11:45:00 YYYY spamd[10214]: util: failed to spawn a process "/usr/bin/pyzor, --homedir, /etc/mail/spamassassin, check": oops: fileno(STDIN) [12] != 0 at /usr/share/perl5/vendor_perl/Mail/SpamAssassin/Util.pm line 1569. at /usr/share/perl5/vendor_perl/Mail/SpamAssassin/Util.pm line 1507.
> May 25 11:45:00 YYYY spamd[2850]: pyzor: [10214] error: exit 6
> May 25 11:45:01 YYYY spamd[2850]: spamd: identified spam (16.1/5.0) for XXXX036:536 in 1.3 seconds, 15953 bytes.
> May 25 11:45:01 YYYY spamd[2850]: spamd: result: Y 16 - BAYES_50,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,MIME_HTML_MOSTLY,MPART_ALT_DIFF,RATS_DYNA,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_BL_SPAMCOP_NET,RCVD_IN_SBL_CSS,RCVD_IN_SORBS_SPAM,SAGREY,SBLXBL_SPAM,SPF_HELO_FAIL scantime=1.3,size=15953,user=XXXX036,uid=536,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/var/run/spamd.sock,mid=<jugging.201705251131.977054 at friendly-viewing-28.club>,bayes=0.500000,autolearn=no autolearn_force=no
> May 25 11:45:01 YYYY sendmail[10206]: v4PFixxr010206: Milter add: header: X-Spam-Flag: YES
> May 25 11:45:01 YYYY sendmail[10206]: v4PFixxr010206: Milter add: header: X-Spam-Status: Yes, score=16.1 required=5.0 tests=BAYES_50,\n\tHTML_FONT_LOW_CONTRAST,HTML_MESSAGE,MIME_HTML_MOSTLY,MPART_ALT_DIFF,RATS_DYNA,\n\tRAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,\n\tRCVD_IN_BL_SPAMCOP_NET,RCVD_IN_SBL_CSS,RCVD_IN_SORBS_SPAM,SAGREY,SBLXBL_SPAM,\n\tSPF_HELO_FAIL autolearn=no autolearn_force=no version=3.4.0
> May 25 11:45:01 YYYY sendmail[10206]: v4PFixxr010206: Milter: data, reject=550 5.7.1 Blocked by SpamAssassin
> May 25 11:45:01 YYYY sendmail[10206]: v4PFixxr010206: to=<myrtle.french at XXXX.org>, delay=00:00:02, pri=45202, stat=Blocked by SpamAssassin
> May 25 11:45:01 YYYY spamd[2546]: prefork: child states: II
> May 25 11:45:01 YYYY dovecot: master: Warning: Killed with signal 15 (by pid=10299 uid=0 code=kill)
> May 25 11:45:01 YYYY dovecot: imap(XXXX274): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX058): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX262): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX267): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX261): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX254): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX041): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX245): Server shutting down. in=18 out=428
> May 25 11:45:01 YYYY dovecot: imap(XXXX267): Server shutting down. in=227 out=1423
> May 25 11:45:01 YYYY dovecot: imap(XXXX058): Server shutting down. in=256 out=12572
> May 25 11:45:01 YYYY dovecot: imap(XXXX254): Server shutting down. in=227 out=971
> May 25 11:45:01 YYYY dovecot: imap(XXXX262): Server shutting down. in=224 out=8993
> May 25 11:45:01 YYYY dovecot: imap(XXXX261): Server shutting down. in=224 out=9406
> May 25 11:45:01 YYYY dovecot: imap(XXXX041): Server shutting down. in=237 out=1142
> May 25 11:45:01 YYYY dovecot: imap(XXXX274): Server shutting down. in=222 out=1638
> May 25 11:45:01 YYYY dovecot: imap(XXXX245): Server shutting down. in=223 out=7084
> May 25 11:45:01 YYYY dovecot: imap(XXXX266): Server shutting down. in=99 out=39684
> May 25 11:45:01 YYYY dovecot: imap(XXXX266): Server shutting down. in=150 out=39818
> May 25 11:45:01 YYYY dovecot: imap(XXXX149): Server shutting down. in=255 out=14047
> May 25 11:45:01 YYYY dovecot: imap(XXXX149): Disconnected: Logged out in=18 out=420
> May 25 11:45:02 YYYY sendmail[10292]: v4PFj1Qp010292: from=root, size=461, class=0, nrcpts=1, msgid=<201705251545.v4PFj1Qp010292 at YYYY.XXXX.org>, relay=root at localhost
> May 25 11:45:02 YYYY sendmail[10466]: STARTTLS=server, relay=localhost.localdomain [127.0.0.1], version=TLSv1/SSLv3, verify=NO, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
> May 25 11:45:02 YYYY sendmail[10292]: STARTTLS=client, relay=[127.0.0.1], version=TLSv1/SSLv3, verify=FAIL, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
> May 25 11:45:02 YYYY milter-geoip: Milter-GeoIP disabled. Accepting email  -> .
> May 25 11:45:02 YYYY milter-geoip: Email-Allowance-Check: ACCEPT
> May 25 11:45:02 YYYY sendmail[10466]: v4PFj2At010466: from=<root at YYYY.XXXX.org>, size=712, class=0, nrcpts=1, msgid=<201705251545.v4PFj1Qp010292 at YYYY.XXXX.org>, proto=ESMTP, daemon=MTA, relay=localhost.localdomain [127.0.0.1]
> May 25 11:45:03 YYYY sendmail[10466]: v4PFj2At010466: Milter add: header: X-Virus-Scanned: clamav-milter 0.99 at YYYY.XXXX.org
> May 25 11:45:03 YYYY sendmail[10466]: v4PFj2At010466: Milter add: header: X-Virus-Status: Clean
> May 25 11:45:03 YYYY sendmail[10292]: v4PFj1Qp010292: to=root, ctladdr=root (0/0), delay=00:00:02, xdelay=00:00:01, mailer=relay, pri=30461, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (v4PFj2At010466 Message accepted for delivery)
> May 25 11:45:03 YYYY sendmail[10469]: v4PFj2At010466: to=admin, ctladdr=<root at YYYY.XXXX.org> (0/0), delay=00:00:01, xdelay=00:00:00, mailer=local, pri=31069, dsn=2.0.0, stat=Sent
> May 25 11:45:07 YYYY dovecot: imap(XXXX036): Server shutting down. in=18 out=428
> May 25 11:45:07 YYYY dovecot: imap(XXXX210): Server shutting down. in=18 out=428
> May 25 11:45:08 YYYY dovecot: imap(XXXX036): Server shutting down. in=268 out=14060
> May 25 11:45:08 YYYY dovecot: imap(XXXX210): Server shutting down. in=228 out=4687
> May 25 11:45:08 YYYY sendmail[9791]: v4PFh2G1009791: from=root, size=400, class=0, nrcpts=1, msgid=<201705251543.v4PFh2G1009791 at YYYY.XXXX.org>, relay=root at localhost
> May 25 11:45:08 YYYY sendmail[10476]: STARTTLS=server, relay=localhost.localdomain [127.0.0.1], version=TLSv1/SSLv3, verify=NO, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
> May 25 11:45:08 YYYY sendmail[9791]: STARTTLS=client, relay=[127.0.0.1], version=TLSv1/SSLv3, verify=FAIL, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
> May 25 11:45:08 YYYY milter-geoip: Milter-GeoIP disabled. Accepting email  -> .
> May 25 11:45:08 YYYY milter-geoip: Email-Allowance-Check: ACCEPT
> May 25 11:45:08 YYYY sendmail[10476]: v4PFj823010476: from=<root at YYYY.XXXX.org>, size=651, class=0, nrcpts=1, msgid=<201705251543.v4PFh2G1009791 at YYYY.XXXX.org>, proto=ESMTP, daemon=MTA, relay=localhost.localdomain [127.0.0.1]
> May 25 11:45:08 YYYY sendmail[10476]: v4PFj823010476: Milter add: header: X-Virus-Scanned: clamav-milter 0.99 at YYYY.XXXX.org
> May 25 11:45:08 YYYY sendmail[10476]: v4PFj823010476: Milter add: header: X-Virus-Status: Clean
> May 25 11:45:08 YYYY sendmail[9791]: v4PFh2G1009791: to=root, ctladdr=root (0/0), delay=00:02:06, xdelay=00:00:00, mailer=relay, pri=30400, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (v4PFj823010476 Message accepted for delivery)
> May 25 11:45:09 YYYY sendmail[10479]: v4PFj823010476: to=admin, ctladdr=<root at YYYY.XXXX.org> (0/0), delay=00:00:01, xdelay=00:00:01, mailer=local, pri=31008, dsn=2.0.0, stat=Sent
> May 25 11:45:22 YYYY sendmail[10485]: v4PFjLsL010485: [200.24.218.202] did not issue MAIL/EXPN/VRFY/ETRN during connection to MTA

The admin user is also receiving mail every few minutes that look like this:

> Cron <root at YYYY> /usr/local/sbin/dfix.sh
> From 	root at YYYY.XXXX.org Add contact
> To 	root at YYYY.XXXX.org Add contact
> Date 	Today 12:02
> Contact photo
> Message Body
> Warning: Dovecot process count = 54 processes
> Stopping Dovecot Imap: [  OK  ]
> dovecot: no process killed
> dovecot-auth: no process killed

Any ideas?