Build/test fail on architectures affected by the time_t transition

[guimard]

From Debian #1068223.

cyrus-imapd is failing to build on the architectures affected by the time_t transition (armel, armhf, several debian-ports architectures) with the following error.

unit: fatal(Internal error: assertion failed: cunit/timeofday.c: 113: tv.tv_usec != 0xffffffff)

A quick look at the code, suggests that the testsuite is trying to intercept gettimeofday, and this interception is broken by the time64 changes.

The specific error appears to be cause by calling the non-time64 gettimeofday function from glibc with the time64 definition of struct timeval, but I suspect there are other issues with the interception code that will rear their ugly head if that one is fixed.

I can launch 3.8.2 build on such architecture if you give me a patch to test.

Best regards,

[elliefm]

That chunk of code is:

static int64_t now(void)
{   
    struct timeval tv = { 0xffffffff, 0xffffffff };
    int r = real_gettimeofday(&tv, NULL);
    assert(r == 0);
    assert(tv.tv_sec != 0xffffffff); 
    assert(tv.tv_usec != 0xffffffff);     // <---- assertion here
    return from_timeval(&tv);
}

Which is interesting because that's the third assertion, meaning that the other two passed. This means that real_gettimeofday() returned 0 indicating success, and filled out a sensible value into the tv.tv_sec field; only the tv.tv_usec field was unmodified from its original value (causing the assertion). I'm not sure what to make of that.

man gettimeofday on Linux debian 6.1.0-18-amd64 tells me that struct timeval is defined like this:

           struct timeval {
               time_t      tv_sec;     /* seconds */
               suseconds_t tv_usec;    /* microseconds */
           };

Digging through headers, it looks like suseconds_t is the same underlying type as time_t:

64:#define __TIME_T_TYPE		__SYSCALL_SLONG_TYPE
66:#define __SUSECONDS_T_TYPE	__SYSCALL_SLONG_TYPE

man gettimeofday also says "Traditionally, the fields of struct timeval were of type long," which might explain why we're initialising those fields with 32-bit values even though they should be 64-bit fields on a normal time64 system.

What does struct timeval look like on non-time64 platforms?

What happens if you apply this patch? All it does is change that function to actually initialise (and check) the full 64-bits:

diff --git a/cunit/timeofday.c b/cunit/timeofday.c
index 50e121bf1..0c3effd71 100644
--- a/cunit/timeofday.c
+++ b/cunit/timeofday.c
@@ -106,11 +106,12 @@ static time_t to_time_t(int64_t t)
 
 static int64_t now(void)
 {
-    struct timeval tv = { 0xffffffff, 0xffffffff };
+    const int64_t init_val = 0xffffffffffffffff;
+    struct timeval tv = { init_val, init_val };
     int r = real_gettimeofday(&tv, NULL);
     assert(r == 0);
-    assert(tv.tv_sec != 0xffffffff);
-    assert(tv.tv_usec != 0xffffffff);
+    assert(tv.tv_sec != init_val);
+    assert(tv.tv_usec != init_val);
     return from_timeval(&tv);
 }
 

I don't expect it to fix anything, but if it changes the failure, we might learn something from the way the failure changes

[elliefm]

I don't see anything else in this source file that seems sensitive to the size changing, it mostly uses all its own types and only uses time_t et al to interact with the outside.

appears to be cause by calling the non-time64 gettimeofday function from glibc with the time64 definition of struct timeval

I don't see how this could be happening, we only ever use the struct timeval the system headers provide us with, which presumably on a non-time64 system is the non-time64 version.

[guimard]

Hi @elliefm,

I tried the patch but the test still failed on a armel machine
build-cyrus-imapd-with-time_t-patch.log

[elliefm]

Interesting. The assertion is testing that we got some value back from the call other than the one we initialised. So I wonder if perhaps the gettimeofday() on these platforms doesn't have sub-second granularity, and so doesn't ever change the tv.tv_usec field.

In that case, I'd suggest patching out that one assertion and see what happens. We won't have sub-second granularity in our time distortion, but maybe that's fine.

