wallace fails to check if resource reservation requests conflicts with any of resource events
Open, 60Public

Description

I've been observing wallace allocating 100% of CPU. After doing some debuging it looks like the problem occurs when wallace tries to determine if there is any conflicts between resource events and reservation conflict.

2016-11-22 14:37:42,102 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 145 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,102 pykolab.wallace DEBUG [20846]: Fetching message UID '146' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,150 pykolab.wallace DEBUG [20846]: * Comparing events 2016-11-24 13:30:00+01:00/2016-11-24 14:30:00+01:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,151 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 146 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,151 pykolab.wallace DEBUG [20846]: Fetching message UID '147' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,196 pykolab.wallace DEBUG [20846]: * Comparing events 2016-11-10 14:30:00+01:00/2016-11-10 15:30:00+01:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,196 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 147 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,197 pykolab.wallace DEBUG [20846]: Fetching message UID '148' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,220 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-12 10:00:00+02:00/2016-09-12 11:00:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,240 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-19 10:00:00+02:00/2016-09-19 11:00:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,259 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,276 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,291 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,306 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,320 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,334 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,347 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,360 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,372 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,385 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,398 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,410 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00

and the last line goes forever. It looks like event conflict checking gets into endless loop. The logs I pasted here I got by uncommenting line ~176, in pykolab/itip/__init__.py, def check_event_conflict(kolab_event, itip_event): method.

The most relevant part of the offending message (148 (or 2564)) has this content (most relevant).

<components>
  <vevent>
    <properties>
      <uid>
        <text>3C93514BA89A1BCC38DA740341DF8D74-EBE2BB8E57A31106</text>
      </uid>
      <created>
        <date-time>2016-09-05T14:33:12Z</date-time>
      </created>
      <dtstamp>
        <date-time>2016-09-05T14:33:11Z</date-time>
      </dtstamp>
      <sequence>
        <integer>0</integer>
      </sequence>
      <class>
        <text>PUBLIC</text>
      </class>
      <dtstart>
        <parameters>
          <tzid>
            <text>/kolab.org/Europe/Berlin</text>
          </tzid>
        </parameters>
        <date-time>2016-09-12T10:00:00</date-time>
      </dtstart>
      <dtend>
        <parameters>
          <tzid>
            <text>/kolab.org/Europe/Berlin</text>
          </tzid>
        </parameters>
        <date-time>2016-09-12T11:00:00</date-time>
      </dtend>
      <rrule>
        <recur>
          <freq>WEEKLY</freq>
          <byday>MO</byday>
        </recur>
      </rrule>
      <summary>
        <text>Enterprise Meeting</text>
      </summary>

can present full payload of the event upon request.
Removing the message from resource makes wallace work again (after restart it doesn't take 100% of CPU anymore).
pykolab 0.7.30-0~kolab1
wallace 0.7.30-0~kolab1

Details

Differential Revisions
D308: T1988: Fix performance issue in check_event_conflict()
Ticket Type
Task
adomaitis added a project: PyKolab.

It is not infinite. It is just so extremally slow... For two weekly recurring events it does around 10 * 50 * 10 * 50 iterations. And every iteration calls getLastOccurrence(), getOccurenceEndDate(), etc. on EventCal (from kolab.calendaring). Looks like these are slow.

There's already "# TODO: compare recurrence rules directly (e.g. matching time slot or weekday or monthday)" in the code. I suppose another solution would be to collect all occurrences of both events in one (optimized) run and then compare them. Or limit the inner loop to only relevant date period.

It is not infinite. It is just so extremally slow... For two weekly recurring events it does around 10 * 50 * 10 * 50 iterations. And every iteration calls getLastOccurrence(), getOccurenceEndDate(), etc. on EventCal (from kolab.calendaring). Looks like these are slow.

Could be, just leaving wallace running at 100% CPU for few days and don't get a result looks like infinite.

There's already "# TODO: compare recurrence rules directly (e.g. matching time slot or weekday or monthday)" in the code. I suppose another solution would be to collect all occurrences of both events in one (optimized) run and then compare them. Or limit the inner loop to only relevant date period.

I'm not sure what is the best. I would vote for a solution which is easiest and could be implemented ASAP, and leave another TODO if it could be done better code review iteration.

D308 is a little bit hacky (and may not find all conflicts), but works. And the old method wasn't perfect anyway.

D308 isn't the proper solution to these symptoms.

vanmeeuwen closed this task as Resolved.Dec 2 2016, 3:17 PM
vanmeeuwen moved this task from Backlog to Done on the PyKolab board.
vanmeeuwen claimed this task.

Resolved per the aforementioned commits.

machniak reopened this task as Open.Dec 3 2016, 1:23 PM

@vanmeeuwen, The issue is fixed, but two tests fail now:

======================================================================
FAIL: test_002_check_event_conflict
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 134, in maybeDeferred
    result = f(*args, **kw)
  File "/usr/lib64/python2.7/site-packages/twisted/internet/utils.py", line 191, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/root/pykolab/tests/unit/test-011-itip.py", line 450, in test_002_check_event_conflict
    self.assertTrue(itip.check_event_conflict(event3, itip_event), "Conflict in two recurring events")
  File "/usr/lib64/python2.7/site-packages/twisted/trial/unittest.py", line 224, in failUnless
    raise self.failureException(msg)
FailTest: Conflict in two recurring events

======================================================================
FAIL: test_002_check_event_conflict_single
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 134, in maybeDeferred
    result = f(*args, **kw)
  File "/usr/lib64/python2.7/site-packages/twisted/internet/utils.py", line 191, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/root/pykolab/tests/unit/test-011-itip.py", line 499, in test_002_check_event_conflict_single
    self.assertTrue(itip.check_event_conflict(event, itip_event), "Conflicting dates (exception)")
  File "/usr/lib64/python2.7/site-packages/twisted/trial/unittest.py", line 224, in failUnless
    raise self.failureException(msg)
FailTest: Conflicting dates (exception)
----------------------------------------------------------------------
pasik added a subscriber: pasik.Nov 25 2017, 2:33 PM
machniak moved this task from Done to Backlog on the PyKolab board.Jul 27 2018, 8:54 AM