[CalendarServer-changes] [1955] CalendarServer/trunk/twistedcaldav
source_changes at macosforge.org
source_changes at macosforge.org
Thu Oct 11 18:32:59 PDT 2007
Revision: 1955
http://trac.macosforge.org/projects/calendarserver/changeset/1955
Author: cdaboo at apple.com
Date: 2007-10-11 18:32:59 -0700 (Thu, 11 Oct 2007)
Log Message:
-----------
Tweak logging and add some other useful log output for tracking scheduling.
Modified Paths:
--------------
CalendarServer/trunk/twistedcaldav/itip.py
CalendarServer/trunk/twistedcaldav/schedule.py
Modified: CalendarServer/trunk/twistedcaldav/itip.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/itip.py 2007-10-11 20:13:32 UTC (rev 1954)
+++ CalendarServer/trunk/twistedcaldav/itip.py 2007-10-12 01:32:59 UTC (rev 1955)
@@ -37,7 +37,7 @@
import md5
import time
-from twisted.python import log, failure
+from twisted.python import failure
from twisted.internet.defer import waitForDeferred, deferredGenerator, maybeDeferred
from twisted.web2.dav import davxml
from twisted.web2.dav.method.report import NumberOfMatchesWithinLimits
@@ -111,7 +111,7 @@
@param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
"""
- logging.info("[ITIP]: Auto-processing iTIP REQUEST for: %s" % (str(principal),))
+ logging.info("Auto-processing iTIP REQUEST for: %s" % (str(principal),), system="iTIP")
processed = "ignored"
# First determine whether this is a full or partial update. A full update is one containing the master
@@ -158,29 +158,29 @@
newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, calendar))
yield newchild
newchild = newchild.getResult()
- logging.info("[ITIP]: replaced calendar component %s with new iTIP message in %s." % (calmatch, calURL))
+ logging.info("Replaced calendar component %s with new iTIP message in %s." % (calmatch, calURL), system="iTIP")
else:
newchild = waitForDeferred(writeResource(request, calURL, updatecal, None, calendar))
yield newchild
newchild.getResult()
- logging.info("[ITIP]: added new calendar component in %s." % (calURL,))
+ logging.info("Added new calendar component in %s." % (calURL,), system="iTIP")
else:
if calmatch:
d = waitForDeferred(deleteResource(updatecal, calmatch))
yield d
d.getResult()
- logging.info("[ITIP]: deleted calendar component %s in %s as update was not accepted." % (calmatch, calURL))
+ logging.info("Deleted calendar component %s in %s as update was not accepted." % (calmatch, calURL), system="iTIP")
# Send a reply if needed.
if doreply:
- logging.info("[ITIP]: sending iTIP REPLY %s" % (("declined","accepted")[accepted],))
+ logging.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), system="iTIP")
newchild = waitForDeferred(writeReply(request, principal, replycal, inbox))
yield newchild
newchild = newchild.getResult()
newInboxResource(child, newchild)
processed = "processed"
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
else:
@@ -231,17 +231,17 @@
newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, cal))
yield newchild
newchild = newchild.getResult()
- logging.info("[ITIP]: merged calendar component %s with new iTIP message in %s." % (calmatch, calURL))
+ logging.info("Merged calendar component %s with new iTIP message in %s." % (calmatch, calURL), system="iTIP")
else:
if accepted:
newchild = waitForDeferred(writeResource(request, calURL, updatecal, None, calendar))
yield newchild
newchild.getResult()
- logging.info("[ITIP]: added new calendar component in %s." % (calURL,))
+ logging.info("Added new calendar component in %s." % (calURL,), system="iTIP")
# Do reply if needed.
if doreply:
- logging.info("[ITIP]: sending iTIP REPLY %s" % (("declined","accepted")[accepted],))
+ logging.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), system="iTIP")
newchild = waitForDeferred(writeReply(request, principal, replycal, inbox))
yield newchild
newchild = newchild.getResult()
@@ -249,7 +249,7 @@
processed = "processed"
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
# Remove the now processed incoming request.
@@ -257,13 +257,13 @@
d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
yield d
d.getResult()
- logging.info("[ITIP]: deleted new iTIP message %s in Inbox because it has been %s." %
+ logging.info("Deleted new iTIP message %s in Inbox because it has been %s." %
(child.fp.basename(),
{"processed":"processed",
"older": "ignored: older",
- "ignored": "ignored: no match"}[processed],))
+ "ignored": "ignored: no match"}[processed],), system="iTIP")
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
yield None
return
@@ -281,7 +281,7 @@
@param calendar: the L{Component} for the iTIP message we are processing.
@param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
"""
- logging.info("[ITIP]: Auto-processing iTIP ADD for: %s" % (str(principal),))
+ logging.info("Auto-processing iTIP ADD for: %s" % (str(principal),), system="iTIP")
raise NotImplementedError
@@ -322,7 +322,7 @@
@param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
"""
- logging.info("[ITIP]: Auto-processing iTIP CANCEL for: %s" % (str(principal),))
+ logging.info("Auto-processing iTIP CANCEL for: %s" % (str(principal),), system="iTIP")
processed = "ignored"
# Get all component info for this iTIP message
@@ -366,9 +366,9 @@
d = waitForDeferred(deleteResource(updatecal, calmatch,))
yield d
d.getResult()
- logging.info("[ITIP]: delete calendar component %s in %s as it was cancelled." % (calmatch, calURL))
+ logging.info("Delete calendar component %s in %s as it was cancelled." % (calmatch, calURL), system="iTIP")
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
processed = "processed"
else:
@@ -429,13 +429,13 @@
d = waitForDeferred(deleteResource(updatecal, calmatch))
yield d
d.getResult()
- logging.info("[ITIP]: deleted calendar component %s after cancellations from iTIP message in %s." % (calmatch, calURL))
+ logging.info("Deleted calendar component %s after cancellations from iTIP message in %s." % (calmatch, calURL), system="iTIP")
else:
# Update the existing calendar object
newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, existing_calendar))
yield newchild
newchild = newchild.getResult()
- logging.info("[ITIP]: updated calendar component %s with cancellations from iTIP message in %s." % (calmatch, calURL))
+ logging.info("Updated calendar component %s with cancellations from iTIP message in %s." % (calmatch, calURL), system="iTIP")
processed = "processed"
else:
processed = "older"
@@ -448,13 +448,13 @@
d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
yield d
d.getResult()
- logging.info("[ITIP]: deleted new iTIP message %s in Inbox because it has been %s." %
+ logging.info("Deleted new iTIP message %s in Inbox because it has been %s." %
(child.fp.basename(),
{"processed":"processed",
"older": "ignored: older",
- "ignored": "ignored: no match"}[processed],))
+ "ignored": "ignored: no match"}[processed],), system="iTIP")
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
yield None
return
@@ -519,7 +519,7 @@
break
except NumberOfMatchesWithinLimits:
accepted = False
- logging.info("[ITIP]: exceeded number of matches whilst trying to find free-time.")
+ logging.info("Exceeded number of matches whilst trying to find free-time.", system="iTIP")
break
if not accepted:
@@ -610,7 +610,7 @@
yield d
d.getResult()
except AccessDeniedError:
- logging.info("[ITIP]: could not send reply as %s does not have CALDAV:schedule permission on %s Inbox." % (principal.principalURL(), organizer))
+ logging.info("Could not send reply as %s does not have CALDAV:schedule permission on %s Inbox." % (principal.principalURL(), organizer), system="iTIP")
yield None
return
@@ -751,9 +751,9 @@
d = waitForDeferred(deleteResource(inbox, i[0]))
yield d
d.getResult()
- logging.info("[ITIP]: deleted iTIP message %s in Inbox that was older than the new one." % (i[0],))
+ logging.info("Deleted iTIP message %s in Inbox that was older than the new one." % (i[0],), system="iTIP")
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
else:
# For any that are newer or the same, mark the new one to be deleted.
@@ -765,9 +765,9 @@
d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
yield d
d.getResult()
- logging.info("[ITIP]: deleted new iTIP message %s in Inbox because it was older than existing ones." % (child.fp.basename(),))
+ logging.info("Deleted new iTIP message %s in Inbox because it was older than existing ones." % (child.fp.basename(),), system="iTIP")
except:
- log.err("Error while auto-processing iTIP: %s" % (failure.Failure(),))
+ logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
raise iTipException
yield delete_child
@@ -797,7 +797,7 @@
continue
calmatch = matchComponentInCalendar(updatecal, calendar)
if calmatch:
- logging.info("[ITIP]: found calendar component %s matching new iTIP message in %s." % (calmatch, calURL))
+ logging.info("Found calendar component %s matching new iTIP message in %s." % (calmatch, calURL), system="iTIP")
break
if calmatch is None and len(fbset):
Modified: CalendarServer/trunk/twistedcaldav/schedule.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/schedule.py 2007-10-11 20:13:32 UTC (rev 1954)
+++ CalendarServer/trunk/twistedcaldav/schedule.py 2007-10-12 01:32:59 UTC (rev 1955)
@@ -27,7 +27,6 @@
from twisted.internet import reactor
from twisted.internet.defer import deferredGenerator, maybeDeferred, succeed, waitForDeferred
-from twisted.python import log
from twisted.python.failure import Failure
from twisted.web2 import responsecode
from twisted.web2.http import HTTPError, Response
@@ -44,6 +43,7 @@
from twistedcaldav.config import config
from twistedcaldav.customxml import calendarserver_namespace
from twistedcaldav.ical import Component
+import logging
from twistedcaldav.method import report_common
from twistedcaldav.method.put_common import storeCalendarObjectResource
from twistedcaldav.resource import isCalendarCollectionResource
@@ -204,13 +204,13 @@
# Must be content-type text/calendar
content_type = request.headers.getHeader("content-type")
if content_type is not None and (content_type.mediaType, content_type.mediaSubtype) != ("text", "calendar"):
- log.err("MIME type %s not allowed in calendar collection" % (content_type,))
+ logging.err("MIME type %s not allowed in calendar collection" % (content_type,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
# Must have Originator header
originator = request.headers.getRawHeaders("originator")
if originator is None or (len(originator) != 1):
- log.err("POST request must have Originator header")
+ logging.err("POST request must have Originator header", system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-specified")))
else:
originator = originator[0]
@@ -218,23 +218,23 @@
# Verify that Originator is a valid calendar user (has an INBOX)
oprincipal = self.principalForCalendarUserAddress(originator)
if oprincipal is None:
- log.err("Could not find principal for originator: %s" % (originator,))
+ logging.err("Could not find principal for originator: %s" % (originator,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
inboxURL = oprincipal.scheduleInboxURL()
if inboxURL is None:
- log.err("Could not find inbox for originator: %s" % (originator,))
+ logging.err("Could not find inbox for originator: %s" % (originator,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
# Verify that Originator matches the authenticated user
if davxml.Principal(davxml.HRef(oprincipal.principalURL())) != self.currentPrincipal(request):
- log.err("Originator: %s does not match authorized user: %s" % (originator, self.currentPrincipal(request).children[0],))
+ logging.err("Originator: %s does not match authorized user: %s" % (originator, self.currentPrincipal(request).children[0],), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
# Get list of Recipient headers
rawrecipients = request.headers.getRawHeaders("recipient")
if rawrecipients is None or (len(rawrecipients) == 0):
- log.err("POST request must have at least one Recipient header")
+ logging.err("POST request must have at least one Recipient header", system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-specified")))
# Recipient header may be comma separated list
@@ -254,24 +254,24 @@
yield d
calendar = d.getResult()
except:
- log.err("Error while handling POST: %s" % (Failure(),))
+ logging.err("Error while handling POST: %s" % (Failure(),), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
# Must be a valid calendar
try:
calendar.validCalendarForCalDAV()
except ValueError:
- log.err("POST request calendar component is not valid: %s" % (calendar,))
+ logging.err("POST request calendar component is not valid: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
# Must have a METHOD
if not calendar.isValidMethod():
- log.err("POST request must have valid METHOD property in calendar component: %s" % (calendar,))
+ logging.err("POST request must have valid METHOD property in calendar component: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
# Verify iTIP behaviour
if not calendar.isValidITIP():
- log.err("POST request must have a calendar component that satisfies iTIP requirements: %s" % (calendar,))
+ logging.err("POST request must have a calendar component that satisfies iTIP requirements: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
# Verify that the ORGANIZER's cu address maps to the request.uri
@@ -282,12 +282,12 @@
if oprincipal is not None:
outboxURL = oprincipal.scheduleOutboxURL()
if outboxURL is None:
- log.err("ORGANIZER in calendar data is not valid: %s" % (calendar,))
+ logging.err("ORGANIZER in calendar data is not valid: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "organizer-allowed")))
# Prevent spoofing of ORGANIZER with specific METHODs
if (calendar.propertyValue("METHOD") in ("PUBLISH", "REQUEST", "ADD", "CANCEL", "DECLINECOUNTER")) and (outboxURL != request.uri):
- log.err("ORGANIZER in calendar data does not match owner of Outbox: %s" % (calendar,))
+ logging.err("ORGANIZER in calendar data does not match owner of Outbox: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "organizer-allowed")))
# Prevent spoofing when doing reply-like METHODs
@@ -298,7 +298,7 @@
# Must have only one
if len(attendees) != 1:
- log.err("ATTENDEE list in calendar data is wrong: %s" % (calendar,))
+ logging.err("ATTENDEE list in calendar data is wrong: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "attendee-allowed")))
# Attendee's Outbox MUST be the request URI
@@ -307,20 +307,21 @@
if aprincipal is not None:
aoutboxURL = aprincipal.scheduleOutboxURL()
if aoutboxURL is None or aoutboxURL != request.uri:
- log.err("ATTENDEE in calendar data does not match owner of Outbox: %s" % (calendar,))
+ logging.err("ATTENDEE in calendar data does not match owner of Outbox: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "attendee-allowed")))
# For free-busy do immediate determination of iTIP result rather than fan-out
+ logging.info("METHOD: %s, Component: %s" % (calendar.propertyValue("METHOD"), calendar.mainType(),), system="CalDAV Outbox POST")
if (calendar.propertyValue("METHOD") == "REQUEST") and (calendar.mainType() == "VFREEBUSY"):
# Extract time range from VFREEBUSY object
vfreebusies = [v for v in calendar.subcomponents() if v.name() == "VFREEBUSY"]
if len(vfreebusies) != 1:
- log.err("iTIP data is not valid for a VFREEBUSY request: %s" % (calendar,))
+ logging.err("iTIP data is not valid for a VFREEBUSY request: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
dtstart = vfreebusies[0].getStartDateUTC()
dtend = vfreebusies[0].getEndDateUTC()
if dtstart is None or dtend is None:
- log.err("VFREEBUSY start/end not valid: %s" % (calendar,))
+ logging.err("VFREEBUSY start/end not valid: %s" % (calendar,), system="CalDAV Outbox POST")
raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
timerange.start = dtstart
timerange.end = dtend
@@ -350,7 +351,7 @@
# Map recipient to their inbox
inbox = None
if principal is None:
- log.err("No principal for calendar user address: %s" % (recipient,))
+ logging.err("No principal for calendar user address: %s" % (recipient,), system="CalDAV Outbox POST")
else:
inboxURL = principal.scheduleInboxURL()
if inboxURL:
@@ -358,7 +359,7 @@
yield inbox
inbox = inbox.getResult()
else:
- log.err("No schedule inbox for principal: %s" % (principal,))
+ logging.err("No schedule inbox for principal: %s" % (principal,), system="CalDAV Outbox POST")
if inbox is None:
err = HTTPError(ErrorResponse(responsecode.NOT_FOUND, (caldav_namespace, "recipient-exists")))
@@ -376,7 +377,7 @@
yield d
d.getResult()
except AccessDeniedError:
- log.err("Could not access Inbox for recipient: %s" % (recipient,))
+ logging.err("Could not access Inbox for recipient: %s" % (recipient,), system="CalDAV Outbox POST")
err = HTTPError(ErrorResponse(responsecode.NOT_FOUND, (caldav_namespace, "recipient-permisions")))
responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
recipients_state["BAD"] += 1
@@ -444,7 +445,7 @@
recipients_state["OK"] += 1
except:
- log.err("Could not determine free busy information: %s" % (recipient,))
+ logging.err("Could not determine free busy information: %s" % (recipient,), system="CalDAV Outbox POST")
err = HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-permissions")))
responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
recipients_state["BAD"] += 1
@@ -489,7 +490,7 @@
if principal.autoSchedule():
autoresponses.append((principal, inbox, child))
except:
- log.err("Could not store data in Inbox : %s" % (inbox,))
+ logging.err("Could not store data in Inbox : %s" % (inbox,), system="CalDAV Outbox POST")
err = HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-permissions")))
responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
recipients_state["BAD"] += 1
@@ -518,7 +519,7 @@
"""
@param xml_responses: an interable of davxml.Response objects.
@param location: the value of the location header to return in the response,
- or None.
+ or None.
"""
Response.__init__(self, code=responsecode.OK,
@@ -548,7 +549,7 @@
def setLocation(self, location):
"""
@param location: the value of the location header to return in the response,
- or None.
+ or None.
"""
self.location = location
@@ -572,7 +573,7 @@
raise AssertionError("Unknown data type: %r" % (what,))
if code > 400: # Error codes only
- log.err("Error during %s for %s: %s" % (self.method, recipient, message))
+ logging.err("Error during %s for %s: %s" % (self.method, recipient, message), system="CalDAV Outbox POST")
children = []
children.append(caldavxml.Recipient(davxml.HRef.fromString(recipient)))
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20071011/b4b667b5/attachment-0001.html
More information about the calendarserver-changes
mailing list