I think the only set of tests that actually use the time distorting features are in search_expr.testc, which so far aren't even running, because the whole test program crashes out much earlier when one of the backend test's set_up functions fails (due to this assert).

[guimard]

Hi @elliefm, I can test some other patches if you want

[guimard]

Interesting. The assertion is testing that we got some value back from the call other than the one we initialised. So I wonder if perhaps the gettimeofday() on these platforms doesn't have sub-second granularity, and so doesn't ever change the tv.tv_usec field.

In that case, I'd suggest patching out that one assertion and see what happens. We won't have sub-second granularity in our time distortion, but maybe that's fine.

No, without patch we have the original issue (see build logs)

I think the only set of tests that actually use the time distorting features are in search_expr.testc, which so far aren't even running, because the whole test program crashes out much earlier when one of the backend test's set_up functions fails (due to this assert).

What can I test now ?

[elliefm]

I didn't mean remove the patch, just remove the failing assert. Here's a new patch, to replace the previous one:

diff --git a/cunit/timeofday.c b/cunit/timeofday.c
index 50e121bf1..eb4aa7240 100644
--- a/cunit/timeofday.c
+++ b/cunit/timeofday.c
@@ -106,11 +106,12 @@ static time_t to_time_t(int64_t t)
 
 static int64_t now(void)
 {
-    struct timeval tv = { 0xffffffff, 0xffffffff };
+    const int64_t init_val = 0xffffffffffffffff;
+    struct timeval tv = { init_val, init_val };
     int r = real_gettimeofday(&tv, NULL);
     assert(r == 0);
-    assert(tv.tv_sec != 0xffffffff);
-    assert(tv.tv_usec != 0xffffffff);
+    assert(tv.tv_sec != init_val);
+//    assert(tv.tv_usec != init_val);
     return from_timeval(&tv);
 }

That will stop the tests from crashing out when microseconds aren't available, and then we'll see what starts failing instead...

[guimard]

Hi @elliefm, it's better but there is another error :

Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...*** stack smashing detected ***: terminated
/bin/bash: line 11: 16247 Aborted                 $vg ./unit $f

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

That looks promising, it made it a lot further before crashing this time. I see a handful of failures from the tests that didn't crash, but that's not surprising. I'll see if I can see a likely cause of the crash, and if so I'll throw you another patch to try.

[elliefm]

The specific error appears to be cause by calling the non-time64 gettimeofday function from glibc with the time64 definition of struct timeval

Oh, I finally understand this comment now, I was confused earlier. These are 32-bit platforms, but they will now have a 64-bit time_t. And yet, this test is somehow calling the 32-bit gettimeofday instead of the 64-bit one, so that's curious. I'll have a look and see if I can figure out why.

I noticed in the build logs a lot of extra warnings, because the build compiles with -O2 rather than -O0, and gcc generally reports a lot more warnings when optimisations are enabled, because it makes a deeper analysis of the code as part of the optimisation. So I'll also do some full builds with optimisations on to reproduce it locally, and see if I can fix the things it warns about.

[elliefm]

Are you able to inject a whole git branch, rather than manually adding individual patches? If you can't inject a git branch, can you inject a github PR?

I've created https://github.com/elliefm/cyrus-imapd/tree/v38/debian-time_t-transition to keep track of the work I'm doing here, hopefully it's easy for you to test the changes I make there, but please let me know what you need. :)

[elliefm]

You can discard the assert patch from a few days ago, now that I understand the gettimeofday problem better it's no longer needed. I think the first commit on my branch should fix cunit/timeofday.testc properly

[guimard]

Hi, I tried this patch but it still fail:

Suite: times
  Test: rfc3501 ...passed
  Test: military_timezones ...passed
  Test: parse_rfc822 ...passed
  Test: gen_rfc822 ...passed
  Test: ctime ...passed
  Test: zerohour ...passed
  Test: parse_iso8601 ...passed
  Test: gen_iso8601 ...passed
  Test: gen_iso8601_secfrac ...FAILED
    1. ./cunit/times.testc:364  - CU_ASSERT_EQUAL(r=36,strlen(DATETIME_STR)=29)
    2. ./cunit/times.testc:365  - CU_ASSERT_STRING_EQUAL(buf="2010-11-26T14:22:02.1411391498+1",DATETIME_STR="2010-11-26T14:22:02.123+11:00")
  Test: leapyear_rfc3501 ...passed
  Test: leapyear_iso8601 ...passed
  Test: leapyear_rfc822 ...passed
  Test: rfc5322 ...passed
  Test: military_timezones_using_rfc5322 ...passed
  Test: leapyear_rfc5322 ...passed
  Test: offsettime_iso8601 ...passed
  Test: offsettime_rfc5322 ...passed
  Test: offsettime_rfc5322_ignore_wday ...passed
[...]
Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...*** stack smashing detected ***: terminated
/bin/bash: line 11: 12591 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

I've made a PR to make it easy to produce a single patch that includes all the fixes I'm trying. Can you try this patch please: https://github.com/cyrusimap/cyrus-imapd/pull/4887.patch

I'm not sure if it will fix the stack smashing problem or not, but it also adds some extra debug logging so that if the problem still happens, hopefully we can see where.

[guimard]

Hi @elliefm , here is the new result:

[...]
Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'bounded rrule'...
*** stack smashing detected ***: terminated
/bin/bash: line 11:  2093 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'
dh_auto_test: error: make -j4 check "TESTSUITEFLAGS=-j4 --verbose" VERBOSE=1 returned exit code 2

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

Thanks, that gets us somewhere! I've just added some more debug logging. Can you download the patch again from the same link (it should be a bit different this time) and try that?

[guimard]

Thanks @elliefm . Here are the new logs:

Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1b49f28
test_icalrecurrenceset_get_utc_timespan: computing span...
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: not recurring okay
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1b49f28
test_icalrecurrenceset_get_utc_timespan: computing span...
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: eternal rrule okay
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1b49f28
test_icalrecurrenceset_get_utc_timespan: computing span...
*** stack smashing detected ***: terminated
/bin/bash: line 11:  3449 Aborted                 $vg ./unit $f

[elliefm]

Thanks, that's narrowed things down! I can see that the stack smashing seems to be happening somewhere in icalrecurrenceset_get_utc_timespan() from imap/ical_support.c. So it's not a bug in the test, it's a bug in the code being tested.

I'll add a bunch more debug logging, and get back to you when I have another patch for you to try. It might take me a couple of days to get back to you, I need to figure out how to usefully log these libical objects! 😅

[elliefm]

I'm assuming libical already builds fine and passes all its tests on these platforms? If libical itself is broken there's not much point debugging Cyrus until it's fixed.

Hmm, this looks like a build log from libical on armel, showing some test failures related to timezones. I don't know if this is the correct build log for the libical being used by Cyrus here, or if it's unrelated.

What I don't see in that build log, though, is the stack being smashed, so I can't trivially blame the stack smashing on libical. I suppose libical might be failing and returning some error flag, and we're not handling it properly and smashing the stack ourselves as a side effect.

[guimard]

Hi, you are looking for an old build log. The package is now named libical3 and passed : https://buildd.debian.org/status/package.php?p=libical3
Here are the armel logs :
https://buildd.debian.org/status/fetch.php?pkg=libical3&arch=armel&ver=3.0.17-1.1%2Bb1&stamp=1712550545&raw=0

[guimard]

Thanks, that's narrowed things down! I can see that the stack smashing seems to be happening somewhere in icalrecurrenceset_get_utc_timespan() from imap/ical_support.c. So it's not a bug in the test, it's a bug in the code being tested.

I'll add a bunch more debug logging, and get back to you when I have another patch for you to try. It might take me a couple of days to get back to you, I need to figure out how to usefully log these libical objects! 😅

Thanks and no problem to wait: Debian 13 will be released around 2025 😉

[kitterma]

...

Thanks and no problem to wait: Debian 13 will be released around 2025 😉

I hope that's a joke. Unless this is solved in the next few weeks, it's going to start impacting the overall t64 transition in Debian.

