[CalendarServer-changes] [2155] CalendarServer/branches/users/cdaboo/better-logging-2152

source_changes at macosforge.org source_changes at macosforge.org
Mon Feb 18 13:32:03 PST 2008


Revision: 2155
          http://trac.macosforge.org/projects/calendarserver/changeset/2155
Author:   cdaboo at apple.com
Date:     2008-02-18 13:32:02 -0800 (Mon, 18 Feb 2008)

Log Message:
-----------
Merged forward from trunk.

Modified Paths:
--------------
    CalendarServer/branches/users/cdaboo/better-logging-2152/conf/caldavd.plist
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/__init__.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/authkerb.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/caldavxml.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/cluster.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/config.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/appleopendirectory.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/calendaruserproxy.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/digest.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/directory.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/principal.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/dropbox.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/extensions.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/ical.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/index.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/itip.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logging.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/copymove.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/mkcalendar.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put_common.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_calquery.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_common.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_freebusy.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_multiget.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/pdmonster.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/root.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/schedule.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/sql.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/static.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/tap.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_config.py

Added Paths:
-----------
    CalendarServer/branches/users/cdaboo/better-logging-2152/conf/logger.plist
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/accounting.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logger.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_accounting.py
    CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_logger.py

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/conf/caldavd.plist
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/conf/caldavd.plist	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/conf/caldavd.plist	2008-02-18 21:32:02 UTC (rev 2155)
@@ -189,8 +189,9 @@
     Logging
   -->
 
-  <key>Verbose</key>
-  <false/>
+  <!-- Options for the logger system -->
+  <key>LoggerOptionsFile</key>
+  <string>/etc/caldavd/logger.plist</string>
 
   <!-- Apache-style access log -->
   <key>AccessLogFile</key>

Copied: CalendarServer/branches/users/cdaboo/better-logging-2152/conf/logger.plist (from rev 2153, CalendarServer/branches/users/cdaboo/better-logging-1957/conf/logger.plist)
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/conf/logger.plist	                        (rev 0)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/conf/logger.plist	2008-02-18 21:32:02 UTC (rev 2155)
@@ -0,0 +1,58 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+
+<!--
+    Logging levels:
+        "none"    - no logging.
+        "error"   - errors only.
+        "warning" - errors and warnings only.
+        "info"    - errors, warnings and info.
+        "debug"   - errors, warnings, info and debug.
+-->
+
+	<!-- Default log level for all systems. -->
+	<key>Default Log Level</key>
+	<string>error</string>
+
+	<!-- Log levels overriding the default level for specific systems. -->
+	<!-- The keys in the dict are the system names, the string values the overridden log levels. -->
+	<key>System Log Levels</key>
+	<dict>
+		<!-- Its useful to have a higher than normal logging for the startup phase. -->
+		<key>Startup</key>
+		<string>info</string>
+
+		<!-- We're likely to want to keep a close eye on security related issues. -->
+		<key>Security</key>
+		<string>warning</string>
+
+		<!-- To track down auto-response issues enable this. -->
+		<!--
+		<key>iTIP</key>
+		<string>info</string>
+		-->
+
+		<!-- To track down iTIP messaging issues enable this. -->
+		<!--
+		<key>CalDAV Outbox POST</key>
+		<string>info</string>
+		-->
+	</dict>
+
+	<!-- Per User Accounting -->
+	<key>Accounting</key>
+	<dict>
+	    <key>Enabled</key>
+	    <false/>
+	    <key>LogDirectory</key>
+	    <string>/var/log/caldavd/logs</string>
+	    <key>iTIP</key>
+	    <false/>
+	    <key>principals</key>
+	    <array></array>
+	</dict>
+
+</dict>
+</plist>

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/__init__.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/__init__.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/__init__.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -23,12 +23,11 @@
 from twisted.web2.static import File, loadMimeTypes
 
 __all__ = [
+    "accounting",
     "authkerb",
     "caldavxml",
     "customxml",
     "dateops",
-    "db",
-    "directory",
     "dropbox",
     "extensions",
     "fileops",
@@ -37,9 +36,9 @@
     "index",
     "instance",
     "itip",
+    "logger",
     "logging",
     "notifications",
-    "principalindex",
     "resource",
     "root",
     "schedule",

Copied: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/accounting.py (from rev 2153, CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/accounting.py)
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/accounting.py	                        (rev 0)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/accounting.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -0,0 +1,150 @@
+##
+# Copyright (c) 2006-2007 Apple Inc. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+##
+
+from twistedcaldav.logger import logger
+
+import itertools
+import datetime
+import os
+
+"""
+Classes and functions for user accounting.
+
+Allows different sub-systems to log data on a per-user basis.
+
+Right now only iTIP logging is supported.
+
+See logger.py for more details.
+"""
+
+class Accounting(object):
+    
+    # Types of account data to store. The first item in the tuple is a name for the account file/directory,
+    # the second item is True if its a directory, False if its a file.
+    type_iTIP  = ("iTIP", True)
+
+    _all_types = (type_iTIP, )
+
+    @staticmethod
+    def isEnabled():
+        """
+        Is accounting enabled.
+        """
+        return logger.accounting().get("Enabled", False)
+    
+    @staticmethod
+    def isiTIPEnabled(principal):
+        """
+        Is iTIP accounting enabled.
+
+        @param principal: the principal for whom a log entry is to be created.
+        @type principal: L{DirectoryPrincipalResource}
+        """
+        return (
+            Accounting.isEnabled() and
+            logger.accounting().get("iTIP", False) and
+            Accounting.isPrincipalEnabled(principal)
+        )
+    
+    @staticmethod
+    def isPrincipalEnabled(principal):
+        """
+        Is principal accounting enabled.
+
+        @param principal: the principal for whom a log entry is to be created.
+        @type principal: L{DirectoryPrincipalResource}
+        """
+        
+        # None specified => all enabled
+        enabled = logger.accounting().get("principals", ())
+        if not enabled:
+            return True
+        
+        for url in itertools.chain((principal.principalURL(),), principal.alternateURIs()):
+            if url in enabled:
+                return True
+            
+        return False
+            
+    @staticmethod
+    def getLog(principal, accounting_type=None):
+        """
+        Get the log file/directory path.
+
+        @param principal: the principal for whom a log entry is to be created.
+        @type principal: L{DirectoryPrincipalResource}
+        @param accounting_type: a tuple of log name and file/directory log type.
+        @type accounting_type: C{tuple}
+        
+        @return: the file/directory path.
+        @type: C{str}
+        """
+
+        assert (accounting_type in Accounting._all_types) or (accounting_type is None), "Supplied type not valid: %s" % (accounting_type,)
+        
+        # Path is the config value + record type + short name + type (if provided)
+        log_path = logger.accounting().get("LogDirectory", "")
+        
+        record = principal.record
+        
+        log_path = os.path.join(log_path, record.recordType)
+        log_path = os.path.join(log_path, record.shortName)
+
+        # Make sure this path exists
+        if not os.path.exists(log_path):
+            os.makedirs(log_path)
+
+        if type:
+            type_name, type_isdirectory = accounting_type
+            log_path = os.path.join(log_path, type_name)
+            if not os.path.exists(log_path) and type_isdirectory:
+                os.mkdir(log_path)
+
+        return log_path
+
+    @staticmethod
+    def writeData(principal, accounting_type, data):
+        """
+        Write the supplied data to the appropriate location for the principal.
+        
+        @param principal: the principal for whom a log entry is to be created.
+        @type principal: L{DirectoryPrincipalResource}
+        @param accounting_type: a tuple of log name and file/directory log type.
+        @type accounting_type: C{tuple}
+        @param data: data to write.
+        @type data: C{str}
+        """
+        
+        assert accounting_type in Accounting._all_types, "Supplied type not valid: %s" % (accounting_type,)
+
+        if not Accounting.isPrincipalEnabled(principal):
+            return
+
+        _ignore_type_name, type_isdirectory = accounting_type
+        log_path = Accounting.getLog(principal, accounting_type)
+        if type_isdirectory:
+            # Generate a timestamp
+            log_path = os.path.join(log_path, datetime.datetime.now().isoformat())
+            if os.path.exists(log_path):
+                for ctr in range(1, 100):
+                    if not os.path.exists(log_path + "-%02d" % (ctr,)):
+                        log_path += "-%02d" % (ctr,)
+                        break
+                    
+        # Now write out the data to the file
+        file = open(log_path, "a")
+        file.write(data)
+        file.close()

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/authkerb.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/authkerb.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/authkerb.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -43,7 +43,7 @@
 from twisted.web2.auth.interfaces import ICredentialFactory
 from twisted.web2.dav.auth import IPrincipalCredentials
 
-from twistedcaldav import logging
+from twistedcaldav.logger import logger
 
 import kerberos
 
@@ -75,7 +75,7 @@
             try:
                 principal = kerberos.getServerPrincipalDetails(type, hostname)
             except kerberos.KrbError, ex:
-                logging.err("getServerPrincipalDetails: %s" % (ex[0],), system="KerberosCredentialFactoryBase")
+                logger.err("getServerPrincipalDetails: %s" % (ex[0],), id=(self, "Security",))
                 raise ValueError('Authentication System Failure: %s' % (ex[0],))
 
         try:
@@ -85,11 +85,12 @@
             service = splits[0].upper()
             realm = splits[1]
         except IndexError:
-            logging.err("Invalid Kerberos principal: %s" % (principal,), system="KerberosCredentialFactoryBase")
+            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.debug("Service: %s  Realm: %s" % (self.service, self.realm,), id=(self, "Security",))
 
 class BasicKerberosCredentials(credentials.UsernamePassword):
     """
@@ -169,7 +170,7 @@
             try:
                 kerberos.checkPassword(creds.username, creds.password, creds.service, creds.default_realm)
             except kerberos.BasicAuthError, ex:
-                logging.err("%s" % (ex[0],), system="BasicKerberosCredentialsChecker")
+                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,))
@@ -217,18 +218,18 @@
         try:
             _ignore_result, context = kerberos.authGSSServerInit(self.service);
         except kerberos.GSSError, ex:
-            logging.err("authGSSServerInit: %s(%s)" % (ex[0][0], ex[1][0],), system="NegotiateCredentialFactory")
+            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:
-            logging.err("authGSSServerStep: %s(%s)" % (ex[0][0], ex[1][0],), system="NegotiateCredentialFactory")
+            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:
-            logging.err("authGSSServerStep: %s" % (ex[0],), system="NegotiateCredentialFactory")
+            logger.debug("authGSSServerStep: %s" % (ex[0],), id=(self, "Security",))
             kerberos.authGSSServerClean(context)
             raise error.UnauthorizedLogin('Bad credentials: %s' % (ex[0],))
 
@@ -242,10 +243,10 @@
             username = splits[0]
             realmname = splits[1]
         
-        # We currently do not support cross-realm authentciation, so we
+        # 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:
-            logging.err("authGSSServer Realms do not match: %s vs %s" % (realmname, self.realm,), system="NegotiateCredentialFactory")
+            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')
 
@@ -254,7 +255,7 @@
         try:
             kerberos.authGSSServerClean(context);
         except kerberos.GSSError, ex:
-            logging.err("authGSSServerClean: %s" % (ex[0][0], ex[1][0],), system="NegotiateCredentialFactory")
+            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-2152/twistedcaldav/caldavxml.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/caldavxml.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/caldavxml.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -25,14 +25,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
 
@@ -101,7 +100,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
@@ -440,7 +439,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:
@@ -1052,32 +1051,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
@@ -1160,7 +1159,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
@@ -1363,16 +1362,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-2152/twistedcaldav/cluster.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/cluster.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/cluster.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -18,13 +18,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, ConfigurationError
+from twistedcaldav.logger import logger
 
 from twistedcaldav.util import getNCPU
 
@@ -151,13 +150,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:
@@ -274,17 +272,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)
 
@@ -295,7 +293,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-2152/twistedcaldav/config.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/config.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/config.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -103,12 +103,12 @@
     #
     # Logging
     #
-    "Verbose": False,
-    "AccessLogFile"  : "/var/log/caldavd/access.log",                   # Apache-style access log
-    "ErrorLogFile"   : "/var/log/caldavd/error.log",                    # Server activity log
-    "ServerStatsFile": "/var/run/caldavd/stats.plist",
-    "PIDFile"        : "/var/run/caldavd.pid",
-    "RotateAccessLog": False,
+    "LoggerOptionsFile"  : "/etc/caldavd/logger.plist",                     # Options for the logger system
+    "AccessLogFile"      : "/var/log/caldavd/access.log",                   # Apache-style access log
+    "ErrorLogFile"       : "/var/log/caldavd/error.log",                    # Server activity log
+    "ServerStatsFile"    : "/var/run/caldavd/stats.plist",
+    "PIDFile"            : "/var/run/caldavd.pid",
+    "RotateAccessLog"    : False,
 
     #
     # SSL/TLS
@@ -213,6 +213,10 @@
                 del self._data["DirectoryService"]["params"][param]
 
         self.updateServerCapabilities()
+        
+        # Make sure logger levels are read in and setup
+        from twistedcaldav.logger import logger
+        logger.readOptions()
 
     def updateServerCapabilities(self):
         """

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/appleopendirectory.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/appleopendirectory.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/appleopendirectory.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -36,7 +36,7 @@
 from twisted.cred.credentials import UsernamePassword
 from twisted.web2.auth.digest import DigestedCredentials
 
-from twistedcaldav import logging
+from twistedcaldav.logger import logger
 from twistedcaldav.config import config
 from twistedcaldav.directory.directory import DirectoryService, DirectoryRecord
 from twistedcaldav.directory.directory import DirectoryError, UnknownRecordTypeError
@@ -69,7 +69,7 @@
         try:
             directory = opendirectory.odInit(node)
         except opendirectory.ODError, e:
-            logging.err("Open Directory (node=%s) Initialization error: %s" % (node, e), system="OpenDirectoryService")
+            logger.err("Open Directory (node=%s) Initialization error: %s" % (node, e), id=(self, "Startup", "Directory",))
             raise
 
         self.realmName = node
@@ -88,7 +88,7 @@
                 try:
                     self._lookupVHostRecord()
                 except Exception, e:
-                    logging.err("Unable to locate virtual host record: %s" % (e,), system="OpenDirectoryService")
+                    logger.err("Unable to locate virtual host record: %s" % (e,), id=(self, "Startup", "Directory",))
                     raise
 
                 if os.path.exists(serverPreferences):
@@ -97,7 +97,7 @@
                     self.isWorkgroupServer = serverInfo.get('ServiceConfig', {}).get('IsWorkgroupServer', False)
 
                     if self.isWorkgroupServer:
-                        logging.info("Enabling Workgroup Server compatibility mode", system="OpenDirectoryService")
+                        logger.info("Enabling Workgroup Server compatibility mode", id=(self, "Startup", "Directory",))
 
             for recordType in self.recordTypes():
                 self.recordsForType(recordType)
@@ -133,9 +133,9 @@
             )
 
             if not result:
-                logging.err(
+                logger.err(
                     "Couldn't find group %s when trying to expand nested groups."
-                    % (groupGUID,), system="OpenDirectoryService"
+                    % (groupGUID,), id=(self, "Directory",)
                 )
                 continue
 
@@ -215,16 +215,16 @@
         # Log all the matching records
         for key, value in self.computerRecords.iteritems():
             _ignore_recordname, enabled, servicetag = value
-            logging.info("Matched Directory record: %s with ServicesLocator: %s, state: %s" % (
+            logger.info("Matched Directory record: %s with ServicesLocator: %s, state: %s" % (
                 key,
                 servicetag,
                 {True:"enabled", False:"disabled"}[enabled]
-            ), system="OpenDirectoryService")
+            ), 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:
-                logging.info("Enabled ServicesLocator: %s" % (tag,), system="OpenDirectoryService")
+                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 "
@@ -247,10 +247,10 @@
         plist = readPlistFromString(plist)
         vhosts = plist.get("com.apple.macosxserver.virtualhosts", None)
         if not vhosts:
-            logging.err(
+            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), system="OpenDirectoryService"
+                % (self.realmName, recordlocation,), id=(self, "Startup", "Directory",)
             )
             return False
         
@@ -271,10 +271,10 @@
         # Get host name
         hostname = vhosts[hostguid].get("hostname", None)
         if not hostname:
-            logging.err(
+            logger.err(
                 "Open Directory (node=%s) %s record does not have "
                 "any host name in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation, ), system="OpenDirectoryService"
+                % (self.realmName, recordlocation, ), id=(self, "Startup", "Directory",)
             )
             return False
         if hostname != vhostname:
@@ -285,20 +285,20 @@
         # ignore the details themselves (scheme/port) as we use our own config for that.
         hostdetails = vhosts[hostguid].get("hostDetails", None)
         if not hostdetails:
-            logging.err(
+            logger.err(
                 "Open Directory (node=%s) %s record does not have "
                 "any host details in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation, ), system="OpenDirectoryService"
+                % (self.realmName, recordlocation, ), id=(self, "Startup", "Directory",)
             )
             return False
         
         # Look at the service data
         serviceInfos = vhosts[hostguid].get("serviceInfo", None)
         if not serviceInfos or not serviceInfos.has_key("calendar"):
-            logging.err(
+            logger.err(
                 "Open Directory (node=%s) %s record does not have a "
                 "calendar service in its apple-serviceinfo attribute value"
-                % (self.realmName, recordlocation), system="OpenDirectoryService"
+                % (self.realmName, recordlocation), id=(self, "Startup", "Directory",)
             )
             return False
         serviceInfo = serviceInfos["calendar"]
@@ -372,9 +372,9 @@
 
                 def onError(f):
                     storage["status"] = "stale" # Keep trying
-                    logging.err(
+                    logger.err(
                         "Unable to load records of type %s from OpenDirectory due to unexpected error: %s"
-                        % (recordType, f), system="OpenDirectoryService"
+                        % (recordType, f), id=(self, "Directory",)
                     )
 
                 d = deferToThread(self.reloadCache, recordType)
@@ -420,18 +420,18 @@
                 self.reloadCache(recordType, guid=guid)
                 record = lookup()
                 if record is not None:
-                    logging.info("Faulted record with GUID %s into %s record cache" % (guid, recordType), system="OpenDirectoryService")
+                    logger.info("Faulted record with GUID %s into %s record cache" % (guid, recordType), id=(self, "Directory",))
                     break
             else:
-                logging.info("Unable to find any record with GUID %s" % (guid,), system="OpenDirectoryService")
+                logger.info("Unable to find any record with GUID %s" % (guid,), id=(self, "Directory",))
 
         return record
 
     def reloadCache(self, recordType, shortName=None, guid=None):
         if shortName:
-            logging.info("Faulting record %s into %s record cache" % (shortName, recordType), system="OpenDirectoryService")
+            logger.info("Faulting record %s into %s record cache" % (shortName, recordType,), id=(self, "Directory",))
         elif guid is None:
-            logging.info("Reloading %s record cache" % (recordType,), system="OpenDirectoryService")
+            logger.info("Reloading %s record cache" % (recordType,), id=(self, "Directory",))
 
         results = self._queryDirectory(recordType, shortName=shortName, guid=guid)
         
@@ -457,14 +457,14 @@
                 if not value.get(dsattributes.kDSNAttrServicesLocator):
                     if recordType == DirectoryService.recordType_groups:
                         enabledForCalendaring = False
-                        logging.debug(
+                        logger.debug(
                             "Group %s is not enabled for calendaring but may be used in ACLs"
-                            % (recordShortName,), system="OpenDirectoryService"
+                            % (recordShortName,), id=(self, "Directory",)
                         )
                     else:
-                        logging.err(
+                        logger.err(
                             "Directory (incorrectly) returned a record with no ServicesLocator attribute: %s"
-                            % (recordShortName,), system="OpenDirectoryService"
+                            % (recordShortName,), id=(self, "Directory",)
                         )
                         continue
 
@@ -474,8 +474,8 @@
             recordNodeName = value.get(dsattributes.kDSNAttrMetaNodeLocation)
 
             if not recordGUID:
-                logging.debug("Record (%s)%s in node %s has no GUID; ignoring." % (recordType, recordShortName, recordNodeName),
-                              system="OpenDirectoryService")
+                logger.debug("Record (%s)%s in node %s has no GUID; ignoring." % (recordType, recordShortName, recordNodeName),
+                              id=(self, "Directory",))
                 continue
 
             # Get calendar user addresses from directory record.
@@ -526,8 +526,8 @@
             del recordShortName
             del recordGUID
 
-            def disableRecord(record):
-                logging.warn("Record disabled due to conflict: %s" % (record,), system="OpenDirectoryService")
+            def disableRecord(record, reason):
+                logger.warn("%s: %s" % (reason, record,), id=(self, "Directory",))
 
                 shortName = record.shortName
                 guid      = record.guid
@@ -542,7 +542,7 @@
 
             # Check for disabled items
             if record.shortName in disabledNames or record.guid in disabledGUIDs:
-                disableRecord(record)
+                disableRecord(record, "Record already disabled")
             else:
                 # Check for duplicate items and disable all names/guids for mismatched duplicates.
                 if record.shortName in records:
@@ -554,12 +554,12 @@
 
                 if existing_record is not None:
                     if record.guid != existing_record.guid or record.shortName != existing_record.shortName:
-                        disableRecord(existing_record)
-                        disableRecord(record)
+                        disableRecord(existing_record, "Existing record now disabled")
+                        disableRecord(record, "New record disabled")
 
                 if record.shortName not in disabledNames:
                     records[record.shortName] = guids[record.guid] = record
-                    logging.debug("Added record %s to OD record cache" % (record,), system="OpenDirectoryService")
+                    logger.debug("Added record %s to OD record cache" % (record,), id=(self, "Directory",))
 
         if shortName is None and guid is None:
             #
@@ -586,7 +586,10 @@
 
             self._records[recordType] = storage
 
-            logging.debug("Added %d records to %s OD record cache" % (len(self._records[recordType]["guids"]), recordType), system="OpenDirectoryService")
+            logger.debug(
+                "Added %d records to %s OD record cache"
+                % (len(self._records[recordType]["guids"]), recordType), id=(self, "Directory",)
+            )
 
     def _queryDirectory(self, recordType, shortName=None, guid=None):
         attrs = [
@@ -645,7 +648,7 @@
                         )
 
                     if not guidQueries:
-                        logging.warn("No SACL enabled users found.", system="OpenDirectoryService")
+                        logger.warn("No SACL enabled users found.", id=(self, "Directory",))
                         return ()
 
                     query = dsquery.expression(dsquery.expression.OR, guidQueries)
@@ -710,7 +713,7 @@
                     attrs,
                 )
         except opendirectory.ODError, ex:
-            logging.err("Open Directory (node=%s) error: %s" % (self.realmName, str(ex)), system="OpenDirectoryService")
+            logger.err("Open Directory (node=%s) error: %s" % (self.realmName, str(ex)), id=(self, "Directory",))
             raise
 
         return results
@@ -775,7 +778,7 @@
         for guid in self._proxyGUIDs:
             proxyRecord = self.service.recordWithGUID(guid)
             if proxyRecord is None:
-                logging.err("No record for proxy in %s with GUID %s" % (self.shortName, guid), system="OpenDirectoryService")
+                logger.err("No record for proxy in %s with GUID %s" % (self.shortName, guid), id=(self, "Directory",))
             else:
                 yield proxyRecord
 
@@ -803,8 +806,8 @@
                     self.password = credentials.password
                     return True
             except opendirectory.ODError, e:
-                logging.err("Open Directory (node=%s) error while performing basic authentication for user %s: %s"
-                            % (self.service.realmName, self.shortName, e), system="OpenDirectoryService")
+                logger.err("Open Directory (node=%s) error while performing basic authentication for user %s: %s"
+                            % (self.service.realmName, self.shortName, e), id=(self, "Directory", "Security",))
 
             return False
 
@@ -824,11 +827,11 @@
                     'algorithm=%(algorithm)s'
                 ) % credentials.fields
             except KeyError, e:
-                logging.err(
+                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),
-                    system="OpenDirectoryService"
+                    id=(self, "Directory", "Security",)
                 )
                 return False
 
@@ -856,10 +859,13 @@
 
                     return True
             except opendirectory.ODError, e:
-                logging.err(
+                logger.err(
                     "Open Directory (node=%s) error while performing digest authentication for user %s: %s"
-                    % (self.service.realmName, self.shortName, e), system="OpenDirectoryService"
+                    % (self.service.realmName, self.shortName, e), id=(self, "Directory", "Security",)
                 )
+            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, "Directory", "Security",))
                 return False
 
             return False

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/calendaruserproxy.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/calendaruserproxy.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/calendaruserproxy.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -22,11 +22,7 @@
     "CalendarUserProxyPrincipalResource",
 ]
 
-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
 from twisted.web2.dav.element.base import dav_namespace

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/digest.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/digest.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/digest.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -15,9 +15,9 @@
 ##
 
 from twistedcaldav.sql import AbstractSQLDatabase
+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
 
@@ -179,7 +179,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):
@@ -194,7 +194,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):
@@ -215,7 +215,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):
@@ -229,7 +229,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):
@@ -247,7 +247,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):
@@ -349,6 +349,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)
@@ -406,9 +407,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
@@ -422,6 +425,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):
@@ -444,21 +448,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
@@ -466,9 +474,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:
@@ -476,6 +486,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
@@ -483,6 +494,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
@@ -511,5 +523,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-2152/twistedcaldav/directory/directory.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/directory.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/directory.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -30,13 +30,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)
@@ -59,10 +59,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-2152/twistedcaldav/directory/principal.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/principal.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/directory/principal.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -29,7 +29,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
@@ -43,6 +42,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
@@ -191,7 +191,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):
@@ -243,7 +243,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):
@@ -295,7 +295,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):
@@ -313,7 +313,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:
@@ -464,12 +464,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")
@@ -512,7 +511,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):
@@ -695,7 +694,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=("format_list",))
             Failure().printTraceback()
             yield "  ** %s **: %s\n" % (e.__class__.__name__, e)
     return "".join(genlist())

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/dropbox.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/dropbox.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/dropbox.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -30,7 +30,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
@@ -40,6 +39,7 @@
 from twistedcaldav import customxml
 from twistedcaldav.config import config
 from twistedcaldav.customxml import calendarserver_namespace
