[CalendarServer-changes] [13244] CalendarServer/trunk

source_changes at macosforge.org source_changes at macosforge.org
Thu Apr 10 13:06:30 PDT 2014


Revision: 13244
          http://trac.calendarserver.org//changeset/13244
Author:   cdaboo at apple.com
Date:     2014-04-10 13:06:30 -0700 (Thu, 10 Apr 2014)
Log Message:
-----------
Add extra logging/tracking of auto-scheduling.

Modified Paths:
--------------
    CalendarServer/trunk/twistedcaldav/accounting.py
    CalendarServer/trunk/twistedcaldav/stdconfig.py
    CalendarServer/trunk/twistedcaldav/test/test_accounting.py
    CalendarServer/trunk/txdav/caldav/datastore/scheduling/icaldiff.py
    CalendarServer/trunk/txdav/caldav/datastore/scheduling/processing.py
    CalendarServer/trunk/txdav/caldav/datastore/scheduling/scheduler.py

Modified: CalendarServer/trunk/twistedcaldav/accounting.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/accounting.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/twistedcaldav/accounting.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -33,13 +33,13 @@
 
 log = Logger()
 
-def accountingEnabled(category, principal):
+def accountingEnabled(category, record):
     """
-    Determine if accounting is enabled for the given category and principal.
+    Determine if accounting is enabled for the given category and record.
     """
     return (
         accountingEnabledForCategory(category) and
-        accountingEnabledForPrincipal(principal)
+        accountingEnabledForRecord(record)
     )
 
 
@@ -55,45 +55,38 @@
 
 
 
-def accountingEnabledForPrincipal(principal):
+def accountingEnabledForRecord(record):
     """
-    Determine if accounting is enabled for the given principal.
+    Determine if accounting is enabled for the given record.
     """
-    enabledPrincipalURIs = config.AccountingPrincipals
+    enabledRecordGUIDs = config.AccountingPrincipals
 
-    if "*" in enabledPrincipalURIs:
+    if "*" in enabledRecordGUIDs:
         return True
 
-    if principal.principalURL() in enabledPrincipalURIs:
-        return True
+    return record.guid in enabledRecordGUIDs
 
-    for principal in principal.alternateURIs():
-        if principal in enabledPrincipalURIs:
-            return True
 
-    return False
 
-
-
-def emitAccounting(category, principal, data, tag=None):
+def emitAccounting(category, record, data, tag=None, filename=None):
     """
     Write the supplied data to the appropriate location for the given
-    category and principal.
+    category and record.
 
-    @param principal: the principal for whom a log entry is to be created.
-    @type principal: L{DirectoryPrincipalResource}
+    @param record: the record for whom a log entry is to be created.
+    @type record: L{DirectoryRecord}
     @param category: accounting category
     @type category: C{tuple}
     @param data: data to write.
     @type data: C{str}
     """
-    if isinstance(principal, str):
-        principalLogPath = principal
-    elif accountingEnabled(category, principal):
+    if isinstance(record, str):
+        principalLogPath = record
+    elif accountingEnabled(category, record):
         principalLogPath = os.path.join(
-            principal.record.guid[0:2],
-            principal.record.guid[2:4],
-            principal.record.guid
+            record.guid[0:2],
+            record.guid[2:4],
+            record.guid
         )
     else:
         return None
@@ -111,29 +104,31 @@
             )
         logFilename = os.path.join(
             logDirectory,
-            datetime.datetime.now().isoformat()
+            datetime.datetime.now().isoformat() if filename is None else filename
         )
 
         if not os.path.isdir(os.path.join(logRoot, logDirectory)):
             os.makedirs(os.path.join(logRoot, logDirectory))
-            logFilename = "%s-01" % (logFilename,)
-            if tag:
-                logFilename += " (%s)" % (tag,)
-            logFilename += ".txt"
-        else:
-            index = 1
-            while True:
-                path = "%s-%02d" % (logFilename, index)
+            if filename is None:
+                logFilename = "%s-01" % (logFilename,)
                 if tag:
-                    path += " (%s)" % (tag,)
-                path += ".txt"
-                if not os.path.isfile(os.path.join(logRoot, path)):
-                    logFilename = path
-                    break
-                if index == 1000:
-                    log.error("Too many %s accounting files for %s" % (category, principal))
-                    return None
-                index += 1
+                    logFilename += " (%s)" % (tag,)
+                logFilename += ".txt"
+        else:
+            if filename is None:
+                index = 1
+                while True:
+                    path = "%s-%02d" % (logFilename, index)
+                    if tag:
+                        path += " (%s)" % (tag,)
+                    path += ".txt"
+                    if not os.path.isfile(os.path.join(logRoot, path)):
+                        logFilename = path
+                        break
+                    if index == 1000:
+                        log.error("Too many %s accounting files for %s" % (category, record))
+                        return None
+                    index += 1
 
         #
         # Now write out the data to the log file

Modified: CalendarServer/trunk/twistedcaldav/stdconfig.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/stdconfig.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/twistedcaldav/stdconfig.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -477,7 +477,12 @@
     "LogID"             : "",
 
     "AccountingCategories": {
+        "HTTP": False,
         "iTIP": False,
+        "iTIP-VFREEBUSY": False,
+        "Implicit Errors": False,
+        "AutoScheduling": False,
+        "iSchedule": False,
     },
     "AccountingPrincipals": [],
     "AccountingLogRoot"   : "accounting",

Modified: CalendarServer/trunk/twistedcaldav/test/test_accounting.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/test/test_accounting.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/twistedcaldav/test/test_accounting.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -33,18 +33,12 @@
         os.mkdir(config.AccountingLogRoot)
 
 
-    class _Principal(object):
+    class _Record(object):
 
-        class _Record(object):
-
-            def __init__(self, guid):
-                self.guid = guid
-
         def __init__(self, guid):
+            self.guid = guid
 
-            self.record = self._Record(guid)
 
-
     def test_permissions_makedirs(self):
         """
         Test permissions when creating accounting
@@ -53,7 +47,7 @@
         # Make log root non-writeable
         os.chmod(config.AccountingLogRoot, stat.S_IRUSR)
 
-        emitAccounting("iTIP", self._Principal("1234-5678"), "bogus")
+        emitAccounting("iTIP", self._Record("1234-5678"), "bogus")
 
 
     def test_file_instead_of_directory(self):
@@ -64,7 +58,7 @@
         # Make log root a file
         config.AccountingLogRoot = "other"
         open(config.AccountingLogRoot, "w").close()
-        emitAccounting("iTIP", self._Principal("1234-5678"), "bogus")
+        emitAccounting("iTIP", self._Record("1234-5678"), "bogus")
 
 
 

Modified: CalendarServer/trunk/txdav/caldav/datastore/scheduling/icaldiff.py
===================================================================
--- CalendarServer/trunk/txdav/caldav/datastore/scheduling/icaldiff.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/txdav/caldav/datastore/scheduling/icaldiff.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -497,6 +497,7 @@
             # If PARTSTAT was changed by the attendee, add a timestamp if needed
             if config.Scheduling.Options.TimestampAttendeePartStatChanges:
                 serverAttendee.setParameter("X-CALENDARSERVER-DTSTAMP", DateTime.getNowUTC().getText())
+            serverAttendee.removeParameter("X-CALENDARSERVER-AUTO")
 
             replyNeeded = True
 

Modified: CalendarServer/trunk/txdav/caldav/datastore/scheduling/processing.py
===================================================================
--- CalendarServer/trunk/txdav/caldav/datastore/scheduling/processing.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/txdav/caldav/datastore/scheduling/processing.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -19,12 +19,12 @@
 from pycalendar.timezone import Timezone
 
 from twext.python.log import Logger
-from txweb2.dav.method.report import NumberOfMatchesWithinLimits
 from txweb2.http import HTTPError
 
 from twisted.internet.defer import inlineCallbacks, returnValue
 
 from twistedcaldav import customxml, caldavxml
+from twistedcaldav.accounting import emitAccounting, accountingEnabled
 from twistedcaldav.config import config
 from twistedcaldav.ical import Property
 from twistedcaldav.instance import InvalidOverriddenInstanceError
@@ -35,11 +35,13 @@
 from txdav.caldav.datastore.scheduling.utils import getCalendarObjectForRecord
 from txdav.caldav.datastore.scheduling.work import ScheduleRefreshWork, \
     ScheduleAutoReplyWork
-from txdav.caldav.icalendarstore import ComponentUpdateState, ComponentRemoveState
+from txdav.caldav.icalendarstore import ComponentUpdateState, \
+    ComponentRemoveState, QueryMaxResources
 from txdav.who.idirectory import AutoScheduleMode
 
 import collections
 import hashlib
+import json
 import uuid
 
 """
