rare infinite loop in cyrus-imapd-2.2.3 seendb processing
Wenzhuo Zhang
wenzhuo at zhmail.com
Fri May 21 20:08:38 EDT 2004
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
More information about the Info-cyrus
mailing list