[CalendarServer-changes] [1960] CalendarServer/branches/users/cdaboo/better-logging-1957/ twistedcaldav

source_changes at macosforge.org source_changes at macosforge.org
Mon Oct 15 08:44:25 PDT 2007


Revision: 1960
          http://trac.macosforge.org/projects/calendarserver/changeset/1960
Author:   cdaboo at apple.com
Date:     2007-10-15 08:44:24 -0700 (Mon, 15 Oct 2007)

Log Message:
-----------
Another tweak to logger: can now specify multiple 'id's. This allows a log item to be "tagged" with multiple items
so that you can filter log messages based on any one or more of those tags. e.g. a "Security" tag can be used
on any log entry for things affecting security and that can have a seperate log level.

All the existing use of twised.python.log was converted to logger and multiple ids added as appropriate.

Modified Paths:
--------------
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/authkerb.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/caldavxml.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/cluster.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/appleopendirectory.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/calendaruserproxy.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/digest.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/directory.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/principal.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/dropbox.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/extensions.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/ical.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/index.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logger.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logging.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/copymove.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/mkcalendar.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/put.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_calquery.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_common.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_freebusy.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_multiget.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/resource.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/root.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/sql.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/static.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/tap.py
    CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_logger.py

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/authkerb.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/authkerb.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/authkerb.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -77,7 +77,7 @@
             try:
                 principal = kerberos.getServerPrincipalDetails(type, hostname)
             except kerberos.KrbError, ex:
-                logger.err("getServerPrincipalDetails: %s" % (ex[0],), id=self)
+                logger.err("getServerPrincipalDetails: %s" % (ex[0],), id=(self, "Security",))
                 raise ValueError('Authentication System Failure: %s' % (ex[0],))
 
         try:
@@ -87,12 +87,12 @@
             service = splits[0].upper()
             realm = splits[1]
         except IndexError:
-            logger.err("Invalid Kerberos principal: %s" % (principal,), id=self)
+            logger.err("Invalid Kerberos principal: %s" % (principal,), id=(self, "Security",))
             raise ValueError('Authentication System Failure: Invalid Kerberos principal: %s' % (principal,))
                 
         self.service = "%s@%s" % (servicetype, service,)
         self.realm = realm
-        logger.info("Service: %s  Realm: %s" % (self.service, self.realm,), id=self)
+        logger.debug("Service: %s  Realm: %s" % (self.service, self.realm,), id=(self, "Security",))
 
 class BasicKerberosCredentials(credentials.UsernamePassword):
     """
@@ -172,7 +172,7 @@
             try:
                 kerberos.checkPassword(creds.username, creds.password, creds.service, creds.default_realm)
             except kerberos.BasicAuthError, ex:
-                logger.err("%s" % (ex[0],), id=self)
+                logger.err("%s" % (ex[0],), id=(self, "Security",))
                 raise error.UnauthorizedLogin("Bad credentials for: %s (%s: %s)" % (pcreds.authnURI, ex[0], ex[1],))
             else:
                 return succeed((pcreds.authnURI, pcreds.authzURI,))
@@ -223,18 +223,18 @@
         try:
             _ignore_result, context = kerberos.authGSSServerInit(self.service);
         except kerberos.GSSError, ex:
-            logger.debug("authGSSServerInit: %s(%s)" % (ex[0][0], ex[1][0],), id=self)
+            logger.debug("authGSSServerInit: %s(%s)" % (ex[0][0], ex[1][0],), id=(self, "Security",))
             raise error.LoginFailed('Authentication System Failure: %s(%s)' % (ex[0][0], ex[1][0],))
 
         # Do the GSSAPI step and get response and username
         try:
             kerberos.authGSSServerStep(context, base64data);
         except kerberos.GSSError, ex:
-            logger.debug("authGSSServerStep: %s(%s)" % (ex[0][0], ex[1][0],), id=self)
+            logger.debug("authGSSServerStep: %s(%s)" % (ex[0][0], ex[1][0],), id=(self, "Security",))
             kerberos.authGSSServerClean(context)
             raise error.UnauthorizedLogin('Bad credentials: %s(%s)' % (ex[0][0], ex[1][0],))
         except kerberos.KrbError, ex:
-            logger.debug("authGSSServerStep: %s" % (ex[0],), id=self)
+            logger.debug("authGSSServerStep: %s" % (ex[0],), id=(self, "Security",))
             kerberos.authGSSServerClean(context)
             raise error.UnauthorizedLogin('Bad credentials: %s' % (ex[0],))
 
@@ -251,7 +251,7 @@
         # We currently do not support cross-realm authentication, so we
         # must verify that the realm we got exactly matches the one we expect.
         if realmname != self.realm:
-            logger.err("authGSSServer Realms do not match: %s vs %s" % (realmname, self.realm,), id=self)
+            logger.err("authGSSServer Realms do not match: %s vs %s" % (realmname, self.realm,), id=(self, "Security",))
             kerberos.authGSSServerClean(context)
             raise error.UnauthorizedLogin('Bad credentials: mismatched realm')
 
@@ -260,7 +260,7 @@
         try:
             kerberos.authGSSServerClean(context);
         except kerberos.GSSError, ex:
-            logger.debug("authGSSServerClean: %s" % (ex[0][0], ex[1][0],), id=self)
+            logger.debug("authGSSServerClean: %s" % (ex[0][0], ex[1][0],), id=(self, "Security",))
             raise error.LoginFailed('Authentication System Failure %s(%s)' % (ex[0][0], ex[1][0],))
         
         # If we successfully decoded and verified the Kerberos credentials we need to add the Kerberos

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/caldavxml.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/caldavxml.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/caldavxml.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -27,14 +27,13 @@
 See draft spec: http://ietf.webdav.org/caldav/draft-dusseault-caldav.txt
 """
 
-from twisted.python import log
-
 from twisted.web2.dav import davxml
 
 from twistedcaldav.dateops import clipPeriod, timeRangesOverlap
 from twistedcaldav.ical import Component as iComponent
 from twistedcaldav.ical import Property as iProperty
 from twistedcaldav.ical import parse_date_or_datetime
+from twistedcaldav.logger import logger
 
 from vobject.icalendar import utc
 
@@ -96,7 +95,7 @@
 #            calendar = self.calendar()
 #            if calendar is None: raise ValueError("No data")
 #        except ValueError, e:
-#            log.err("Invalid iCalendar data (%s): %r" % (calendar, e))
+#            logger.err("Invalid iCalendar data (%s): %r" % (calendar, e), id=self)
 #            raise
 #
 #        found = False
@@ -435,7 +434,7 @@
                 #try:
                 #    self.calendar()
                 #except ValueError, e:
-                #    log.err("Invalid iCalendar data (%s): %r" % (e, data))
+                #    logger.err("Invalid iCalendar data (%s): %r" % (e, data), id=self)
                 #    raise
 
         if "content-type" in attributes:
@@ -900,32 +899,32 @@
         if level == 0:
             # Must have VCALENDAR at the top
             if (self.filter_name != "VCALENDAR") or timerange:
-                log.msg("Top-level comp-filter must be VCALENDAR, instead: %s" % (self.filter_name,))
+                logger.err("Top-level comp-filter must be VCALENDAR, instead: %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
         elif level == 1:
             # Dissallow VCALENDAR, VALARM, STANDARD, DAYLIGHT, AVAILABLE at the top, everything else is OK
             if self.filter_name in ("VCALENDAR", "VALARM", "STANDARD", "DAYLIGHT", "AVAILABLE"):
-                log.msg("comp-filter wrong component type: %s" % (self.filter_name,))
+                logger.err("comp-filter wrong component type: %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
             
             # time-range only on VEVENT, VTODO, VJOURNAL, VFREEBUSY, VAVAILABILITY
             if timerange and self.filter_name not in ("VEVENT", "VTODO", "VJOURNAL", "VFREEBUSY", "VAVAILABILITY"):
-                log.msg("time-range cannot be used with component %s" % (self.filter_name,))
+                logger.err("time-range cannot be used with component %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
         elif level == 2:
             # Dissallow VCALENDAR, VTIMEZONE, VEVENT, VTODO, VJOURNAL, VFREEBUSY, VAVAILABILITY at the top, everything else is OK
             if (self.filter_name in ("VCALENDAR", "VTIMEZONE", "VEVENT", "VTODO", "VJOURNAL", "VFREEBUSY", "VAVAILABILITY")):
-                log.msg("comp-filter wrong sub-component type: %s" % (self.filter_name,))
+                logger.err("comp-filter wrong sub-component type: %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
             
             # time-range only on VALARM, AVAILABLE
             if timerange and self.filter_name not in ("VALARM", "AVAILABLE",):
-                log.msg("time-range cannot be used with sub-component %s" % (self.filter_name,))
+                logger.err("time-range cannot be used with sub-component %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
         else:
             # Dissallow all std iCal components anywhere else
             if (self.filter_name in ("VCALENDAR", "VTIMEZONE", "VEVENT", "VTODO", "VJOURNAL", "VFREEBUSY", "VALARM", "STANDARD", "DAYLIGHT", "AVAILABLE")) or timerange:
-                log.msg("comp-filter wrong standard component type: %s" % (self.filter_name,))
+                logger.err("comp-filter wrong standard component type: %s" % (self.filter_name,), id=(self, "caldav",))
                 return False
         
         # Test each property
@@ -996,7 +995,7 @@
         
         # time-range only on COMPLETED, CREATED, DTSTAMP, LAST-MODIFIED
         if timerange and self.filter_name not in ("COMPLETED", "CREATED", "DTSTAMP", "LAST-MODIFIED"):
-            log.msg("time-range cannot be used with property %s" % (self.filter_name,))
+            logger.err("time-range cannot be used with property %s" % (self.filter_name,), id=(self, "caldav",))
             return False
 
         # Test the time-range
@@ -1199,16 +1198,16 @@
         """
         
         if not isinstance(self.start, datetime.datetime):
-            log.msg("start attribute in <time-range> is not a date-time: %s" % (self.start,))
+            logger.err("start attribute in <time-range> is not a date-time: %s" % (self.start,), id=(self, "caldav",))
             return False
         if not isinstance(self.end, datetime.datetime):
-            log.msg("end attribute in <time-range> is not a date-time: %s" % (self.end,))
+            logger.err("end attribute in <time-range> is not a date-time: %s" % (self.end,), id=(self, "caldav",))
             return False
         if self.start.tzinfo != utc:
-            log.msg("start attribute in <time-range> is not UTC: %s" % (self.start,))
+            logger.err("start attribute in <time-range> is not UTC: %s" % (self.start,), id=(self, "caldav",))
             return False
         if self.end.tzinfo != utc:
-            log.msg("end attribute in <time-range> is not UTC: %s" % (self.start,))
+            logger.err("end attribute in <time-range> is not UTC: %s" % (self.start,), id=(self, "caldav",))
             return False
 
         # No other tests

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/cluster.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/cluster.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/cluster.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -20,13 +20,12 @@
 import sys
 import tempfile
 
-from twisted.python import log
-
 from twisted.runner import procmon
 from twisted.application import internet, service
 
 from twistedcaldav import logging
 from twistedcaldav.config import config
+from twistedcaldav.logger import logger
 
 from twistedcaldav.util import getNCPU
 
@@ -143,13 +142,12 @@
     if config.MultiProcess['ProcessCount'] == 0:
         try:
             config.MultiProcess['ProcessCount'] = getNCPU()
-            log.msg("%d processors found, configuring %d processes." % (
+            logger.info("%d processors found, configuring %d processes." % (
                     config.MultiProcess['ProcessCount'],
-                    config.MultiProcess['ProcessCount']))
+                    config.MultiProcess['ProcessCount']), id="Startup")
 
         except NotImplementedError, err:
-            log.msg('Could not autodetect number of CPUs:')
-            log.msg(err)
+            logger.warn('Could not autodetect number of CPUs: %s' % (err,), id="Startup")
             config.MultiProcess['ProcessCount'] = 1
 
     if config.MultiProcess['ProcessCount'] > 1:
@@ -266,17 +264,17 @@
         os.write(fd, pdconfig)
         os.close(fd)
 
-        log.msg("Adding pydirector service with configuration: %s" % (fname,))
+        logger.info("Adding pydirector service with configuration: %s" % (fname,), id="Startup")
 
         monitor.addProcess('pydir', [sys.executable,
                                      config.PythonDirector['pydir'],
                                      fname],
                            env=parentEnv)
 
-    logger = logging.AMPLoggingFactory(
+    factory = logging.AMPLoggingFactory(
         logging.RotatingFileAccessLoggingObserver(config.AccessLogFile))
 
-    loggingService = internet.UNIXServer(config.ControlSocket, logger)
+    loggingService = internet.UNIXServer(config.ControlSocket, factory)
 
     loggingService.setServiceParent(s)
 
@@ -287,7 +285,7 @@
 
     parentEnv = {'PYTHONPATH': os.environ.get('PYTHONPATH', ''),}
 
-    log.msg("Adding pydirector service with configuration: %s" % (config.PythonDirector['ConfigFile'],))
+    logger.info("Adding pydirector service with configuration: %s" % (config.PythonDirector['ConfigFile'],), id="Startup")
 
     service.addProcess('pydir', [sys.executable,
                                  config.PythonDirector['pydir'],

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/appleopendirectory.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/appleopendirectory.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/appleopendirectory.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -71,7 +71,7 @@
         try:
             directory = opendirectory.odInit(node)
         except opendirectory.ODError, e:
-            logger.err("Open Directory (node=%s) Initialization error: %s" % (node, e), id=self)
+            logger.err("Open Directory (node=%s) Initialization error: %s" % (node, e), id=(self, "Startup", "Directory",))
             raise
 
         self.realmName = node
@@ -90,7 +90,7 @@
                 try:
                     self._lookupVHostRecord()
                 except Exception, e:
-                    logger.err("Unable to locate virtual host record: %s" % (e,), id=self)
+                    logger.err("Unable to locate virtual host record: %s" % (e,), id=(self, "Startup", "Directory",))
                     raise
 
                 if os.path.exists(_serverPreferences):
@@ -101,7 +101,7 @@
                         'IsWorkgroupServer', False)
 
                     if self.isWorkgroupServer:
-                        logger.info("Enabling Workgroup Server compatibility mode", id="OpenDirectoryService:starting")
+                        logger.info("Enabling Workgroup Server compatibility mode", id=(self, "Startup", "Directory",))
 
             for recordType in self.recordTypes():
                 self.recordsForType(recordType)
@@ -137,7 +137,7 @@
                  dsattributes.kDSNAttrNestedGroups])
 
             if not result:
-                logger.err("Couldn't find group %s when trying to expand nested groups." % (groupGUID,), id=self)
+                logger.err("Couldn't find group %s when trying to expand nested groups." % (groupGUID,), id=(self, "Directory",))
                 continue
 
             group = result[0][1]
@@ -220,12 +220,12 @@
                 key,
                 servicetag,
                 {True:"enabled", False:"disabled"}[enabled]
-            ), id="OpenDirectoryService:starting")
+            ), id=(self, "Startup", "Directory",))
 
         # Log all the enabled service tags - or generate an error if there are none
         if self.servicetags:
             for tag in self.servicetags:
-                logger.info("Enabled ServicesLocator: %s" % (tag,), id="OpenDirectoryService:starting")
+                logger.info("Enabled ServicesLocator: %s" % (tag,), id=(self, "Startup", "Directory",))
         else:
             raise OpenDirectoryInitError(
                 "Open Directory (node=%s) no /Computers records with an enabled and valid "
@@ -251,7 +251,7 @@
             logger.err(
                 "Open Directory (node=%s) %s record does not have a "
                 "com.apple.macosxserver.virtualhosts in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation,), id=self
+                % (self.realmName, recordlocation,), id=(self, "Startup", "Directory",)
             )
             return False
         
@@ -275,7 +275,7 @@
             logger.err(
                 "Open Directory (node=%s) %s record does not have "
                 "any host name in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation, ), id=self
+                % (self.realmName, recordlocation, ), id=(self, "Startup", "Directory",)
             )
             return False
         if hostname != vhostname:
@@ -289,7 +289,7 @@
             logger.err(
                 "Open Directory (node=%s) %s record does not have "
                 "any host details in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation, ), id=self
+                % (self.realmName, recordlocation, ), id=(self, "Startup", "Directory",)
             )
             return False
         
@@ -299,7 +299,7 @@
             logger.err(
                 "Open Directory (node=%s) %s record does not have a "
                 "calendar service in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation), id=self
+                % (self.realmName, recordlocation), id=(self, "Startup", "Directory",)
             )
             return False
         serviceInfo = serviceInfos["calendar"]
@@ -375,7 +375,7 @@
                 def onError(f):
                     storage["status"] = "stale" # Keep trying
                     logger.err("Unable to load records of type %s from OpenDirectory due to unexpected error: %s"
-                            % (recordType, f), id=self)
+                            % (recordType, f), id=(self, "Directory",))
 
                 d = deferToThread(self.reloadCache, recordType)
                 d.addErrback(onError)
@@ -415,9 +415,9 @@
     def reloadCache(self, recordType, shortName=None):
         
         if shortName:
-            logger.info("Trying to add record %s to %s record cache" % (shortName, recordType,), id=self)
+            logger.info("Trying to add record %s to %s record cache" % (shortName, recordType,), id=(self, "Directory",))
         else:
-            logger.info("Reloading %s record cache" % (recordType,), id=self)
+            logger.info("Reloading %s record cache" % (recordType,), id=(self, "Directory",))
 
         results = self._queryDirectory(recordType, shortName)
         
@@ -433,9 +433,9 @@
                 if not value.get(dsattributes.kDSNAttrServicesLocator):
                     if recordType == DirectoryService.recordType_groups:
                         enabledForCalendaring = False
-                        logger.debug("Group %s is not enabled for calendaring but may be used in ACLs" % (key,), id=self)
+                        logger.debug("Group %s is not enabled for calendaring but may be used in ACLs" % (key,), id=(self, "Directory",))
                     else:
-                        logger.err("Directory (incorrectly) returned a record with no ServicesLocator attribute: %s" % (key,), id=self)
+                        logger.err("Directory (incorrectly) returned a record with no ServicesLocator attribute: %s" % (key,), id=(self, "Directory",))
                         continue
 
             # Now get useful record info.
@@ -507,8 +507,8 @@
                         disabled_guids.add(existing_record.guid)
                         del records[existing_record.shortName]
                         del guids[existing_record.guid]
-                        logger.warn("Record disabled: %s, with GUID: %s" % (existing_record.shortName, existing_record.guid,), id=self)
-                        logger.warn("Record disabled: %s, with GUID: %s" % (recordShortName, guid,), id=self)
+                        logger.warn("Record disabled: %s, with GUID: %s" % (existing_record.shortName, existing_record.guid,), id=(self, "Directory",))
+                        logger.warn("Record disabled: %s, with GUID: %s" % (recordShortName, guid,), id=(self, "Directory",))
                         ok_to_add = False
                 elif guid in guids:
                     existing_record = guids[guid]
@@ -518,13 +518,13 @@
                         disabled_names.add(existing_record.shortName)
                         del records[existing_record.shortName]
                         del guids[existing_record.guid]
-                        logger.warn("Record disabled: %s, with GUID: %s" % (existing_record.shortName, existing_record.guid,), id=self)
-                        logger.warn("Record disabled: %s, with GUID: %s" % (recordShortName, guid,), id=self)
+                        logger.warn("Record disabled: %s, with GUID: %s" % (existing_record.shortName, existing_record.guid,), id=(self, "Directory",))
+                        logger.warn("Record disabled: %s, with GUID: %s" % (recordShortName, guid,), id=(self, "Directory",))
                         ok_to_add = False
                 
                 if ok_to_add:
                     records[recordShortName] = guids[guid] = record
-                    logger.debug("Populated record: %s, with GUID: %s" % (records[recordShortName], guid,), id=self)
+                    logger.debug("Populated record: %s, with GUID: %s" % (records[recordShortName], guid,), id=(self, "Directory",))
 
         if shortName is None:
             #
@@ -562,23 +562,23 @@
             if shortName in storage["disabled_names"] or record.guid in storage["disabled_guids"]:
                 storage["disabled_guids"].add(record.guid)
                 storage["disabled_names"].add(shortName)
-                logger.warn("Record disabled: %s, with GUID: %s" % (shortName, record.guid,), id=self)
+                logger.warn("Record disabled: %s, with GUID: %s" % (shortName, record.guid,), id=(self, "Directory",))
                 records = {}
             elif record.guid in storage["guids"]:
                 # Got a duplicate GUID - for now we disable the record  being looked up. On the next cache refresh
                 # the existing record will also get disabled.
                 storage["disabled_guids"].add(record.guid)
                 storage["disabled_names"].add(shortName)
-                logger.warn("Record disabled: %s, with GUID: %s" % (shortName, record.guid,), id=self)
+                logger.warn("Record disabled: %s, with GUID: %s" % (shortName, record.guid,), id=(self, "Directory",))
                 records = {}
             else:
                 storage["records"][shortName] = record
                 storage["guids"][record.guid] = record
 
         if shortName:
-            logger.info("Added %d records for %s in %s record cache" % (len(records), shortName, recordType,), id=self)
+            logger.info("Added %d records for %s in %s record cache" % (len(records), shortName, recordType,), id=(self, "Directory",))
         else:
-            logger.info("Found %d records for %s record cache" % (len(self._records[recordType]["guids"]), recordType,), id=self)
+            logger.info("Found %d records for %s record cache" % (len(self._records[recordType]["guids"]), recordType,), id=(self, "Directory",))
 
     def _queryDirectory(self, recordType, shortName=None):
 
@@ -698,7 +698,7 @@
                     attrs,
                 )
         except opendirectory.ODError, ex:
-            logger.err("Open Directory (node=%s) error: %s" % (self.realmName, str(ex)), id=self)
+            logger.err("Open Directory (node=%s) error: %s" % (self.realmName, str(ex)), id=(self, "Directory",))
             raise
 
         return results
@@ -747,7 +747,7 @@
         for guid in self._proxyGUIDs:
             proxyRecord = self.service.recordWithGUID(guid)
             if proxyRecord is None:
-                logger.err("No record for proxy in %s with GUID %s" % (self.shortName, guid), id=self)
+                logger.err("No record for proxy in %s with GUID %s" % (self.shortName, guid), id=(self, "Directory",))
             else:
                 yield proxyRecord
 
@@ -765,7 +765,7 @@
                 return opendirectory.authenticateUserBasic(self.service.directory, self._nodename, self.shortName, credentials.password)
             except opendirectory.ODError, e:
                 logger.err("Open Directory (node=%s) error while performing basic authentication for user %s: %s"
-                        % (self.service.realmName, self.shortName, e), id=self)
+                        % (self.service.realmName, self.shortName, e), id=(self, "Directory", "Security",))
                 return False
         elif isinstance(credentials, DigestedCredentials):
             try:
@@ -782,7 +782,7 @@
                                 'algorithm=%(algorithm)s') % credentials.fields
                 except KeyError, e:
                     logger.err("Open Directory (node=%s) error while performing digest authentication for user %s: missing digest response field: %s in: %s"
-                            % (self.service.realmName, self.shortName, e, credentials.fields), id=self)
+                            % (self.service.realmName, self.shortName, e, credentials.fields), id=(self, "Directory", "Security",))
                     return False
 
                 return opendirectory.authenticateUserDigest(
@@ -795,7 +795,7 @@
                 )
             except opendirectory.ODError, e:
                 logger.err("Open Directory (node=%s) error while performing digest authentication for user %s: %s"
-                        % (self.service.realmName, self.shortName, e), id=self)
+                        % (self.service.realmName, self.shortName, e), id=(self, "Directory", "Security",))
                 return False
 
         return super(OpenDirectoryRecord, self).verifyCredentials(credentials)

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/calendaruserproxy.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/calendaruserproxy.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/calendaruserproxy.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -27,7 +27,6 @@
 from cgi import escape
 
 from twisted.internet.defer import succeed
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
@@ -38,6 +37,7 @@
 from twistedcaldav.config import config
 from twistedcaldav.extensions import DAVFile, DAVPrincipalResource
 from twistedcaldav.extensions import ReadOnlyWritePropertiesResourceMixIn
+from twistedcaldav.logger import logger
 from twistedcaldav.sql import AbstractSQLDatabase
 from twistedcaldav.sql import db_prefix
 from twistedcaldav.static import AutoProvisioningFileMixIn
@@ -214,7 +214,7 @@
                     if item is None:
                         yield " '()\n"
                 except Exception, e:
-                    log.err("Exception while rendering: %s" % (e,))
+                    logger.err("Exception while rendering: %s" % (e,), id=self)
                     Failure().printTraceback()
                     yield "  ** %s **: %s\n" % (e.__class__.__name__, e)
             return "".join(genlist())

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/digest.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/digest.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/digest.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -18,9 +18,9 @@
 
 from twistedcaldav.sql import AbstractSQLDatabase
 from twistedcaldav.sql import db_prefix
+from twistedcaldav.logger import logger
 
 from twisted.cred import error
-from twisted.python import log
 from twisted.web2.auth.digest import DigestCredentialFactory
 from twisted.web2.auth.digest import DigestedCredentials
 
@@ -182,7 +182,7 @@
             self.exceptions += 1
             if self.exceptions >= self.exceptionLimit:
                 self._db_close()
-                log.err("Reset digest credentials database connection: %s" % (e,))
+                logger.err("Reset digest credentials database connection: %s" % (e,), id=(self, "Security",))
             raise
 
     def set(self, key, value):
@@ -197,7 +197,7 @@
             self.exceptions += 1
             if self.exceptions >= self.exceptionLimit:
                 self._db_close()
-                log.err("Reset digest credentials database connection: %s" % (e,))
+                logger.err("Reset digest credentials database connection: %s" % (e,), id=(self, "Security",))
             raise
 
     def get(self, key):
@@ -218,7 +218,7 @@
             self.exceptions += 1
             if self.exceptions >= self.exceptionLimit:
                 self._db_close()
-                log.err("Reset digest credentials database connection: %s" % (e,))
+                logger.err("Reset digest credentials database connection: %s" % (e,), id=(self, "Security",))
             raise
 
     def delete(self, key):
@@ -232,7 +232,7 @@
             self.exceptions += 1
             if self.exceptions >= self.exceptionLimit:
                 self._db_close()
-                log.err("Reset digest credentials database connection: %s" % (e,))
+                logger.err("Reset digest credentials database connection: %s" % (e,), id=(self, "Security",))
             raise
 
     def keys(self):
@@ -250,7 +250,7 @@
             self.exceptions += 1
             if self.exceptions >= self.exceptionLimit:
                 self._db_close()
-                log.err("Reset digest credentials database connection: %s" % (e,))
+                logger.err("Reset digest credentials database connection: %s" % (e,), id=(self, "Security",))
             raise
 
     def _set_in_db(self, key, value):
@@ -352,6 +352,7 @@
         
         # Make sure it is not a duplicate
         if self.db.has_key(c):
+            logger.err("nonce value already cached in credentials database: %s" % (c,), id=(self, "Security",))
             raise AssertionError("nonce value already cached in credentials database: %s" % (c,))
 
         # The database record is a tuple of (client ip, nonce-count, timestamp)
@@ -409,9 +410,11 @@
 
         username = auth.get('username')
         if not username:
+            logger.warn("No username", id=(self, "Security",))
             raise error.LoginFailed('Invalid response, no username given.')
 
         if 'nonce' not in auth:
+            logger.warn("No nonce for: %s" % (auth.get('username'),), id=(self, "Security",))
             raise error.LoginFailed('Invalid response, no nonce given.')
 
         # Now verify the nonce/cnonce values for this client
@@ -425,6 +428,7 @@
                 del credentials.fields['qop']
             return credentials
         else:
+            logger.warn("Invalid nonce/cnonce for: %s" % (auth.get('username'),), id=(self, "Security",))
             raise error.LoginFailed('Invalid nonce/cnonce values')
 
     def validate(self, auth, request):
@@ -447,21 +451,25 @@
 
         # First check we have this nonce
         if not self.db.has_key(nonce):
+            logger.warn("Invalid nonce for: %s" % (auth.get('username'),), id=(self, "Security",))
             raise error.LoginFailed('Invalid nonce value: %s' % (nonce,))
         db_clientip, db_nonce_count, db_timestamp = self.db.get(nonce)
 
         # Next check client ip
         if db_clientip != clientip:
             self.invalidate(nonce)
+            logger.warn("Client IPs do not match for: %s" % (auth.get('username'),), id=(self, "Security",))
             raise error.LoginFailed('Client IPs do not match: %s and %s' % (clientip, db_clientip,))
         
         # cnonce and nonce-count MUST be present if qop is present
         if auth.get('qop') is not None:
             if auth.get('cnonce') is None:
                 self.invalidate(nonce)
+                logger.warn("Missing cnonce for: %s" % (auth.get('username'),), id=(self, "Security",))
                 raise error.LoginFailed('cnonce is required when qop is specified')
             if nonce_count is None:
                 self.invalidate(nonce)
+                logger.warn("Missing nonce-count for: %s" % (auth.get('username'),), id=(self, "Security",))
                 raise error.LoginFailed('nonce-count is required when qop is specified')
                 
             # Next check the nonce-count is one greater than the previous one and update it in the DB
@@ -469,9 +477,11 @@
                 nonce_count = int(nonce_count, 16)
             except ValueError:
                 self.invalidate(nonce)
+                logger.warn("nonce-count not valid for: %s" % (auth.get('username'),), id=(self, "Security",))
                 raise error.LoginFailed('nonce-count is not a valid hex string: %s' % (auth.get('nonce-count'),))            
             if nonce_count != db_nonce_count + 1:
                 self.invalidate(nonce)
+                logger.warn("nonce-count out of sequence for: %s" % (auth.get('username'),), id=(self, "Security",))
                 raise error.LoginFailed('nonce-count value out of sequence: %s should be one more than %s' % (nonce_count, db_nonce_count,))
             self.db.set(nonce, (db_clientip, nonce_count, db_timestamp))
         else:
@@ -479,6 +489,7 @@
             # i.e. we can't allow a qop auth then a non-qop auth with the same nonce
             if db_nonce_count != 0:
                 self.invalidate(nonce)
+                logger.warn("nonce-count not allowed for: %s" % (auth.get('username'),), id=(self, "Security",))
                 raise error.LoginFailed('nonce-count was sent with this nonce: %s' % (nonce,))                
         
         # Now check timestamp
@@ -486,6 +497,7 @@
             self.invalidate(nonce)
             if request.remoteAddr:
                 request.remoteAddr.stale = True
+            logger.warn("Digest credentials expired for: %s" % (auth.get('username'),), id=(self, "Security",))
             raise error.LoginFailed('Digest credentials expired')
 
         return True
@@ -514,5 +526,5 @@
                         self.invalidate(key)
             except Exception, e:
                 # Clean-up errors can be logged but we should ignore them
-                log.err("Error cleaning digest credentials: %s" % (e,))
+                logger.err("Error cleaning digest credentials: %s" % (e,), id=(self, "Security",))
                 pass

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/directory.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/directory.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/directory.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -32,13 +32,13 @@
 
 from zope.interface import implements
 
-from twisted.python import log
 from twisted.cred.error import UnauthorizedLogin
 from twisted.cred.checkers import ICredentialsChecker
 from twisted.web2.dav.auth import IPrincipalCredentials
 
 from twistedcaldav.directory.idirectory import IDirectoryService, IDirectoryRecord
 from twistedcaldav.directory.util import uuidFromName
+from twistedcaldav.logger import logger
 
 class DirectoryService(object):
     implements(IDirectoryService, ICredentialsChecker)
@@ -61,10 +61,10 @@
             assert self.baseGUID, "Class %s must provide a baseGUID attribute" % (self.__class__.__name__,)
 
             if realmName is None:
-                log.err("Directory service %s has no realm name or GUID; generated service GUID will not be unique." % (self,))
+                logger.warn("Directory service %s has no realm name or GUID; generated service GUID will not be unique." % (self,), id=(self, "Directory",))
                 realmName = ""
             else:
-                log.err("Directory service %s has no GUID; generating service GUID from realm name." % (self,))
+                logger.warn("Directory service %s has no GUID; generating service GUID from realm name." % (self,), id=(self, "Directory",))
 
             self._guid = uuidFromName(self.baseGUID, realmName)
 

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/principal.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/principal.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/directory/principal.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -31,7 +31,6 @@
 from urllib import unquote
 from urlparse import urlparse
 
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.internet.defer import succeed
 from twisted.web2 import responsecode
@@ -45,6 +44,7 @@
 from twistedcaldav.directory.calendaruserproxy import CalendarUserProxyPrincipalResource
 from twistedcaldav.directory.directory import DirectoryService
 from twistedcaldav.extensions import ReadOnlyResourceMixIn, DAVFile, DAVPrincipalResource
+from twistedcaldav.logger import logger
 from twistedcaldav.resource import CalendarPrincipalCollectionResource, CalendarPrincipalResource
 from twistedcaldav.static import AutoProvisioningFileMixIn
 from twistedcaldav.directory.idirectory import IDirectoryService
@@ -193,7 +193,7 @@
     ##
 
     def createSimilarFile(self, path):
-        log.err("Attempt to create clone %r of resource %r" % (path, self))
+        logger.err("Attempt to create clone %r of resource %r" % (path, self), id=(self, "Directory",))
         raise HTTPError(responsecode.NOT_FOUND)
 
     def getChild(self, name):
@@ -245,7 +245,7 @@
     ##
 
     def createSimilarFile(self, path):
-        log.err("Attempt to create clone %r of resource %r" % (path, self))
+        logger.err("Attempt to create clone %r of resource %r" % (path, self), id=(self, "Directory",))
         raise HTTPError(responsecode.NOT_FOUND)
 
     def getChild(self, name):
@@ -297,7 +297,7 @@
     ##
 
     def createSimilarFile(self, path):
-        log.err("Attempt to create clone %r of resource %r" % (path, self))
+        logger.err("Attempt to create clone %r of resource %r" % (path, self), id=(self, "Directory",))
         raise HTTPError(responsecode.NOT_FOUND)
 
     def getChild(self, name):
@@ -315,7 +315,7 @@
         record = self.directory.recordWithGUID(primaryUID)
 
         if record is None:
-            log.err("No principal found for UID: %s" % (name,))
+            logger.err("No principal found for UID: %s" % (name,), id=(self, "Directory",))
             return None
 
         if record.enabledForCalendaring:
@@ -397,7 +397,7 @@
                     if item is None:
                         yield " '()\n"
                 except Exception, e:
-                    log.err("Exception while rendering: %s" % (e,))
+                    logger.err("Exception while rendering: %s" % (e,), id=self)
                     Failure().printTraceback()
                     yield "  ** %s **: %s\n" % (e.__class__.__name__, e)
             return "".join(genlist())
@@ -489,12 +489,11 @@
 
         if record not in records:
             records.add(record)
-            myRecordType = self.record.recordType
             for relative in getattr(record, method)():
                 if relative not in records:
                     found = self.parent.principalForRecord(relative)
                     if found is None:
-                        log.err("No principal found for directory record: %r" % (relative,))
+                        logger.err("No principal found for directory record: %r" % (relative,), id=(self, "Directory",))
                     else:
                         if proxy:
                             found = found.getChild("calendar-proxy-write")
@@ -537,7 +536,7 @@
     ##
 
     def createSimilarFile(self, path):
-        log.err("Attempt to create clone %r of resource %r" % (path, self))
+        logger.err("Attempt to create clone %r of resource %r" % (path, self), id=(self, "Directory",))
         raise HTTPError(responsecode.NOT_FOUND)
 
     def getChild(self, name):
@@ -563,7 +562,7 @@
                     if item is None:
                         yield " '()\n"
                 except Exception, e:
-                    log.err("Exception while rendering: %s" % (e,))
+                    logger.err("Exception while rendering: %s" % (e,), id=self)
                     Failure().printTraceback()
                     yield "  ** %s **: %s\n" % (e.__class__.__name__, e)
             return "".join(genlist())

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/dropbox.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/dropbox.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/dropbox.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -32,7 +32,6 @@
 import time
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
 from twisted.web2.dav.http import HTTPError, ErrorResponse, StatusResponse
@@ -42,6 +41,7 @@
 from twistedcaldav import customxml
 from twistedcaldav.config import config
 from twistedcaldav.customxml import calendarserver_namespace
+from twistedcaldav.logger import logger
 
 class DropBoxHomeResource (DAVResource):
     """
@@ -211,7 +211,7 @@
         """
         
         if not self.fp.exists():
-            log.err("File not found: %s" % (self.fp.path,))
+            logger.err("File not found: %s" % (self.fp.path,), id=(self, "dropbox",))
             raise HTTPError(responsecode.NOT_FOUND)
 
         # Read request body
@@ -221,7 +221,7 @@
             doc = doc.getResult()
         except ValueError, e:
             error = "Must have valid XML request body for POST on a dropbox: %s" % (e,)
-            log.err(error)
+            logger.err(error, id=(self, "dropbox",))
             raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, error))
         
         # Determine whether we are subscribing or unsubscribing and handle that
@@ -233,12 +233,12 @@
                 action = self.unsubscribe
             else:
                 error = "XML request body for POST on a dropbox must contain a single <subscribe> or <unsubscribe> element"
-                log.err(error)
+                logger.err(error, id=(self, "dropbox",))
                 raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, error))
         else:
             # If we get here we got an invalid request
             error = "Must have valid XML request body for POST on a dropbox"
-            log.err(error)
+            logger.err(error, id=(self, "dropbox",))
             raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, error))
 
         d = waitForDeferred(action(request))
@@ -262,7 +262,7 @@
     
         # Error if attempt to subscribe more than once
         if authid in principals:
-            log.err("Cannot x_apple_subscribe to resource %s as principal %s is already subscribed" % (request.uri, repr(authid),))
+            logger.err("Cannot x_apple_subscribe to resource %s as principal %s is already subscribed" % (request.uri, repr(authid),), id=(self, "dropbox",))
             raise HTTPError(ErrorResponse(
                 responsecode.FORBIDDEN,
                 (calendarserver_namespace, "principal-must-not-be-subscribed"))
@@ -291,7 +291,7 @@
     
         # Error if attempt to subscribe more than once
         if authid not in principals:
-            log.err("Cannot x_apple_unsubscribe from resource %s as principal %s is not currently subscribed" % (request.uri, repr(authid),))
+            logger.err("Cannot x_apple_unsubscribe from resource %s as principal %s is not currently subscribed" % (request.uri, repr(authid),), id=(self, "dropbox",))
             raise HTTPError(ErrorResponse(
                 responsecode.FORBIDDEN,
                 (calendarserver_namespace, "principal-must-be-subscribed"))

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/extensions.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/extensions.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/extensions.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -32,7 +32,6 @@
 import cgi
 import time
 
-from twisted.python import log
 from twisted.internet.defer import succeed, deferredGenerator, waitForDeferred
 from twisted.web2 import responsecode
 from twisted.web2.http import HTTPError, Response, RedirectResponse
@@ -48,6 +47,7 @@
 from twisted.web2.dav.util import joinURL
 from twistedcaldav.directory.sudo import SudoDirectoryService
 from twistedcaldav.directory.directory import DirectoryService
+from twistedcaldav.logger import logger
 
 class SudoSACLMixin(object):
     """
@@ -116,7 +116,7 @@
         if isSudoPrincipal(authid):
             if authz:
                 if isSudoPrincipal(authz):
-                    log.msg("Cannot proxy as another proxy: user '%s' as user '%s'" % (authid, authz))
+                    logger.err("Cannot proxy as another proxy: user '%s' as user '%s'" % (authid, authz), id=(self, "Security",))
                     raise HTTPError(responsecode.FORBIDDEN)
                 else:
                     authzPrincipal = getPrincipalForType(
@@ -126,18 +126,17 @@
                         authzPrincipal = self.findPrincipalForAuthID(authz)
 
                     if authzPrincipal is not None:
-                        log.msg("Allow proxy: user '%s' as '%s'" % (authid, authz,))
+                        logger.info("Allow proxy: user '%s' as '%s'" % (authid, authz,), id=(self, "Security",))
                         yield authzPrincipal
                         return
                     else:
-                        log.msg("Could not find authorization user id: '%s'" % 
-                                (authz,))
+                        logger.err("Could not find authorization user id: '%s'" % (authz,), id=(self, "Security",))
                         raise HTTPError(responsecode.FORBIDDEN)
             else:
-                log.msg("Cannot authenticate proxy user '%s' without X-Authorize-As header" % (authid, ))
+                logger.err("Cannot authenticate proxy user '%s' without X-Authorize-As header" % (authid, ), id=(self, "Security",))
                 raise HTTPError(responsecode.BAD_REQUEST)
         elif authz:
-            log.msg("Cannot proxy: user '%s' as '%s'" % (authid, authz,))
+            logger.err("Cannot proxy: user '%s' as '%s'" % (authid, authz,), id=(self, "Security",))
             raise HTTPError(responsecode.FORBIDDEN)
         else:
             # No proxy - do default behavior
@@ -520,12 +519,12 @@
                         value = property.toxml()
                 except HTTPError, e:
                     if e.response.code == responsecode.NOT_FOUND:
-                        log.err("Property {%s}%s was returned by listProperties() but does not exist for resource %s."
-                                % (qname[0], qname[1], self))
+                        logger.err("Property {%s}%s was returned by listProperties() but does not exist for resource %s."
+                                % (qname[0], qname[1], self), id=(self, "http",))
                         continue
 
                     if e.response.code != responsecode.UNAUTHORIZED:
-                        log.err("Unable to read property %s for dirlist: %s" % (qname, e))
+                        logger.err("Unable to read property %s for dirlist: %s" % (qname, e), id=(self, "http",))
                         raise
 
                     name = "{%s}%s" % qname

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/ical.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/ical.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/ical.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -42,12 +42,12 @@
 from vobject.icalendar import stringToDate, stringToDateTime, stringToDurations
 from vobject.icalendar import utc
 
-from twisted.python import log
 from twisted.web2.stream import IStream
 from twisted.web2.dav.util import allDataFromStream
 
 from twistedcaldav.dateops import compareDateTime, normalizeToUTC, timeRangesOverlap
 from twistedcaldav.instance import InstanceList
+from twistedcaldav.logger import logger
 
 iCalendarProductID = "-//CALENDARSERVER.ORG//NONSGML Version 1//EN"
 
@@ -856,8 +856,8 @@
         for timezone in timezones:
             if timezone not in timezone_refs:
                 #raise ValueError(
-                log.msg(
-                    "Timezone %s is not referenced by any non-timezone component" % (timezone,)
+                logger.warn(
+                    "Timezone %s is not referenced by any non-timezone component" % (timezone,), id=(self, "iCalendar",)
                 )
 
     def transformAllFromNative(self):

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/index.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/index.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/index.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -37,9 +37,8 @@
 except ImportError:
     from pysqlite2 import dbapi2 as sqlite
 
-from twisted.python import log
-
 from twistedcaldav.ical import Component
+from twistedcaldav.logger import logger
 from twistedcaldav.query import calendarquery
 from twistedcaldav.sql import AbstractSQLDatabase
 from twistedcaldav.sql import db_prefix
@@ -161,7 +160,7 @@
             name_utf8 = name.encode("utf-8")
             if name is not None and self.resource.getChild(name_utf8) is None:
                 # Clean up
-                log.err("Stale resource record found for child %s with UID %s in %s" % (name, uid, self.resource))
+                logger.err("Stale resource record found for child %s with UID %s in %s" % (name, uid, self.resource), id=self)
                 self._delete_from_db(name, uid)
                 self._db_commit()
             else:
@@ -282,8 +281,8 @@
             if self.resource.getChild(name.encode("utf-8")):
                 yield row
             else:
-                log.err("Calendar resource %s is missing from %s. Removing from index."
-                        % (name, self.resource))
+                logger.err("Calendar resource %s is missing from %s. Removing from index."
+                        % (name, self.resource), id=self)
                 self.deleteResource(name)
 
     def _db_version(self):
@@ -473,7 +472,7 @@
                 % (uid, self.resource)
             )
         except sqlite.Error, e:
-            log.err("Unable to reserve UID: %s", (e,))
+            logger.err("Unable to reserve UID: %s", (e,), id=self)
             self._db_rollback()
             raise
     
@@ -494,7 +493,7 @@
             self._db_execute("delete from RESERVED where UID = :1", uid)
             self._db_commit()
         except sqlite.Error, e:
-            log.err("Unable to unreserve UID: %s", (e,))
+            logger.err("Unable to unreserve UID: %s", (e,), id=self)
             self._db_rollback()
             raise
     
@@ -516,7 +515,7 @@
                     self._db_execute("delete from RESERVED where UID = :1", uid)
                     self._db_commit()
                 except sqlite.Error, e:
-                    log.err("Unable to unreserve UID: %s", (e,))
+                    logger.err("Unable to unreserve UID: %s", (e,), id=self)
                     self._db_rollback()
                     raise
                 return False
@@ -572,7 +571,7 @@
             try:
                 stream = fp.child(name).open()
             except (IOError, OSError), e:
-                log.err("Unable to open resource %s: %s" % (name, e))
+                logger.err("Unable to open resource %s: %s" % (name, e), id=self)
                 continue
 
             try:
@@ -581,9 +580,9 @@
                     calendar = Component.fromStream(stream)
                     calendar.validateForCalDAV()
                 except ValueError:
-                    log.err("Non-calendar resource: %s" % (name,))
+                    logger.err("Non-calendar resource: %s" % (name,), id=self)
                 else:
-                    #log.msg("Indexing resource: %s" % (name,))
+                    logger.debug("Indexing resource: %s" % (name,), id=self)
                     self.addResource(name, calendar, True)
             finally:
                 stream.close()
@@ -683,7 +682,7 @@
             try:
                 stream = fp.child(name).open()
             except (IOError, OSError), e:
-                log.err("Unable to open resource %s: %s" % (name, e))
+                logger.err("Unable to open resource %s: %s" % (name, e), id=self)
                 continue
 
             try:
@@ -693,9 +692,9 @@
                     calendar.validCalendarForCalDAV()
                     calendar.validateComponentsForCalDAV(True)
                 except ValueError:
-                    log.err("Non-calendar resource: %s" % (name,))
+                    logger.err("Non-calendar resource: %s" % (name,), id=self)
                 else:
-                    #log.msg("Indexing resource: %s" % (name,))
+                    logger.debug("Indexing resource: %s" % (name,), id=self)
                     self.addResource(name, calendar)
             finally:
                 stream.close()

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logger.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logger.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logger.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -116,15 +116,33 @@
         @return:     True if the log level is currently active.
         """
         
+        current_level = -1
         if kwargs.has_key("id"):
             id = kwargs["id"]
-            if type(id) == types.ClassType:
-                kwargs["system"] = id.__name__
-            elif type(id) == types.InstanceType:
-                kwargs["system"] = id.__class__.__name__
-            elif type(id) in types.StringTypes:
-                kwargs["system"] = id
-        current_level = self.options.systemLogLevels.get(kwargs.get("system", ""), self.options.currentLogLevel)
+            if type(id) not in (types.TupleType, types.ListType,):
+                id = (id,)
+            items = []
+            for item in id:
+                if type(item) in (
+                    types.StringType,
+                    types.UnicodeType,
+                    types.IntType,
+                    types.LongType,
+                    types.FloatType,
+                    types.BooleanType,
+                ):
+                    item = str(item)
+                elif getattr(item, "__name__", None):
+                    item = item.__name__
+                elif getattr(item, "__class__", None):
+                    item = item.__class__.__name__
+                else:
+                    item = str(item)
+                current_level = max(current_level, self.options.systemLogLevels.get(item, self.options.currentLogLevel))
+                items.append(item)
+            kwargs["system"] = ",".join(items)
+        if current_level == -1:
+            current_level = self.options.currentLogLevel
         return current_level >= Logger.logtypes.get(level, 1)
     
     def info(self, message, **kwargs):

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logging.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logging.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logging.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -214,7 +214,7 @@
 
         newpath = "%s.%s" % (self.logpath, self.suffix(self.lastDate))
         if os.path.exists(newpath):
-            log.msg("Cannot rotate log file to %s because it already exists." % (newpath,))
+            logger.err("Cannot rotate log file to %s because it already exists." % (newpath,), id="Logging")
             return
         self.logMessage("Log closed - rotating: [%s]." % (datetime.datetime.now().ctime(),), False)
         logger.info("Rotating log file to: %s" % (newpath,), id="Logging")

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/copymove.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/copymove.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/copymove.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -25,7 +25,6 @@
 from urlparse import urlsplit
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.filter.location import addLocation
 from twisted.web2.dav import davxml
@@ -34,6 +33,7 @@
 from twisted.web2.http import StatusResponse, HTTPError
 
 from twistedcaldav.caldavxml import caldav_namespace
+from twistedcaldav.logger import logger
 from twistedcaldav.method.put_common import storeCalendarObjectResource
 from twistedcaldav.resource import isCalendarCollectionResource
 
@@ -78,8 +78,8 @@
     # Check for existing destination resource
     overwrite = request.headers.getHeader("overwrite", True)
     if destination.exists() and not overwrite:
-        log.err("Attempt to copy onto existing file without overwrite flag enabled: %s"
-                % (destination.fp.path,))
+        logger.err("Attempt to copy onto existing file without overwrite flag enabled: %s"
+                % (destination.fp.path,), id=(self, "http",))
         raise HTTPError(StatusResponse(
             responsecode.PRECONDITION_FAILED,
             "Destination %s already exists." % (destination_uri,))
@@ -87,12 +87,12 @@
 
     # Checks for copying a calendar collection
     if self.isCalendarCollection():
-        log.err("Attempt to copy a calendar collection into another calendar collection %s" % destination)
+        logger.err("Attempt to copy a calendar collection into another calendar collection %s" % destination, id=(self, "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "calendar-collection-location-ok")))
 
     # We also do not allow regular collections in calendar collections
     if self.isCollection():
-        log.err("Attempt to copy a collection into a calendar collection")
+        logger.err("Attempt to copy a collection into a calendar collection", id=(self, "http",))
         raise HTTPError(StatusResponse(
             responsecode.NOT_ALLOWED,
             "Cannot create collection within special collection %s" % (destination,))
@@ -161,8 +161,8 @@
     # Check for existing destination resource
     overwrite = request.headers.getHeader("overwrite", True)
     if destination.exists() and not overwrite:
-        log.err("Attempt to copy onto existing file without overwrite flag enabled: %s"
-                % (destination.fp.path,))
+        logger.err("Attempt to copy onto existing file without overwrite flag enabled: %s"
+                % (destination.fp.path,), id=(self, "http",))
         raise HTTPError(StatusResponse(
             responsecode.PRECONDITION_FAILED,
             "Destination %s already exists." % (destination_uri,)
@@ -171,12 +171,12 @@
     if destinationcal:
         # Checks for copying a calendar collection
         if self.isCalendarCollection():
-            log.err("Attempt to copy a calendar collection into another calendar collection %s" % destination)
+            logger.err("Attempt to copy a calendar collection into another calendar collection %s" % destination, id=(self, "http",))
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "calendar-collection-location-ok")))
     
         # We also do not allow regular collections in calendar collections
         if self.isCollection():
-            log.err("Attempt to copy a collection into a calendar collection")
+            logger.err("Attempt to copy a collection into a calendar collection", id=(self, "http",))
             raise HTTPError(StatusResponse(
                 responsecode.NOT_ALLOWED,
                 "Cannot create collection within special collection %s" % (destination,)
@@ -209,15 +209,15 @@
     if that is the case.
     @return: tuple::
         result:           True if special CalDAV processing required, False otherwise
-                          NB If there is any type of error with the request, return False
-                          and allow normal COPY/MOVE processing to return the error.
+            NB If there is any type of error with the request, return False
+            and allow normal COPY/MOVE processing to return the error.
         sourcecal:        True if source is in a calendar collection, False otherwise
         sourceparent:     The parent resource for the source
         destination_uri:  The URI of the destination resource
         destination:      CalDAVFile of destination if special proccesing required,
         None otherwise
         destinationcal:   True if the destination is in a calendar collection,
-                          False otherwise
+            False otherwise
         destinationparent:The parent resource for the destination
         
     """
@@ -228,7 +228,7 @@
     
     # Check the source path first
     if not self.fp.exists():
-        log.err("File not found: %s" % (self.fp.path,))
+        logger.err("File not found: %s" % (self.fp.path,), id=(self, "http",))
         raise HTTPError(StatusResponse(
             responsecode.NOT_FOUND,
             "Source resource %s not found." % (request.uri,)
@@ -249,7 +249,7 @@
 
     if not destination_uri:
         msg = "No destination header in %s request." % (request.method,)
-        log.err(msg)
+        logger.err(msg, id=(self, "http",))
         raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, msg))
     
     destination = waitForDeferred(request.locateResource(destination_uri))

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/mkcalendar.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/mkcalendar.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/mkcalendar.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -23,7 +23,6 @@
 __all__ = ["http_MKCALENDAR"]
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
@@ -33,6 +32,7 @@
 from twisted.web2.http import HTTPError, StatusResponse
 
 from twistedcaldav import caldavxml
+from twistedcaldav.logger import logger
 
 def http_MKCALENDAR(self, request):
     """
@@ -52,16 +52,16 @@
     x.getResult()
 
     if self.exists():
-        log.err("Attempt to create collection where file exists: %s"
-                % (self.fp.path,))
+        logger.err("Attempt to create collection where file exists: %s"
+                % (self.fp.path,), id=(self, "http",))
         raise HTTPError(ErrorResponse(
             responsecode.FORBIDDEN,
             (davxml.dav_namespace, "resource-must-be-null"))
         )
 
     if not parent.isCollection():
-        log.err("Attempt to create collection with non-collection parent: %s"
-                % (self.fp.path,))
+        logger.err("Attempt to create collection with non-collection parent: %s"
+                % (self.fp.path,), id=(self, "http",))
         raise HTTPError(ErrorResponse(
             responsecode.CONFLICT,
             (caldavxml.caldav_namespace, "calendar-collection-location-ok"))
@@ -79,7 +79,7 @@
         yield result
         result = result.getResult()
     except ValueError, e:
-        log.err("Error while handling MKCALENDAR: %s" % (e,))
+        logger.err("Error while handling MKCALENDAR: %s" % (e,), id=(self, "http",))
         raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, str(e)))
 
     if doc is not None:
@@ -90,7 +90,7 @@
 
             error = ("Non-%s element in MKCALENDAR request body: %s"
                      % (caldavxml.MakeCalendar.name, makecalendar))
-            log.err(error)
+            logger.err(error, id=(self, "http",))
             raise HTTPError(StatusResponse(responsecode.UNSUPPORTED_MEDIA_TYPE, error))
 
         errors = PropertyStatusResponseQueue("PROPPATCH", request.uri, responsecode.NO_CONTENT)

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/put.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/put.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/put.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -23,13 +23,13 @@
 __all__ = ["http_PUT"]
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav.http import ErrorResponse
 from twisted.web2.dav.util import allDataFromStream, parentForURL
 from twisted.web2.http import HTTPError, StatusResponse
 
 from twistedcaldav.caldavxml import caldav_namespace
+from twistedcaldav.logger import logger
 from twistedcaldav.method.put_common import storeCalendarObjectResource
 from twistedcaldav.resource import isPseudoCalendarCollectionResource
 
@@ -46,7 +46,7 @@
         # Content-type check
         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,))
+            logger.err("MIME type %s not allowed in calendar collection" % (content_type,), id=(self, "http",))
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
             
         # Read the calendar component from the stream
@@ -74,7 +74,7 @@
             return
 
         except ValueError, e:
-            log.err("Error while handling (calendar) PUT: %s" % (e,))
+            logger.err("Error while handling (calendar) PUT: %s" % (e,), id=(self, "http",))
             raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, str(e)))
 
     else:

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -31,7 +31,6 @@
 
 import string
 
-from twisted.python import log
 from twisted.internet.defer import deferredGenerator, waitForDeferred
 from twisted.web2 import responsecode
 from twisted.web2.http import HTTPError, StatusResponse
@@ -41,6 +40,7 @@
 from twisted.web2.dav.util import davXMLFromStream
 
 from twistedcaldav import caldavxml
+from twistedcaldav.logger import logger
 
 max_number_of_matches = 500
 
@@ -52,7 +52,7 @@
     Respond to a REPORT request. (RFC 3253, section 3.6)
     """
     if not self.fp.exists():
-        log.err("File not found: %s" % (self.fp.path,))
+        logger.err("File not found: %s" % (self.fp.path,), id=(self, "http",))
         raise HTTPError(responsecode.NOT_FOUND)
 
     #
@@ -63,7 +63,7 @@
         yield doc
         doc = doc.getResult()
     except ValueError, e:
-        log.err("Error while handling REPORT body: %s" % (e,))
+        logger.err("Error while handling REPORT body: %s" % (e,), id=(self, "http",))
         raise HTTPError(StatusResponse(responsecode.BAD_REQUEST, str(e)))
 
     if doc is None:
@@ -108,8 +108,8 @@
         #
         # Requested report is not supported.
         #
-        log.err("Unsupported REPORT {%s}%s for resource %s (no method %s)"
-                % (namespace, name, self, method_name))
+        logger.err("Unsupported REPORT {%s}%s for resource %s (no method %s)"
+                % (namespace, name, self, method_name), id=(self, "http",))
 
         raise HTTPError(ErrorResponse(
             responsecode.FORBIDDEN,

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_calquery.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_calquery.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_calquery.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -23,7 +23,6 @@
 __all__ = ["report_urn_ietf_params_xml_ns_caldav_calendar_query"]
 
 from twisted.internet.defer import deferredGenerator, succeed, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
 from twisted.web2.dav.element.base import dav_namespace
@@ -33,6 +32,7 @@
 from twisted.web2.http import HTTPError, StatusResponse
 
 from twistedcaldav.caldavxml import caldav_namespace
+from twistedcaldav.logger import logger
 from twistedcaldav.method import report_common
 
 import urllib
@@ -54,7 +54,7 @@
         yield parent
         parent = parent.getResult()
         if not parent.isPseudoCalendarCollection():
-            log.err("calendar-query report is not allowed on a resource outside of a calendar collection %s" % (self,))
+            logger.err("calendar-query report is not allowed on a resource outside of a calendar collection %s" % (self,), id=(self, "http",))
             raise HTTPError(StatusResponse(responsecode.FORBIDDEN, "Must be calendar collection or calendar resource"))
 
     responses = []
@@ -67,7 +67,7 @@
     # Get the original timezone provided in the query, if any, and validate it now
     query_tz = calendar_query.timezone
     if query_tz is not None and not query_tz.valid():
-        log.err("CalDAV:timezone must contain one VTIMEZONE component only: %s" % (query_tz,))
+        logger.err("CalDAV:timezone must contain one VTIMEZONE component only: %s" % (query_tz,), id=(self, "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
     if query_tz:
         filter.settimezone(query_tz)
@@ -86,7 +86,7 @@
         # Verify that any calendar-data element matches what we can handle
         result, message, generate_calendar_data = report_common.validPropertyListCalendarDataTypeVersion(query)
         if not result:
-            log.err(message)
+            logger.err(message, id=(self, "http",))
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
         
     else:
@@ -94,7 +94,7 @@
 
     # Verify that the filter element is valid
     if (filter is None) or not filter.valid():
-        log.err("Invalid filter element: %r" % (filter,))
+        logger.err("Invalid filter element: %r" % (filter,), id=(self, "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-filter")))
 
     matchcount = [0]
@@ -221,7 +221,7 @@
         yield d
         d.getResult()
     except NumberOfMatchesWithinLimits:
-        log.err("Too many matching components in calendar-query report")
+        logger.err("Too many matching components in calendar-query report", id=(self, "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (dav_namespace, "number-of-matches-within-limits")))
     
     yield MultiStatusResponse(responses)

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_common.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_common.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_common.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -29,7 +29,6 @@
 ]
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
@@ -46,6 +45,7 @@
 from twistedcaldav.dateops import clipPeriod, normalizePeriodList, timeRangesOverlap
 from twistedcaldav.ical import Component, Property, iCalendarProductID
 from twistedcaldav.instance import InstanceList
+from twistedcaldav.logger import logger
 
 from vobject.icalendar import utc
 
@@ -104,8 +104,8 @@
     @param href: the L{HRef} element of the resource being targetted.
     @param resource: the L{CalDAVFile} for the targetted resource.
     @param calendar: the L{Component} for the calendar for the resource. This may be None
-                     if the calendar has not already been read in, in which case the resource
-                     will be used to get the calendar if needed.
+        if the calendar has not already been read in, in which case the resource
+        will be used to get the calendar if needed.
     @param propertiesForResource: the method to use to get the list of properties to return.
     @param propertyreq: the L{PropertyContainer} element for the properties of interest.
     """
@@ -135,8 +135,8 @@
     @param prop: the L{PropertyContainer} element for the properties of interest.
     @param resource: the L{CalDAVFile} for the targetted resource.
     @param calendar: the L{Component} for the calendar for the resource. This may be None
-                     if the calendar has not already been read in, in which case the resource
-                     will be used to get the calendar if needed.
+        if the calendar has not already been read in, in which case the resource
+        will be used to get the calendar if needed.
     @return: a map of OK and NOT FOUND property values.
     """
 
@@ -154,8 +154,8 @@
     @param prop: the L{PropertyContainer} element for the properties of interest.
     @param resource: the L{CalDAVFile} for the targetted resource.
     @param calendar: the L{Component} for the calendar for the resource. This may be None
-                     if the calendar has not already been read in, in which case the resource
-                     will be used to get the calendar if needed.
+        if the calendar has not already been read in, in which case the resource
+        will be used to get the calendar if needed.
     @return: a map of OK and NOT FOUND property values.
     """
 
@@ -176,8 +176,8 @@
     @param prop: the L{PropertyContainer} element for the properties of interest.
     @param resource: the L{CalDAVFile} for the targetted resource.
     @param calendar: the L{Component} for the calendar for the resource. This may be None
-                     if the calendar has not already been read in, in which case the resource
-                     will be used to get the calendar if needed.
+        if the calendar has not already been read in, in which case the resource
+        will be used to get the calendar if needed.
     @return: a map of OK and NOT FOUND property values.
     """
     
@@ -213,8 +213,8 @@
     @param props: a list of property elements or qname tuples for the properties of interest.
     @param resource: the L{CalDAVFile} for the targetted resource.
     @param calendar: the L{Component} for the calendar for the resource. This may be None
-                     if the calendar has not already been read in, in which case the resource
-                     will be used to get the calendar if needed.
+        if the calendar has not already been read in, in which case the resource
+        will be used to get the calendar if needed.
     @return: a map of OK and NOT FOUND property values.
     """
     properties_by_status = {
@@ -253,7 +253,7 @@
     
                 status = statusForFailure(f, "getting property: %s" % (qname,))
                 if status != responsecode.NOT_FOUND:
-                    log.err("Error reading property %r for resource %s: %s" % (qname, request.uri, f.value))
+                    logger.err("Error reading property %r for resource %s: %s" % (qname, request.uri, f.value), id=("report_common", "http",))
                 if status not in properties_by_status: properties_by_status[status] = []
                 properties_by_status[status].append(propertyName(qname))
         else:
@@ -346,7 +346,7 @@
         # between our initial index query and getting here. For now we will ignore this errror, but in
         # the longer term we need to simplement some form of locking, perhaps.
         if calendar is None:
-            log.err("Calendar %s is missing from calendar collection %r" % (name, calresource))
+            logger.err("Calendar %s is missing from calendar collection %r" % (name, calresource), id=("report_common", "http",))
             continue
         
         # Ignore ones of this UID

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_freebusy.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_freebusy.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_freebusy.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -23,7 +23,6 @@
 __all__ = ["report_urn_ietf_params_xml_ns_caldav_free_busy_query"]
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav.element.base import dav_namespace
 from twisted.web2.dav.http import ErrorResponse
@@ -33,6 +32,7 @@
 from twisted.web2.stream import MemoryStream
 
 from twistedcaldav import caldavxml
+from twistedcaldav.logger import logger
 from twistedcaldav.method import report_common
 
 def report_urn_ietf_params_xml_ns_caldav_free_busy_query(self, request, freebusy): #@UnusedVariable
@@ -41,7 +41,7 @@
     (CalDAV-access-09, section 7.8)
     """
     if not self.isCollection():
-        log.err("freebusy report is only allowed on collection resources %s" % (self,))
+        logger.err("freebusy report is only allowed on collection resources %s" % (self,), id=("report_freebusy", "http",))
         raise HTTPError(StatusResponse(responsecode.FORBIDDEN, "Not a calendar collection"))
 
     if freebusy.qname() != (caldavxml.caldav_namespace, "free-busy-query"):
@@ -75,7 +75,7 @@
         yield d
         d.getResult()
     except NumberOfMatchesWithinLimits:
-        log.err("Too many matching components in free-busy report")
+        logger.err("Too many matching components in free-busy report", id=("report_freebusy", "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (dav_namespace, "number-of-matches-within-limits")))
     
     # Now build a new calendar object with the free busy info we have

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_multiget.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_multiget.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/method/report_multiget.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -23,7 +23,6 @@
 __all__ = ["report_urn_ietf_params_xml_ns_caldav_calendar_multiget"]
 
 from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
 from twisted.web2.dav.element.base import dav_namespace
@@ -33,6 +32,7 @@
 from twisted.web2.http import HTTPError, StatusResponse
 
 from twistedcaldav.caldavxml import caldav_namespace
+from twistedcaldav.logger import logger
 from twistedcaldav.method import report_common
 
 from urllib import unquote
@@ -55,7 +55,7 @@
         yield parent
         parent = parent.getResult()
         if not parent.isPseudoCalendarCollection():
-            log.err("calendar-multiget report is not allowed on a resource outside of a calendar collection %s" % (self,))
+            logger.err("calendar-multiget report is not allowed on a resource outside of a calendar collection %s" % (self,), id=("report_multiget", "http",))
             raise HTTPError(StatusResponse(responsecode.FORBIDDEN, "Must be calendar resource"))
 
     responses = []
@@ -77,14 +77,14 @@
         # Verify that any calendar-data element matches what we can handle
         result, message, generate_calendar_data = report_common.validPropertyListCalendarDataTypeVersion(propertyreq)
         if not result:
-            log.err(message)
+            logger.err(message, id=("report_multiget", "http",))
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
     else:
         raise AssertionError("We shouldn't be here")
 
     # Check size of results is within limit
     if len(resources) > max_number_of_multigets:
-        log.err("Too many results in multiget report: %d" % len(resources))
+        logger.err("Too many results in multiget report: %d" % len(resources), id=("report_multiget", "http",))
         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (dav_namespace, "number-of-matches-within-limits")))
 
     """

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/resource.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/resource.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/resource.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -32,8 +32,6 @@
 
 from twisted.internet import reactor
 from twisted.internet.defer import Deferred, maybeDeferred, succeed
-from twisted.internet.defer import deferredGenerator, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
 from twisted.web2.dav.idav import IDAVPrincipalCollectionResource
@@ -58,9 +56,6 @@
 from twistedcaldav.ical import allowedComponents
 from twistedcaldav.ical import Component as iComponent
 
-from twistedcaldav.directory.directory import DirectoryService
-from twistedcaldav.directory.sudo import SudoDirectoryService
-
 if twistedcaldav.__version__:
     serverVersion = twisted.web2.server.VERSION + " TwistedCalDAV/" + twistedcaldav.__version__
 else:

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/root.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/root.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/root.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -17,7 +17,6 @@
 ##
 
 from twisted.internet import defer
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.cred.error import LoginFailed, UnauthorizedLogin
 
@@ -28,6 +27,7 @@
 
 from twistedcaldav.extensions import DAVFile
 from twistedcaldav.config import config
+from twistedcaldav.logger import logger
 
 class RootResource(DAVFile):
     """
@@ -45,9 +45,9 @@
             if RootResource.CheckSACL:
                 self.useSacls = True
             else:
-                log.msg(("RootResource.CheckSACL is unset but "
+                logger.warn(("RootResource.CheckSACL is unset but "
                          "config.EnableSACLs is True, SACLs will not be "
-                         "turned on."))
+                         "turned on."), id=[self, "Startup", "Security",])
 
         self.contentFilters = []
 
@@ -65,7 +65,7 @@
             # SACLs are authorization for the use of the service,
             # so unauthenticated access doesn't make any sense.
             if authzUser == davxml.Principal(davxml.Unauthenticated()):
-                log.msg("Unauthenticated users not enabled with the '%s' SACL" % (self.saclService,))
+                logger.warn("Unauthenticated users not enabled with the '%s' SACL" % (self.saclService,), id=["self", "Security",])
                 return Failure(HTTPError(UnauthorizedResponse(
                             request.credentialFactories,
                             request.remoteAddr)))
@@ -94,7 +94,7 @@
                 username = principal.record.shortName
                 
                 if RootResource.CheckSACL(username, self.saclService) != 0:
-                    log.msg("User '%s' is not enabled with the '%s' SACL" % (username, self.saclService,))
+                    logger.warn("User '%s' is not enabled with the '%s' SACL" % (username, self.saclService,), id=[self, "Security",])
                     return Failure(HTTPError(403))
     
                 # Mark SACL's as having been checked so we can avoid doing it multiple times

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/sql.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/sql.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/sql.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -31,7 +31,7 @@
 except ImportError:
     from pysqlite2 import dbapi2 as sqlite
 
-from twisted.python import log
+from twistedcaldav.logger import logger
 
 db_prefix = ".db."
 
@@ -109,11 +109,11 @@
 
                     if (version != self._db_version()) or (type != self._db_type()):
                         if version != self._db_version():
-                            log.err("Database %s has different schema (v.%s vs. v.%s)"
-                                    % (db_filename, version, self._db_version()))
+                            logger.err("Database %s has different schema (v.%s vs. v.%s)"
+                                       % (db_filename, version, self._db_version()), id=self)
                         if type != self._db_type():
-                            log.err("Database %s has different type (%s vs. %s)"
-                                    % (db_filename, type, self._db_type()))
+                            logger.err("Database %s has different type (%s vs. %s)"
+                                    % (db_filename, type, self._db_type()), id=self)
 
                         # Delete this index and start over
                         q.close()
@@ -137,7 +137,7 @@
         @param db_filename: the file name of the index database.
         @param q:           a database cursor to use.
         """
-        log.msg("Initializing database %s" % (db_filename,))
+        logger.info("Initializing database %s" % (db_filename,), id=self)
 
         self._db_init_schema_table(q)
         self._db_init_data_tables(q)
@@ -231,7 +231,7 @@
             try:
                 q.execute(sql, query_params)
             except:
-                log.err("Exception while executing SQL: %r %r" % (sql, query_params))
+                logger.err("Exception while executing SQL: %r %r" % (sql, query_params), id=self)
                 raise
             return q.fetchall()
         finally:

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/static.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/static.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/static.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -40,7 +40,6 @@
 from urlparse import urlsplit
 
 from twisted.internet.defer import deferredGenerator, fail, succeed, waitForDeferred
-from twisted.python import log
 from twisted.web2 import responsecode
 from twisted.web2.http import HTTPError, StatusResponse
 from twisted.web2.dav import davxml
@@ -56,11 +55,11 @@
 from twistedcaldav import customxml
 from twistedcaldav.caldavxml import caldav_namespace
 from twistedcaldav.config import config
-from twistedcaldav.directory.directory import DirectoryService
 from twistedcaldav.extensions import DAVFile
 from twistedcaldav.ical import Component as iComponent
 from twistedcaldav.ical import Property as iProperty
 from twistedcaldav.index import Index, IndexSchedule
+from twistedcaldav.logger import logger
 from twistedcaldav.notifications import NotificationsCollectionResource, NotificationResource
 from twistedcaldav.resource import CalDAVResource, isCalendarCollectionResource, isPseudoCalendarCollectionResource
 from twistedcaldav.schedule import ScheduleInboxResource, ScheduleOutboxResource
@@ -97,21 +96,21 @@
         #
 
         if self.fp.exists():
-            log.err("Attempt to create collection where file exists: %s" % (self.fp.path,))
+            logger.err("Attempt to create collection where file exists: %s" % (self.fp.path,), id=(self, "http",))
             raise HTTPError(StatusResponse(responsecode.NOT_ALLOWED, "File exists"))
 
         if not os.path.isdir(os.path.dirname(self.fp.path)):
-            log.err("Attempt to create collection with no parent: %s" % (self.fp.path,))
+            logger.err("Attempt to create collection with no parent: %s" % (self.fp.path,), id=(self, "http",))
             raise HTTPError(StatusResponse(responsecode.CONFLICT, "No parent collection"))
 
         #
         # Verify that no parent collection is a calendar also
         #
-        log.msg("Creating calendar collection %s" % (self,))
+        logger.info("Creating calendar collection %s" % (self,), id=(self, "http",))
 
         def _defer(parent):
             if parent is not None:
-                log.err("Cannot create a calendar collection within a calendar collection %s" % (parent,))
+                logger.err("Cannot create a calendar collection within a calendar collection %s" % (parent,), id=(self, "http",))
                 raise HTTPError(ErrorResponse(
                     responsecode.FORBIDDEN,
                     (caldavxml.caldav_namespace, "calendar-collection-location-ok")
@@ -158,7 +157,7 @@
             try:
                 rmdir(self.fp)
             except Exception, e:
-                log.err("Unable to clean up after failed MKCOL (special resource type: %s): %s" % (e, resourceType,))
+                logger.err("Unable to clean up after failed MKCOL (special resource type: %s): %s" % (e, resourceType,), id=(self, "http",))
             return f
 
         d = mkcollection(self.fp)
@@ -346,7 +345,7 @@
         @param request: the request currently in progress
         @param uri: the URI to test
         @return: True if the supplied URI is a child resource
-                 False if not
+            False if not
         """
         if uri is None: return False
 
@@ -406,7 +405,7 @@
         if fp.exists():
             return False
 
-        log.msg("Provisioning file: %s" % (self,))
+        logger.info("Provisioning file: %s" % (self,), id=(self, "Directory",))
 
         if hasattr(self, "parent"):
             parent = self.parent
@@ -465,11 +464,11 @@
         record = self.directory.recordWithShortName(self.recordType, name)
 
         if record is None:
-            log.msg("No directory record %r of type %r" % (name, self.recordType))
+            logger.err("No directory record %r of type %r" % (name, self.recordType), id=(self, "Directory",))
             return None
 
         if not record.enabledForCalendaring:
-            log.msg("Directory record %r of type %r is not enabled for calendaring" % (name, self.recordType))
+            logger.err("Directory record %r of type %r is not enabled for calendaring" % (name, self.recordType), id=(self, "Directory",))
             return None
 
         child = CalendarHomeFile(self.fp.child(name).path, self, record)

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/tap.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/tap.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/tap.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -426,10 +426,10 @@
             ),
         ]
 
-        logger.info("Setting up AdminPrincipals", id="Startup")
+        logger.info("Setting up AdminPrincipals", id=["Startup", "Security",])
 
         for principal in config.AdminPrincipals:
-            logger.info("Added %s as admin principal" % (principal,), id="Startup")
+            logger.info("Added %s as admin principal" % (principal,), id=["Startup", "Security",])
 
             rootACEs.append(
                 davxml.ACE(
@@ -440,7 +440,7 @@
                 )
             )
 
-        logger.info("Setting root ACL", id="Startup")
+        logger.info("Setting root ACL", id=["Startup", "Security",])
 
         root.setAccessControlList(davxml.ACL(*rootACEs))
 
@@ -456,7 +456,7 @@
 
         realm = directory.realmName or ""
 
-        logger.info("Configuring authentication for realm: %s" % (realm,), id="Startup")
+        logger.info("Configuring authentication for realm: %s" % (realm,), id=["Startup", "Security",])
 
         for scheme, schemeConfig in config.Authentication.iteritems():
             scheme = scheme.lower()
@@ -464,11 +464,11 @@
             credFactory = None
 
             if schemeConfig['Enabled']:
-                logger.info("Setting up scheme: %s" % (scheme,), id="Startup")
+                logger.info("Setting up scheme: %s" % (scheme,), id=["Startup", "Security",])
 
                 if scheme == 'kerberos':
                     if not NegotiateCredentialFactory:
-                        logger.info("Kerberos support not available", id="Startup")
+                        logger.warn("Kerberos support not available", id=["Startup", "Security",])
                         continue
 
                     try:
@@ -478,7 +478,7 @@
                         else:
                             credFactory = NegotiateCredentialFactory(principal=principal)
                     except ValueError:
-                        logger.info("Could not start Kerberos", id="Startup")
+                        logger.warn("Could not start Kerberos", id=["Startup", "Security",])
                         continue
 
                 elif scheme == 'digest':
@@ -493,12 +493,12 @@
                     credFactory = BasicCredentialFactory(realm)
 
                 else:
-                    logger.err("Unknown scheme: %s" % (scheme,), id="Startup")
+                    logger.err("Unknown scheme: %s" % (scheme,), id=["Startup", "Security",])
 
             if credFactory:
                 credentialFactories.append(credFactory)
 
-        logger.info("Configuring authentication wrapper", id="Startup")
+        logger.info("Configuring authentication wrapper", id=["Startup", "Security",])
 
         authWrapper = auth.AuthenticationWrapper(
             root,

Modified: CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_logger.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_logger.py	2007-10-12 18:39:49 UTC (rev 1959)
+++ CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_logger.py	2007-10-15 15:44:24 UTC (rev 1960)
@@ -189,3 +189,71 @@
         self.assertFalse(logger.canLog("warning", {"id":"Dummy"}))
         self.assertFalse(logger.canLog("info", {"id":"Dummy"}))
         self.assertFalse(logger.canLog("debug", {"id":"Dummy"}))
+
+    def testMultipleLogging(self):
+        self.loadLogfile(testLogger_More)
+
+        args = {"id": ["Startup",]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+        args = {"id": ["Startup", "iTIP"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "Startup,iTIP")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertTrue(logger.canLog("debug", args))
+
+        args = {"id": ["Dummy1", "Dummy2"]}
+        self.assertFalse(logger.canLog("error", args))
+        self.assertEquals(args["system"], "Dummy1,Dummy2")
+        self.assertFalse(logger.canLog("warning", args))
+        self.assertFalse(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+        args = {"id": ["Dummy1", "Startup"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "Dummy1,Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+    def testTypesLogging(self):
+        self.loadLogfile(testLogger_More)
+
+        class _A(object):
+            pass
+
+        class _B(object):
+            pass
+
+        args = {"id": [_A, "Startup"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "_A,Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+        args = {"id": [_B(), "Startup"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "_B,Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+        args = {"id": [123, "Startup"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "123,Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))
+
+        args = {"id": [u'Testing', "Startup"]}
+        self.assertTrue(logger.canLog("error", args))
+        self.assertEquals(args["system"], "Testing,Startup")
+        self.assertTrue(logger.canLog("warning", args))
+        self.assertTrue(logger.canLog("info", args))
+        self.assertFalse(logger.canLog("debug", args))

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20071015/66891a76/attachment-0001.html


More information about the calendarserver-changes mailing list