[elliefm]

@guimard Can you fetch a fresh copy of the patch from the same link as before, and try that please?

I've added a bunch of debug logging to icalrecurrenceset_get_utc_timespan() so we can see more precisely where it gets to before it fails.

I've also made a small-but-real change that might fix an edge case arising from compiling with optimisations enabled on ARM. I'm crossing my fingers that this change fixes the stack smashing problem, but if not, hopefully the extra debug logging at least narrows the search!

Thanks :)

[guimard]

Let's go 😉

[guimard]

I used last commits from v38/debian-time_t-transition, and get the following errors. (I included also warnings about time_t)

...
checking size of time_t... 8
...
checking underlying integer type of `time_t'... long long int
checking printf format string for `time_t'... %lld
checking strtol-like parse function for `time_t'... strtoll
...
imap/http_dav_sharing.c: In function 'dav_store_notification':
imap/http_dav_sharing.c:845:34: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
  845 |     buf_printf(&txn->buf, "<%s-%ld@%s>", resource, time(0), config_servername);
      |                                ~~^                 ~~~~~~~
      |                                  |                 |
      |                                  long int          time_t {aka long long int}
      |                                %lld
...
imap/jmap_backup.c: In function 'restore_collection_cb':
imap/jmap_backup.c:388:42: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
  388 |                "skipping '%s': cutoff (%ld) prior to mailbox history (" TIME_T_FMT")",
      |                                        ~~^
      |                                          |
      |                                          long int
      |                                        %lld
  389 |                mailbox_name(rrock->mailbox), rrock->jrestore->cutoff,
      |                                              ~~~~~~~~~~~~~~~~~~~~~~~
      |                                                             |
      |                                                             time_t {aka long long int}
imap/jmap_backup.c: In function 'jmap_backup_restore_notes':
imap/jmap_backup.c:1423:64: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
 1423 |     syslog(restore.log_level, "jmap_backup_restore_notes(%s, %ld)",
      |                                                              ~~^
      |                                                                |
      |                                                                long int
      |                                                              %lld
 1424 |            subfolder ? subfolder : "NULL", restore.cutoff);
      |                                            ~~~~~~~~~~~~~~
      |                                                   |
      |                                                   time_t {aka long long int}
...
imap/jmap_backup.c: In function 'restore_collection_cb':
imap/jmap_backup.c:388:42: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
  388 |                "skipping '%s': cutoff (%ld) prior to mailbox history (" TIME_T_FMT")",
      |                                        ~~^
      |                                          |
      |                                          long int
      |                                        %lld
  389 |                mailbox_name(rrock->mailbox), rrock->jrestore->cutoff,
      |                                              ~~~~~~~~~~~~~~~~~~~~~~~
      |                                                             |
      |                                                             time_t {aka long long int}
imap/jmap_backup.c: In function 'jmap_backup_restore_notes':
imap/jmap_backup.c:1423:64: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
 1423 |     syslog(restore.log_level, "jmap_backup_restore_notes(%s, %ld)",
      |                                                              ~~^
      |                                                                |
      |                                                                long int
      |                                                              %lld
 1424 |            subfolder ? subfolder : "NULL", restore.cutoff);
      |                                            ~~~~~~~~~~~~~~
      |                                                   |
      |                                                   time_t {aka long long int}
...
Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x910af0
test_icalrecurrenceset_get_utc_timespan: computing span...
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x910af0
test_icalrecurrenceset_get_utc_timespan: computing span...
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'bounded rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x910af0
test_icalrecurrenceset_get_utc_timespan: computing span...
*** stack smashing detected ***: terminated
/bin/bash: line 11:  2023 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

Thanks. Turns out I forgot to push my latest changes last time, whoops! I've just done that now. Can you please fetch a fresh copy and go again?

[guimard]

Hi,

here are the new errors:

checking size of time_t... 8
...
checking underlying integer type of `time_t'... long long int
checking printf format string for `time_t'... %lld
...
checking strtol-like parse function for `time_t'... strtoll
...
imap/http_dav.c: In function 'my_dav_init':
imap/http_dav.c:8509:45: warning: macro "__TIME__" might prevent reproducible builds [-Wdate-time]
 8509 |     time_t compile_time = calc_compile_time(__TIME__, __DATE__);
      |                                             ^~~~~~~~