+from twistedcaldav.logger import logger
 
 class DropBoxHomeResource (DAVResource):
     """
@@ -209,7 +209,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
@@ -219,7 +219,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
@@ -231,12 +231,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))
@@ -260,7 +260,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"))
@@ -289,7 +289,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-2152/twistedcaldav/extensions.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/extensions.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/extensions.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -33,7 +33,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
@@ -49,6 +48,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
@@ -519,12 +518,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-2152/twistedcaldav/ical.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/ical.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/ical.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -40,12 +40,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"
 
@@ -891,8 +891,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-2152/twistedcaldav/index.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/index.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/index.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -35,9 +35,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
@@ -159,7 +158,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:
@@ -280,8 +279,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):
@@ -471,7 +470,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
     
@@ -492,7 +491,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
     
@@ -514,7 +513,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
@@ -570,7 +569,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:
@@ -579,9 +578,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()
@@ -681,7 +680,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:
@@ -691,9 +690,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-2152/twistedcaldav/itip.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/itip.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/itip.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -43,7 +43,7 @@
 from twisted.web2.dav.resource import AccessDeniedError
 
 from twistedcaldav import caldavxml
-from twistedcaldav import logging
+from twistedcaldav.logger import logger
 from twistedcaldav.ical import Property, iCalendarProductID
 from twistedcaldav.method import report_common
 from twistedcaldav.method.put_common import storeCalendarObjectResource
@@ -109,7 +109,7 @@
     @param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
     """
     
-    logging.info("Auto-processing iTIP REQUEST for: %s" % (str(principal),), system="iTIP")
+    logger.info("Auto-processing iTIP REQUEST for: %s" % (str(principal),), id="iTIP")
     processed = "ignored"
 
     # First determine whether this is a full or partial update. A full update is one containing the master
@@ -156,29 +156,29 @@
                         newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, calendar))
                         yield newchild
                         newchild = newchild.getResult()
-                        logging.info("Replaced calendar component %s with new iTIP message in %s." % (calmatch, calURL), system="iTIP")
+                        logger.info("Replaced calendar component %s with new iTIP message in %s." % (calmatch, calURL), id="iTIP")
                     else:
                         newchild = waitForDeferred(writeResource(request, calURL, updatecal, None, calendar))
                         yield newchild
                         newchild.getResult()
-                        logging.info("Added new calendar component in %s." % (calURL,), system="iTIP")
+                        logger.info("Added new calendar component in %s." % (calURL,), id="iTIP")
                 else:
                     if calmatch:
                         d = waitForDeferred(deleteResource(updatecal, calmatch))
                         yield d
                         d.getResult()
-                        logging.info("Deleted calendar component %s in %s as update was not accepted." % (calmatch, calURL), system="iTIP")
+                        logger.info("Deleted calendar component %s in %s as update was not accepted." % (calmatch, calURL), id="iTIP")
                         
                 # Send a reply if needed. 
                 if doreply:
-                    logging.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), system="iTIP")
+                    logger.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), id="iTIP")
                     newchild = waitForDeferred(writeReply(request, principal, replycal, inbox))
                     yield newchild
                     newchild = newchild.getResult()
                     newInboxResource(child, newchild)
                 processed = "processed"
             except:
-                logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+                logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
                 raise iTipException
             
     else:
@@ -229,17 +229,17 @@
                     newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, cal))
                     yield newchild
                     newchild = newchild.getResult()
-                    logging.info("Merged calendar component %s with new iTIP message in %s." % (calmatch, calURL), system="iTIP")
+                    logger.info("Merged calendar component %s with new iTIP message in %s." % (calmatch, calURL), id="iTIP")
                 else:
                     if accepted:
                         newchild = waitForDeferred(writeResource(request, calURL, updatecal, None, calendar))
                         yield newchild
                         newchild.getResult()
-                        logging.info("Added new calendar component in %s." % (calURL,), system="iTIP")
+                        logger.info("Added new calendar component in %s." % (calURL,), id="iTIP")
                         
                 # Do reply if needed. 
                 if doreply:
-                    logging.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), system="iTIP")
+                    logger.info("Sending iTIP REPLY %s" % (("declined","accepted")[accepted],), id="iTIP")
                     newchild = waitForDeferred(writeReply(request, principal, replycal, inbox))
                     yield newchild
                     newchild = newchild.getResult()
@@ -247,7 +247,7 @@
                     
                 processed = "processed"
             except:
-                logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+                logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
                 raise iTipException
 
     # Remove the now processed incoming request.
@@ -255,13 +255,13 @@
         d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
         yield d
         d.getResult()
-        logging.info("Deleted new iTIP message %s in Inbox because it has been %s." %
+        logger.info("Deleted new iTIP message %s in Inbox because it has been %s." %
             (child.fp.basename(),
              {"processed":"processed",
               "older":    "ignored: older",
-              "ignored":  "ignored: no match"}[processed],), system="iTIP")
+              "ignored":  "ignored: no match"}[processed],), id="iTIP")
     except:
-        logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+        logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
         raise iTipException
     yield None
     return
@@ -279,7 +279,7 @@
     @param calendar: the L{Component} for the iTIP message we are processing.
     @param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
     """
-    logging.info("Auto-processing iTIP ADD for: %s" % (str(principal),), system="iTIP")
+    logger.info("Auto-processing iTIP ADD for: %s" % (str(principal),), id="iTIP")
 
     raise NotImplementedError
 
@@ -320,7 +320,7 @@
     @param child: the L{CalDAVFile} for the iTIP message resource already saved to the Inbox.
     """
     
-    logging.info("Auto-processing iTIP CANCEL for: %s" % (str(principal),), system="iTIP")
+    logger.info("Auto-processing iTIP CANCEL for: %s" % (str(principal),), id="iTIP")
     processed = "ignored"
 
     # Get all component info for this iTIP message
@@ -364,9 +364,9 @@
                     d = waitForDeferred(deleteResource(updatecal, calmatch,))
                     yield d
                     d.getResult()
-                    logging.info("Delete calendar component %s in %s as it was cancelled." % (calmatch, calURL), system="iTIP")
+                    logger.info("Delete calendar component %s in %s as it was cancelled." % (calmatch, calURL), id="iTIP")
                 except:
-                    logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+                    logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
                     raise iTipException
                 processed = "processed"
             else:
@@ -427,13 +427,13 @@
                     d = waitForDeferred(deleteResource(updatecal, calmatch))
                     yield d
                     d.getResult()
-                    logging.info("Deleted calendar component %s after cancellations from iTIP message in %s." % (calmatch, calURL), system="iTIP")
+                    logger.info("Deleted calendar component %s after cancellations from iTIP message in %s." % (calmatch, calURL), id="iTIP")
                 else:
                     # Update the existing calendar object
                     newchild = waitForDeferred(writeResource(request, calURL, updatecal, calmatch, existing_calendar))
                     yield newchild
                     newchild = newchild.getResult()
-                    logging.info("Updated calendar component %s with cancellations from iTIP message in %s." % (calmatch, calURL), system="iTIP")
+                    logger.info("Updated calendar component %s with cancellations from iTIP message in %s." % (calmatch, calURL), id="iTIP")
                 processed = "processed"
             else:
                 processed = "older"
@@ -446,13 +446,13 @@
         d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
         yield d
         d.getResult()
-        logging.info("Deleted new iTIP message %s in Inbox because it has been %s." %
+        logger.info("Deleted new iTIP message %s in Inbox because it has been %s." %
             (child.fp.basename(),
              {"processed":"processed",
               "older":    "ignored: older",
-              "ignored":  "ignored: no match"}[processed],), system="iTIP")
+              "ignored":  "ignored: no match"}[processed],), id="iTIP")
     except:
-        logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+        logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
         raise iTipException
     yield None
     return
@@ -517,7 +517,7 @@
                     break
             except NumberOfMatchesWithinLimits:
                 accepted = False
-                logging.info("Exceeded number of matches whilst trying to find free-time.", system="iTIP")
+                logger.warn("Exceeded number of matches whilst trying to find free-time.", id="iTIP")
                 break
             
         if not accepted:
@@ -608,7 +608,7 @@
         yield d
         d.getResult()
     except AccessDeniedError:
-        logging.info("Could not send reply as %s does not have CALDAV:schedule permission on %s Inbox." % (principal.principalURL(), organizer), system="iTIP")
+        logger.warn("Could not send reply as %s does not have CALDAV:schedule permission on %s Inbox." % (principal.principalURL(), organizer), id="iTIP")
         yield None
         return
     
@@ -749,9 +749,9 @@
                 d = waitForDeferred(deleteResource(inbox, i[0]))
                 yield d
                 d.getResult()
-                logging.info("Deleted iTIP message %s in Inbox that was older than the new one." % (i[0],), system="iTIP")
+                logger.info("Deleted iTIP message %s in Inbox that was older than the new one." % (i[0],), id="iTIP")
             except:
-                logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+                logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
                 raise iTipException
         else:
             # For any that are newer or the same, mark the new one to be deleted.
@@ -763,9 +763,9 @@
             d = waitForDeferred(deleteResource(inbox, child.fp.basename()))
             yield d
             d.getResult()
-            logging.info("Deleted new iTIP message %s in Inbox because it was older than existing ones." % (child.fp.basename(),), system="iTIP")
+            logger.info("Deleted new iTIP message %s in Inbox because it was older than existing ones." % (child.fp.basename(),), id="iTIP")
         except:
-            logging.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), system="iTIP")
+            logger.err("Error while auto-processing iTIP: %s" % (failure.Failure(),), id="iTIP")
             raise iTipException
     
     yield delete_child
@@ -795,7 +795,7 @@
             continue
         calmatch = matchComponentInCalendar(updatecal, calendar)
         if calmatch:
-            logging.info("Found calendar component %s matching new iTIP message in %s." % (calmatch, calURL), system="iTIP")
+            logger.info("Found calendar component %s matching new iTIP message in %s." % (calmatch, calURL), id="iTIP")
             break
     
     if calmatch is None and len(fbset):

