DBERROR: skiplist recovery mailboxes.db 0090 - suddenly all is failing!

[Gregor Wenkelewsky]

Hi there,

Cyrus has been installed here just a few weeks ago, and after some hard days it was working smoothly and very well. Until suddenly, sadly today it started to fail completely with this error message in mail.warn, mail.error and syslog:

cyrus/imap[..]: DBERROR: skiplist recovery /var/lib/cyrus/mailboxes.db: 0090 should be ADD or DELETE
cyrus/imap[..]: DBERROR: opening /var/lib/cyrus/mailboxes.db: cyrusdb error

There was a post by Florin Andrei on March 12 2004 in which he described a similar problem and a solution, but his setting is much different to mine and I can't just follow to that. My setup is: cyrus-imapd2.2.13, postfix, Xubuntu 6.10 and I have not one, but currently 20 users and plans are for about 500.

As I found out from the logs, first time the error occured this morning was after I was rebooting the system once. The log showed no failures during the night, i.e. multiple squatter runs with no errors. ((BTW, for a low-end server PC with up to 500 accounts and no intention to store huge messages or files - the mail system is for use with SquirrelMail in a grammar school - to what setting should I set squatter, if at all?))

I guess the error was created when shutting down and restarting, so I show here the entries before and after that.

===excerpt from mail.log (changed domain names)===
Feb 15 07:35:52 Heimdall cyrus/master[8845]: about to exec /usr/lib/cyrus/bin/lmtpd
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: executed
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: accepted connection
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: lmtp connection preauth'd as postman
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: IOERROR: fstating sieve script /var/spool/sieve/l/lehrer/defaultbc: No such file or directory
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: duplicate_check: <20070215063552.636DF6035F at school.edu> user.lehrer          0
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: duplicate_check: <20070215063552.636DF6035F at school.edu> user.lehrer          0
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: mystore: starting txn 2147483815
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: mystore: committing txn 2147483815
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: duplicate_mark: <20070215063552.636DF6035F at school.edu> user.lehrer          1171521352 135568128
Feb 15 07:35:52 Heimdall cyrus/lmtpunix[8845]: Delivered: <20070215063552.636DF6035F at school.edu> to mailbox: user.lehrer
Feb 15 07:35:52 Heimdall postfix/pipe[8843]: 636DF6035F: to=<lehrer at borni.mine.nu>, orig_to=<root>, relay=cyrus, delay=0.38, delays=0.17/0.02/0/0.19, dsn=2.0.0, status=sent (delivered via cyrus service)
Feb 15 07:35:52 Heimdall postfix/qmgr[4124]: 636DF6035F: removed
Feb 15 07:36:00 Heimdall cyrus/master[8846]: about to exec /usr/sbin/ctl_cyrusdb
Feb 15 07:36:00 Heimdall cyrus/master[8847]: about to exec /usr/bin/nice
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: checkpointing cyrus databases
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: archiving database file: /var/lib/cyrus/annotations.db
Feb 15 07:36:00 Heimdall cyrus/squatter[8847]: indexing mailboxes

***squatter[8847] skipping many mailboxes***

Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: archiving database file: /var/lib/cyrus/mailboxes.db
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 07:36:00 Heimdall cyrus/ctl_cyrusdb[8846]: done checkpointing cyrus databases
Feb 15 07:36:00 Heimdall cyrus/master[3795]: process 8846 exited, status 0

***squatter[8847] skipping more mailboxes***

Feb 15 07:36:00 Heimdall cyrus/squatter[8847]: indexing mailbox user/lehrer... 

***squatter[8847] skipping all other mailboxes***

Feb 15 07:36:01 Heimdall cyrus/squatter[8847]: skipping mailbox user.test
Feb 15 07:36:01 Heimdall cyrus/squatter[8847]: done indexing mailboxes
Feb 15 07:36:01 Heimdall cyrus/master[3795]: process 8847 exited, status 0
Feb 15 07:36:52 Heimdall cyrus/master[3795]: process 8845 exited, status 0
Feb 15 08:06:00 Heimdall cyrus/master[8882]: about to exec /usr/sbin/ctl_cyrusdb
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: checkpointing cyrus databases
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: archiving database file: /var/lib/cyrus/annotations.db
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: archiving database file: /var/lib/cyrus/mailboxes.db
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 08:06:00 Heimdall cyrus/ctl_cyrusdb[8882]: done checkpointing cyrus databases
Feb 15 08:06:00 Heimdall cyrus/master[3795]: process 8882 exited, status 0
Feb 15 08:10:27 Heimdall cyrus/master[3795]: exiting on SIGTERM/SIGINT
Feb 15 08:10:35 Heimdall postfix/master[4104]: terminating on signal 15

***nothing cut, this was when system was rebooted***