imap/http_dav.c:8509:55: warning: macro "__DATE__" might prevent reproducible builds [-Wdate-time]
 8509 |     time_t compile_time = calc_compile_time(__TIME__, __DATE__);
      |
...
imap/jmap_backup.c: In function 'restore_collection_cb':
imap/jmap_backup.c:388:42: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
  388 |                "skipping '%s': cutoff (%ld) prior to mailbox history (" TIME_T_FMT")",
      |                                        ~~^
      |                                          |
      |                                          long int
      |                                        %lld
  389 |                mailbox_name(rrock->mailbox), rrock->jrestore->cutoff,
      |                                              ~~~~~~~~~~~~~~~~~~~~~~~
      |                                                             |
      |                                                             time_t {aka long long int}
imap/jmap_backup.c: In function 'jmap_backup_restore_notes':
imap/jmap_backup.c:1423:64: warning: format '%ld' expects argument of type 'long int', but argument 4 has type 'time_t' {aka 'long long int'} [-Wformat=]
 1423 |     syslog(restore.log_level, "jmap_backup_restore_notes(%s, %ld)",
      |                                                              ~~^
      |                                                                |
      |                                                                long int
      |                                                              %lld
 1424 |            subfolder ? subfolder : "NULL", restore.cutoff);
      |                                            ~~~~~~~~~~~~~~       
      |                                                   |
      |                                                   time_t {aka long long int}
...
imap/mbtool.c: In function 'do_timestamp':
imap/mbtool.c:208:13: warning: absolute value function 'labs' given an argument of type 'time_t' {aka 'long long int'} but has parameter of type 'long int' which may cause truncation of value [-Wabsolute-value]
  208 |         if (labs(record->internaldate - record->gmtime) < 86400)
      |             ^~~~
...
Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1058e20
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20160928T170000Z>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1058e20
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY
>
icalrecurrenceset_get_utc_timespan: recur.count is 0, set end of period to eternity
icalrecurrenceset_get_utc_timespan: span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'bounded rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1052a18
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3
>
*** stack smashing detected ***: terminated
/bin/bash: line 11: 22604 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'

build-cyrus-imapd-with-time_t-patch.log

[guimard]

...

Thanks and no problem to wait: Debian 13 will be released around 2025 😉

I hope that's a joke. Unless this is solved in the next few weeks, it's going to start impacting the overall t64 transition in Debian.

Please keep Debian-only comments inside bugs.debian.org. And there is no such issue since cyrus-imapd was automatically removed from testing and will return in it only after having being fixed

[elliefm]

Hmm. Looks like the edge case fix didn't help, but at least the additional logging has narrowed it down a bit more.

I've added some more logging yet again, fingers crossed that maybe this time we might find the culprit! Can you grab a fresh copy of https://github.com/cyrusimap/cyrus-imapd/pull/4887.patch to replace what you already had and try again? Thanks :)

[guimard]

Hi,

here is the result:

Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1964240
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20160928T170000Z>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1964240
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY^M
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'bounded rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x1961aa8
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3^M
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY;COUNT=3>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: about to call utc_timespan_cb for each recurrence
*** stack smashing detected ***: terminated
/bin/bash: line 11:  4259 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

Thanks!

[elliefm]

That's fascinating, we hit "about to call utc_timespan_cb" but didn't hit "utc_timespan_cb: entered". That means it's either something wrong with icalcomponent_foreach_recurrence, or something wrong with how we're calling it.

I've added some more logging again, including pulling some function parameters out into local variables before the call. I don't know if that'll make any difference, but let's see what happens and what it logs...

Can you re-fetch https://github.com/cyrusimap/cyrus-imapd/pull/4887.patch and try again? Thanks :)

[guimard]