@@ -437,7 +439,15 @@
             if (yield self.recipient.principal.canAutoSchedule(organizer=organizer)):
                 # auto schedule mode can depend on who the organizer is
                 mode = yield self.recipient.principal.getAutoScheduleMode(organizer=organizer)
-                send_reply, store_inbox, partstat = (yield self.checkAttendeeAutoReply(new_calendar, mode))
+                send_reply, store_inbox, partstat, accounting = (yield self.checkAttendeeAutoReply(new_calendar, mode))
+                if accounting is not None:
+                    accounting["action"] = "create"
+                    emitAccounting(
+                        "AutoScheduling",
+                        self.recipient.principal,
+                        json.dumps(accounting) + "\r\n",
+                        filename=self.uid + ".txt"
+                    )
 
                 # Only store inbox item when reply is not sent or always for users
                 store_inbox = store_inbox or self.recipient.principal.getCUType() == "INDIVIDUAL"
@@ -470,7 +480,15 @@
                 if (yield self.recipient.principal.canAutoSchedule(organizer=organizer)) and not hasattr(self.txn, "doing_attendee_refresh"):
                     # auto schedule mode can depend on who the organizer is
                     mode = yield self.recipient.principal.getAutoScheduleMode(organizer=organizer)
-                    send_reply, store_inbox, partstat = (yield self.checkAttendeeAutoReply(new_calendar, mode))
+                    send_reply, store_inbox, partstat, accounting = (yield self.checkAttendeeAutoReply(new_calendar, mode))
+                    if accounting is not None:
+                        accounting["action"] = "modify"
+                        emitAccounting(
+                            "AutoScheduling",
+                            self.recipient.principal,
+                            json.dumps(accounting) + "\r\n",
+                            filename=self.uid + ".txt"
+                        )
 
                     # Only store inbox item when reply is not sent or always for users
                     store_inbox = store_inbox or self.recipient.principal.getCUType() == "INDIVIDUAL"
@@ -554,6 +572,19 @@
             # Check to see if this is a cancel of the entire event
             processed_message, delete_original, rids = iTipProcessing.processCancel(self.message, self.recipient_calendar, autoprocessing=autoprocessed)
             if processed_message:
+                if autoprocessed and accountingEnabled("AutoScheduling", self.recipient.principal):
+                    accounting = {
+                        "action": "cancel",
+                        "when": DateTime.getNowUTC().getText(),
+                        "deleting": delete_original,
+                    }
+                    emitAccounting(
+                        "AutoScheduling",
+                        self.recipient.principal,
+                        json.dumps(accounting) + "\r\n",
+                        filename=self.uid + ".txt"
+                    )
+
                 if delete_original:
 
                     # Delete the attendee's copy of the event
