Hi, I think I hit a rare infinite loop somewhere in the seendb processing code of cyrus-imapd-2.2.3, during which an imapd process takes 99% CPU cycles and keep accessing the hard disk and updating the user seendb. I cannot reproduce the problem. So I can only describe what I was doing.
I was experimenting to migrate an imap folder from UW-IMAP to Cyrus IMAP v2.2.3 on Red Hat Linux 9, with both IMAP servers running on different IP addresses of the same machine. First, I accessed an Cyrus IMAP account "wenzhuo" using Mozilla Mail and kept it open. Then I deleted the IMAP account and recreated it immediately. After that, I tried to run the migration script. No sooner had I started the script, did I notice the significant slowdown of the system. The system exhibits the following symptoms: 1. One Cyrus imap process eats 99% CPU cycles. 2. vmstat shows several block writes per second (bi) and around 200 block reads per second (bo), and around 130 interrupts per second. 3. The timestamp of the flat seendb file wenzhuo.seen kept changing. Here is the system log of the misbehaving process during its lifetime: ------------------------------------------------------------------------ May 21 17:56:45 matrix master[15715]: about to exec /usr/lib/cyrus-imapd/imapd May 21 17:56:45 matrix imap[15715]: executed May 21 17:58:30 matrix imap[15715]: accepted connection May 21 17:58:30 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:30 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:30 matrix imap[15715]: open: user wenzhuo opened INBOX May 21 17:58:32 matrix imap[15715]: accepted connection May 21 17:58:32 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:32 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:32 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:33 matrix imap[15715]: accepted connection May 21 17:58:34 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:34 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:34 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:34 matrix imap[15715]: accepted connection May 21 17:58:34 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:34 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:34 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:35 matrix imap[15715]: accepted connection May 21 17:58:35 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:35 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:35 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:37 matrix imap[15715]: accepted connection May 21 17:58:37 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:37 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:37 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:38 matrix imap[15715]: accepted connection May 21 17:58:38 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:38 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:38 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:39 matrix imap[15715]: accepted connection May 21 17:58:39 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:39 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:40 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:41 matrix imap[15715]: accepted connection May 21 17:58:41 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:41 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:41 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:42 matrix imap[15715]: accepted connection May 21 17:58:42 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:42 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:42 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:43 matrix imap[15715]: accepted connection May 21 17:58:43 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:43 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:43 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:44 matrix imap[15715]: accepted connection May 21 17:58:44 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:44 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:44 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:46 matrix imap[15715]: accepted connection May 21 17:58:46 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:46 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:46 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:47 matrix imap[15715]: accepted connection May 21 17:58:47 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:47 matrix imap[15715]: open: user wenzhuo opened sent-mail May 21 17:58:47 matrix imap[15715]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 17:58:49 matrix imap[15715]: accepted connection May 21 17:58:49 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:49 matrix imap[15715]: open: user wenzhuo opened &XfJT0ZABkK5O9g- May 21 17:58:50 matrix imap[15715]: accepted connection May 21 17:58:50 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 17:58:50 matrix imap[15715]: open: user wenzhuo opened spam May 21 17:59:50 matrix imap[15715]: accepted connection May 21 17:59:51 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] cyrus plaintext May 21 18:00:21 matrix imap[15715]: accepted connection May 21 18:00:21 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:21 matrix imap[15715]: IOERROR: stating /var/lib/imap/user/w/wenzhuo.seen: No such file or directory May 21 18:00:21 matrix imap[15715]: DBERROR: error fetching txn cyrusdb error May 21 18:00:21 matrix imap[15715]: Could not open seen state for wenzhuo (System I/O error) May 21 18:00:21 matrix imap[15715]: open: user wenzhuo opened INBOX May 21 18:00:22 matrix imap[15715]: accepted connection May 21 18:00:23 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:23 matrix imap[15715]: accepted connection May 21 18:00:24 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:25 matrix imap[15715]: accepted connection May 21 18:00:25 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:25 matrix imap[15715]: open: user wenzhuo opened INBOX May 21 19:19:22 matrix master[7098]: process 15715 exited, signaled to death by 15 May 21 19:19:22 matrix master[7098]: service imap pid 15715 in BUSY state: terminated abnormally ------------------------------------------------------------------------ (At last, I killed the process manually.) and all logs through the facility mail when the problem occurred: (Note: imap is Cyrus IMAP, imapd is UW-IMAP.) ------------------------------------------------------------------------ May 21 18:00:02 matrix imap[15713]: accepted connection May 21 18:00:02 matrix master[15848]: about to exec /usr/lib/cyrus-imapd/imapd May 21 18:00:02 matrix imap[15848]: executed May 21 18:00:02 matrix imap[15713]: login: localhost.localdomain [127.0.0.1] cyrus plaintext May 21 18:00:03 matrix imap[15716]: accepted connection May 21 18:00:03 matrix imap[15716]: login: localhost.localdomain [127.0.0.1] cyrus plaintext May 21 18:00:21 matrix imapd[15851]: imap service init from 127.0.0.143 May 21 18:00:21 matrix imapd[15851]: pam_sm_authenticate called. May 21 18:00:21 matrix imapd[15851]: dbuser changed. May 21 18:00:21 matrix imapd[15851]: dbpasswd changed. May 21 18:00:21 matrix imapd[15851]: host changed. May 21 18:00:21 matrix imapd[15851]: database changed. May 21 18:00:21 matrix imapd[15851]: table changed. May 21 18:00:21 matrix imapd[15851]: usercolumn changed. May 21 18:00:21 matrix imapd[15851]: passwdcolumn changed. May 21 18:00:21 matrix imapd[15851]: crypt changed. May 21 18:00:21 matrix imapd[15851]: logtable changed. May 21 18:00:21 matrix imapd[15851]: logmsgcolumn changed. May 21 18:00:21 matrix imapd[15851]: logusercolumn changed. May 21 18:00:21 matrix imapd[15851]: loghostcolumn changed. May 21 18:00:21 matrix imapd[15851]: logpidcolumn changed. May 21 18:00:21 matrix imapd[15851]: logtimecolumn changed. May 21 18:00:21 matrix imapd[15851]: db_connect called. May 21 18:00:21 matrix imapd[15851]: returning 0 . May 21 18:00:21 matrix imapd[15851]: db_checkpasswd called. May 21 18:00:21 matrix imapd[15851]: pam_mysql: where clause = May 21 18:00:21 matrix imapd[15851]: SELECT password FROM accountuser WHERE username='wenzhuo' May 21 18:00:21 matrix imapd[15851]: pam_mysql: select returned more than one result May 21 18:00:21 matrix imapd[15851]: returning 7 after db_checkpasswd. May 21 18:00:21 matrix imapd[15851]: pam_mysql: acct_mgmt called but not implemented. Dont panic though :) May 21 18:00:21 matrix imapd[15851]: pam_mysql: setcred called but not implemented. May 21 18:00:21 matrix imapd[15851]: Authenticated user=wenzhuo host=[127.0.0.143] May 21 18:00:21 matrix imap[15715]: accepted connection May 21 18:00:21 matrix imapd[15851]: Logout user=wenzhuo host=[127.0.0.143] May 21 18:00:21 matrix imap[15715]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:21 matrix imap[15715]: IOERROR: stating /var/lib/imap/user/w/wenzhuo.seen: No such file or directory May 21 18:00:21 matrix imap[15715]: DBERROR: error fetching txn cyrusdb error May 21 18:00:21 matrix imap[15715]: Could not open seen state for wenzhuo (System I/O error) May 21 18:00:21 matrix imap[15715]: open: user wenzhuo opened INBOX May 21 18:00:21 matrix imapd[15854]: imap service init from 127.0.0.143 May 21 18:00:21 matrix imapd[15854]: pam_sm_authenticate called. May 21 18:00:21 matrix imapd[15854]: dbuser changed. May 21 18:00:21 matrix imapd[15854]: dbpasswd changed. May 21 18:00:21 matrix imapd[15854]: host changed. May 21 18:00:21 matrix imapd[15854]: database changed. May 21 18:00:21 matrix imapd[15854]: table changed. May 21 18:00:21 matrix imapd[15854]: usercolumn changed. May 21 18:00:21 matrix imapd[15854]: passwdcolumn changed. May 21 18:00:21 matrix imapd[15854]: crypt changed. May 21 18:00:21 matrix imapd[15854]: logtable changed. May 21 18:00:21 matrix imapd[15854]: logmsgcolumn changed. May 21 18:00:21 matrix imapd[15854]: logusercolumn changed. May 21 18:00:21 matrix imapd[15854]: loghostcolumn changed. May 21 18:00:21 matrix imapd[15854]: logpidcolumn changed. May 21 18:00:21 matrix imapd[15854]: logtimecolumn changed. May 21 18:00:21 matrix imapd[15854]: db_connect called. May 21 18:00:21 matrix imapd[15854]: returning 0 . May 21 18:00:21 matrix imapd[15854]: db_checkpasswd called. May 21 18:00:21 matrix imapd[15854]: pam_mysql: where clause = May 21 18:00:21 matrix imapd[15854]: SELECT password FROM accountuser WHERE username='wenzhuo' May 21 18:00:21 matrix imapd[15854]: pam_mysql: select returned more than one result May 21 18:00:21 matrix imapd[15854]: returning 7 after db_checkpasswd. May 21 18:00:21 matrix imapd[15854]: pam_mysql: acct_mgmt called but not implemented. Dont panic though :) May 21 18:00:21 matrix imapd[15854]: pam_mysql: setcred called but not implemented. May 21 18:00:21 matrix imapd[15854]: Authenticated user=wenzhuo host=[127.0.0.143] May 21 18:00:21 matrix imap[15846]: accepted connection May 21 18:00:21 matrix imap[15846]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:21 matrix imap[15846]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 18:00:21 matrix imap[15846]: open: user wenzhuo opened INBOX May 21 18:00:21 matrix imap[15845]: accepted connection May 21 18:00:21 matrix imapd[15854]: Logout user=wenzhuo host=[127.0.0.143] May 21 18:00:22 matrix imap[15845]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:22 matrix imap[15845]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 18:00:22 matrix imap[15845]: open: user wenzhuo opened INBOX May 21 18:00:22 matrix imapd[15858]: imap service init from 127.0.0.143 May 21 18:00:22 matrix imapd[15858]: pam_sm_authenticate called. May 21 18:00:22 matrix imapd[15858]: dbuser changed. May 21 18:00:22 matrix imapd[15858]: dbpasswd changed. May 21 18:00:22 matrix imapd[15858]: host changed. May 21 18:00:22 matrix imapd[15858]: database changed. May 21 18:00:22 matrix imapd[15858]: table changed. May 21 18:00:22 matrix imapd[15858]: usercolumn changed. May 21 18:00:22 matrix imapd[15858]: passwdcolumn changed. May 21 18:00:22 matrix imapd[15858]: crypt changed. May 21 18:00:22 matrix imapd[15858]: logtable changed. May 21 18:00:22 matrix imapd[15858]: logmsgcolumn changed. May 21 18:00:22 matrix imapd[15858]: logusercolumn changed. May 21 18:00:22 matrix imapd[15858]: loghostcolumn changed. May 21 18:00:22 matrix imapd[15858]: logpidcolumn changed. May 21 18:00:22 matrix imapd[15858]: logtimecolumn changed. May 21 18:00:22 matrix imapd[15858]: db_connect called. May 21 18:00:22 matrix imapd[15858]: returning 0 . May 21 18:00:22 matrix imapd[15858]: db_checkpasswd called. May 21 18:00:22 matrix imapd[15858]: pam_mysql: where clause = May 21 18:00:22 matrix imapd[15858]: SELECT password FROM accountuser WHERE username='wenzhuo' May 21 18:00:22 matrix imapd[15858]: pam_mysql: select returned more than one result May 21 18:00:22 matrix imapd[15858]: returning 7 after db_checkpasswd. May 21 18:00:22 matrix imapd[15858]: pam_mysql: acct_mgmt called but not implemented. Dont panic though :) May 21 18:00:22 matrix imapd[15858]: pam_mysql: setcred called but not implemented. May 21 18:00:22 matrix imapd[15858]: Authenticated user=wenzhuo host=[127.0.0.143] May 21 18:00:22 matrix imap[15713]: accepted connection May 21 18:00:22 matrix imap[15713]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:22 matrix imap[15848]: accepted connection May 21 18:00:22 matrix imapd[15858]: Logout user=wenzhuo host=[127.0.0.143] May 21 18:00:22 matrix imap[15848]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:22 matrix imap[15848]: seen_db: user wenzhuo opened /var/lib/imap/user/w/wenzhuo.seen May 21 18:00:22 matrix imap[15848]: open: user wenzhuo opened INBOX May 21 18:00:22 matrix imapd[15862]: imap service init from 127.0.0.143 May 21 18:00:22 matrix imapd[15862]: pam_sm_authenticate called. May 21 18:00:22 matrix imapd[15862]: dbuser changed. May 21 18:00:22 matrix imapd[15862]: dbpasswd changed. May 21 18:00:22 matrix imapd[15862]: host changed. May 21 18:00:22 matrix imapd[15862]: database changed. May 21 18:00:22 matrix imapd[15862]: table changed. May 21 18:00:22 matrix imapd[15862]: usercolumn changed. May 21 18:00:22 matrix imapd[15862]: passwdcolumn changed. May 21 18:00:22 matrix imapd[15862]: crypt changed. May 21 18:00:22 matrix imapd[15862]: logtable changed. May 21 18:00:22 matrix imapd[15862]: logmsgcolumn changed. May 21 18:00:22 matrix imapd[15862]: logusercolumn changed. May 21 18:00:22 matrix imapd[15862]: loghostcolumn changed. May 21 18:00:22 matrix imapd[15862]: logpidcolumn changed. May 21 18:00:22 matrix imapd[15862]: logtimecolumn changed. May 21 18:00:22 matrix imapd[15862]: db_connect called. May 21 18:00:22 matrix imapd[15862]: returning 0 . May 21 18:00:22 matrix imapd[15862]: db_checkpasswd called. May 21 18:00:22 matrix imapd[15862]: pam_mysql: where clause = May 21 18:00:22 matrix imapd[15862]: SELECT password FROM accountuser WHERE username='wenzhuo' May 21 18:00:22 matrix imapd[15862]: pam_mysql: select returned more than one result May 21 18:00:22 matrix imapd[15862]: returning 7 after db_checkpasswd. May 21 18:00:22 matrix imapd[15862]: pam_mysql: acct_mgmt called but not implemented. Dont panic though :) May 21 18:00:22 matrix imapd[15862]: pam_mysql: setcred called but not implemented. May 21 18:00:22 matrix imapd[15862]: Authenticated user=wenzhuo host=[127.0.0.143] May 21 18:00:22 matrix imap[15716]: accepted connection May 21 18:00:22 matrix imap[15716]: login: localhost.localdomain [127.0.0.1] wenzhuo plaintext May 21 18:00:22 matrix imap[15715]: accepted connection May 21 18:00:22 matrix master[15865]: about to exec /usr/lib/cyrus-imapd/imapd May 21 18:00:22 matrix imap[15865]: executed ------------------------------------------------------------------------ # vmstat 3 ------------------------------------------------------------------------ May 21 18:00:25 matrix imap[15715]: open: user wenzhuo opened INBOX procs memory swap io system cpu r b w swpd free buff cache si so bi bo in cs us sy id 3 0 0 137056 1636 27988 33976 3 72 101 227 142 127 96 4 0 2 1 1 137148 1872 27276 34772 0 53 15 211 140 133 99 1 0 3 0 0 137224 2104 27044 35044 3 55 3 276 132 113 100 0 0 2 0 0 137520 1612 26640 35504 5 108 5 325 143 145 98 2 0 2 0 0 137684 1608 26476 35712 0 55 0 213 131 116 100 0 0 2 0 0 137808 2032 26252 35956 1 51 1 205 135 120 100 0 0 2 0 0 137800 2036 26244 36000 3 11 3 164 129 106 100 0 0 2 0 0 137728 2412 26264 36004 5 0 5 213 124 112 99 1 0 2 1 1 137720 2480 26332 35972 1 0 1 147 124 102 100 0 0 ------------------------------------------------------------------------ -- Wenzhuo GnuPG Key ID 0xBA586A68 Key fingerprint = 89C7 C6DE D956 F978 3F12 A8AF 5847 F840 BA58 6A68 --- Cyrus Home Page: http://asg.web.cmu.edu/cyrus Cyrus Wiki/FAQ: http://cyruswiki.andrew.cmu.edu List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