Copied: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logger.py (from rev 2153, CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/logger.py)
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logger.py	                        (rev 0)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logger.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -0,0 +1,218 @@
+##
+# Copyright (c) 2006-2007 Apple Inc. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+##
+
+"""
+Classes and functions to do better logging.
+
+This logger class replaces the old logging.msg etc methods.
+
+Logging now supports tagging by multiple 'id's. These can be strings, ints etc, or
+class objects or __name__s.
+
+Logging can be turned on/off on a per-id basis. i.e. its possible to log certain
+sub-systems at 'debug' level whilst the rest are at 'error' level.
+
+accounting.py creates a new per-user logging option. This will store a log of user activity
+in separate files for each user. Currently can log all iTIP messages.
+
+Logging and accounting options are all controlled through a .plist file.
+
+kill -USR1 can be used to toggle between the normal logging level and 'debug' level in a
+running server.
+
+kill -URS2 can be used to force a re-read of the .plist options to allow changing
+of logging behavior whilst the server continues to run.
+
+"""
+
+from twisted.python import log
+
+from twistedcaldav.config import config
+
+from plistlib import readPlist
+import os
+import types
+
+
+class LoggerOptions(object):
+    """
+    Manages the set of options controlling logging.
+    """
+    
+    def __init__(self):
+        
+        self.fname = None
+
+        self.currentLogLevel = Logger.logtypes["error"]
+        self.previousLogLevel = Logger.logtypes["debug"]
+        
+        self.systemLogLevels = {}
+        
+        self.accounting = {}
+        
+    def read(self, fname=None):
+        
+        if not fname:
+            fname = config.LoggerOptionsFile
+        
+        if fname and os.path.exists(fname):
+            options = readPlist(fname)
+            
+            level = options.get("Default Log Level", "error")
+            if not Logger.logtypes.has_key(level):
+                log.msg("Unknown default logger level '%s', using 'error' level instead" % (level,))
+                level = "error"
+            self.currentLogLevel = Logger.logtypes[level]
+            
+            systems = options.get("System Log Levels", {})
+            newLogLevels = {}
+            for key, value in systems.iteritems():
+                if Logger.logtypes.has_key(value):
+                    newLogLevels[key] = Logger.logtypes[value]
+                else:
+                    log.msg("Ignoring unknown logging level '%s' for system: %s" % (value, key,), system="Logger")
+            
+            self.systemLogLevels = newLogLevels
+            
+            self.accounting = options.get("Accounting", {"Enabled":False,})
+
+class Logger(object):
+    #
+    # Logging levels:
+    #  0 - no logging
+    #  1 - errors only
+    #  2 - errors and warnings only
+    #  3 - errors, warnings and info
+    #  4 - errors, warnings, info and debug
+    #
+    
+    logtypes = {"none": 0, "error": 1, "warning": 2, "info": 3, "debug": 4}
+    
+    def __init__(self):
+        
+        self.options = LoggerOptions()
+
+    def readOptions(self):
+        """
+        Read or re-read the options file.
+        """
+    
+        log.msg("Reading logger options file.", system="Logger")
+        self.options.read()
+
+    def toggle(self):
+        """
+        Toggle between normal mode and full debug mode.
+        """
+    
+        tempLevel = self.options.currentLogLevel
+        self.options.currentLogLevel = self.options.previousLogLevel
+        self.options.previousLogLevel = tempLevel
+        
+        for key, value in Logger.logtypes.iteritems():
+            if value == self.options.currentLogLevel:
+                log.msg("Switching to default log level: %s" % (key,), system="Logger")
+                break
+        else:
+            log.msg("Switching to default log level: %d" % (self.options.currentLogLevel,), system="Logger")
+
+    def canLog(self, level, kwargs):
+        """
+        Determine whether a particular log level type is current active for the current system.
+    
+        @param level: a string with one of the supported levels.
+        @param kwargs: a dict containing logging parameters. 
+        @return:     True if the log level is currently active.
+        """
+        
+        current_level = -1
+        if kwargs.has_key("id"):
+            id = kwargs["id"]
+            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):
+        """
+        Log a message at the "info" level.
+    
+        @param message:  message to log.
+        @param **kwargs: additional log arguments.
+        """
+    
+        if self.canLog("info", kwargs):
+            log.msg(message, **kwargs)
+    
+    def warn(self, message, **kwargs):
+        """
+        Log a message at the "warning" level.
+    
+        @param message:  message to log.
+        @param **kwargs: additional log arguments.
+        """
+    
+        if self.canLog("warning", kwargs):
+            log.msg(message, **kwargs)
+    
+    def err(self, message, **kwargs):
+        """
+        Log a message at the "error" level.
+    
+        @param message:  message to log.
+        @param **kwargs: additional log arguments.
+        """
+    
+        if self.canLog("error", kwargs):
+            log.msg(message, **kwargs)
+    
+    def debug(self, message, **kwargs):
+        """
+        Log a message at the "debug" level.
+    
+        @param message:  message to log.
+        @param **kwargs: additional log arguments.
+        """
+    
+        if self.canLog("debug", kwargs):
+            log.msg(message, debug=True, **kwargs)
+
+    def accounting(self):
+        return self.options.accounting
+
+# Create the global instance of the logger
+logger = Logger()

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logging.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logging.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/logging.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -32,94 +32,8 @@
 
 from twistedcaldav.config import config
 from twistedcaldav.directory.directory import DirectoryService
+from twistedcaldav.logger import logger
 
-#
-# Logging levels:
-#  0 - no logging
-#  1 - errors only
-#  2 - errors and warnings only
-#  3 - errors, warnings and info
-#  4 - errors, warnings, info and debug
-#
-
-logtypes = {"none": 0, "error": 1, "warning": 2, "info": 3, "debug": 4}
-
-currentLogLevel = logtypes["error"]
-previousLogLevel = logtypes["debug"]
-
-def toggle():
-    """
-    Toggle between normal mode and full debug mode.
-    """
-
-    global currentLogLevel
-    global previousLogLevel
-    tempLevel = currentLogLevel
-    currentLogLevel = previousLogLevel
-    previousLogLevel = tempLevel
-    
-    for key, value in logtypes.iteritems():
-        if value == currentLogLevel:
-            log.msg("Switching to log level: %s" % (key,))
-            break
-    else:
-        log.msg("Switching to log level: %d" % (currentLogLevel,))
-            
-
-def canLog(type):
-    """
-    Determine whether a particular log level type is current active.
-
-    @param type: a string with one of the types above.
-    @return:     True if the log level is currently active.
-    """
-
-    return currentLogLevel >= logtypes.get(type, 1)
-
-def info(message, **kwargs):
-    """
-    Log a message at the "info" level.
-
-    @param message:  message to log.
-    @param **kwargs: additional log arguments.
-    """
-
-    if canLog("info"):
-        log.msg(message, **kwargs)
-
-def warn(message, **kwargs):
-    """
-    Log a message at the "warning" level.
-
-    @param message:  message to log.
-    @param **kwargs: additional log arguments.
-    """
-
-    if canLog("warning"):
-        log.msg(message, **kwargs)
-
-def err(message, **kwargs):
-    """
-    Log a message at the "error" level.
-
-    @param message:  message to log.
-    @param **kwargs: additional log arguments.
-    """
-
-    if canLog("error"):
-        log.msg(message, **kwargs)
-
-def debug(message, **kwargs):
-    """
-    Log a message at the "debug" level.
-
-    @param message:  message to log.
-    @param **kwargs: additional log arguments.
-    """
-
-    if canLog("debug"):
-        log.msg(message, debug=True, **kwargs)
-
 class DirectoryLogWrapperResource(LogWrapperResource):
     
     def __init__(self, resource, directory):
@@ -192,7 +106,6 @@
                 )
             )
 
-
 class RotatingFileAccessLoggingObserver(CommonAccessLoggingObserverExtensions):
     """
     Class to do 'apache' style access logging to a rotating log file. The log
@@ -299,10 +212,10 @@
 
         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)
-        info("Rotating log file to: %s" % (newpath,), system="Logging")
+        logger.info("Rotating log file to: %s" % (newpath,), id="Logging")
         self.f.close()
         os.rename(self.logpath, newpath)
         self._open()

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/copymove.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/copymove.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/copymove.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -23,7 +23,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
@@ -32,6 +31,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
 
@@ -76,8 +76,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,))
@@ -85,12 +85,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.FORBIDDEN,
             "Cannot create collection within special collection %s" % (destination,))
@@ -159,8 +159,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,)
@@ -169,12 +169,12 @@
     if destinationcal:
         # Checks for copying a calendar collection
         if self.isCalendarCollection():
-            log.err("Attempt to move a calendar collection into another calendar collection %s" % destination)
+            logger.err("Attempt to move 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 move a collection into a calendar collection")
+            logger.err("Attempt to move a collection into a calendar collection", id=(self, "http",))
             raise HTTPError(StatusResponse(
                 responsecode.FORBIDDEN,
                 "Cannot create collection within special collection %s" % (destination,)
@@ -207,15 +207,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
         
     """
@@ -226,7 +226,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,)
@@ -247,7 +247,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-2152/twistedcaldav/method/mkcalendar.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/mkcalendar.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/mkcalendar.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -21,7 +21,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
@@ -31,6 +30,7 @@
 from twisted.web2.http import HTTPError, StatusResponse
 
 from twistedcaldav import caldavxml
+from twistedcaldav.logger import logger
 
 def http_MKCALENDAR(self, request):
     """
@@ -50,16 +50,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"))
@@ -77,7 +77,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:
@@ -88,7 +88,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-2152/twistedcaldav/method/put.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -21,13 +21,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
 
@@ -44,7 +44,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
@@ -72,7 +72,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-2152/twistedcaldav/method/put_common.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put_common.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/put_common.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -25,7 +25,7 @@
 from twisted.internet.defer import deferredGenerator
 from twisted.internet.defer import maybeDeferred
 from twisted.internet.defer import waitForDeferred
-from twisted.python import failure, log
+from twisted.python import failure
 from twisted.python.filepath import FilePath
 from twisted.web2 import responsecode
 from twisted.web2.dav import davxml
@@ -41,7 +41,7 @@
 from twisted.web2.iweb import IResponse
 from twisted.web2.stream import MemoryStream
 
-from twistedcaldav import logging
+from twistedcaldav.logger import logger
 from twistedcaldav.config import config
 from twistedcaldav.caldavxml import NoUIDConflict
 from twistedcaldav.caldavxml import NumberOfRecurrencesWithinLimits
@@ -90,19 +90,19 @@
         assert (calendardata is None and source is not None) or (calendardata is not None and source is None)
         assert not deletesource or (deletesource and source is not None)
     except AssertionError:
-        log.err("Invalid arguments to storeCalendarObjectResource():")
-        log.err("request=%s\n" % (request,))
-        log.err("sourcecal=%s\n" % (sourcecal,))
-        log.err("destinationcal=%s\n" % (destinationcal,))
-        log.err("source=%s\n" % (source,))
-        log.err("source_uri=%s\n" % (source_uri,))
-        log.err("sourceparent=%s\n" % (sourceparent,))
-        log.err("destination=%s\n" % (destination,))
-        log.err("destination_uri=%s\n" % (destination_uri,))
-        log.err("destinationparent=%s\n" % (destinationparent,))
-        log.err("calendardata=%s\n" % (calendardata,))
-        log.err("deletesource=%s\n" % (deletesource,))
-        log.err("isiTIP=%s\n" % (isiTIP,))
+        logger.err("Invalid arguments to storeCalendarObjectResource():", id="Store Resource")
+        logger.err("request=%s\n" % (request,), id="Store Resource")
+        logger.err("sourcecal=%s\n" % (sourcecal,), id="Store Resource")
+        logger.err("destinationcal=%s\n" % (destinationcal,), id="Store Resource")
+        logger.err("source=%s\n" % (source,), id="Store Resource")
+        logger.err("source_uri=%s\n" % (source_uri,), id="Store Resource")
+        logger.err("sourceparent=%s\n" % (sourceparent,), id="Store Resource")
+        logger.err("destination=%s\n" % (destination,), id="Store Resource")
+        logger.err("destination_uri=%s\n" % (destination_uri,), id="Store Resource")
+        logger.err("destinationparent=%s\n" % (destinationparent,), id="Store Resource")
+        logger.err("calendardata=%s\n" % (calendardata,), id="Store Resource")
+        logger.err("deletesource=%s\n" % (deletesource,), id="Store Resource")
+        logger.err("isiTIP=%s\n" % (isiTIP,), id="Store Resource")
         raise
 
     class RollbackState(object):
@@ -129,52 +129,52 @@
             """
             if self.active:
                 self.active = False