@@ -612,9 +643,18 @@
         @return: C{tuple} of C{bool}, C{bool}, C{str} indicating whether changes were made, whether the inbox item
             should be added, and the new PARTSTAT.
         """
+        if accountingEnabled("AutoScheduling", self.recipient.principal):
+            accounting = {
+                "when": DateTime.getNowUTC().getText(),
+                "automode": automode,
+                "changed": False,
+            }
+        else:
+            accounting = None
+
         # First ignore the none mode
         if automode == AutoScheduleMode.none:
-            returnValue((False, True, "",))
+            returnValue((False, True, "", accounting,))
         elif not automode:
             automode = {
                 "none": AutoScheduleMode.none,
@@ -637,6 +677,10 @@
         expand_max = DateTime.getToday() + default_future_expansion_duration
         instances = calendar.expandTimeRanges(expand_max, ignoreInvalidInstances=True)
 
+        if accounting is not None:
+            accounting["expand-max"] = expand_max.getText()
+            accounting["instances"] = len(instances.instances)
+
         # We are going to ignore auto-accept processing for anything more than a day old (actually use -2 days
         # to add some slop to account for possible timezone offsets)
         min_date = DateTime.getToday()
@@ -653,11 +697,15 @@
             if instance.active:
                 allOld = False
 
+        instances = sorted(instances.instances.values(), key=lambda x: x.rid)
+
         # If every instance is in the past we punt right here so we don't waste time on freebusy lookups etc.
         # There will be no auto-accept and no inbox item stored (so as not to waste storage on items that will
         # never be processed).
         if allOld:
-            returnValue((False, False, "",))
+            if accounting is not None:
+                accounting["status"] = "all instances are old"
+            returnValue((False, False, "", accounting,))
 
         # Extract UID from primary component as we want to ignore this one if we match it
         # in any calendars.
@@ -666,6 +714,9 @@
         # Now compare each instance time-range with the index and see if there is an overlap
         fbset = (yield self.recipient.inbox.ownerHome().loadCalendars())
         fbset = [fbcalendar for fbcalendar in fbset if fbcalendar.isUsedForFreeBusy()]
+        if accounting is not None:
+            accounting["fbset"] = [testcal.name() for testcal in fbset]
+            accounting["tr"] = []
 
         for testcal in fbset:
 
@@ -675,8 +726,11 @@
             tzinfo = tz.gettimezone() if tz is not None else Timezone(utc=True)
 
             # Now do search for overlapping time-range and set instance.free based
-            # on whether there is an overlap or not
-            for instance in instances.instances.itervalues():
+            # on whether there is an overlap or not.
+            # NB Do this in reverse order so that the date farthest in the future is tested first - that will
+            # ensure that freebusy that far into the future is determined and will trigger time-range caching
+            # and indexing out that far - and that will happen only once through this loop.
+            for instance in reversed(instances):
                 if instance.partstat == "NEEDS-ACTION" and instance.free and instance.active:
                     try:
                         # First list is BUSY, second BUSY-TENTATIVE, third BUSY-UNAVAILABLE
@@ -702,19 +756,26 @@
                         # If any fbinfo entries exist we have an overlap
                         if len(fbinfo[0]) or len(fbinfo[1]) or len(fbinfo[2]):
                             instance.free = False
-                    except NumberOfMatchesWithinLimits:
+                        if accounting is not None:
+                            accounting["tr"].insert(0, (tr.attributes["start"], tr.attributes["end"], instance.free,))
+                    except QueryMaxResources:
                         instance.free[instance] = False
                         log.info("Exceeded number of matches whilst trying to find free-time.")
+                        if accounting is not None:
+                            accounting["problem"] = "Exceeded number of matches"
 
             # If everything is declined we can exit now
-            if not any([instance.free for instance in instances.instances.itervalues()]):
+            if not any([instance.free for instance in instances]):
                 break
 
+        if accounting is not None:
+            accounting["tr"] = accounting["tr"][:30]
+
         # Now adjust the instance.partstat currently set to "NEEDS-ACTION" to the
         # value determined by auto-accept logic based on instance.free state. However,
         # ignore any instance in the past - leave them as NEEDS-ACTION.
         partstat_counts = collections.defaultdict(int)
-        for instance in instances.instances.itervalues():
+        for instance in instances:
             if instance.partstat == "NEEDS-ACTION" and instance.active:
                 if automode == AutoScheduleMode.accept:
                     freePartstat = busyPartstat = "ACCEPTED"
@@ -734,14 +795,18 @@
 
         if len(partstat_counts) == 0:
             # Nothing to do
-            returnValue((False, False, "",))
+            if accounting is not None:
+                accounting["status"] = "no partstat changes"
+            returnValue((False, False, "", accounting,))
 
         elif len(partstat_counts) == 1:
             # Do the simple case of all PARTSTATs the same separately
             # Extract the ATTENDEE property matching current recipient from the calendar data
             attendeeProps = calendar.getAttendeeProperties(cuas)
             if not attendeeProps:
-                returnValue((False, False, "",))
+                if accounting is not None:
+                    accounting["status"] = "no attendee to change"
+                returnValue((False, False, "", accounting,))
 
             made_changes = False
             partstat = partstat_counts.keys()[0]
@@ -749,6 +814,10 @@
                 made_changes |= self.resetAttendeePartstat(component, cuas, partstat)
             store_inbox = partstat == "NEEDS-ACTION"
 
+            if accounting is not None:
+                accounting["status"] = "setting all partstats to {}".format(partstat) if made_changes else "all partstats correct"
+                accounting["changed"] = made_changes
+
         else:
             # Hard case: some accepted, some declined, some needs-action
             # What we will do is mark any master instance as accepted, then mark each existing
@@ -774,7 +843,7 @@
                     made_changes |= self.resetAttendeePartstat(master, cuas, defaultPartStat)
 
             # Look at expanded instances and change partstat accordingly
-            for instance in sorted(instances.instances.values(), key=lambda x: x.rid):
+            for instance in instances:
 
                 overridden = calendar.overriddenComponent(instance.rid)
                 if not overridden and instance.partstat == defaultPartStat:
@@ -799,11 +868,15 @@
                             made_changes = True
                             calendar.addComponent(derived)
 
+            if accounting is not None:
+                accounting["status"] = "mixed partstat changes" if made_changes else "mixed partstats correct"
+                accounting["changed"] = made_changes
+
         # Fake a SCHEDULE-STATUS on the ORGANIZER property
         if made_changes:
             calendar.setParameterToValueForPropertyWithValue("SCHEDULE-STATUS", iTIPRequestStatus.MESSAGE_DELIVERED_CODE, "ORGANIZER", None)
 
-        returnValue((made_changes, store_inbox, partstat,))
+        returnValue((made_changes, store_inbox, partstat, accounting,))
 
 
     @inlineCallbacks
@@ -889,6 +962,10 @@
             # Adjust TRANSP to OPAQUE if PARTSTAT is ACCEPTED, otherwise TRANSPARENT
             component.replaceProperty(Property("TRANSP", "OPAQUE" if partstat == "ACCEPTED" else "TRANSPARENT"))
 
+            if madeChanges:
+                attendee.setParameter("X-CALENDARSERVER-AUTO", DateTime.getNowUTC().getText())
+                attendee.removeParameter("X-CALENDARSERVER-DTSTAMP")
+
         return madeChanges
 
 

Modified: CalendarServer/trunk/txdav/caldav/datastore/scheduling/scheduler.py
===================================================================
--- CalendarServer/trunk/txdav/caldav/datastore/scheduling/scheduler.py	2014-04-10 20:05:20 UTC (rev 13243)
+++ CalendarServer/trunk/txdav/caldav/datastore/scheduling/scheduler.py	2014-04-10 20:06:30 UTC (rev 13244)
@@ -404,7 +404,8 @@
             accountingType = "iTIP-VFREEBUSY" if self.calendar.mainType() == "VFREEBUSY" else "iTIP"
             if accountingEnabled(accountingType, self.organizer.principal):
                 emitAccounting(
-                    accountingType, self.organizer.principal,
+                    accountingType,
+                    self.organizer.principal,
                     "Originator: %s\nRecipients:\n%sMethod:%s\n\n%s"
                     % (
                         str(self.originator),
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20140410/876ef8c1/attachment-0001.html>


More information about the calendarserver-changes mailing list