cyrusimap / cyrus-imapd

Cyrus IMAP is an email, contacts and calendar server
http://cyrusimap.org
Other
517 stars 142 forks source link

Build/test fail on architectures affected by the time_t transition #4876

Open guimard opened 2 months ago

guimard commented 2 months ago

From Debian #1068223.

cyrus-imapd is failing to build on the architectures affected by the timet 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 commented 2 months ago

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 commented 2 months ago

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 commented 1 month ago

Hi @elliefm,

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

elliefm commented 1 month ago

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 commented 1 month ago

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

guimard commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 :wink:

kitterma commented 1 month ago

...

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 commented 1 month ago

@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 commented 1 month ago

Let's go :wink:

guimard commented 1 month ago

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

...
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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

...

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

Thanks!

elliefm commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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

guimard commented 1 month ago

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 commented 1 month ago

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

guimard commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

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 :wink:

guimard commented 2 weeks ago

@elliefm, what can I do to help here ?