-                logging.debug("Rollback: rollback", system="Store Resource")
+                logger.debug("Rollback: rollback", id="Store Resource")
                 try:
                     if self.source_copy and self.source_deleted:
                         self.source_copy.moveTo(source.fp)
-                        logging.debug("Rollback: source restored %s to %s" % (self.source_copy.path, source.fp.path), system="Store Resource")
+                        logger.debug("Rollback: source restored %s to %s" % (self.source_copy.path, source.fp.path), id="Store Resource")
                         self.source_copy = None
                         self.source_deleted = False
                     if self.destination_copy:
                         destination.fp.remove()
-                        logging.debug("Rollback: destination restored %s to %s" % (self.destination_copy.path, destination.fp.path), system="Store Resource")
+                        logger.debug("Rollback: destination restored %s to %s" % (self.destination_copy.path, destination.fp.path), id="Store Resource")
                         self.destination_copy.moveTo(destination.fp)
                         self.destination_copy = None
                     elif self.destination_created:
                         if destinationcal:
                             doRemoveDestinationIndex()
-                            logging.debug("Rollback: destination index removed %s" % (destination.fp.path,), system="Store Resource")
+                            logger.debug("Rollback: destination index removed %s" % (destination.fp.path,), id="Store Resource")
                             self.destination_index_deleted = False
                         destination.fp.remove()
-                        logging.debug("Rollback: destination removed %s" % (destination.fp.path,), system="Store Resource")
+                        logger.debug("Rollback: destination removed %s" % (destination.fp.path,), id="Store Resource")
                         self.destination_created = False
                     if self.destination_index_deleted:
                         # Must read in calendar for destination being re-indexed
                         doDestinationIndex(destination.iCalendar())
                         self.destination_index_deleted = False
-                        logging.debug("Rollback: destination re-indexed %s" % (destination.fp.path,), system="Store Resource")
+                        logger.debug("Rollback: destination re-indexed %s" % (destination.fp.path,), id="Store Resource")
                     if self.source_index_deleted:
                         doSourceIndexRecover()
                         self.destination_index_deleted = False
-                        logging.debug("Rollback: source re-indexed %s" % (source.fp.path,), system="Store Resource")
+                        logger.debug("Rollback: source re-indexed %s" % (source.fp.path,), id="Store Resource")
                 except:
-                    log.err("Rollback: exception caught and not handled: %s" % failure.Failure())
+                    logger.err("Rollback: exception caught and not handled: %s" % failure.Failure(), id="Store Resource")
 
         def Commit(self):
             """
             Commit the resource changes by wiping the rollback state.
             """
             if self.active:
-                logging.debug("Rollback: commit", system="Store Resource")
+                logger.debug("Rollback: commit", id="Store Resource")
                 self.active = False
                 if self.source_copy:
                     self.source_copy.remove()
-                    logging.debug("Rollback: removed source backup %s" % (self.source_copy.path,), system="Store Resource")
+                    logger.debug("Rollback: removed source backup %s" % (self.source_copy.path,), id="Store Resource")
                     self.source_copy = None
                 if self.destination_copy:
                     self.destination_copy.remove()
-                    logging.debug("Rollback: removed destination backup %s" % (self.destination_copy.path,), system="Store Resource")
+                    logger.debug("Rollback: removed destination backup %s" % (self.destination_copy.path,), id="Store Resource")
                     self.destination_copy = None
                 self.destination_created = False
                 self.source_deleted = False
@@ -349,7 +349,7 @@
             # Valid resource name check
             result, message = validResourceName()
             if not result:
-                log.err(message)
+                logger.err(message, id="Store Resource")
                 raise HTTPError(StatusResponse(responsecode.FORBIDDEN, "Resource name not allowed"))
 
             if not sourcecal:
@@ -357,7 +357,7 @@
                 if source is not None:
                     result, message = validContentType()
                     if not result:
-                        log.err(message)
+                        logger.err(message, id="Store Resource")
                         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
                 
                     # At this point we need the calendar data to do more tests
@@ -366,19 +366,19 @@
                     try:
                         calendar = Component.fromString(calendardata)
                     except ValueError, e:
-                        log.err(str(e))
+                        logger.err(str(e), id="Store Resource")
                         raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
                         
                 # Valid calendar data check
                 result, message = validCalendarDataCheck()
                 if not result:
-                    log.err(message)
+                    logger.err(message, id="Store Resource")
                     raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
                     
                 # Valid calendar data for CalDAV check
                 result, message = validCalDAVDataCheck()
                 if not result:
-                    log.err(message)
+                    logger.err(message, id="Store Resource")
                     raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-object-resource")))
 
                 # Must have a valid UID at this point
@@ -388,7 +388,7 @@
                 source_index = sourceparent.index()
                 uid = source_index.resourceUIDForName(source.fp.basename())
                 if uid is None:
-                    log.err("Source calendar does not have a UID: %s" % source.fp.basename())
+                    logger.err("Source calendar does not have a UID: %s" % source.fp.basename(), id="Store Resource")
                     raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-object-resource")))
 
                 # FIXME: We need this here because we have to re-index the destination. Ideally it
@@ -398,7 +398,7 @@
             # Valid calendar data size check
             result, message = validSizeCheck()
             if not result:
-                log.err(message)
+                logger.err(message, id="Store Resource")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "max-resource-size")))
 
             # Check access
@@ -438,7 +438,7 @@
             if not isiTIP:
                 result, message, rname = noUIDConflict(uid)
                 if not result:
-                    log.err(message)
+                    logger.err(message, id="Store Resource")
                     raise HTTPError(ErrorResponse(responsecode.FORBIDDEN,
                         NoUIDConflict(davxml.HRef.fromString(joinURL(parentForURL(destination_uri), rname.encode("utf-8"))))
                     ))
@@ -484,16 +484,16 @@
             rollback.destination_copy = FilePath(destination.fp.path)
             rollback.destination_copy.path += ".rollback"
             copyToWithXAttrs(destination.fp, rollback.destination_copy)
-            logging.debug("Rollback: backing up destination %s to %s" % (destination.fp.path, rollback.destination_copy.path), system="Store Resource")
+            logger.debug("Rollback: backing up destination %s to %s" % (destination.fp.path, rollback.destination_copy.path), id="Store Resource")
         else:
             rollback.destination_created = True
-            logging.debug("Rollback: will create new destination %s" % (destination.fp.path,), system="Store Resource")
+            logger.debug("Rollback: will create new destination %s" % (destination.fp.path,), id="Store Resource")
 
         if deletesource:
             rollback.source_copy = FilePath(source.fp.path)
             rollback.source_copy.path += ".rollback"
             copyToWithXAttrs(source.fp, rollback.source_copy)
-            logging.debug("Rollback: backing up source %s to %s" % (source.fp.path, rollback.source_copy.path), system="Store Resource")
+            logger.debug("Rollback: backing up source %s to %s" % (source.fp.path, rollback.source_copy.path), id="Store Resource")
     
         """
         Handle actual store operations here.
@@ -557,15 +557,15 @@
             # Add or update the index for this resource.
             try:
                 destination_index.addResource(destination.fp.basename(), caltoindex)
-                logging.debug("Destination indexed %s" % (destination.fp.path,), system="Store Resource")
+                logger.debug("Destination indexed %s" % (destination.fp.path,), id="Store Resource")
             except TooManyInstancesError, ex:
-                log.err("Cannot index calendar resource as there are too many recurrence instances %s" % destination)
+                logger.err("Cannot index calendar resource as there are too many recurrence instances %s" % destination, id="Store Resource")
                 raise HTTPError(ErrorResponse(
                     responsecode.FORBIDDEN,
                     NumberOfRecurrencesWithinLimits(PCDATAElement(str(ex.max_allowed)))
                 ))
             except (ValueError, TypeError), ex:
-                log.err("Cannot index calendar resource: %s" % (ex,))
+                logger.err("Cannot index calendar resource: %s" % (ex,), id="Store Resource")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
 
             destination.writeDeadProperty(davxml.GETContentType.fromString("text/calendar"))
@@ -580,19 +580,19 @@
             if destinationcal:
                 destination_index.deleteResource(destination.fp.basename())
                 rollback.destination_index_deleted = True
-                logging.debug("Destination index removed %s" % (destination.fp.path,), system="Store Resource")
+                logger.debug("Destination index removed %s" % (destination.fp.path,), id="Store Resource")
 
         def doSourceDelete():
             # Delete index for original item
             if sourcecal:
                 source_index.deleteResource(source.fp.basename())
                 rollback.source_index_deleted = True
-                logging.debug("Source index removed %s" % (source.fp.path,), system="Store Resource")
+                logger.debug("Source index removed %s" % (source.fp.path,), id="Store Resource")
 
             # Delete the source resource
             delete(source_uri, source.fp, "0")
             rollback.source_deleted = True
-            logging.debug("Source removed %s" % (source.fp.path,), system="Store Resource")
+            logger.debug("Source removed %s" % (source.fp.path,), id="Store Resource")
 
         def doSourceIndexRecover():
             """
@@ -642,7 +642,7 @@
             new_dest_size = new_dest_size.getResult()
             diff_size = new_dest_size - old_dest_size
             if diff_size >= destquota[0]:
-                log.err("Over quota: available %d, need %d" % (destquota[0], diff_size))
+                logger.err("Over quota: available %d, need %d" % (destquota[0], diff_size), id="Store Resource")
                 raise HTTPError(ErrorResponse(responsecode.INSUFFICIENT_STORAGE_SPACE, (dav_namespace, "quota-not-exceeded")))
             d = waitForDeferred(destination.quotaSizeAdjust(request, diff_size))
             yield d

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -29,7 +29,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
@@ -39,6 +38,7 @@
 from twisted.web2.dav.util import davXMLFromStream
 
 from twistedcaldav import caldavxml
+from twistedcaldav.logger import logger
 
 max_number_of_matches = 500
 
@@ -50,7 +50,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)
 
     #
@@ -61,7 +61,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:
@@ -106,8 +106,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-2152/twistedcaldav/method/report_calquery.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_calquery.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_calquery.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -21,7 +21,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
@@ -32,6 +31,7 @@
 
 from twistedcaldav.caldavxml import caldav_namespace
 from twistedcaldav.customxml import TwistedCalendarAccessProperty
+from twistedcaldav.logger import logger
 from twistedcaldav.method import report_common
 
 import urllib
@@ -53,7 +53,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 = []
@@ -66,7 +66,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)
@@ -85,7 +85,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:
@@ -93,7 +93,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]
@@ -239,7 +239,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-2152/twistedcaldav/method/report_common.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_common.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_common.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -27,7 +27,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
@@ -45,6 +44,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
 
@@ -271,7 +271,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:
@@ -364,7 +364,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-2152/twistedcaldav/method/report_freebusy.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_freebusy.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_freebusy.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -21,7 +21,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
@@ -31,6 +30,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
@@ -39,7 +39,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"):
@@ -73,7 +73,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-2152/twistedcaldav/method/report_multiget.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_multiget.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/method/report_multiget.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -21,7 +21,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
@@ -31,6 +30,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
@@ -53,7 +53,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 = []
@@ -73,14 +73,14 @@
         # Verify that any calendar-data element matches what we can handle
         result, message, _ignore = 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-2152/twistedcaldav/pdmonster.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/pdmonster.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/pdmonster.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -4,7 +4,7 @@
 
 from twisted.web2.resource import WrapperResource
 
-from twistedcaldav import logging
+from twistedcaldav.logger import logger
 
 class PDClientAddressWrapper(WrapperResource):
     def __init__(self, resource, socket, directory):
@@ -31,10 +31,10 @@
             result.trap(amp.RemoteAmpError)
             if result.value.errorCode != 'UNKNOWN_PORT':
                 return result
-            logging.err('Unknown Port: %s' % (request.remoteAddr,), system="PDClientAddressWrapper")
+            logger.err('Unknown Port: %s' % (request.remoteAddr,), id=self)
 
         def _gotAddress(result):