Feb 15 08:12:12 Heimdall cyrus/master[3884]: process started
Feb 15 08:12:13 Heimdall cyrus/master[3979]: about to exec /usr/sbin/ctl_cyrusdb
Feb 15 08:12:14 Heimdall cyrus/ctl_cyrusdb[3979]: recovering cyrus databases
Feb 15 08:12:14 Heimdall cyrus/ctl_cyrusdb[3979]: DBERROR: skiplist recovery /var/lib/cyrus/mailboxes.db: 0090 should be ADD or DELETE
Feb 15 08:12:14 Heimdall cyrus/ctl_cyrusdb[3979]: DBERROR: opening /var/lib/cyrus/mailboxes.db: cyrusdb error
Feb 15 08:12:14 Heimdall cyrus/master[3884]: process 3979 exited, status 75 
Feb 15 08:12:14 Heimdall cyrus/master[3982]: about to exec /usr/sbin/cyr_expire
Feb 15 08:12:14 Heimdall cyrus/master[3982]: can't exec /usr/sbin/cyr_expire for startup: No such file or directory
Feb 15 08:12:14 Heimdall cyrus/master[3884]: process 3982 exited, status 71 
===end of excerpt from mail.log===

Then, during the rest of the morning, there was no usage of the mail system. Squatter tried to run some times, always with the same error, like here:

===2nd excerpt from mail.log ===
Feb 15 12:12:14 Heimdall cyrus/master[4449]: about to exec /usr/sbin/ctl_cyrusdb
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: checkpointing cyrus databases
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: archiving database file: /var/lib/cyrus/annotations.db
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 12:12:14 Heimdall cyrus/master[4450]: about to exec /usr/bin/nice
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: archiving database file: /var/lib/cyrus/mailboxes.db
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: archiving log file: /var/lib/cyrus/db/log.0000000001
Feb 15 12:12:14 Heimdall cyrus/ctl_cyrusdb[4449]: done checkpointing cyrus databases
Feb 15 12:12:14 Heimdall cyrus/master[3884]: process 4449 exited, status 0
Feb 15 12:12:14 Heimdall cyrus/squatter[4450]: indexing mailboxes
Feb 15 12:12:14 Heimdall cyrus/squatter[4450]: DBERROR: skiplist recovery /var/lib/cyrus/mailboxes.db: 0090 should be ADD or DELETE
Feb 15 12:12:15 Heimdall cyrus/squatter[4450]: DBERROR: opening /var/lib/cyrus/mailboxes.db: cyrusdb error
Feb 15 12:12:15 Heimdall cyrus/master[3884]: process 4450 exited, status 75
===end of 2nd excerpt from mail.log===

But then, when later I wanted to open one of the IMAP accounts with Thunderbird, Cyrus went totally crazy:

=== last excerpt from mail.log ===
Feb 15 13:21:43 Heimdall cyrus/master[4510]: about to exec /usr/lib/cyrus/bin/imapd
Feb 15 13:21:43 Heimdall cyrus/imap[4510]: executed
Feb 15 13:21:43 Heimdall cyrus/imap[4510]: DBERROR: skiplist recovery /var/lib/cyrus/mailboxes.db: 0090 should be ADD or DELETE
Feb 15 13:21:43 Heimdall cyrus/imap[4510]: DBERROR: opening /var/lib/cyrus/mailboxes.db: cyrusdb error
Feb 15 13:21:43 Heimdall cyrus/imap[4510]: Fatal error: can't read mailboxes file
Feb 15 13:21:43 Heimdall cyrus/master[3884]: process 4510 exited, status 75
Feb 15 13:21:43 Heimdall cyrus/master[3884]: service imap pid 4510 in READY state: terminated abnormally
Feb 15 13:21:43 Heimdall cyrus/master[4511]: about to exec /usr/lib/cyrus/bin/imapd
Feb 15 13:21:43 Heimdall cyrus/imap[4511]: executed
Feb 15 13:21:43 Heimdall cyrus/imap[4511]: DBERROR: skiplist recovery /var/lib/cyrus/mailboxes.db: 0090 should be ADD or DELETE
Feb 15 13:21:43 Heimdall cyrus/imap[4511]: DBERROR: opening /var/lib/cyrus/mailboxes.db: cyrusdb error
Feb 15 13:21:43 Heimdall cyrus/imap[4511]: Fatal error: can't read mailboxes file
Feb 15 13:21:43 Heimdall cyrus/master[3884]: process 4511 exited, status 75
Feb 15 13:21:43 Heimdall cyrus/master[3884]: service imap pid 4511 in READY state: terminated abnormally
Feb 15 13:21:43 Heimdall cyrus/master[4512]: about to exec /usr/lib/cyrus/bin/imapd
=== end of last excerpt from mail.log ===

This went on and on hundreds of times, until I stopped cyrus!

No need to mention: I NEED HELP, desperately. :-( Sorry.
mail.warn is now 1.6 MB, mail.log 3.2 MB, syslog 2.4 MB - that is much too much IMHO....
What shall I do to fix this, and to make sure it never happens again?!?

Yours, Gregor

-- 
Ist Ihr Browser Vista-kompatibel? Jetzt die neuesten 
Browser-Versionen downloaden: http://www.gmx.net/de/go/browser