Cassandane unhappy on 32-bit machine

[jasontibbitts]

I noticed several additional cassandane test failures when running on a 32-bit machine. Turns out that you can't use the 'Q' type in unpack on 32-bit perl. Oops.

There's one place in Cassandane/Cyrus/Metadata.pm that uses this:

    if ($entry[2]) {
        my ($modseq, $modtime, $flags) =
            unpack("Q>Q>C", bytes::substr($entry[2], $Config{longsize}));
        if ($flags and not $tombstones) {
            next;
        }
        if ($withmdata) {
            $annot->{modseq} = $modseq;
            $annot->{flags} = $flags;
        }
    }

Some searching tells me that you can replace "Q>" with "N2" if you process the entries in the list in pairs. But I've never really gotten into Perl at this level and so this is a bit beyond me.

[jasontibbitts]

I instrumented that code to see what the unpack call gets passed and what it returns and it turns out that it gets called about 50 times in a regular Cassandane run and every single time, $entry[2] simply contains eight zero bytes. And on a 64-bit machine, $Config{longsize} is 8. Which kind of makes me wonder.... The first 'Q' would take eight bytes. What is supposed to be left to unpack into $modtime or $flags?

But that does tell me that to get things going today, I can probably just set modseq=0 and leave modtime and flags undefined and everything should progress unchanged.

[rsto]

We'll need to the modseq to test the latest features for annotations.

I'd rather update cyr_buildinfo to output if it is built for 32-bit or 64-bit. We already read cyr_buildinfo in Cassandane and update the Perl unpacking accordingly.

[rsto]

Sorry, that was written too hastily, I meant: we already read cyr_buildinfo in Cassandane and need to update the Perl unpacking accordingly. I'll work on this now.

[rsto]

@jasontibbitts i've pushed a fix to Cassandane master: 64153d7

does this work out on your 32-bit system?

[jasontibbitts]

Unfortunately I still see a number of failures which I don't have on a 64-bit platform.

You can see a build using cyrus 3.0.1 and the current Cassandane code at https://koji.fedoraproject.org/koji/taskinfo?taskID=19785301