Thanks, here are the new logs:

Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x18bb4b8
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20160928T170000Z>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x18bb4b8
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'bounded rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x187f8d8
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY;COUNT=3>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: computing start/end for utc_timespan_cb
icalrecurrenceset_get_utc_timespan: about to call utc_timespan_cb for each recurrence
icalrecurrenceset_get_utc_timespan: with start=<19011213T204552> end=<20380119T031407>
*** stack smashing detected ***: terminated
/bin/bash: line 11:  5375 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134

build-cyrus-imapd-with-time_t-patch.log

[elliefm]

Well then! At this point I'm pretty sure the stack smashing is happening in icalcomponent_foreach_recurrence, which is a libical function, not a Cyrus one. We might be able to put together a regression test for libical that does the same thing this one Cyrus test does, and then send patches up for testing. Are you able to test patches for libical, or will that need to be handled by the libical package maintainer?

In the meantime, I've made one more change, this time it just disables the bit we know is broken. I don't think that's a solution, but it'll let the tests keep running beyond this point, so we can see what else is failing. Can you fetch a fresh copy of https://github.com/cyrusimap/cyrus-imapd/pull/4887.patch and retry please? Thanks :)

[guimard]

Hi,
I'm able to launch a build for libical. I'm going to launch new build

[guimard]

Here is the result:

uite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0xa19be0
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20160928T170000Z>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0xa19be0
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'one bounded rrule, one eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x9e4988
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY;COUNT=3>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: expanding 1th rrule=<RRULE:FREQ=MONTHLY
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=MONTHLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'one bounded rrule, one eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 3 'two bounded rrules'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x9e4988
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY;COUNT=3>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: expanding 1th rrule=<RRULE:FREQ=MONTHLY;UNTIL=20170228T160000Z
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=MONTHLY;UNTIL=20170228T160000Z>
icalrecurrenceset_get_utc_timespan: recur.until exists
icalrecurrenceset_get_utc_timespan: got utc timezone utc=<UTC>
icalrecurrenceset_get_utc_timespan: calculated duration=<PT1H>
icalrecurrenceset_get_utc_timespan: calculated end=<20170228T170000Z>
icalrecurrenceset_get_utc_timespan: updated period=<20160928T160000Z/20170228T170000Z>
icalrecurrenceset_get_utc_timespan: added rrule=<RRULE:FREQ=MONTHLY;UNTIL=20170228T160000Z
> to detached rrules
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: computing start/end for utc_timespan_cb
icalrecurrenceset_get_utc_timespan: about to call utc_timespan_cb for each recurrence
icalrecurrenceset_get_utc_timespan: with start=<19011213T204552> end=<20380119T031407>
*** stack smashing detected ***: terminated
/bin/bash: line 11: 19776 Aborted                 $vg ./unit $f
make[4]: *** [Makefile:9037: check-local] Error 134
make[4]: Leaving directory '/home/yadd/cyrus-imapd'
make[3]: *** [Makefile:7871: check-am] Error 2
make[3]: Leaving directory '/home/yadd/cyrus-imapd'
make[2]: *** [Makefile:7571: check-recursive] Error 1
make[2]: Leaving directory '/home/yadd/cyrus-imapd'
make[1]: *** [Makefile:7873: check] Error 2
make[1]: Leaving directory '/home/yadd/cyrus-imapd'

[elliefm]

Thanks! I've just pushed another patch that disables "two bounded rrules" too. Can you try that please :)

[guimard]

Thanks! I've just pushed another patch that disables "two bounded rrules" too. Can you try that please :)

It's running. So it confirms that the bug is in libical ?

[guimard]

Build and test succeed with your last patch:

Suite: ical_support
  Test: icalrecurrenceset_get_utc_timespan ...test_icalrecurrenceset_get_utc_timespan: trying test 0 'not recurring'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x111b6c0
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20160928T170000Z>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=9
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20160928T170000Z'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'not recurring' okay
test_icalrecurrenceset_get_utc_timespan: trying test 1 'eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x111b6c0
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'eternal rrule' okay
test_icalrecurrenceset_get_utc_timespan: trying test 2 'one bounded rrule, one eternal rrule'...
test_icalrecurrenceset_get_utc_timespan: creating icalcomponent...
test_icalrecurrenceset_get_utc_timespan: okay, ical=0x10ea1c0
test_icalrecurrenceset_get_utc_timespan: computing span...
icalrecurrenceset_get_utc_timespan: initialised span to be nothing: span=<20380119T031407/19011213T204552>
icalrecurrenceset_get_utc_timespan: processing 0th component...
icalrecurrenceset_get_utc_timespan: initialised period to period=<20160928T160000Z/20160928T170000Z>
icalrecurrenceset_get_utc_timespan: expanding 0th rrule=<RRULE:FREQ=WEEKLY;COUNT=3
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=WEEKLY;COUNT=3>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: expanding 1th rrule=<RRULE:FREQ=MONTHLY
>
icalrecurrenceset_get_utc_timespan: recur=<FREQ=MONTHLY>
icalrecurrenceset_get_utc_timespan: recur.count is 0, setting end of period to eternity
icalrecurrenceset_get_utc_timespan: period=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished with this rrule, about to try next
icalrecurrenceset_get_utc_timespan: fininished expanding rrules
icalrecurrenceset_get_utc_timespan: finished component span=<20160928T160000Z/20380119T031407>
icalrecurrenceset_get_utc_timespan: finished, returning span=<20160928T160000Z/20380119T031407>
test_icalrecurrenceset_get_utc_timespan: okay, span.start.month=9 span.end.month=1
test_icalrecurrenceset_get_utc_timespan: converting to strings...
test_icalrecurrenceset_get_utc_timespan: okay, start='20160928T160000Z', end='20380119T031407'
test_icalrecurrenceset_get_utc_timespan: finished, freeing temporaries...
test_icalrecurrenceset_get_utc_timespan: test 'one bounded rrule, one eternal rrule' okay
passed
Suite: http_jwt
  Test: init_multi ...passed
  Test: init_nokeys ...passed
  Test: validate ...passed
  Test: auth ...passed
Suite: jmap_util
  Test: patchobject_create ...passed
  Test: decode_to_utf8 ...passed
  Test: caleventid ...passed

Run Summary:    Type  Total    Ran Passed Failed Inactive
              suites     53     53    n/a      0        0
               tests    568    568    568      0        0
             asserts 851626 851626 851626      0      n/a

[elliefm]

It's running. So it confirms that the bug is in libical ?

I think it confirms that the stack smashing is occurring inside libical. It's not yet known whether that's because of a bug in libical, or a bug in how we're calling it.

I guess it could also be an architectural limitation -- perhaps this platform doesn't provide enough stack space for libical to work with, or something. I don't know much about the gcc stack protector functionality, so I don't know if simply running out of stack space would cause this particular symptom.

My next step will be putting together a regression test for libical that runs as close to the same code as possible as these cyrus tests, and providing that as a patch against libical, so we can try to reproduce it there. If we can, hopefully we can then add enough diagnostic information to the test to isolate the problem, like we've been doing here.

[elliefm]

Build and test succeed with your last patch

Great! At least now we know there's no other obvious problems on this platform. :)

Is the package build system able to run Cassandane?

[guimard]

Build and test succeed with your last patch

Great! At least now we know there's no other obvious problems on this platform. :)

Is the package build system able to run Cassandane?

Hi, I think I provided all Cyrus's features in my package. So I think the response is yes 😉

[guimard]

@elliefm, what can I do to help here ?

[guimard]

Hi @elliefm, do you plan to work on this issue ?

[elliefm]

I haven't made any progress in figuring out how to patch libical to keep investigating the stack smashing on armel/armhf, and I'm probably not going to get around to that. From what I can tell, these architectures are mostly used by mobile phones, old Raspberry Pis, etc. There's no good reason to run a real IMAP server on those, so it's not a priority for us. It would be fine with us if Debian just didn't package Cyrus-IMAP for those architectures.

There was a few good commits in my draft PR, and I would like to clean that up and get the good bits landed. I hope to do that soon, cause it's on my list and I would like to cross it off!