SOGo | BTS

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0004289SOGoBackend Calendarpublic2017-09-15 09:062018-11-07 06:16
Reporterrongten 
Assigned To 
PrioritynormalSeverityblockReproducibilityalways
StatusnewResolutionopen 
Platform[Server] LinuxOSRHEL/CentOSOS Version7
Product Version3.2.10 
Target VersionFixed in Version 
Summary0004289: Freebusy lookup fails with proxy error for certain users but not for others
DescriptionA freebusy lockup initiated from outlook or from wget fails 100% of the time for a couple of users.
The error is ERROR 502: Proxy Error, and it is after the last SQL query on the calendar of the user, I assume for the building of the freebusy answer. A sogo worker goes 100% of cpu and then it is killed.
Steps To Reproducewget https://URL/SOGo/dav/public/USER1@DOMAIN/freebusy.ifb [^]

gets
HTTP request sent, awaiting response... 502 Proxy Error
2017-09-15 14:02:41 ERROR 502: Proxy Error.

another user (i.e. USER2) gets the file immediately (i.e.)

HTTP request sent, awaiting response... 200 OK
Length: 1181 (1.2K) [text/calendar]
Saving to: ‘freebusy.ifb.3’

Additional Informationactivating the debug, the log for the two users (USER1 and USER2), one that works, one that does not work are identical until to a certain SQL query:

2017-09-15 13:48:39.145 sogod[467:467] PG0x0x7f49aaeeb290 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 sogoUSER100168fa0a38_quick a, sogoUSER100168fa0a38 b WHERE ((c_component = 'vevent') AND (c_classification != 1) AND ((c_startdate IS NULL) OR (c_startdate <= 1513206000)) AND ((c_cycleenddate IS NULL) OR (c_cycleenddate >= 1504828800)) AND (c_iscycle = 1)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)

after for USER1 there is no more activity of the process with pid 467 until it start saying that
Sep 15 13:49:38 sogod [456]: [WARN] <0x0x7f49aabb5910[WOWatchDogChild]> pid 467 has been hanging in the same request for 1 minutes
until the safety bet kills it.
For the USER2 instead there is immediately a closure

Sep 15 14:01:19 sogod [1095]: |SOGo| request took 0.733621 seconds to execute.


If I use psql, I can execute both final queries and I get the output immediately for USER1, so my guess is that maybe there is something in the output that cannot be formatted interpreted.

Is there any way to know how to fix this issue?

I could try to add one appointment at a time, but it is a calendar imported from outlook with caldav syncronizer with around 150 entries, so...

Tagspossible memory leak
Attached Files

- Relationships Relation Graph ] Dependency Graph ]

-  Notes
(0012293)
rongten (reporter)
2017-09-15 09:31

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...
(0012294)
rongten (reporter)
2017-09-15 11:01

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...
(0012306)
rongten (reporter)
2017-09-18 11:59

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.
(0012340)
rongten (reporter)
2017-09-29 04:00

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?
(0012526)
rongten (reporter)
2018-01-19 09:11

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.
(0012527)
rongten (reporter)
2018-01-19 10:07

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?
(0012615)
Nterowski (reporter)
2018-02-21 01:23

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 ?
(0012616)
Nterowski (reporter)
2018-02-21 01:57

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
(0012617)
rongten (reporter)
2018-02-21 08:31

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...
User avatar (0012623)
ludovic (administrator)
2018-03-05 11:02

@Nterowski

Regarding the exception you get, please generate a stack trace.

https://sogo.nu/support/faq/how-do-i-debug-sogo.html [^]
(0012646)
sy-subrc (reporter)
2018-03-09 11:48
edited on: 2018-03-09 12:00

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

(0012821)
sy-subrc (reporter)
2018-04-09 10:05
edited on: 2018-08-09 11:27

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

(0012993)
sy-subrc (reporter)
2018-08-09 11:27

Meanwhile we are running Version 4.0.1 (@shiva2.inverse 201808090043), but still the same error.
(0012994)
rongten (reporter)
2018-08-10 07:16

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..
(0013124)
rongten (reporter)
2018-10-23 02:32

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.
(0013161)
sy-subrc (reporter)
2018-11-07 06:16

@rongten
Thank you for testing!
I hope the SOGo-team will fix this issue soon because it's a show-stopper to us.

- Issue History
Date Modified Username Field Change
2017-09-15 09:06 rongten New Issue
2017-09-15 09:31 rongten Note Added: 0012293
2017-09-15 11:01 rongten Note Added: 0012294
2017-09-18 03:25 rongten Tag Attached: possible memory leak
2017-09-18 11:59 rongten Note Added: 0012306
2017-09-29 04:00 rongten Note Added: 0012340
2018-01-19 09:11 rongten Note Added: 0012526
2018-01-19 10:07 rongten Note Added: 0012527
2018-02-21 01:23 Nterowski Note Added: 0012615
2018-02-21 01:57 Nterowski Note Added: 0012616
2018-02-21 08:31 rongten Note Added: 0012617
2018-03-05 11:02 ludovic Note Added: 0012623
2018-03-09 11:48 sy-subrc Note Added: 0012646
2018-03-09 12:00 sy-subrc Note Edited: 0012646 View Revisions
2018-04-09 10:05 sy-subrc Note Added: 0012821
2018-08-09 11:25 sy-subrc Note Edited: 0012821 View Revisions
2018-08-09 11:27 sy-subrc Note Edited: 0012821 View Revisions
2018-08-09 11:27 sy-subrc Note Added: 0012993
2018-08-10 07:16 rongten Note Added: 0012994
2018-10-23 02:32 rongten Note Added: 0013124
2018-11-07 06:16 sy-subrc Note Added: 0013161


Copyright © 2000 - 2018 MantisBT Team
Powered by Mantis Bugtracker