Note that x86_64 passes, while i686 and armv7hl fail identically. (I know there are tests which are expected to fail when run against 3.0.1; they are already excluded so that things are fine on x86_64.) Please also ignore failures relating to ppc64 and s390x; those are big-endian machines and Cyrus seems to have a separate issue there (it fails in the test suite, which is cyrusimap/cyrus-imapd#1993).

So if you click through to the i686 build log at https://kojipkgs.fedoraproject.org//work/tasks/5307/19785307/build.log and search for "Bug3470" or something like that, you'll see the Cassandane run and all of the output it gives for the failing tests. Sadly I'm still seeing Perl exception: Invalid type 'Q' in unpack in there. That seems to account for most of the errors, but not all of them. There's also Perl exception: child process (binary reconstruct pid 30591) exited with code 75 in test_reconstruct_orphans(Cassandane::Cyrus::Quota) and test_reconstruct(Cassandane::Cyrus::Quota).

There are also some plain failures; this one looks odd:

1) test_setcontacts_importance_later(Cassandane::Cyrus::JMAPContacts)
 expected -0.1, got -0.1 at Cassandane/Cyrus/JMAPContacts.pm line 1066.
	Cassandane::Cyrus::JMAPContacts::test_setcontacts_importance_later(Cassandane::Cyrus::JMAPContacts=HASH(0xa9c88c0)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75

and three others which fail with expected 10, got 0.

And looking at that patch, it can't help because if the 64-bit types are supported you can simply never call unpack("Q"). However, I note that soon at least the development version of Fedora will have the compile flag turned on so that the 64-bit types will be supported on 32-bit perl. That won't help me for Fedora 26 but I can work around it.

The failures that aren't due to unpack("Q") are also problematic, though. Sorry I didn't mention them earlier but I hadn't yet managed to dig through the entire failed test log.

[jasontibbitts]

So the Perl churn in Fedora rawhide is done and 32-bit Perl now supports the quad types, so the failures related to that are no longer problematic for me but might still be to someone else depending on how their Perl is built. However, there are still five tests which fail on 32-bit machines for reasons I simply do not understand, but it can't be a coincidence that they all involve "reconstruct" somehow:

• Reconstruct.reconstruct_removedfile
• Reconstruct.reconstruct_truncated
• Reconstruct.reconstruct_zerouid
• Quota.reconstruct
• Quota.reconstruct_orphans

The reconstruct tests all fail pretty much identically:

 Perl exception: child process (binary reconstruct pid 42954) exited with code 75
 at Cassandane/Instance.pm line 1427.
	Cassandane::Instance::__ANON__(HASH(0x5c28a584), 75) called at Cassandane/Instance.pm line 1609
	Cassandane::Instance::_handle_wait_status(Cassandane::Instance=HASH(0x59d6914c), 42954) called at Cassandane/Instance.pm line 1399
	Cassandane::Instance::reap_command(Cassandane::Instance=HASH(0x59d6914c), 42954) called at Cassandane/Instance.pm line 1389
	Cassandane::Instance::run_command(Cassandane::Instance=HASH(0x59d6914c), HASH(0x5b97fa90), "reconstruct", "user.cassandane") called at Cassandane/Cyrus/Quota.pm line 2383
	Cassandane::Cyrus::Quota::test_reconstruct(Cassandane::Cyrus::Quota=HASH(0x5b2543e4)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
	[...framework calls elided...]

The Quota tests both fail with:

 expected 10, got 0 at Cassandane/Cyrus/Reconstruct.pm line 194.
	Cassandane::Cyrus::Reconstruct::test_reconstruct_removedfile(Cassandane::Cyrus::Reconstruct=HASH(0x5b2a97dc)) called at /usr/share/perl5/vendor_perl/Test/Unit/TestCase.pm line 75
	[...framework calls elided...]

If you would like the complete output, a full build log is at https://kojipkgs.fedoraproject.org//work/tasks/8985/20038985/build.log

I note that exit code 75 is EX_TEMPFAIL, and that in at least some places in the cyrus code, that's an intentional return. So maybe what remains is now a Cyrus bug instead of a Cassandane bug but honestly I don't know enough to make that determination. If that is the case, please let me know and I'll move this over.

[elliefm]

if you look in 'lib/exitcodes.h' you can see that we really unhelpfully define a bunch of Cyrus exit codes to actually just be EX_TEMPFAIL (I think this is for integration with sendmail?), so "75" is about the least meaningful number that reconstruct could possibly return :/

But all the places that imap/reconstruct.c exits (either via fatal() or exit()) seem to be usage errors exiting with EC_USAGE (== EX_TEMPFAIL).

So if you fiddle with lib/exitcodes.c and change EC_USAGE to some value other than EX_TEMPFAIL, rebuild and test again, do the reconstruct tests start whinging about the new number? Or do they continue to get 75?

Alternatively, if you change each of the fatal() and exit() calls in imap/reconstruct.c to exit with a distinct value, rather than EC_USAGE, we could nail down where exactly it's barfing out...

[jasontibbitts]

I just set every exit and fatal call to be different positive integers. And.... no dice; it still exits 75.

So I just set up a i686 chroot and ran it all there. I did some bind mounting to get syslog to work and got some logs:

Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: SQL backend defaulting to engine 'pgsql'
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: reconstructing user.cassandane
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: IOERROR: opening index user.cassandane: System I/O error
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: create new mailbox user.cassandane
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: failed to read index header for user.cassandane
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: auditlog: create sessionid=<1642131-28240-1497631334-1-12215880127013081496> mailbox=<user.cassandane> uniqueid=<912cae39-c727-4d94-8728-db82b9860590> uidvalidity=<1497631335>
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 4110043912 not found
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 7 found - adding
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 9 found - adding
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 842282544 not found
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 1534354292 not found
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 5 rediscovered - appending
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 4 rediscovered - appending
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 3 rediscovered - appending
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 2 rediscovered - appending
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: user.cassandane uid 1 rediscovered - appending
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: removing stale annotations for 4110043888
Jun 16 11:42:14 epithumia.math.uh.edu 1642131/reconstruct[28240]: removing stale annotations for 0

Which doesn't look bad, though I'm not sure if those "not found" things are expected. I'm also not sure why it's defaulting to pgsql. Maybe it's just picking one of the configured ones at random and that doesn't matter.

I had also run cassandane under strace and at the end there:

send(3, "<21>Jun 16 11:54:15 1654141/reconstruct[31220]: removing stale annotations for 0", 80, MSG_NOSIGNAL) = 80
write(2, "fatal error: Internal error: assertion failed: imap/annotate.c: 3390: uid\n", 74) = 74
write(1, "user.cassandane: failed to read index header\nuser.cassandane uid 4110154504 not founduser.cassandane uid 7 found - adding\nuser.cassandane uid 9 found - adding\nuser.cassandane uid 875902512 not founduser.cassandane uid 1534354292 not founduser.cassandane uid 5 rediscovered - appending\nuser.cassandane uid 4 rediscovered - appending\nuser.cassandane uid 3 rediscovered - appending\nuser.cassandane uid 2 rediscovered - appending\nuser.cassandane uid 1 rediscovered - appending\nremoving stale annotations for 4110154480\nremoving stale annotations for 0\n", 548) = 548
exit_group(75)                          = ?

So, the reason we're still getting 75 is that this is going through the assertionfailed() function in lib/assert.c, so that's one question answered.

But now we can also see just what's going on. That assert is in HIDDEN int annotate_msg_cleanup(struct mailbox *mailbox, unsigned int uid). And uid is simply being passed as zero. Too bad we don't get a backtrace. Of course with those large uid numbers and this being a 32-bit issue I'm wondering if there's an integer overflow somewhere.

Also, does Cassandane save the output from the commands it's running anywhere? Because having that immediately available would have made this a bit easier.

[jasontibbitts]

I used my vague recollections of C syntax and some searching to hack up a patch to get the result of the glibc backtrace() function into the output of the assert function. But it appears that's not as useful as I would have hoped, maybe because Cyrus appears to do some internal static linking. Nevertheless, here's the backtrace from that assertion.

fatal error: Internal error: assertion failed: imap/annotate.c: 3390: uid
lib/libcyrus_min.so.0(assertionfailed+0xa3) [0xf70d54c3]
lib/libcyrus_imap.so.0(+0x1e8c9) [0xf71e18c9]
lib/libcyrus_imap.so.0(mailbox_reconstruct+0x1b13) [0xf7211753]
sbin/reconstruct(+0x24da) [0x566054da]
lib/libcyrus_imap.so.0(+0x5633d) [0xf721933d]
lib/libcyrus.so.0(+0x42465) [0xf7145465]
lib/libcyrus_imap.so.0(+0x536db) [0xf72166db]
lib/libcyrus_imap.so.0(+0x5410e) [0xf721710e]
lib/libcyrus_imap.so.0(mboxlist_findallmulti+0xe8) [0xf721d928]
lib/libcyrus_imap.so.0(mboxlist_findall+0xa1) [0xf721da11]
sbin/reconstruct(main+0x663) [0x56604c53]
/lib/libc.so.6(__libc_start_main+0xf3) [0xf4e5f373]
usr/sbin/reconstruct(+0x2183) [0x56605183]

[elliefm]

This looks like a bug in reconstruct -- might be worth moving this issue to the cyrus-imapd repo?

If you add this patch, where does the assertion throw?

diff --git a/imap/mailbox.c b/imap/mailbox.c
index 9116bd1..713d182 100644
--- a/imap/mailbox.c
+++ b/imap/mailbox.c
@@ -6331,6 +6331,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
         /* bogus annotations? */
         while (annots.pos < annots.nused && annots.found[annots.pos].uid < record.uid) {
+            assert(annots.found[annots.pos].uid != 0);
             add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
             annots.pos++;
         }
@@ -6404,6 +6405,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
         /* bogus annotations? */
         while (annots.pos < annots.nused && annots.found[annots.pos].uid < uid) {
+            assert(annots.found[annots.pos].uid != 0);
             add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
             annots.pos++;
         }
@@ -6416,6 +6418,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
     /* bogus annotations after the end? */
     while (annots.pos < annots.nused) {
+        assert(annots.found[annots.pos].uid != 0);
         add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
         annots.pos++;
     }

[elliefm]

The SQL database to use is taken from the sql_engine setting in imapd.conf. If this is not set, the default is the first of "mysql", "pgsql" or "sqlite" that has been compiled in. So it's defaulting to pgsql because you have that compiled in, but don't have mysql compiled in.

Though, why it's using an SQL database here (as opposed to, say, twoskip) is another interesting question...

I guess it could also be a bug in cyrusdb_sql, or the pgsql backend specificially, maybe let's hold off on making a new issue for the time being, and I'll see what further insight I can gain here. I'll probably send you through some more diagnostic patches too.

[elliefm]

Okay, that "SQL backend defaulting to engine" thing is a total red herring -- it's just a helpful notice that prints during cyrus initialisation if cyrusdb SQL support is available (which it is for you, because you've enabled postgres as one of the backends). I hadn't seen it before myself, because I don't usually build with sql backends enabled

The annotations code won't use sql backends anyway (annotation_db setting only permits skiplist, twoskip or lmdb), so whatever the problem is here, it's not some sql translation issue.

[jasontibbitts]

With that patch, this is how both Quota.reconstruct and Quota.reconstruct_orphans fail:

fatal error: Internal error: assertion failed: imap/mailbox.c: 6406: annots.found[annots.pos].uid != 0

Feel free to move this to wherever you think might be appropriate, or tell me and I'll report the two remaining issues (the two Quota.reconstruct* errors and the three Reconstruct.reconstruct* failures) separately.

[elliefm]

Hmmm... still puzzled about what's going on!

Here's a newer, longer, diagnostic patch -- can you please run Quota.reconstruct and Quota.reconstruct_orphans with this applied, and collect the syslog output for each? I'm syslogging to LOG_DEBUG -- if that log level is difficult to obtain in your chroot, you could just replace LOG_DEBUG with LOG_ERR in the patch before applying it.

diff --git a/imap/mailbox.c b/imap/mailbox.c
index 713d182..03ce16e 100644
--- a/imap/mailbox.c
+++ b/imap/mailbox.c
@@ -5292,7 +5292,7 @@ EXPORTED int mailbox_copyfile(const char *from, const char *to, int nolink)
 /*                      RECONSTRUCT SUPPORT                               */
 /* ---------------------------------------------------------------------- */
 
-#define UIDGROW 300
+#define UIDGROW 16
 
 struct found_uid {
     uint32_t uid;
@@ -6179,11 +6179,11 @@ static int mailbox_wipe_index_record(struct mailbox *mailbox,
     return 0;
 }
 
-static int addannot_uid(const char *mailbox __attribute__((unused)),
+static int addannot_uid(const char *mailbox,
                         uint32_t uid,
-                        const char *entry __attribute__((unused)),
+                        const char *entry,
                         const char *userid __attribute__((unused)),
-                        const struct buf *value __attribute__((unused)),
+                        const struct buf *value,
                         void *rock)
 {
     struct found_uids *annots = (struct found_uids *)rock;
@@ -6192,6 +6192,8 @@ static int addannot_uid(const char *mailbox __attribute__((unused)),
      * will be together in a 'foreach' response */
     if (!annots->nused || annots->found[annots->nused-1].uid != uid) {
         /* we don't support an archive annotations DB yet */
+        syslog(LOG_DEBUG, "%s: adding found annot: uid=%u mailbox=%s %s=%.20s...",
+                          __func__, uid, mailbox, entry, buf_cstring(value));
         add_found(annots, uid, /*isarchive*/0);
     }
 
@@ -6242,6 +6244,20 @@ out:
     return r;
 }
 
+static void dump_found_uids(const struct found_uids *found, const char *d1, const char *d2)
+{
+    unsigned z;
+    syslog(LOG_DEBUG, "%s: %s: nalloc=%u nused=%u pos=%u",
+                      d1, d2, found->nalloc, found->nused, found->pos);
+    for (z = 0; z < found->nused; z++) {
+        syslog(LOG_DEBUG, "%s: %s: found uid=%u isarchive=%u",
+                          d1, d2, found->found[z].uid, found->found[z].isarchive);
+    }
+    for (; z < found->nalloc; z++) {
+        syslog(LOG_DEBUG, "%s: %s: empty uid=%u isarchive=%u",
+                          d1, d2, found->found[z].uid, found->found[z].isarchive);
+    }
+}
 
 /*
  * Reconstruct the single mailbox named 'name'
@@ -6308,9 +6324,11 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
     r = find_files(mailbox, &files, flags);
     if (r) goto close;
+    dump_found_uids(&files, __func__, "find files");
 
     r = find_annots(mailbox, &annots);
     if (r) goto close;
+    dump_found_uids(&annots, __func__, "find annots");
 
     uint32_t recno;
     struct index_record record;
@@ -6330,6 +6348,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
         last_seen_uid = record.uid;
 
         /* bogus annotations? */
+        syslog(LOG_DEBUG, "%s: want to delete annotations with uid < %u", __func__, record.uid);
         while (annots.pos < annots.nused && annots.found[annots.pos].uid < record.uid) {
             assert(annots.found[annots.pos].uid != 0);
             add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
@@ -6338,10 +6357,12 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
         /* skip over current */
         while (annots.pos < annots.nused && annots.found[annots.pos].uid == record.uid) {
+            syslog(LOG_DEBUG, "%s: skipping annotation with uid == %u", __func__, record.uid);
             annots.pos++;
         }
 
         /* lower UID file exists */
+        syslog(LOG_DEBUG, "%s: discover files with uid < %u", __func__, record.uid);
         while (files.pos < files.nused && files.found[files.pos].uid < record.uid) {
             add_found(&discovered, files.found[files.pos].uid, files.found[files.pos].isarchive);
             files.pos++;
@@ -6387,6 +6408,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
     }
 
     /* add discovered messages before last_uid to the list in order */
+    syslog(LOG_DEBUG, "%s: discover files with uid <= %u", __func__, mailbox->i.last_uid);
     while (files.pos < files.nused && files.found[files.pos].uid <= mailbox->i.last_uid) {
         add_found(&discovered, files.found[files.pos].uid, files.found[files.pos].isarchive);
         files.pos++;
@@ -6404,6 +6426,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
         /* we can keep this annotation too... */
 
         /* bogus annotations? */
+        syslog(LOG_DEBUG, "%s: want to delete annotations with uid < %u", __func__, uid);
         while (annots.pos < annots.nused && annots.found[annots.pos].uid < uid) {
             assert(annots.found[annots.pos].uid != 0);
             add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
@@ -6412,11 +6435,13 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
 
         /* skip over current */
         while (annots.pos < annots.nused && annots.found[annots.pos].uid == uid) {
+            syslog(LOG_DEBUG, "%s: skipping annotation with uid == %u", __func__, uid);
             annots.pos++;
         }
     }
 
     /* bogus annotations after the end? */
+    syslog(LOG_DEBUG, "%s: want to delete remaining annotations", __func__);
     while (annots.pos < annots.nused) {
         assert(annots.found[annots.pos].uid != 0);
         add_found(&delannots, annots.found[annots.pos].uid, /*isarchive*/0);
@@ -6424,6 +6449,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
     }
 
     /* handle new list - note, we don't copy annotations for these */
+    dump_found_uids(&discovered, __func__, "discovered files");
     while (discovered.pos < discovered.nused) {
         r = mailbox_reconstruct_append(mailbox, discovered.found[discovered.pos].uid,
                                        discovered.found[discovered.pos].isarchive, flags);
@@ -6431,6 +6457,7 @@ EXPORTED int mailbox_reconstruct(const char *name, int flags)
         discovered.pos++;
     }
 
+    dump_found_uids(&delannots, __func__, "delannots");
     if (delannots.nused) {
         r = reconstruct_delannots(mailbox, &delannots, flags);
         if (r) goto close;