|
Comparing another user with a similar problem, it seems that the issue is linked to repeated events.
The last user had 1 single event repeated every Monday. Removing the event repetition allowed to download the freebusy.ifb file without any issue.
If I sent the end of repetition, it works too, but more distant in the future I put the end of the repetition, longer it takes to generate the freebusy (i.e. 14 secs for end in 2030, 1 sec for end in 2019).
I think I should change the title of the ticket now... |
|
|
And it seems that when a sogod process is taking 100% cpu trying to handle the repetition, its memory consumption grows, from 0.2% memory like to the other sogod workers to 15%, 20%, 30%, growing ever more until is killed.
So if we have multiple sogo workers that start hoarding memory, we start swapping and the server slows to a crawl... |
|
|
On a side note, changing SOGoFreeBusyDefaultInterval seems having no effect. My starting value is (7,30), but decreasing progressively does not have any effect.
even at (1,1) the sogod worker process takes 100% cpu and start hoarding memory. |
|
|
Another useful info: it seems that repeating events are not included at all in the freebusy.ifb file returned, even when their repetition is limited in time (i.e. weekly event that stops after 4 repetitions) and the sogod does not crash. More info below.
I take a newly generated account, with an empty calendar, and I download the freebusy.ifb via wget (after giving to Public permission to view Date & Time for public and confidential events).
No problems, it downloads a file with no events:
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 3.2.10//EN
VERSION:2.0
BEGIN:VFREEBUSY
ATTENDEE:mailto:ciccio@domain
DTSTAMP:20170928T144057Z
DTSTART:117612381011T000000Z
DTEND:20171027T220000Z
END:VFREEBUSY
END:VCALENDAR
If I put a single event tomorrow, with weekly repetition and no end, one sogo worker starts taking 100% cpu and hoarding memory. I have now a script that checks every 5 seconds if a sogod process takes more than 1GB of ram and kills it, so I get rather rapidly:
HTTP request sent, awaiting response... 502 Proxy Error
2017-09-28 16:43:31 ERROR 502: Proxy Error.
If I limit the repetition to 4 times only, it downloads exactly the same ifb file then before, the only difference being the DTSTAMP field. So the freebusy file seems not built correctly.
If I put a simple, not repeating event tomorrow (just before the event being repeated 4 times), I get a freebusy ifb that only mention the non repeating event:
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 3.2.10//EN
VERSION:2.0
BEGIN:VFREEBUSY
ATTENDEE:mailto:ciccio@domain
DTSTAMP:20170928T145040Z
DTSTART:117612381011T000000Z
DTEND:20171027T220000Z
FREEBUSY;FBTYPE=BUSY:20170929T124500Z/20170929T134500Z
END:VFREEBUSY
END:VCALENDAR
Maybe this could shed some light on the issue? |
|
|
Just installed a clean machine, installed iReadMail 0.9.7 with sogo-3.2.10.20180116-1.el7.centos.x86_64.
With only one user (the default postmaster of iReadMail), with 1 single weekly repeating event I have the same problem.
I only add to the default settings:
/ For Freebusy info /
SOGoEnablePublicAccess=YES;
SOGoFreeBusyDefaultInterval = (7,30);
in sogo.conf,
and when I do from another machine
wget --no-check-certificate https://${MACHINE}/SOGo/dav/public/postmaster@${DOMAIN}/freebusy.ifb
I get a series of
HTTP request sent, awaiting response... 504 Gateway Time-out
Retrying.
In the meantime I see a sogod taking 100% and slowing increasing the memory use.
When there is the timeout, another sogod process starts taking 100% and slowly increasing the memory use.
I am really surprised that no-one else has this problem.
I could provide the vm (lxc centos7 image) if necessary.
Is there any way to pay for a bounty or buy a reasonable support package from Inverse to fix this? I surely cannot afford the platinum support package that it is it seems the only one that promise bug fixes. |
|
|
Possible explaination.
Consider an event like this (it repeats only 30 times):
###########
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 3.2.10//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:America/New_York
X-LIC-LOCATION:America/New_York
BEGIN:DAYLIGHT
TZOFFSETFROM:-0500
TZOFFSETTO:-0400
TZNAME:EDT
DTSTART:19700308T020000
RRULE:FREQ=YEARLY;BYMONTH=3;BYDAY=2SU
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:-0400
TZOFFSETTO:-0500
TZNAME:EST
DTSTART:19701101T020000
RRULE:FREQ=YEARLY;BYMONTH=11;BYDAY=1SU
END:STANDARD
END:VTIMEZONE
BEGIN:VEVENT
UID:2FF-5A61F880-1-7D603A80
SUMMARY:Testing repetition
CLASS:PUBLIC
TRANSP:OPAQUE
DTSTART;TZID=America/New_York:20180119T150000
DTEND;TZID=America/New_York:20180119T160000
CREATED:20180119T135442Z
DTSTAMP:20180119T135442Z
LAST-MODIFIED:20180119T150145Z
RRULE:FREQ=WEEKLY;COUNT=30
SEQUENCE:1
END:VEVENT
END:VCALENDAR
################
Now I have the (7,30) like SOGoFreeBusyDefaultInterval, and when I go the wget of the freebusy I get:
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 3.2.10//EN
VERSION:2.0
BEGIN:VFREEBUSY
ATTENDEE:mailto:USER@DOMAIN
DTSTAMP:20180119T150456Z
DTSTART:117612390201T050000Z
DTEND:20180218T050000Z
FREEBUSY;FBTYPE=BUSY:20180223T200000Z/20180223T210000Z
FREEBUSY;FBTYPE=BUSY:20180302T200000Z/20180302T210000Z
FREEBUSY;FBTYPE=BUSY:20180309T200000Z/20180309T210000Z
FREEBUSY;FBTYPE=BUSY:20180316T190000Z/20180316T200000Z
FREEBUSY;FBTYPE=BUSY:20180323T190000Z/20180323T200000Z
FREEBUSY;FBTYPE=BUSY:20180330T190000Z/20180330T200000Z
FREEBUSY;FBTYPE=BUSY:20180406T190000Z/20180406T200000Z
FREEBUSY;FBTYPE=BUSY:20180413T190000Z/20180413T200000Z
FREEBUSY;FBTYPE=BUSY:20180420T190000Z/20180420T200000Z
FREEBUSY;FBTYPE=BUSY:20180427T190000Z/20180427T200000Z
FREEBUSY;FBTYPE=BUSY:20180504T190000Z/20180504T200000Z
FREEBUSY;FBTYPE=BUSY:20180511T190000Z/20180511T200000Z
FREEBUSY;FBTYPE=BUSY:20180518T190000Z/20180518T200000Z
FREEBUSY;FBTYPE=BUSY:20180525T190000Z/20180525T200000Z
FREEBUSY;FBTYPE=BUSY:20180601T190000Z/20180601T200000Z
FREEBUSY;FBTYPE=BUSY:20180608T190000Z/20180608T200000Z
FREEBUSY;FBTYPE=BUSY:20180615T190000Z/20180615T200000Z
FREEBUSY;FBTYPE=BUSY:20180622T190000Z/20180622T200000Z
FREEBUSY;FBTYPE=BUSY:20180629T190000Z/20180629T200000Z
FREEBUSY;FBTYPE=BUSY:20180706T190000Z/20180706T200000Z
FREEBUSY;FBTYPE=BUSY:20180713T190000Z/20180713T200000Z
FREEBUSY;FBTYPE=BUSY:20180720T190000Z/20180720T200000Z
FREEBUSY;FBTYPE=BUSY:20180727T190000Z/20180727T200000Z
FREEBUSY;FBTYPE=BUSY:20180803T190000Z/20180803T200000Z
FREEBUSY;FBTYPE=BUSY:20180810T190000Z/20180810T200000Z
END:VFREEBUSY
END:VCALENDAR
it looks like the freebusy is not looking within the -7 and +30 days of the DefaultInterval, but after 30 days...
It is possible a negation has been lost somewhere? |
|
|
If in ics You add UNTIL (for example: RRULE:FREQ=YEARLY;BYMONTH=11;BYDAY=1SU;UNTIL=20201231), should work properly and .ibf file will be generate.
But This is still debugging, not a solution.
Some problems with Repetitive events ? |
|
|
And some logs:
sogod[26313:26313] EXCEPTION: <NSException: 0x56322e876990> NAME:NSInternalInconsistencyException REASON:NSIncrementExtraRefCount() asked to increment too far INFO:(null)
sogod [26313]: |SOGo| request took 48.906093 seconds to execute
sogod [26313]: xxx.xxx.xxx.xxx, xxx.xxx.xxx.xxx "GET /SOGo/dav/public/XXXXXX/freebusy.ifb HTTP/1.1" 501 0/0 48.910 - - 2524M
GET request has grown up to ~2500M |
|
|
Hello Nterowski,
The biggest issue I am afraid is that sogo seems to look outside the
SOGoFreeBusyDefaultInterval...
So if you have an event that always repeat, the process goes on collecting info until it exhaust the memory... |
|
|
@Nterowski
Regarding the exception you get, please generate a stack trace.
https://sogo.nu/support/faq/how-do-i-debug-sogo.html |
|
|
Hi,
I'am facing the same error.
I created a fresh SOGO-User account to run the test
Created a none repeating calender event
When I now request the freebusy URL the result is correct
https://sogo.xyz.de/SOGo/dav/public/test01/freebusy.ifb
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 4.0.0//EN
VERSION:2.0
BEGIN:VFREEBUSY
ATTENDEE:mailto:test01@xyz.de
DTSTAMP:20180309T163053Z
DTSTART:117612390321T230000Z
DTEND:20180315T230000Z
FREEBUSY;FBTYPE=BUSY:20180310T110000Z/20180310T114500Z
END:VFREEBUSY
END:VCALENDAR
When I now create a second calender event repeating each day and fetch the same URL sogod is consuming 100% CPU and is using more and more and more memory
The following messages are written into the SOGo-Log
Mar 09 17:37:44 sogod [3730]: [WARN] <0x0x55b025fb0260[WOWatchDogChild]> pid 3731 has been hanging in the same request for 1 minutes
Mar 09 17:38:44 sogod [3730]: [WARN] <0x0x55b025fb0260[WOWatchDogChild]> pid 3731 has been hanging in the same request for 2 minutes
Mar 09 17:39:44 sogod [3730]: [WARN] <0x0x55b025fb0260[WOWatchDogChild]> pid 3731 has been hanging in the same request for 3 minutes
Mar 09 17:40:44 sogod [3730]: [WARN] <0x0x55b025fb0260[WOWatchDogChild]> pid 3731 has been hanging in the same request for 4 minutes
Mar 09 17:41:44 sogod [3730]: [WARN] <0x0x55b025fb0260[WOWatchDogChild]> pid 3731 has been hanging in the same request for 5 minutes
I tested with SOGo 3.2.10 and SOGo 4.0.0 still the same behaviour
Best regards
Harald |
|
|
Hello Nterowski,
is there any progress regarding this issue?
Is there possibly an approximate date on which a correction can be expected?
Best regards
Harald |
|
|
Meanwhile we are running Version 4.0.1 (@shiva2.inverse 201808090043), but still the same error. |
|
|
I have a subscription but did not have the time to install a server with the official rpms instead of the nightly, I suppose the problem is there as well.. |
|
|
On stable 4.0.3-1.el7.centos on a new server, still an issue.
If you change the number of repeats for a recurrent event, the freebusy file will report all the occurrences (i.e. 30, 200, 3000...) without respecting SOGoFreeBusyDefaultInterval.
Even commenting it out from the config file (and therefore assuming a sane default) does not change affect it.
As it stands this means that SOGo cannot inter-operate with outlook users and we will be probably forced to look elsewhere.
As interim we would be satisfied with something like what proposed here (https://community.nethserver.org/t/sogo-outlook-free-busy-information/6809/6) where a script parses the output of sogo-tool.
Pity that the source code is not available. |
|
|
@rongten
Thank you for testing!
I hope the SOGo-team will fix this issue soon because it's a show-stopper to us. |
|
|
@ludovic
I have seen that in version 4.0.5 some ActiveSync fixes are included. Is there a chance that this problem here is also fixed? |
|
|
I've tested everything with v4.0.6 and I don't have any issue - SOGoFreeBusyDefaultInterval is respected.
If you have a hanging child, please attach to it using gdb and produce a stack trace. Before doing so, install SOPE, SOGo and GNUstep debugging packages and restart SOGo. |
|
|
Hello Ludovic,
I just tested on an ubuntu 18.04 (to see if the problem is linked to centos), sogo 4.0.7-1, fresh install (up to the version my subscription allows), I have exactly the same issue.
With 1 recurring weekly event, sogo daemon 100% cpu time, wget the freebusy file hangs, and I need to kill the sogo process by hand.
If I define a recurring weekly event that repeats 100 times starting today 5th of March, I get a ifb where the first event is a
FREEBUSY;FBTYPE=BUSY:20190409T100000Z/20190409T110000Z
and the last one is
FREEBUSY;FBTYPE=BUSY:20210126T110000Z/20210126T120000Z
Where 2021/01/26 is exactly the last occurrence of the repeating event.
Please note that the freebusy reports correctly a dummy event the 2019/03/07 but not one the 2019/03/28 as for the SOGoFreeBusyDefaultInterval, so the problem is only with recurring events. |
|
|
Changing the interval of the event does not affect the behavior: daily, weekly, monthly and yearly events all give the same error.
Enabling SQL debug we can see that the sql queries correctly identify the non repetitive events and the repetitive events inside the FreeBusy interval (from SOPE/GDLContentStore/GCSFolder.m I think), but after it seems that it cannot process correctly the repeating event (the RRULE:FREQ=WEEKLY;COUNT=100 settings for example).
I do not know where it expands the recurring event, in sogo/SoObjects/Appointments/SOGoFreeBusyObject.m maybe? Is not very clear to me.. |
|
|
Hello Ludovic,
I also tested this in our environment (Version 4.0.7 (@shiva2.inverse 201903070216).
If at least one recurring event exist in the account cpu usage on the server climbs up to 100% when the freebusy request for the account is made.
Still the same behavior as described last year https://sogo.nu/bugs/view.php?id=4289#c12646 |
|
|
@sy-subrc - please show me the full iCalendar data for that event. |
|
|
@ludovic
I created a PDF with detailed information.
You can download the document here:
https://filehorst.de/d/ctqhItkp |
|
|
It works for me.
Show your complete list of installed SOPE, SOGo and GNUstep packages. |
|
|
Personally I have
dpkg -l | grep -i -e sope -e sogo -e gnustep
ii gnustep-base-common 1.25.1-2ubuntu3 all GNUstep Base library - common files
ii gnustep-base-runtime 1.25.1-2ubuntu3 amd64 GNUstep Base library - daemons and tools
ii gnustep-common 2.7.0-3 amd64 Common files for the core GNUstep environment
ii gnustep-make 2.7.0-3 all GNUstep build system
ii libgnustep-base1.25 1.25.1-2ubuntu3 amd64 GNUstep Base library
ii libsope-appserver4.9 4.9.r1664.20190221 amd64 SOPE application server libraries
ii libsope-core4.9 4.9.r1664.20190221 amd64 Core libraries of the SOPE application server
ii libsope-gdl1-4.9 4.9.r1664.20190221 amd64 GNUstep database libraries for SOPE
ii libsope-ldap4.9 4.9.r1664.20190221 amd64 SOPE libraries for LDAP access
ii libsope-mime4.9 4.9.r1664.20190221 amd64 SOPE libraries for MIME processing
ii libsope-xml4.9 4.9.r1664.20190221 amd64 SOPE libraries for XML processing
ii sogo 4.0.7-1 amd64 a modern and scalable groupware
ii sogo-dbg 4.0.7-1 amd64 a modern and scalable groupware - debugging symbols
ii sope4.9-gdl1-mysql 4.9.r1664.20190221 amd64 MySQL connector for SOPE's fork of the GNUstep database environment
ii sope4.9-gdl1-postgresql 4.9.r1664.20190221 amd64 PostgreSQL connector for SOPE's fork of the GNUstep database environment
ii sope4.9-libxmlsaxdriver 4.9.r1664.20190221 amd64 XML Parser for SOPE's SAX engine
Just installed sogo-dbg, will try to see if I am able to use it. |
|
|
Running in gdb, and giving Cntrl-c when the wget is hanging gives the following bt:
2019-03-18 09:45:33.917 sogod[6165:6165] PG0x0x555555996700 SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'LOGIN' AND c_folder_type = 'Appointment'
2019-03-18 09:45:33.918 sogod[6165:6165] PG0x0x555555996700 SQL: SELECT c_folder_id, c_path, c_location, c_quick_location, c_acl_location, c_folder_type FROM sogo_folder_info WHERE c_path1 = 'Users' AND c_path2 = 'LOGIN' AND c_path3 = 'Calendar' AND c_path4 = 'personal'
2019-03-18 09:45:33.919 sogod[6165:6165] PG0x0x555555996700 SQL: SELECT c_uid, c_object, c_role FROM sogoLOGIN0015516d229_acl WHERE (c_object = '/LOGIN/Calendar/personal') AND ((c_uid = 'anonymous') OR (c_uid LIKE '@%'))
2019-03-18 09:45:33.920 sogod[6165:6165] PG0x0x555555996700 SQL: SELECT b.c_content,a.c_partmails,a.c_partstates,a.c_isopaque,a.c_status,a.c_cycleinfo,a.c_orgmail,b.c_name,a.c_uid,a.c_startdate,a.c_enddate,a.c_isallday FROM sogoLOGIN0015516d229_quick a, sogoLOGIN0015516d229 b WHERE ((c_component = 'vevent') AND (c_classification = 0) AND ((c_startdate IS NULL) OR (c_startdate <= 1553468400)) AND ((c_enddate IS NULL) OR (c_enddate >= 1552262400)) AND (c_iscycle = 0)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)
2019-03-18 09:45:33.921 sogod[6165:6165] PG0x0x555555996700 SQL: SELECT b.c_content,a.c_partmails,a.c_partstates,a.c_isopaque,a.c_status,a.c_cycleinfo,a.c_orgmail,b.c_name,a.c_uid,a.c_startdate,a.c_enddate,a.c_isallday FROM sogoLOGIN0015516d229_quick a, sogoLOGIN0015516d229 b WHERE ((c_component = 'vevent') AND (c_classification = 0) AND ((c_startdate IS NULL) OR (c_startdate <= 1553468400)) AND ((c_cycleenddate IS NULL) OR (c_cycleenddate >= 1552262400)) AND (c_iscycle = 1)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)
^C
Program received signal SIGINT, Interrupt.
0x00007ffff52df1a5 in ?? () from /usr/lib/libgnustep-base.so.1.25
(gdb) bt
#0 0x00007ffff52df1a5 in ?? () from /usr/lib/libgnustep-base.so.1.25
0000001 0x00007ffff6034038 in -[NSCalendarDate(misc) dateByAddingYears:months:days:] (self=0x555555f179b0, _cmd=0x7ffff7264780 <_OBJC_SELECTOR_TABLE+192>,
_years=0, _months=0, _days=2927351) at NSCalendarDate+misc.m:440
0000002 0x00007ffff703c9c0 in -[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00,
_cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>, _r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:143
0000003 0x00007ffff7036364 in +[iCalRecurrenceCalculator _fillRanges:fromRules:withinRange:startingWithDate:] (
self=0x7ffff725f8a0 <_OBJC_Class_iCalRecurrenceCalculator>, _cmd=0x7ffff725fb20 <_OBJC_SELECTOR_TABLE+512>, ranges=0x555555f22ff0,
rrules=0x555555f22070, limits=0x555555f21b40, first=0x555555f1f2d0) at iCalRecurrenceCalculator.m:133
0000004 0x00007ffff7036b95 in +[iCalRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:firstInstanceCalendarDateRange:recurrenceRules:exceptionRules:recurrenceDates:exceptionDates:] (self=0x7ffff725f8a0 <_OBJC_Class_iCalRecurrenceCalculator>, _cmd=0x7fffe9363980 <_OBJC_SELECTOR_TABLE+2272>,
_r=0x555555f21b40, _fir=0x555555f1f2d0, _rRules=0x555555f22070, _exRules=0x555555f221e0, _rDates=0x555555f21d60, _exDates=0x555555f21b70)
at iCalRecurrenceCalculator.m:268
0000005 0x00007fffe91204af in -[SOGoAppointmentFolder flattenCycleRecord:forRange:intoArray:withCalendar:] (self=0x555555b75200,
_cmd=0x7fffe9363a00 <_OBJC_SELECTOR_TABLE+2400>, theRecord=0x555555ed96e0, theRange=0x555555ed8b00, theRecords=0x555555ed8ac0, calendar=0x555555f00fd0)
at SOGoAppointmentFolder.m:1355
0000006 0x00007fffe9120956 in -[SOGoAppointmentFolder _flattenCycleRecords:fetchRange:] (self=0x555555b75200, _cmd=0x7fffe9363ad0 <_OBJC_SELECTOR_TABLE+2608>,
_records=0x555555ed9450, _r=0x555555ed8b00) at SOGoAppointmentFolder.m:1421
0000007 0x00007fffe91218f6 in -[SOGoAppointmentFolder fetchFields:from:to:title:component:additionalFilters:includeProtectedInformation:] (self=0x555555b75200,
_cmd=0x7fffe9364300 <_OBJC_SELECTOR_TABLE+4704>, _fields=0x555555e93a10, _startDate=0x555555e87900, _endDate=0x555555e87a40, title=0x0,
_component=0x7fffe9360240 <_OBJC_INSTANCE_43>, filters=0x0, _includeProtectedInformation=1 '\001') at SOGoAppointmentFolder.m:1643
0000008 0x00007fffe912704b in -[SOGoAppointmentFolder fetchFreeBusyInfosFrom:to:] (self=0x555555b75200, _cmd=0x7fffe936b480 <_OBJC_SELECTOR_TABLE+992>,
_startDate=0x555555e87900, _endDate=0x555555e87a40) at SOGoAppointmentFolder.m:2900
0000009 0x00007fffe9132284 in -[SOGoFreeBusyObject fetchFreeBusyInfosFrom:to:] (self=0x555555e6dca0, _cmd=0x7fffe936b420 <_OBJC_SELECTOR_TABLE+896>,
startDate=0x555555e87900, endDate=0x555555e87a40) at SOGoFreeBusyObject.m:334
0000010 0x00007fffe91320bb in -[SOGoFreeBusyObject fetchFreeBusyInfosFrom:to:forContact:] (self=0x555555e6dca0, _cmd=0x7fffe936b390 <_OBJC_SELECTOR_TABLE+752>,
startDate=0x555555e87900, endDate=0x555555e87a40, uid=0x0) at SOGoFreeBusyObject.m:300
0000011 0x00007fffe9131d4b in -[SOGoFreeBusyObject contentAsStringWithMethod:andUID:andOrganizer:andContact:from:to:] (self=0x555555e6dca0,
_cmd=0x7fffe936b3b0 <_OBJC_SELECTOR_TABLE+784>, method=0x0, UID=0x0, organizer=0x0, contactID=0x0, _startDate=0x555555e87900, _endDate=0x555555e87a40)
at SOGoFreeBusyObject.m:234
0000012 0x00007fffe9131df9 in -[SOGoFreeBusyObject contentAsStringFrom:to:] (self=0x555555e6dca0, _cmd=0x7fffe936b380 <_OBJC_SELECTOR_TABLE+736>,
_startDate=0x555555e87900, _endDate=0x555555e87a40) at SOGoFreeBusyObject.m:251
0000013 0x00007fffe9131cea in -[SOGoFreeBusyObject contentAsString] (self=0x555555e6dca0, _cmd=0x7fffe936b580 <_OBJC_SELECTOR_TABLE+1248>)
at SOGoFreeBusyObject.m:222
0000014 0x00007fffe9132a45 in -[SOGoFreeBusyObject GETAction:] (self=0x555555e6dca0, _cmd=0x55555589f7c0, _ctx=0x555555e12e40) at SOGoFreeBusyObject.m:421
0000015 0x00007ffff6ca29c2 in -[SoSelectorInvocation primaryCallSelector:withArguments:] (self=0x555555e7e4f0, _cmd=0x7ffff6fde9c0 <_OBJC_SELECTOR_TABLE+992>,
_sel=0x55555589f7c0, _args=0x555555e7e540) at SoSelectorInvocation.m:226
0000016 0x00007ffff6ca30e7 in -[SoSelectorInvocation callOnObject:inContext:] (self=0x555555e7e4f0, _cmd=0x7ffff6fde920 <_OBJC_SELECTOR_TABLE+832>,
_client=0x555555e6dca0, _ctx=0x555555e12e40) at SoSelectorInvocation.m:323
0000017 0x00007ffff6ca2d01 in -[SoSelectorInvocation callOnObject:inContext:] (self=0x555555c50690, _cmd=0x7ffff6ff28c0 <_OBJC_SELECTOR_TABLE+480>,
_client=0x555555e6dca0, _ctx=0x555555e12e40) at SoSelectorInvocation.m:280
0000018 0x00007ffff6cb3156 in -[SoObjectWebDAVDispatcher doGET:] (self=0x555555e405c0, _cmd=0x5555558e3560, _ctx=0x555555e12e40)
at SoObjectWebDAVDispatcher.m:192
0000019 0x00007ffff6cb95b3 in -[SoObjectWebDAVDispatcher performMethod:inContext:] (self=0x555555e405c0, _cmd=0x7ffff6ff3110 <_OBJC_SELECTOR_TABLE+2608>,
_method=0x7ffff6f6a720 <_OBJC_INSTANCE_4>, _ctx=0x555555e12e40) at SoObjectWebDAVDispatcher.m:1740
0000020 0x00007ffff6cb98a6 in -[SoObjectWebDAVDispatcher dispatchInContext:] (self=0x555555e405c0, _cmd=0x7ffff6fd5920 <_OBJC_SELECTOR_TABLE+1536>,
_ctx=0x555555e12e40) at SoObjectWebDAVDispatcher.m:1775
0000021 0x00007ffff6c93e60 in -[SoObjectRequestHandler handleRequest:inContext:session:application:] (self=0x555555c53a80,
_cmd=0x7ffff6f56b10 <_OBJC_SELECTOR_TABLE+848>, _rq=0x555555bdd4f0, _ctx=0x555555e12e40, _sn=0x0, app=0x555555bbf630) at SoObjectRequestHandler.m:584
0000022 0x00007ffff6c17fb0 in -[WORequestHandler handleRequest:] (self=0x555555c53a80, _cmd=0x7ffff6f1f1d0 <_OBJC_SELECTOR_TABLE+1616>, _request=0x555555bdd4f0)
at WORequestHandler.m:237
0000023 0x00007ffff6bd8214 in -[WOCoreApplication dispatchRequest:usingHandler:] (self=0x555555bbf630, _cmd=0x7ffff6f1f220 <_OBJC_SELECTOR_TABLE+1696>,
---Type <return> to continue, or q <return> to quit---
_request=0x555555bdd4f0, handler=0x555555c53a80) at WOCoreApplication.m:712
0000024 0x00007ffff6bd852d in -[WOCoreApplication dispatchRequest:] (self=0x555555bbf630, _cmd=0x555555764520 <_OBJC_SELECTOR_TABLE+1664>,
_request=0x555555bdd4f0) at WOCoreApplication.m:752
0000025 0x000055555555cdc5 in -[SOGo dispatchRequest:] (self=0x555555bbf630, _cmd=0x7ffff6fbcf80 <_OBJC_SELECTOR_TABLE+1760>, _request=0x555555bdd4f0)
at SOGo.m:584
0000026 0x00007ffff6c823b7 in -[WOHttpTransaction _run] (self=0x555555dffc20, _cmd=0x7ffff6fbcfb0 <_OBJC_SELECTOR_TABLE+1808>) at WOHttpTransaction.m:566
0000027 0x00007ffff6c8272d in -[WOHttpTransaction run] (self=0x555555dffc20, _cmd=0x7ffff6fbacf0 <_OBJC_SELECTOR_TABLE+1168>) at WOHttpTransaction.m:619
0000028 0x00007ffff6c7e3b6 in -[WOHttpAdaptor runConnection:] (self=0x555555deb950, _cmd=0x7ffff6fbad90 <_OBJC_SELECTOR_TABLE+1328>, _socket=0x555555dfc060)
at WOHttpAdaptor.m:373
0000029 0x00007ffff6c7e5d6 in -[WOHttpAdaptor _handleAcceptedConnection:] (self=0x555555deb950, _cmd=0x7ffff6fbada0 <_OBJC_SELECTOR_TABLE+1344>,
_connection=0x555555dfc060) at WOHttpAdaptor.m:407
0000030 0x00007ffff6c7e9dc in -[WOHttpAdaptor _handleConnection:] (self=0x555555deb950, _cmd=0x7ffff6fbae40 <_OBJC_SELECTOR_TABLE+1504>,
connection=0x555555dfc060) at WOHttpAdaptor.m:466
0000031 0x00007ffff6c7ee7b in -[WOHttpAdaptor acceptConnection:] (self=0x555555deb950, _cmd=0x7ffff6fbacb0 <_OBJC_SELECTOR_TABLE+1104>,
_notification=0x555555dfb3e0) at WOHttpAdaptor.m:527
0000032 0x00007ffff538004e in ?? () from /usr/lib/libgnustep-base.so.1.25
0000033 0x00007ffff603aa49 in -[NSObject(FileObjectWatcher) receivedEvent:type:extra:forMode:] (self=0x555555deb3b0, _cmd=0x7ffff58fb1d0, _fdData=0x6,
_type=ET_RDESC, _extra=0x6, _mode=0x7ffff58832c0) at NSRunLoop+FileObjects.m:58
0000034 0x00007ffff5496641 in ?? () from /usr/lib/libgnustep-base.so.1.25
0000035 0x00007ffff53c8913 in ?? () from /usr/lib/libgnustep-base.so.1.25
0000036 0x00007ffff53c85e4 in ?? () from /usr/lib/libgnustep-base.so.1.25
0000037 0x00007ffff6bd7a44 in -[WOCoreApplication run] (self=0x555555bbf630, _cmd=0x555555764280 <_OBJC_SELECTOR_TABLE+992>) at WOCoreApplication.m:584
0000038 0x000055555555bf0c in -[SOGo run] (self=0x555555bbf630, _cmd=0x7ffff6f41db0 <_OBJC_SELECTOR_TABLE+208>) at SOGo.m:337
0000039 0x00007ffff6c023ea in WOApplicationMain (_appClassName=0x5555557620c0 <_OBJC_INSTANCE_0>, argc=13, argv=0x7fffffffebe8) at WOApplicationMain.m:42
0000040 0x00007ffff6c23971 in WOWatchDogApplicationMain (appName=0x5555557620c0 <_OBJC_INSTANCE_0>, argc=13, argv=0x7fffffffebe8)
at WOWatchDogApplicationMain.m:1049
0000041 0x000055555555aaa3 in main (argc=13, argv=0x7fffffffebe8, env=0x7fffffffec58) at sogod.m:51 |
|
|
The runaway behavior is observed as well during a debug session.
If i do a break as b iCalWeeklyRecurrenceCalculator.m:143 and then i just step into all the functions, I see that there is a loop where
[NSCalendarDate(misc) dateByAddingYears:months:days:] (self=0x555555f179b0, _cmd=0x7ffff7264780 <_OBJC_SELECTOR_TABLE+192>, _years=0, _months=0, _days=XXX)
is called over and over again in steps of 7 (273,280,287)...
This is the loop that seems to be repeating over and over:
-[NSCalendarDate(misc) dateByAddingYears:months:days:] (self=0x555555f179b0, _cmd=0x7ffff7264780 <_OBJC_SELECTOR_TABLE+192>, _years=0, _months=0, _days=280)
at NSCalendarDate+misc.m:440
0000440 NSCalendarDate+misc.m: No such file or directory.
(gdb)
0000442 in NSCalendarDate+misc.m
(gdb)
-[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00, _cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>,
_r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:130
0000130 iCalWeeklyRecurrenceCalculator.m: No such file or directory.
(gdb)
0000133 in iCalWeeklyRecurrenceCalculator.m
(gdb)
-[NGCalendarDateRange duration] (self=0x555555f1f2d0, _cmd=0x7ffff7264790 <_OBJC_SELECTOR_TABLE+208>) at NGCalendarDateRange.m:156
0000156 NGCalendarDateRange.m: No such file or directory.
(gdb)
0000157 in NGCalendarDateRange.m
(gdb)
-[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00, _cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>,
_r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:134
0000134 iCalWeeklyRecurrenceCalculator.m: No such file or directory.
(gdb)
0000138 in iCalWeeklyRecurrenceCalculator.m
(gdb)
0000139 in iCalWeeklyRecurrenceCalculator.m
(gdb)
0000138 in iCalWeeklyRecurrenceCalculator.m
(gdb)
+[NGCalendarDateRange calendarDateRangeWithStartDate:endDate:] (self=0x7ffff627c580 <_OBJC_Class_NGCalendarDateRange>,
_cmd=0x7ffff72647e0 <_OBJC_SELECTOR_TABLE+288>, start=0x555555f27890, end=0x555555f278d0) at NGCalendarDateRange.m:33
0000033 NGCalendarDateRange.m: No such file or directory.
(gdb)
-[NGCalendarDateRange initWithStartDate:endDate:] (self=0x555555f27910, _cmd=0x7ffff627c610 <_OBJC_SELECTOR_TABLE+16>, start=0x555555f27890,
end=0x555555f278d0) at NGCalendarDateRange.m:36
0000036 in NGCalendarDateRange.m
(gdb)
0000037 in NGCalendarDateRange.m
(gdb)
0000038 in NGCalendarDateRange.m
(gdb)
0000040 in NGCalendarDateRange.m
(gdb)
0000041 in NGCalendarDateRange.m
(gdb)
0000042 in NGCalendarDateRange.m
(gdb)
0000043 in NGCalendarDateRange.m
(gdb)
0000050 in NGCalendarDateRange.m
(gdb)
0000051 in NGCalendarDateRange.m
(gdb)
+[NGCalendarDateRange calendarDateRangeWithStartDate:endDate:] (self=0x7ffff627c580 <_OBJC_Class_NGCalendarDateRange>,
_cmd=0x7ffff72647e0 <_OBJC_SELECTOR_TABLE+288>, start=0x555555f27890, end=0x555555f278d0) at NGCalendarDateRange.m:34
0000034 in NGCalendarDateRange.m
(gdb)
-[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00, _cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>,
_r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:140
0000140 iCalWeeklyRecurrenceCalculator.m: No such file or directory.
(gdb)
0000142 in iCalWeeklyRecurrenceCalculator.m
(gdb)
0000145 in iCalWeeklyRecurrenceCalculator.m
(gdb)
Breakpoint 1, -[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00,
_cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>, _r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:143
0000143 in iCalWeeklyRecurrenceCalculator.m
(gdb)
-[NSCalendarDate(misc) dateByAddingYears:months:days:] (self=0x555555f179b0, _cmd=0x7ffff7264780 <_OBJC_SELECTOR_TABLE+192>, _years=0, _months=0, _days=287) |
|
|
From your first stacktrace:
#0 0x00007ffff52df1a5 in ?? () from /usr/lib/libgnustep-base.so.1.25
0000001 0x00007ffff6034038 in -[NSCalendarDate(misc) dateByAddingYears:months:days:] (self=0x555555f179b0, _cmd=0x7ffff7264780 <_OBJC_SELECTOR_TABLE+192>,
_years=0, _months=0, _days=2927351) at NSCalendarDate+misc.m:440
0000002 0x00007ffff703c9c0 in -[iCalWeeklyRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:] (self=0x555555f23d00,
_cmd=0x7ffff725f9e0 <_OBJC_SELECTOR_TABLE+192>, _r=0x555555f21b40) at iCalWeeklyRecurrenceCalculator.m:143
0000003 0x00007ffff7036364 in +[iCalRecurrenceCalculator _fillRanges:fromRules:withinRange:startingWithDate:] (
self=0x7ffff725f8a0 <_OBJC_Class_iCalRecurrenceCalculator>, _cmd=0x7ffff725fb20 <_OBJC_SELECTOR_TABLE+512>, ranges=0x555555f22ff0,
rrules=0x555555f22070, limits=0x555555f21b40, first=0x555555f1f2d0) at iCalRecurrenceCalculator.m:133
0000004 0x00007ffff7036b95 in +[iCalRecurrenceCalculator recurrenceRangesWithinCalendarDateRange:firstInstanceCalendarDateRange:recurrenceRules:exceptionRules:recurrenceDates:exceptionDates:] (self=0x7ffff725f8a0 <_OBJC_Class_iCalRecurrenceCalculator>, _cmd=0x7fffe9363980 <_OBJC_SELECTOR_TABLE+2272>,
_r=0x555555f21b40, _fir=0x555555f1f2d0, _rRules=0x555555f22070, _exRules=0x555555f221e0, _rDates=0x555555f21d60, _exDates=0x555555f21b70)
at iCalRecurrenceCalculator.m:268
0000005 0x00007fffe91204af in -[SOGoAppointmentFolder flattenCycleRecord:forRange:intoArray:withCalendar:] (self=0x555555b75200,
_cmd=0x7fffe9363a00 <_OBJC_SELECTOR_TABLE+2400>, theRecord=0x555555ed96e0, theRange=0x555555ed8b00, theRecords=0x555555ed8ac0, calendar=0x555555f00fd0)
at SOGoAppointmentFolder.m:1355
Reproduce it, and when that happens, do:
f 5
po theRecord
p *theRange
Basically, show use the variables' content in method -[SOGoAppointmentFolder flattenCycleRecord:forRange:intoArray:withCalendar:] |
|
|
Here it is (I hope these are useful info..):
Program received signal SIGINT, Interrupt.
0x00007ffff52df147 in ?? () from /usr/lib/libgnustep-base.so.1.25
(gdb) f 5
0000005 0x00007fffe91204af in -[SOGoAppointmentFolder flattenCycleRecord:forRange:intoArray:withCalendar:] (self=0x5555561cfaa0,
_cmd=0x7fffe9363a00 <_OBJC_SELECTOR_TABLE+2400>, theRecord=0x55555622b5a0, theRange=0x55555625e4f0, theRecords=0x55555625e4b0, calendar=0x55555629ade0)
at SOGoAppointmentFolder.m:1355
1355 SOGoAppointmentFolder.m: No such file or directory.
(gdb) po theRecord
{"c_content" = "BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 4.0.7//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Europe/Brussels
X-LIC-LOCATION:Europe/Brussels
BEGIN:DAYLIGHT
TZOFFSETFROM:+0100
TZOFFSETTO:+0200
TZNAME:CEST
DTSTART:19700329T020000
RRULE:FREQ=YEARLY;BYMONTH=3;BYDAY=-1SU
END:DAYLIGHT
BEGIN:STANDARD
TZOFFSETFROM:+0200
TZOFFSETTO:+0100
TZNAME:CET
DTSTART:19701025T030000
RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=-1SU
END:STANDARD
END:VTIMEZONE
BEGIN:VEVENT
UID:1696-5C8F5980-3-75EB6100
SUMMARY:Testing
CLASS:PUBLIC
RRULE:FREQ=WEEKLY
TRANSP:OPAQUE
DTSTART;TZID=Europe/Brussels:20190318T094500
DTEND;TZID=Europe/Brussels:20190318T104500
CREATED:20190318T084044Z
DTSTAMP:20190318T084044Z
LAST-MODIFIED:20190318T084044Z
END:VEVENT
END:VCALENDAR"; "c_cycleinfo" = "{rules = (\"FREQ=WEEKLY\"); }"; "c_enddate" = 1552902300; "c_isallday" = 0; "c_isopaque" = 1; "c_name" = "1696-5C8F5980-3-75EB6100.ics"; "c_orgmail" = ""; "c_partmails" = "<null>"; "c_partstates" = ""; "c_startdate" = 1552898700; "c_status" = 1; "c_uid" = "1696-5C8F5980-3-75EB6100"; }
(gdb) p theRange
$1 = {{isa = 0x7ffff627c580 <_OBJC_Class_NGCalendarDateRange>}, startDate = 0x5555562628b0, endDate = 0x5555562627b0}
(gdb) ptype theRange
type = struct NGCalendarDateRange {
protected:
struct NSCalendarDate startDate;
struct NSCalendarDate endDate;
}
(gdb) ptype theRange.startDate
type = struct NSCalendarDate {
protected:
NSTimeInterval _seconds_since_ref;
struct NSString _calendar_format;
struct NSTimeZone _time_zone;
}
(gdb) p theRange.startDate
$4 = (struct NSCalendarDate ) 0x5555562628b0
(gdb) p theRange.startDate
$5 = {{{isa = 0x7ffff5815fe0}}, _seconds_since_ref = 575161200, _calendar_format = 0x7ffff5816b80, _time_zone = 0x555555ceebc0}
(gdb) p theRange.endDate
$6 = {{{isa = 0x7ffff5815fe0}}, _seconds_since_ref = 371085748329600, _calendar_format = 0x7ffff5816b80, _time_zone = 0x555555ceebc0} |
|
|
do:
po theRange |
|
|
That's easier! ;)
(gdb) po theRange
<NGCalendarDateRange[0x0x55555625e4f0]: startDate:2019-03-24 23:00:00 +0000 endDate: 11761240-03-30 00:00:00 +0000>
The horror! |
|
|
For the moment in sogo.d the FreeBusy interval is commented out to use the defaults:
//SOGoFreeBusyDefaultInterval = (7,30);
If I remove the comment restarting the gdb session, I get:
(gdb) po theRange
<NGCalendarDateRange[0x0x555556224700]: startDate:2019-04-16 22:00:00 +0000 endDate: 11761240-03-30 00:00:00 +0000> |
|
|
As you can see, the end date is fucked up.
Do:
f 7
po r
po _startDate
po _endDate
po endDate
p delta |
|
|
Here:
(gdb) f 7
0000007 0x00007fffe91218f6 in -[SOGoAppointmentFolder fetchFields:from:to:title:component:additionalFilters:includeProtectedInformation:] (self=0x5555561d0250,
_cmd=0x7fffe9364300 <_OBJC_SELECTOR_TABLE+4704>, _fields=0x555556293f40, _startDate=0x555556262a60, _endDate=0x555556262fe0, title=0x0,
_component=0x7fffe9360240 <_OBJC_INSTANCE_43>, filters=0x0, _includeProtectedInformation=1 '\001') at SOGoAppointmentFolder.m:1643
1643 in SOGoAppointmentFolder.m
(gdb) po r
<NGCalendarDateRange[0x0x5555561f84e0]: startDate:2019-04-16 22:00:00 +0000 endDate: 11761240-03-30 00:00:00 +0000>
(gdb) po _startDate
11761240-03-30 00:00:00 +0000
(gdb) po _endDate
2019-04-16 22:00:00 +0000
(gdb) po endDate
2019-04-16 22:00:00 +0000
(gdb) p delta
$1 = 1 |
|
|
Ok do:
f 10
po startDate
po endDate
f 13
po today
po interval
po startDate
po endDate |
|
|
(gdb) f 10
0000010 0x00007fffe91320bb in -[SOGoFreeBusyObject fetchFreeBusyInfosFrom:to:forContact:] (
self=0x5555562ddf40, _cmd=0x7fffe936b390 <_OBJC_SELECTOR_TABLE+752>,
startDate=0x555556262a60, endDate=0x555556262fe0, uid=0x0) at SOGoFreeBusyObject.m:300
300 SOGoFreeBusyObject.m: No such file or directory.
(gdb) po startDate
11761240-03-30 00:00:00 +0000
(gdb) po endDate
2019-04-16 22:00:00 +0000
(gdb) f 13
0000013 0x00007fffe9131cea in -[SOGoFreeBusyObject contentAsString] (self=0x5555562ddf40,
_cmd=0x7fffe936b580 <_OBJC_SELECTOR_TABLE+1248>) at SOGoFreeBusyObject.m:222
222 in SOGoFreeBusyObject.m
(gdb) po today
2019-03-18 00:00:00 +0100
(gdb) po interval
(7, 30)
(gdb) po startDate
11761240-03-30 00:00:00 +0000
(gdb) po endDate
2019-04-16 22:00:00 +0000 |
|
|
Do:
f 13
p start
p -start
po NSStringFromClass([interval class]) |
|
|
Here:
(gdb) f 13
0000013 0x00007fffe9131cea in -[SOGoFreeBusyObject contentAsString] (self=0x5555562ddf40,
_cmd=0x7fffe936b580 <_OBJC_SELECTOR_TABLE+1248>) at SOGoFreeBusyObject.m:222
222 in SOGoFreeBusyObject.m
(gdb) p start
$2 = 7
(gdb) p -start
$3 = 4294967289
(gdb) po NSStringFromClass([interval class])
Program received signal SIGSEGV, Segmentation fault.
0x00007ffff5295736 in ?? () from /usr/lib/libgnustep-base.so.1.25
The program being debugged was signaled while in a function called from GDB.
GDB remains in the frame where the signal was received.
To change this behavior use "set unwindonsignal on".
Evaluation of the expression containing the function
(NSStringFromClass) will be abandoned.
When the function is done executing, GDB will silently stop. |
|
|
Try the upcoming nightly builds. |
|
|
It works!!!
wget gets the proper info!
BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 4.0.7//EN
VERSION:2.0
BEGIN:VFREEBUSY
ATTENDEE:mailto:BLA@BLA.BLA
DTSTAMP:20190319T082002Z
DTSTART:20190304T230000Z
DTEND:20190417T220000Z
FREEBUSY;FBTYPE=BUSY:20190307T110000Z/20190307T120000Z
FREEBUSY;FBTYPE=BUSY:20190328T111500Z/20190328T121500Z
FREEBUSY;FBTYPE=BUSY:20190318T084500Z/20190318T094500Z
FREEBUSY;FBTYPE=BUSY:20190325T084500Z/20190325T094500Z
FREEBUSY;FBTYPE=BUSY:20190401T074500Z/20190401T084500Z
FREEBUSY;FBTYPE=BUSY:20190408T074500Z/20190408T084500Z
FREEBUSY;FBTYPE=BUSY:20190415T074500Z/20190415T084500Z
END:VFREEBUSY
END:VCALENDAR
Was it the signed-unsigned start end? Anyway, thank you!
I will check with the production server asap once the change is in the stable packages. |
|
|
Actually, it is sufficient to set 0 as start date like
SOGoFreeBusyDefaultInterval = (0,90);
To fix the issue already in the existing installations, no need to wait! |
|
|
https://github.com/inverse-inc/sogo/commit/d75fe573b2802f08864858dd28cffe810c79d754 |
|