-            logging.debug('result = %r' % (result,), system="PDClientAddressWrapper")
+            logger.debug('result = %r' % (result,), id=self)
             request.remoteAddr = address.IPv4Address(
                 'TCP',
                 result['host'],
@@ -46,7 +46,7 @@
                 return
 
             host, port = request.remoteAddr.host, request.remoteAddr.port
-            logging.debug("GetClientAddress(host=%r, port=%r)" % (host, port), system="PDClientAddressWrapper")
+            logger.debug("GetClientAddress(host=%r, port=%r)" % (host, port), id=self)
             d = self.protocol.callRemoteString("GetClientAddress",
                                                   host=host,
                                                   port=str(port))

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/root.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/root.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/root.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -15,7 +15,6 @@
 ##
 
 from twisted.internet import defer
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.cred.error import LoginFailed, UnauthorizedLogin
 
@@ -26,6 +25,7 @@
 
 from twistedcaldav.extensions import DAVFile
 from twistedcaldav.config import config
+from twistedcaldav.logger import logger
 
 class RootResource(DAVFile):
     """
@@ -43,9 +43,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 = []
 
@@ -63,7 +63,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)))
@@ -92,7 +92,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-2152/twistedcaldav/schedule.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/schedule.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/schedule.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -35,9 +35,9 @@
 from twisted.web2.dav.util import joinURL
 
 from twistedcaldav import caldavxml
-from twistedcaldav import customxml
 from twistedcaldav import itip
-from twistedcaldav import logging
+from twistedcaldav.accounting import Accounting
+from twistedcaldav.logger import logger
 from twistedcaldav.resource import CalDAVResource
 from twistedcaldav.caldavxml import caldav_namespace, TimeRange
 from twistedcaldav.config import config
@@ -203,13 +203,13 @@
         # Must be content-type text/calendar
         content_type = request.headers.getHeader("content-type")
         if content_type is not None and (content_type.mediaType, content_type.mediaSubtype) != ("text", "calendar"):
-            logging.err("MIME type %s not allowed in calendar collection" % (content_type,), system="CalDAV Outbox POST")
+            logger.warn("MIME type %s not allowed in calendar collection" % (content_type,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "supported-calendar-data")))
     
         # Must have Originator header
         originator = request.headers.getRawHeaders("originator")
         if originator is None or (len(originator) != 1):
-            logging.err("POST request must have Originator header", system="CalDAV Outbox POST")
+            logger.warn("POST request must have Originator header", id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-specified")))
         else:
             originator = originator[0]
@@ -217,23 +217,23 @@
         # Verify that Originator is a valid calendar user (has an INBOX)
         oprincipal = self.principalForCalendarUserAddress(originator)
         if oprincipal is None:
-            logging.err("Could not find principal for originator: %s" % (originator,), system="CalDAV Outbox POST")
+            logger.warn("Could not find principal for originator: %s" % (originator,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
 
         inboxURL = oprincipal.scheduleInboxURL()
         if inboxURL is None:
-            logging.err("Could not find inbox for originator: %s" % (originator,), system="CalDAV Outbox POST")
+            logger.warn("Could not find inbox for originator: %s" % (originator,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
     
         # Verify that Originator matches the authenticated user
         if davxml.Principal(davxml.HRef(oprincipal.principalURL())) != self.currentPrincipal(request):
-            logging.err("Originator: %s does not match authorized user: %s" % (originator, self.currentPrincipal(request).children[0],), system="CalDAV Outbox POST")
+            logger.warn("Originator: %s does not match authorized user: %s" % (originator, self.currentPrincipal(request).children[0],), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "originator-allowed")))
 
         # Get list of Recipient headers
         rawrecipients = request.headers.getRawHeaders("recipient")
         if rawrecipients is None or (len(rawrecipients) == 0):
-            logging.err("POST request must have at least one Recipient header", system="CalDAV Outbox POST")
+            logger.warn("POST request must have at least one Recipient header", id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-specified")))
 
         # Recipient header may be comma separated list
@@ -253,29 +253,29 @@
             yield d
             calendar = d.getResult()
         except:
-            logging.err("Error while handling POST: %s" % (Failure(),), system="CalDAV Outbox POST")
+            logger.warn("Error while handling POST: %s" % (Failure(),), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
  
         # Must be a valid calendar
         try:
             calendar.validCalendarForCalDAV()
         except ValueError:
-            logging.err("POST request calendar component is not valid: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.warn("POST request calendar component is not valid: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
 
         # Must have a METHOD
         if not calendar.isValidMethod():
-            logging.err("POST request must have valid METHOD property in calendar component: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.warn("POST request must have valid METHOD property in calendar component: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
         
         # Verify iTIP behaviour
         if not calendar.isValidITIP():
-            logging.err("POST request must have a calendar component that satisfies iTIP requirements: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.warn("POST request must have a calendar component that satisfies iTIP requirements: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
 
         # X-CALENDARSERVER-ACCESS is not allowed in Outbox POSTs
         if calendar.hasProperty(Component.ACCESS_PROPERTY):
-            logging.err("X-CALENDARSERVER-ACCESS not allowed in a calendar component POST request: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.err("X-CALENDARSERVER-ACCESS not allowed in a calendar component POST request: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (calendarserver_namespace, "no-access-restrictions")))
     
         # Verify that the ORGANIZER's cu address maps to the request.uri
@@ -286,12 +286,12 @@
             if oprincipal is not None:
                 outboxURL = oprincipal.scheduleOutboxURL()
         if outboxURL is None:
-            logging.err("ORGANIZER in calendar data is not valid: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.warn("ORGANIZER in calendar data is not valid: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "organizer-allowed")))
 
         # Prevent spoofing of ORGANIZER with specific METHODs
         if (calendar.propertyValue("METHOD") in ("PUBLISH", "REQUEST", "ADD", "CANCEL", "DECLINECOUNTER")) and (outboxURL != request.uri):
-            logging.err("ORGANIZER in calendar data does not match owner of Outbox: %s" % (calendar,), system="CalDAV Outbox POST")
+            logger.warn("ORGANIZER in calendar data does not match owner of Outbox: %s" % (calendar,), id="CalDAV Outbox POST")
             raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "organizer-allowed")))
 
         # Prevent spoofing when doing reply-like METHODs
@@ -302,7 +302,7 @@
         
             # Must have only one
             if len(attendees) != 1:
-                logging.err("ATTENDEE list in calendar data is wrong: %s" % (calendar,), system="CalDAV Outbox POST")
+                logger.warn("ATTENDEE list in calendar data is wrong: %s" % (calendar,), id="CalDAV Outbox POST")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "attendee-allowed")))
             
             # Attendee's Outbox MUST be the request URI
@@ -311,21 +311,21 @@
             if aprincipal is not None:
                 aoutboxURL = aprincipal.scheduleOutboxURL()
             if aoutboxURL is None or aoutboxURL != request.uri:
-                logging.err("ATTENDEE in calendar data does not match owner of Outbox: %s" % (calendar,), system="CalDAV Outbox POST")
+                logger.warn("ATTENDEE in calendar data does not match owner of Outbox: %s" % (calendar,), id="CalDAV Outbox POST")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "attendee-allowed")))
 
         # For free-busy do immediate determination of iTIP result rather than fan-out
-        logging.info("METHOD: %s, Component: %s" % (calendar.propertyValue("METHOD"), calendar.mainType(),), system="CalDAV Outbox POST")
+        logger.info("METHOD: %s, Component: %s" % (calendar.propertyValue("METHOD"), calendar.mainType(),), id="CalDAV Outbox POST")
         if (calendar.propertyValue("METHOD") == "REQUEST") and (calendar.mainType() == "VFREEBUSY"):
             # Extract time range from VFREEBUSY object
             vfreebusies = [v for v in calendar.subcomponents() if v.name() == "VFREEBUSY"]
             if len(vfreebusies) != 1:
-                logging.err("iTIP data is not valid for a VFREEBUSY request: %s" % (calendar,), system="CalDAV Outbox POST")
+                logger.warn("iTIP data is not valid for a VFREEBUSY request: %s" % (calendar,), id="CalDAV Outbox POST")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
             dtstart = vfreebusies[0].getStartDateUTC()
             dtend = vfreebusies[0].getEndDateUTC()
             if dtstart is None or dtend is None:
-                logging.err("VFREEBUSY start/end not valid: %s" % (calendar,), system="CalDAV Outbox POST")
+                logger.warn("VFREEBUSY start/end not valid: %s" % (calendar,), id="CalDAV Outbox POST")
                 raise HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "valid-calendar-data")))
             timerange.start = dtstart
             timerange.end = dtend
@@ -339,6 +339,11 @@
             # Do regular invite (fan-out)
             freebusy = False
 
+        # Do accounting
+        if not freebusy and Accounting.isiTIPEnabled(oprincipal):
+            data = "Originator: %s\nRecipients: %s\n\n%s" % (originator, ", ".join(recipients), str(calendar),)
+            Accounting.writeData(oprincipal, Accounting.type_iTIP, data)
+
         # Prepare for multiple responses
         responses = ScheduleResponseQueue("POST", responsecode.OK)
     
@@ -355,7 +360,7 @@
             # Map recipient to their inbox
             inbox = None
             if principal is None:
-                logging.err("No principal for calendar user address: %s" % (recipient,), system="CalDAV Outbox POST")
+                logger.warn("No principal for calendar user address: %s" % (recipient,), id="CalDAV Outbox POST")
             else:
                 inboxURL = principal.scheduleInboxURL()
                 if inboxURL:
@@ -363,7 +368,7 @@
                     yield inbox
                     inbox = inbox.getResult()
                 else:
-                    logging.err("No schedule inbox for principal: %s" % (principal,), system="CalDAV Outbox POST")
+                    logger.warn("No schedule inbox for principal: %s" % (principal,), id="CalDAV Outbox POST")
 
             if inbox is None:
                 err = HTTPError(ErrorResponse(responsecode.NOT_FOUND, (caldav_namespace, "recipient-exists")))
@@ -381,7 +386,7 @@
                     yield d
                     d.getResult()
                 except AccessDeniedError:
-                    logging.err("Could not access Inbox for recipient: %s" % (recipient,), system="CalDAV Outbox POST")
+                    logger.warn("Could not access Inbox for recipient: %s" % (recipient,), id="CalDAV Outbox POST")
                     err = HTTPError(ErrorResponse(responsecode.NOT_FOUND, (caldav_namespace, "recipient-permisions")))
                     responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
                     recipients_state["BAD"] += 1
@@ -448,8 +453,8 @@
                         responses.add(recipient, responsecode.OK, reqstatus="2.0;Success", calendar=fbresult)
                         recipients_state["OK"] += 1
                 
-                    except:
-                        logging.err("Could not determine free busy information: %s" % (recipient,), system="CalDAV Outbox POST")
+                    except Exception, ex:
+                        logger.err("Could not determine free busy information: %s, %s" % (recipient, ex), id="CalDAV Outbox POST")
                         err = HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-permissions")))
                         responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
                         recipients_state["BAD"] += 1
@@ -493,8 +498,8 @@
                         # Look for auto-schedule option
                         if principal.autoSchedule():
                             autoresponses.append((principal, inbox, child))
-                    except:
-                        logging.err("Could not store data in Inbox : %s" % (inbox,), system="CalDAV Outbox POST")
+                    except Exception, ex:
+                        logger.err("Could not store data in Inbox : %s, %s" % (inbox, ex), id="CalDAV Outbox POST")
                         err = HTTPError(ErrorResponse(responsecode.FORBIDDEN, (caldav_namespace, "recipient-permissions")))
                         responses.add(recipient, Failure(exc_value=err), reqstatus="3.8;No authority")
                         recipients_state["BAD"] += 1
@@ -577,7 +582,7 @@
             raise AssertionError("Unknown data type: %r" % (what,))
 
         if code > 400: # Error codes only
-            logging.err("Error during %s for %s: %s" % (self.method, recipient, message), system="CalDAV Outbox POST")
+            logger.err("Error during %s for %s: %s" % (self.method, recipient, message), id="CalDAV Outbox POST")
 
         children = []
         children.append(caldavxml.Recipient(davxml.HRef.fromString(recipient)))

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/sql.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/sql.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/sql.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -29,7 +29,7 @@
 except ImportError:
     from pysqlite2 import dbapi2 as sqlite
 
-from twisted.python import log
+from twistedcaldav.logger import logger
 
 db_prefix = ".db."
 
@@ -74,7 +74,7 @@
                 else:
                     self._db_connection = sqlite.connect(db_filename)
             except:
-                log.err("Unable to open database: %s" % (db_filename,))
+                logger.err("Unable to open database: %s" % (db_filename,), id=self)
                 raise
 
             #
@@ -105,11 +105,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()
@@ -140,7 +140,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)
 
         # We need an exclusive lock here as we are making a big change to the database and we don't
         # want other processes to get stomped on or stomp on us.
@@ -247,7 +247,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-2152/twistedcaldav/static.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/static.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/static.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -38,7 +38,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
@@ -58,6 +57,7 @@
 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
@@ -94,21 +94,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")
@@ -155,7 +155,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)
@@ -343,7 +343,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
 
@@ -403,7 +403,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
@@ -462,11 +462,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-2152/twistedcaldav/tap.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/tap.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/tap.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -39,6 +39,7 @@
 from twisted.web2.server import Site
 
 from twistedcaldav import logging
+from twistedcaldav.logger import logger
 from twistedcaldav.cluster import makeService_Combined, makeService_Master
 from twistedcaldav.config import config, parseConfig, defaultConfig, ConfigurationError
 from twistedcaldav.root import RootResource
@@ -346,11 +347,6 @@
 
     def makeService_Slave(self, options):
         
-        # Change log level to at least "info" as its useful to have that during startup
-        old_logging = logging.currentLogLevel
-        if logging.currentLogLevel < logging.logtypes["info"]:
-            logging.currentLogLevel = logging.logtypes["info"]
-
         #
         # Setup the Directory
         #
@@ -358,8 +354,8 @@
 
         directoryClass = namedClass(config.DirectoryService['type'])
 
-        logging.info("Configuring directory service of type: %s"
-                % (config.DirectoryService['type'],), system="startup")
+        logger.info("Configuring directory service of type: %s"
+                % (config.DirectoryService['type'],), id="Startup")
 
         baseDirectory = directoryClass(**config.DirectoryService['params'])
 
@@ -368,8 +364,8 @@
         sudoDirectory = None
 
         if config.SudoersFile and os.path.exists(config.SudoersFile):
-            logging.info("Configuring SudoDirectoryService with file: %s"
-                    % (config.SudoersFile,), system="startup")
+            logger.info("Configuring SudoDirectoryService with file: %s"
+                    % (config.SudoersFile,), id="Startup")
 
             sudoDirectory = SudoDirectoryService(config.SudoersFile)
             sudoDirectory.realmName = baseDirectory.realmName
@@ -377,8 +373,8 @@
             CalDAVResource.sudoDirectory = sudoDirectory
             directories.insert(0, sudoDirectory)
         else:
-            logging.info("Not using SudoDirectoryService; file doesn't exist: %s"
-                    % (config.SudoersFile,), system="startup")
+            logger.info("Not using SudoDirectoryService; file doesn't exist: %s"
+                    % (config.SudoersFile,), id="Startup")
 
         directory = AggregateDirectoryService(directories)
 
@@ -390,9 +386,9 @@
         # Setup Resource hierarchy
         #
 
-        logging.info("Setting up document root at: %s" % (config.DocumentRoot,), system="startup")
+        logger.info("Setting up document root at: %s" % (config.DocumentRoot,), id="Startup")
 
-        logging.info("Setting up principal collection: %r" % (self.principalResourceClass,), system="startup")
+        logger.info("Setting up principal collection: %r" % (self.principalResourceClass,), id="Startup")
 
         principalCollection = self.principalResourceClass(
             os.path.join(config.DocumentRoot, 'principals'),
@@ -400,7 +396,7 @@
             directory
         )
 
-        logging.info("Setting up calendar collection: %r" % (self.calendarResourceClass,), system="startup")
+        logger.info("Setting up calendar collection: %r" % (self.calendarResourceClass,), id="Startup")
 
         calendarCollection = self.calendarResourceClass(
             os.path.join(config.DocumentRoot, 'calendars'),
@@ -408,7 +404,7 @@
             '/calendars/'
         )
 
-        logging.info("Setting up root resource: %r" % (self.rootResourceClass,), system="startup")
+        logger.info("Setting up root resource: %r" % (self.rootResourceClass,), id="Startup")
 
         root = self.rootResourceClass(
             config.DocumentRoot,
@@ -420,7 +416,7 @@
 
         # Configure default ACLs on the root resource
 
-        logging.info("Setting up default ACEs on root resource", system="startup")
+        logger.info("Setting up default ACEs on root resource", id="Startup")
 
         rootACEs = [
             davxml.ACE(
@@ -429,10 +425,10 @@
             ),
         ]
 
-        logging.info("Setting up AdminPrincipals", system="startup")
+        logger.info("Setting up AdminPrincipals", id=["Startup", "Security",])
 
         for principal in config.AdminPrincipals:
-            logging.info("Added %s as admin principal" % (principal,), system="startup")
+            logger.info("Added %s as admin principal" % (principal,), id=["Startup", "Security",])
 
             rootACEs.append(
                 davxml.ACE(
@@ -443,14 +439,14 @@
                 )
             )
 
-        logging.info("Setting root ACL", system="startup")
+        logger.info("Setting root ACL", id=["Startup", "Security",])
 
         root.setAccessControlList(davxml.ACL(*rootACEs))
 
         #
         # Configure ancillary data
         #
-        logging.info("Setting up Timezone Cache", system="startup")
+        logger.info("Setting up Timezone Cache", id="Startup")
         TimezoneCache().register()
 
         #
@@ -465,7 +461,7 @@
 
         realm = directory.realmName or ""
 
-        logging.info("Configuring authentication for realm: %s" % (realm,), system="startup")
+        logger.info("Configuring authentication for realm: %s" % (realm,), id=["Startup", "Security",])
 
         for scheme, schemeConfig in config.Authentication.iteritems():
             scheme = scheme.lower()
@@ -473,11 +469,11 @@
             credFactory = None
 
             if schemeConfig['Enabled']:
-                logging.info("Setting up scheme: %s" % (scheme,), system="startup")
+                logger.info("Setting up scheme: %s" % (scheme,), id=["Startup", "Security",])
 
                 if scheme == 'kerberos':
                     if not NegotiateCredentialFactory:
-                        logging.info("Kerberos support not available", system="startup")
+                        logger.warn("Kerberos support not available", id=["Startup", "Security",])
                         continue
 
                     try:
@@ -487,7 +483,7 @@
                         else:
                             credFactory = NegotiateCredentialFactory(principal=principal)
                     except ValueError:
-                        logging.info("Could not start Kerberos", system="startup")
+                        logger.warn("Could not start Kerberos", id=["Startup", "Security",])
                         continue
 
                 elif scheme == 'digest':
@@ -502,12 +498,12 @@
                     credFactory = BasicCredentialFactory(realm)
 
                 else:
-                    logging.err("Unknown scheme: %s" % (scheme,), system="startup")
+                    logger.err("Unknown scheme: %s" % (scheme,), id=["Startup", "Security",])
 
             if credFactory:
                 credentialFactories.append(credFactory)
 
-        logging.info("Configuring authentication wrapper", system="startup")
+        logger.info("Configuring authentication wrapper", id=["Startup", "Security",])
 
         authWrapper = auth.AuthenticationWrapper(
             root,
@@ -522,7 +518,7 @@
         # Configure the service
         #
 
-        logging.info("Setting up service", system="startup")
+        logger.info("Setting up service", id="Startup")
 
         if config.ProcessType == 'Slave':
             if config.MultiProcess['ProcessCount'] > 1 and config.MultiProcess['LoadBalancer']['Enabled']:
@@ -541,8 +537,7 @@
 
             logObserver = logging.RotatingFileAccessLoggingObserver(config.AccessLogFile)
 
-        logging.info("Configuring log observer: %s" % (
-            logObserver,), system="startup")
+        logger.info("Configuring log observer: %s" % (logObserver,), id="Startup")
 
         service = CalDAVService(logObserver)
 
@@ -567,21 +562,18 @@
                 config.BindSSLPorts = [config.SSLPort]
 
             for port in config.BindHTTPPorts:
-                logging.info("Adding server at %s:%s" % (bindAddress, port), system="startup")
+                logger.info("Adding server at %s:%s" % (bindAddress, port), id="Startup")
 
                 httpService = internet.TCPServer(int(port), channel, interface=bindAddress)
                 httpService.setServiceParent(service)
 
             for port in config.BindSSLPorts:
-                logging.info("Adding SSL server at %s:%s" % (bindAddress, port), system="startup")
+                logger.info("Adding SSL server at %s:%s" % (bindAddress, port), id="Startup")
 
                 contextFactory = ChainingOpenSSLContextFactory(config.SSLPrivateKey, config.SSLCertificate, certificateChainFile=config.SSLAuthorityChain)
                 httpsService = internet.SSLServer(int(port), channel, contextFactory, interface=bindAddress)
                 httpsService.setServiceParent(service)
 
-        # Change log level back to what it was before
-        logging.currentLogLevel = old_logging
-
         return service
 
     makeService_Combined = makeService_Combined
@@ -610,7 +602,7 @@
                     location = "Unknown"
                 else:
                     location = str(frame.f_code.co_name) + ": " + str(frame.f_lineno)
-                log.msg("SIGHUP recieved at " + location)
+                log.msg("SIGHUP received at " + location)
             signal.signal(signal.SIGHUP, sighup_handler)
 
             def sigusr1_handler(num, frame):
@@ -618,10 +610,20 @@
                     location = "Unknown"
                 else:
                     location = str(frame.f_code.co_name) + ": " + str(frame.f_lineno)
-                log.msg("SIGUSR1 recieved at " + location)
-                logging.toggle()
+                log.msg("SIGUSR1 received at " + location)
+                logger.toggle()
 
             signal.signal(signal.SIGUSR1, sigusr1_handler)
 
+            def sigusr2_handler(num, frame):
+                if frame is None:
+                    location = "Unknown"
+                else:
+                    location = str(frame.f_code.co_name) + ": " + str(frame.f_lineno)
+                log.msg("SIGUSR2 received at " + location)
+                logger.readOptions()
+
+            signal.signal(signal.SIGUSR2, sigusr2_handler)
+
             return service
 

Copied: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_accounting.py (from rev 2153, CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_accounting.py)
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_accounting.py	                        (rev 0)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_accounting.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -0,0 +1,197 @@
+##
+# Copyright (c) 2005-2007 Apple Inc. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+##
+
+from twisted.trial import unittest
+
+from twistedcaldav.config import config, defaultConfig
+from twistedcaldav.directory.directory import DirectoryRecord
+from twistedcaldav.directory.directory import DirectoryService
+from twistedcaldav.accounting import Accounting
+from twistedcaldav.logger import logger
+import os
+
+testConfig = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>LoggerOptionsFile</key>
+    <string>%s</string>
+</dict>
+</plist>
+"""
+
+testAccounting_Disabled = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>error</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+    </dict>
+    <key>Accounting</key>
+    <dict>
+        <key>Enabled</key>
+        <false/>
+        <key>LogDirectory</key>
+        <string>%s</string>
+        <key>iTIP</key>
+        <false/>
+        <key>principals</key>
+        <array></array>
+    </dict>
+</dict>
+</plist>
+"""
+
+testAccounting_EnabledAll = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>error</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+    </dict>
+    <key>Accounting</key>
+    <dict>
+        <key>Enabled</key>
+        <true/>
+        <key>LogDirectory</key>
+        <string>%s</string>
+        <key>iTIP</key>
+        <true/>
+        <key>principals</key>
+        <array></array>
+    </dict>
+</dict>
+</plist>
+"""
+
+testAccounting_EnabledSome = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>error</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+    </dict>
+    <key>Accounting</key>
+    <dict>
+        <key>Enabled</key>
+        <true/>
+        <key>LogDirectory</key>
+        <string>%s</string>
+        <key>iTIP</key>
+        <true/>
+        <key>principals</key>
+        <array>
+            <string>/principals/users/user01/</string>
+            <string>/principals/__uids__/user02/</string>
+        </array>
+    </dict>
+</dict>
+</plist>
+"""
+
+class LoggerTests(unittest.TestCase):
+
+    class DummyPrincipal(object):
+        
+        class DummyDirectoryService(DirectoryService):
+            def __init__(self):
+                self.realmName = "example.com"
+
+        def __init__(self, url, alturis, rtype, rname):
+            self.url = url
+            self.alturis = alturis
+            self.record = DirectoryRecord(self.DummyDirectoryService(), rtype, rname, rname, rname, set(), False, True)
+
+        def principalURL(self):
+            return self.url
+            
+        def alternateURIs(self):
+            return self.alturis
+
+    principal01 = DummyPrincipal("/principals/__uids__/user01/", ("/principals/users/user01/",), DirectoryService.recordType_users, "user01")
+    principal02 = DummyPrincipal("/principals/__uids__/user02/", ("/principals/users/user02/",), DirectoryService.recordType_users, "user02")
+    principal03 = DummyPrincipal("/principals/__uids__/user03/", ("/principals/users/user03/",), DirectoryService.recordType_users, "user03")
+
+    def setUp(self):
+        config.update(defaultConfig)
+        self.testLogger = self.mktemp()
+        self.testConfig = self.mktemp()
+        open(self.testConfig, 'w').write(testConfig % (self.testLogger,))
+        config.loadConfig(self.testConfig)
+        
+        self.temp_disabled = self.mktemp()
+        self.test_Disabled = testAccounting_Disabled % (self.temp_disabled,)
+        self.temp_enabledall = self.mktemp()
+        self.test_EnabledAll = testAccounting_EnabledAll % (self.temp_enabledall,)
+        self.temp_enabledsome = self.mktemp()
+        self.test_EnabledSome = testAccounting_EnabledSome % (self.temp_enabledsome,)
+
+    def tearDown(self):
+        self.loadLogfile(self.test_Disabled)
+
+    def loadLogfile(self, plist):
+        open(self.testLogger, 'w').write(plist)
+        logger.readOptions()
+
+    def validAccount(self, principal, root_path):
+        self.assertTrue(Accounting.isiTIPEnabled(principal))
+        self.assertEquals(Accounting.getLog(principal, Accounting.type_iTIP), os.path.join(root_path, principal.record.recordType, principal.record.shortName, "iTIP",))
+        self.assertTrue(os.path.exists(os.path.join(root_path, principal.record.recordType, principal.record.shortName, "iTIP",)))
+    
+    def testDefaultAccounting(self):
+        self.assertFalse(Accounting.isEnabled())
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal01))
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal02))
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal03))
+
+    def testDisabledAccounting(self):
+        self.loadLogfile(self.test_Disabled)
+
+        self.assertFalse(Accounting.isEnabled())
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal01))
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal02))
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal03))
+
+    def testEnabledAllAccounting(self):
+        self.loadLogfile(self.test_EnabledAll)
+
+        self.validAccount(LoggerTests.principal01, self.temp_enabledall)
+        self.validAccount(LoggerTests.principal02, self.temp_enabledall)
+        self.validAccount(LoggerTests.principal03, self.temp_enabledall)
+
+    def testEnabledSomeAccounting(self):
+        self.loadLogfile(self.test_EnabledSome)
+
+        self.validAccount(LoggerTests.principal01, self.temp_enabledsome)
+        self.validAccount(LoggerTests.principal02, self.temp_enabledsome)
+        self.assertFalse(Accounting.isiTIPEnabled(LoggerTests.principal03))
+
+    def testInvalidAccountingType(self):
+        self.loadLogfile(self.test_EnabledSome)
+
+        self.assertRaises(AssertionError, Accounting.getLog, LoggerTests.principal02, ("PUT", True,))

Modified: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_config.py
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_config.py	2008-02-18 21:29:17 UTC (rev 2154)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_config.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -25,17 +25,16 @@
 <!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
 <plist version="1.0">
 <dict>
-  <key>Verbose</key>
-  <true/>
-  <key>HTTPPort</key>
-  <integer>8008</integer>
+    <key>RotateAccessLog</key>
+    <true/>
+    <key>HTTPPort</key>
+    <integer>8008</integer>
 </dict>
 </plist>
 """
 
-def _testVerbose(testCase):
-    from twistedcaldav.config import config
-    testCase.assertEquals(config.Verbose, True)
+def _testRotateAccessLog(testCase):
+    testCase.assertEquals(config.RotateAccessLog, True)
 
 
 class ConfigTests(unittest.TestCase):
@@ -54,20 +53,20 @@
             self.assertEquals(getattr(config, key), value)
 
     def testLoadConfig(self):
-        self.assertEquals(config.Verbose, False)
+        self.assertEquals(config.RotateAccessLog, False)
 
         config.loadConfig(self.testConfig)
 
-        self.assertEquals(config.Verbose, True)
+        self.assertEquals(config.RotateAccessLog, True)
 
     def testScoping(self):
-        self.assertEquals(config.Verbose, False)
+        self.assertEquals(config.RotateAccessLog, False)
 
         config.loadConfig(self.testConfig)
 
-        self.assertEquals(config.Verbose, True)
+        self.assertEquals(config.RotateAccessLog, True)
 
-        _testVerbose(self)
+        _testRotateAccessLog(self)
 
     def testReloading(self):
         self.assertEquals(config.HTTPPort, 0)
@@ -174,7 +173,7 @@
 
         self.assertEquals(
             config.DirectoryService["params"],
-            SuperDuperAwesomeService.defaultParameters
+            SuperDuperAwesomeService.defaultParameters #@UndefinedVariable
         )
 
     testDirectoryService_unknownType.todo = "unimplemented"
@@ -222,3 +221,9 @@
         
         config.EnableProxyPrincipals = False
         self.assertTrue("calendar-proxy" not in resource.davComplianceClasses())
+        
+        config.EnablePrivateEvents = True
+        self.assertTrue("calendarserver-private-events" in resource.davComplianceClasses())
+        
+        config.EnablePrivateEvents = False
+        self.assertTrue("calendarserver-private-events" not in resource.davComplianceClasses())

Copied: CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_logger.py (from rev 2153, CalendarServer/branches/users/cdaboo/better-logging-1957/twistedcaldav/test/test_logger.py)
===================================================================
--- CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_logger.py	                        (rev 0)
+++ CalendarServer/branches/users/cdaboo/better-logging-2152/twistedcaldav/test/test_logger.py	2008-02-18 21:32:02 UTC (rev 2155)
@@ -0,0 +1,257 @@
+##
+# Copyright (c) 2005-2007 Apple Inc. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+##
+
+from twisted.trial import unittest
+
+from twistedcaldav.config import config, defaultConfig
+from twistedcaldav.logger import logger, Logger
+from twistedcaldav.logger import LoggerOptions
+
+testConfig = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>LoggerOptionsFile</key>
+    <string>%s</string>
+</dict>
+</plist>
+"""
+
+testLogger_Standard = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>error</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+    </dict>
+</dict>
+</plist>
+"""
+
+systemLogLevels_Standard = {
+    "Startup": Logger.logtypes["info"],
+}
+
+testLogger_More = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>none</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+        <key>iTIP</key>
+        <string>debug</string>
+        <key>CalDAV Outbox POST</key>
+        <string>warning</string>
+    </dict>
+</dict>
+</plist>
+"""
+
+systemLogLevels_More = {
+    "Startup":            Logger.logtypes["info"],
+    "iTIP":               Logger.logtypes["debug"],
+    "CalDAV Outbox POST": Logger.logtypes["warning"],
+}
+
+testLogger_Broken = """<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+    <key>Default Log Level</key>
+    <string>bogus</string>
+    <key>System Log Levels</key>
+    <dict>
+        <key>Startup</key>
+        <string>info</string>
+        <key>iTIP</key>
+        <string>busted</string>
+    </dict>
+</dict>
+</plist>
+"""
+
+systemLogLevels_Broken = {
+    "Startup": Logger.logtypes["info"],
+}
+
+class LoggerTests(unittest.TestCase):
+    def setUp(self):
+        config.update(defaultConfig)
+        self.testLogger = self.mktemp()
+        self.testConfig = self.mktemp()
+        open(self.testConfig, 'w').write(testConfig % (self.testLogger,))
+        config.loadConfig(self.testConfig)
+
+    def tearDown(self):
+        self.loadLogfile(testLogger_Standard)
+
+    def loadLogfile(self, plist):
+        open(self.testLogger, 'w').write(plist)
+        logger.readOptions()
+
+    def verify(self, options, current, previous, system):
+        self.assertEquals(options.currentLogLevel, current)
+        self.assertEquals(options.previousLogLevel, previous)
+        self.assertEquals(options.systemLogLevels, system)
+
+    def testDefaultLogger(self):
+        options = LoggerOptions()
+        self.verify(options, Logger.logtypes["error"], Logger.logtypes["debug"], {})
+
+    def testStandardLogger(self):
+        self.loadLogfile(testLogger_Standard)
+
+        self.verify(logger.options, Logger.logtypes["error"], Logger.logtypes["debug"], systemLogLevels_Standard)
+
+    def testMoreLogger(self):
+        self.loadLogfile(testLogger_Standard)
+
+        self.loadLogfile(testLogger_More)
+
+        self.verify(logger.options, Logger.logtypes["none"], Logger.logtypes["debug"], systemLogLevels_More)
+
+    def testBrokenLogger(self):
+        self.testDefaultLogger()
+
+        self.loadLogfile(testLogger_Broken)
+
+        self.verify(logger.options, Logger.logtypes["error"], Logger.logtypes["debug"], systemLogLevels_Broken)
+
+    def testToggle(self):
+        self.loadLogfile(testLogger_Standard)
+
+        logger.toggle()
+
+        self.verify(logger.options, Logger.logtypes["debug"], Logger.logtypes["error"], systemLogLevels_Standard)
+
+        logger.toggle()
+
+        self.verify(logger.options, Logger.logtypes["error"], Logger.logtypes["debug"], systemLogLevels_Standard)
+
+    def testDefaultLogging(self):
+        self.loadLogfile(testLogger_Standard)
+
+        self.assertTrue(logger.canLog("error", {"id":"Dummy"}))
+        self.assertFalse(logger.canLog("warning", {"id":"Dummy"}))
+        self.assertFalse(logger.canLog("info", {"id":"Dummy"}))
+        self.assertFalse(logger.canLog("debug", {"id":"Dummy"}))
+
+    def testStandardLogging(self):
+        self.loadLogfile(testLogger_Standard)
+
+        self.assertTrue(logger.canLog("error", {"id":"Startup"}))
+        self.assertTrue(logger.canLog("warning", {"id":"Startup"}))
+        self.assertTrue(logger.canLog("info", {"id":"Startup"}))
+        self.assertFalse(logger.canLog("debug", {"id":"Startup"}))
+
+    def testMoreLogging(self):
+        self.loadLogfile(testLogger_More)
+
+        self.assertTrue(logger.canLog("error", {"id":"Startup"}))
+        self.assertTrue(logger.canLog("warning", {"id":"Startup"}))
+        self.assertTrue(logger.canLog("info", {"id":"Startup"}))
+        self.assertFalse(logger.canLog("debug", {"id":"Startup"}))
+
+        self.assertTrue(logger.canLog("error", {"id":"iTIP"}))
+        self.assertTrue(logger.canLog("warning", {"id":"iTIP"}))
+        self.assertTrue(logger.canLog("info", {"id":"iTIP"}))
+        self.assertTrue(logger.canLog("debug", {"id":"iTIP"}))
+
+        self.assertTrue(logger.canLog("error", {"id":"CalDAV Outbox POST"}))
+        self.assertTrue(logger.canLog("warning", {"id":"CalDAV Outbox POST"}))
+        self.assertFalse(logger.canLog("info", {"id":"CalDAV Outbox POST"}))
+        self.assertFalse(logger.canLog("debug", {"id":"CalDAV Outbox POST"}))
+
+        self.assertFalse(logger.canLog("error", {"id":"Dummy"}))
+        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/20080218/d06ab675/attachment-0001.html 


More information about the calendarserver-changes mailing list