El Capitan Mail.app causes massive load on Cyrus IMAPd server
Hello,
Updating three of our 40 users to El Capitan has caused a service-affecting emergency for the entire company. There is some sort of interop problem here. I admit it could be a misconfiguration of our Cyrus IMAPd server, but we use it successfully with a great number of IMAP client applications, Apple Mail.app included, until that all changed on October 1.
Background:
Cyrus IMAPd maintains three files for each IMAP mailbox:
1. cyrus.header
2. cyrus.index
3. cyrus.cache
These files can grow to be very large (especially the cyrus.cache file)
For some reason, this latest version of Apple Mail seems to get itself into a tight loop talking to our Cyrus IMAPd, causing the cyrus.cache to get repeatedly re-written (or at least written to heavily). With only three employees' IMAPd clients checking their email, the disk sub-system of the IMAP server is almost completely consumed, resulting in high IOWAIT times, terrible performance for all other clients, and even rejection of new incoming connections (because of the extreme load).
Steps to Reproduce:
1. Configure Apple Mail to connect to my email account (which contains a lot of messages, and a lot of folders)
2. Wait until mail check is completed.
3. Open Mail.app's connection doctor, tell it to show detail, and an intense stream of "EXPUNGE, OK Completed" scrolls past.
Expected Results:
We expect to see an idled IMAPd connection once the initial mail check is complete - it should not checking again for 15 minutes as we have configured it do.
Actual Results:
Disk I/O on our IMAPd server is thrashed, and we see the following type of messages repeating over and over in Mail's logs:
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16156.18 OK
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16157.18 EXPUNGE
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16157.18 OK
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16158.18 IDLE
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16158.18 OK
Oct 5 22:06:07 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16159.18 EXPUNGE
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16159.18 OK
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16160.18 IDLE
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16160.18 OK
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16161.18 EXPUNGE
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16161.18 OK
Oct 5 22:06:08 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16162.18 IDLE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16162.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16163.18 EXPUNGE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16163.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16164.18 IDLE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16164.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16165.18 EXPUNGE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16165.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16166.18 IDLE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16166.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16167.18 EXPUNGE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16167.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16168.18 IDLE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16168.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16169.18 EXPUNGE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16169.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16170.18 IDLE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16170.18 OK
Oct 5 22:06:09 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16171.18 EXPUNGE
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16171.18 OK
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16172.18 IDLE
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16172.18 OK
Oct 5 22:06:10 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16173.18 EXPUNGE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16173.18 OK
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16174.18 IDLE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16174.18 OK
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16175.18 EXPUNGE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16175.18 OK
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16176.18 IDLE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: +
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Wrote: DONE
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Idle mailbox=Trash - darren@dazza]> Read: 16176.18 OK
Oct 5 22:06:11 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16177.18 EXPUNGE
Oct 5 22:06:12 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * EXISTS 459
Oct 5 22:06:12 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: * RECENT 9
Oct 5 22:06:12 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Read: 16177.18 OK
Oct 5 22:06:12 Mail[17422] <Debug>: <0x7f8f890c8a30:[Selected mailbox=Trash - darren@dazza]> Wrote: 16178.18 IDLE
There's many thousands of these lines in Mail's syslog.
I'm a bit of a newcomer to Apple's forums, please let me know if there's other information I can provide.
-Darren
Mac Pro (Late 2013), OS X El Capitan (10.11)