Cyrus 2.3.10 RC3

Tue Oct 23 06:20:21 EDT 2007

On Tue, 23 Oct 2007 09:32:18 +0100 (BST), "David Carter" <dpc22 at cam.ac.uk> said:
> On Tue, 23 Oct 2007, Bron Gondwana wrote:
> 
> > Oct 23 03:47:06 imap4 slot407/sync_client[20103]: IOERROR: opening 
> > message file 10 of MAILBOXNAME: No such file or directory
> 
> I think that this error relates to the master rather than the replica.
> 
> It looks like an UPLOAD is failing because it can't open message with UID 
> 10 on the master. Errors from the replica will typically get reported as 
> UPLOAD received NO response: (whatever the error was).
> 
> The following looks like a different slot. Is this the replica?
> 
> > [root at imap10 hm]$ utils/oneoff/index_uids.pl -D /mnt/meta11/slot1011/
> >  store46/meta/domain/f/fastmail.net/s/user/USERNAME/cyrus.index

Yes, but the master is identical.  When we had the earlier problems that
I emailed about the other day, there were actually bogus "UID 10" index
records on the replica.  They were the first record in the index
(followed by messages with lower UIDs!) and had a GUID which was all zeros
except for a single '1' close to the middle.  Looked remarkably like a
chunk of misplaced binary protocol from somewhere!

Every single one of them was "UID 10".

Look here - a brand new conversion!  Here's what I did:

a) updated the imapd.conf and cyrus.conf files on both master and replica
   with new versions, also updated the init scripts with paths into 
   /usr/cyrusnew/ (where our 2.3.10 is installed)

b) shut down the master

c) shut down and started the replica

d) started the master

That's all.  I had made no attempt to upgrade the indexes with any tools,
or perform any reconstructs.

Oct 23 05:01:19 imap9 slot908/sync_client[13528]: IOERROR: opening message file 10 of user.e------.Drafts: No such file or directory
Oct 23 05:01:34 imap9 slot908/sync_client[13528]: IOERROR: opening message file 10 of airpost.net!user.s----------: No such file or directory
Oct 23 05:04:50 imap9 slot908/sync_client[13528]: IOERROR: opening message file 10 of fastem.com!user.a------------.Sent Items: No such file or directory
Oct 23 05:07:57 imap9 slot908/sync_client[13528]: IOERROR: opening message file 10 of fmail.co.uk!user.h-------.Sent Items: No such file or directory

I have redacted all but the first letter in each of those names, but that's a
"grep IOERROR /var/log/imapd.log" on the machine that's just been updated.

Seems a little too much of a coincidence that they're _ALL_ UID 10, especially
since these are the contents of those index files:

[root at imap9 hm]$ utils/oneoff/index_uids.pl /mnt/meta8/slot908/store24/meta/e/user/e------/Drafts/cyrus.index
V:10 E:3 U:9
7 0209053a5adcbc29337dbdb90000000000000000 6808
8 02a8b6e19b4d9512f5f81fc70000000000000000 2436
9 cae1994a4c7e67392f24cbaa188af3899d2c62ba 2080

[root at imap9 hm]$ utils/oneoff/index_uids.pl /mnt/meta8/slot908/store24/meta/domain/a/airpost.net/s/user/s----------/cyrus.index
V:10 E:2 U:3
2 029083af6e19600204f2ca390000000000000000 3090
3 da2a8c989ef89545f3fb43ddc35911722531a77d 4243

[root at imap9 hm]$ utils/oneoff/index_uids.pl /mnt/meta8/slot908/store24/meta/domain/f/fastem.com/a/user/a------------/Sent\ Items/cyrus.index
V:10 E:9 U:9
1 02a0c2128edd5d904139ad390000000000000000 1387249
2 022d685b9c76cd47a8e760e80000000000000000 1268791
3 02eec7265ba01658a42362f60000000000000000 1373574
4 02cc24451b35a5081ec9dfbd0000000000000000 1230890
5 02a9a81c0e809e339c12f2160000000000000000 1392941
6 022fa67eef0edf704b6e037d0000000000000000 1111104
7 02ff9b83ab3ab6d90e9977d00000000000000000 40843
8 026fda908864a7206bd054db0000000000000000 40762
9 3d84e09922cdc1e62d3f65366e619da17bad0385 66190

[root at imap9 hm]$ utils/oneoff/index_uids.pl /mnt/meta8/slot908/store24/meta/domain/f/fmail.co.uk/h/user/h------/Sent\ Items/cyrus.index
V:10 E:1 U:1
1 2fb0584230837f74d26778169c0209299b7ba59e 2363264

=============

(that's "MinorVersion", "Exists" and "LastUid" in the header line by the way,
and Uid, MessageGuid, Size in the record lines)

The only really interesting pattern I can see is that all the mailboxes have
had one new message delivered since the upgrade.  It would make sense that
"Sent Items" already existed on the replica, because it's a folder we generate
at account creation.

LastAppenddate: 1193130477
UidValidity: 1180772382

Yep - it was there.

So the pattern I'm seeing is that if an index upgrade is
required, then this error is generated.  Possibly not
every time, but often enough, and possibly this pattern
is bogus.  Look, here's another:

Oct 23 05:47:58 imap9 slot908/sync_client[6795]: IOERROR: opening message file 10 of user.p----.Drafts: No such file or directory
Oct 23 05:47:58 imap9 slot908/sync_client[6795]: UPLOAD received BAD response: Syntax error in Append at item 1: Invalid flags or missing message

Occurred as I was writing this message!

[root at imap9 hm]$ utils/oneoff/index_uids.pl /mnt/meta8/slot908/store24/meta/p/user/p----/Drafts/cyrus.index
V:10 E:2 U:2
1 02ad52d7d80228ce3e3e39db0000000000000000 389
2 9f66e897c8cadc8c0246db204377ae707948622d 1290

[root at imap9 hm]$ limap | grep slot908 | grep sync | grep RESTART | wc -l
19

Apart from those 19 "RESTART" messages, this is all that sync_client has had to say
on the master.

Over on the replica, we have no log records of any relevance.  A bunch of skiplist
recoveries and checkpoints on seen files, a pile of "Unlocked", a pile of expunged,
a couple of "RenameCopy" and "Deleted mailbox" pairs, but they're for a user who
isn't mentioned at all above.

Oh, just for fun.. user "p----" above on the replica:

[root at imap5 hm]$ utils/oneoff/index_uids.pl /mnt/meta3/slot503/store24/meta/p/user/p----/Drafts/cyrus.index
V:10 E:2 U:2
1 02ad52d7d80228ce3e3e39db0000000000000000 389
2 9f66e897c8cadc8c0246db204377ae707948622d 1290

So no visible corruption (this time at least!) - just errors in the log file.

Bron.
-- 
  Bron Gondwana
  brong at fastmail.fm