partial from pbiering-testing

config

@@ -120,15 +120,38 @@
 # http://docs.python.org/library/logging.config.html
 #config = /etc/radicale/logging
 
-# Set the default logging level to debug
+# Set the default logging level to debug (this enables also request/response logging)
 #debug = False
 
+# suppress selectable debug messages (to keep debug log cleaner)
+debug_filter = 0x0000
+# 0x0001: suppress "header content"
+# 0x0002: suppress "request content"
+# 0x0004: suppress "response content"
+# 0x0008: suppress "item content (on read)"
+# 0x0040: suppress "sanitized path"
+# 0x0080: suppress "rights" "Test if" + "Section"
+# 0x0100: suppress "read object"
+# 0x0200: suppress "delete object from cache"
+# 0x0400: suppress "read props"
+# 0x0800: suppress "delete props from cache"
+# 0x1000: suppress "store object in cache"
+# 0x2000: suppress "retrieve object from cache"
+# 0x4000: suppress "store props in cache"
+# 0x8000: suppress "retrieve props from cache"
+
 # Store all environment variables (including those set in the shell)
 #full_environment = False
 
 # Don't include passwords in logs
 #mask_passwords = True
 
+# Include performance statistics in logs on info level
+performance = False
+
+# Include exceptions in logs
+exceptions = False
+
 
 [headers]
 

logging

@@ -22,7 +22,7 @@ keys = console,file
 
 [formatters]
 # Logging formatters
-keys = simple,full
+keys = simple,full,filedebug
 
 
 # Loggers
@@ -31,6 +31,8 @@ keys = simple,full
 # Root logger
 level = DEBUG
 handlers = console,file
+# Disable line above and enable following line for dedicated additional debug log
+#handlers = console,file,filedebug
 
 
 # Handlers
@@ -43,10 +45,27 @@ args = (sys.stderr,)
 formatter = simple
 
 [handler_file]
+formatter = full
+# Enable following line in case dedicated debug log (see below) is activated
+#level = INFO
 # File handler
 class = FileHandler
 args = ('/var/log/radicale',)
+# Time Rotating File Handler (class+args: disable above and enable below)
+# (filename, when, interval, backupCount, ...) [see https://docs.python.org/3/library/logging.handlers.html#logging.handlers.TimedRotatingFileHandler]
+#  example: rollover at midnight every day, keep 90 files (means 90 days)
+#class = handlers.TimedRotatingFileHandler
+#args = ('/var/log/radicale/radicale.log', 'midnight', 1, 90)
+
+[handler_filedebug]
 formatter = full
+# File handler (for dedicated debug log)
+class = FileHandler
+args = ('/var/log/radicale/radicale-debug.log',)
+# Time Rotating File Handler (class+args: disable above and enable below)
+#  example: rollover every hour, keep 24 files (means 1 days)
+#class = handlers.TimedRotatingFileHandler
+#args = ('/var/log/radicale/radicale-debug.log', 'H', 1, 24)
 
 
 # Formatters

radicale/__init__.py

@@ -205,6 +205,8 @@ def __init__(self, configuration, logger):
         self.Collection = storage.load(configuration, logger)
         self.authorized = rights.load(configuration, logger)
         self.encoding = configuration.get("encoding", "request")
+        self.debug = configuration.getboolean("logging", "debug")
+        self.debug_filter = int(configuration.get("logging", "debug_filter"), 0)
 
     def headers_log(self, environ):
         """Sanitize headers for logging."""
@@ -261,18 +263,20 @@ def collect_allowed_items(self, items, user):
             else:
                 path = item.collection.path
             if self.authorized(user, path, "r"):
-                self.logger.debug(
-                    "%s has read access to collection %s",
-                    user or "Anonymous", path or "/")
+                if not self.debug_filter & 0x0080:
+                    self.logger.debug(
+                        "%s has read access to collection %s",
+                        user or "Anonymous", path or "/")
                 read_allowed_items.append(item)
             else:
                 self.logger.debug(
                     "%s has NO read access to collection %s",
                     user or "Anonymous", path or "/")
             if self.authorized(user, path, "w"):
-                self.logger.debug(
-                    "%s has write access to collection %s",
-                    user or "Anonymous", path or "/")
+                if not self.debug_filter & 0x0080:
+                    self.logger.debug(
+                        "%s has write access to collection %s",
+                        user or "Anonymous", path or "/")
                 write_allowed_items.append(item)
             else:
                 self.logger.debug(
@@ -287,7 +291,8 @@ def response(status, headers=(), answer=None):
             headers = dict(headers)
             # Set content length
             if answer:
-                self.logger.debug("Response content:\n%s", answer)
+                if self.debug and not (self.debug_filter & 0x0004):
+                    self.logger.debug("Response content:\n%s", answer)
                 answer = answer.encode(self.encoding)
                 accept_encoding = [
                     encoding.strip() for encoding in
@@ -354,7 +359,8 @@ def response(status, headers=(), answer=None):
         base_prefix = environ["SCRIPT_NAME"]
         # Sanitize request URI
         environ["PATH_INFO"] = storage.sanitize_path(environ["PATH_INFO"])
-        self.logger.debug("Sanitized path: %s", environ["PATH_INFO"])
+        if not (self.debug_filter & 0x0040):
+            self.logger.debug("Sanitized path: %s", environ["PATH_INFO"])
         path = environ["PATH_INFO"]
 
         # Get function corresponding to method
@@ -450,7 +456,8 @@ def _read_content(self, environ):
         if content_length > 0:
             content = self.decode(
                 environ["wsgi.input"].read(content_length), environ)
-            self.logger.debug("Request content:\n%s", content.strip())
+            if self.debug and not (self.debug_filter & 0x0002):
+                self.logger.debug("Request content:\n%s", content.strip())
         else:
             content = None
         return content
@@ -672,6 +679,9 @@ def do_PUT(self, environ, base_prefix, path, user):
                     parent_item.set_meta({"tag": tag})
                 href = posixpath.basename(path.strip("/"))
                 new_item = parent_item.upload(href, items[0])
+                if not new_item:
+                    # upload not possible because of error
+                    return PRECONDITION_FAILED
             headers = {"ETag": new_item.etag}
             return client.CREATED, headers, None
 

radicale/__main__.py

@@ -188,10 +188,10 @@ def cleanup():
         server = make_server(
             address, port, application, server_class, RequestHandler)
         servers[server.socket] = server
-        logger.debug("Listening to %s port %s",
+        logger.info("Listening to %s port %s",
                      server.server_name, server.server_port)
         if configuration.getboolean("server", "ssl"):
-            logger.debug("Using SSL")
+            logger.info("Using SSL")
 
     # Create a socket pair to notify the select syscall of program shutdown
     # This is not available in python < 3.5 on Windows
@@ -224,7 +224,10 @@ def shutdown(*args):
     else:
         # Fallback to busy waiting
         select_timeout = 1.0
-    logger.debug("Radicale server ready")
+    if configuration.getboolean("logging", "debug"):
+        logger.info("Radicale server ready (with 'debug' enabled)")
+    else:
+        logger.info("Radicale server ready")
     while not shutdown_program:
         try:
             rlist, _, xlist = select.select(

radicale/auth.py

@@ -63,7 +63,7 @@
 def load(configuration, logger):
     """Load the authentication manager chosen in configuration."""
     auth_type = configuration.get("auth", "type")
-    logger.debug("Authentication type is %s", auth_type)
+    logger.info("Authentication type is %s", auth_type)
     if auth_type == "None":
         class_ = NoneAuth
     elif auth_type == "htpasswd":

radicale/config.py

@@ -126,6 +126,15 @@
             "value": "False",
             "help": "print debug information",
             "aliases": ["-D", "--debug"]}),
+        ("debug_filter", {
+            "value": "0x0000",
+            "help": "filter debug log (binary mask)"}),
+        ("exceptions", {
+            "value" : "False",
+            "help": "include exceptions in logs"}),
+        ("performance", {
+            "value": "False",
+            "help": "include performance statistics in logs on info level"}),
         ("full_environment", {
             "value": "False",
             "help": "store all environment variables"}),

radicale/rights.py

@@ -91,6 +91,7 @@ class BaseRights:
     def __init__(self, configuration, logger):
         self.configuration = configuration
         self.logger = logger
+        self.debug_filter = int(configuration.get("logging", "debug_filter"), 0)
 
     def authorized(self, user, collection, permission):
         """Check if the user is allowed to read or write the collection.
@@ -122,7 +123,8 @@ def authorized(self, user, path, permission):
             self.logger.debug("Rights type '%s'", self.rights_type)
             regex.readfp(StringIO(DEFINED_RIGHTS[self.rights_type]))
         else:
-            self.logger.debug("Reading rights from file '%s'", self.filename)
+            if not self.debug_filter & 0x0080:
+                self.logger.debug("Reading rights from file '%s'", self.filename)
             if not regex.read(self.filename):
                 self.logger.error(
                     "File '%s' not found for rights", self.filename)
@@ -131,17 +133,20 @@ def authorized(self, user, path, permission):
         for section in regex.sections():
             re_user = regex.get(section, "user")
             re_collection = regex.get(section, "collection")
-            self.logger.debug(
-                "Test if '%s:%s' matches against '%s:%s' from section '%s'",
-                user, sane_path, re_user, re_collection, section)
+            if not self.debug_filter & 0x0080:
+                self.logger.debug(
+                    "Test if '%s:%s' matches against '%s:%s' from section '%s'",
+                    user, sane_path, re_user, re_collection, section)
             # Emulate fullmatch
             user_match = re.match(r"(?:%s)\Z" % re_user, user)
             if user_match:
                 re_collection = re_collection.format(*user_match.groups())
                 # Emulate fullmatch
                 if re.match(r"(?:%s)\Z" % re_collection, sane_path):
-                    self.logger.debug("Section '%s' matches", section)
+                    if not self.debug_filter & 0x0080:
+                        self.logger.debug("Section '%s' matches", section)
                     return permission in regex.get(section, "permission")
                 else:
-                    self.logger.debug("Section '%s' does not match", section)
+                    if not self.debug_filter & 0x0080:
+                        self.logger.debug("Section '%s' does not match", section)
         return False

radicale/storage.py

@@ -717,11 +717,18 @@ def serialize(self):
         items = []
         time_begin = datetime.datetime.now()
         for href in self.list():
-            items.append(self.get(href).item)
+            if hasattr(self.get(href),'item'):
+                items.append(self.get(href).item)
         time_end = datetime.datetime.now()
-        self.logger.info(
-            "Collection read %d items in %s sec from %s", len(items),
-            (time_end - time_begin).total_seconds(), self._filesystem_path)
+        if self.configuration.getboolean("logging", "performance"):
+            self.logger.info(
+                "Collection read %d items in %.3f sec from %s", len(items),
+                (time_end - time_begin).total_seconds(), self._filesystem_path)
+        else:
+            self.logger.debug(
+                "Collection read %d items in %.3f sec from %s", len(items),
+                (time_end - time_begin).total_seconds(), self._filesystem_path)
+        result = ""
         if self.get_meta("tag") == "VCALENDAR":
             collection = vobject.iCalendar()
             for item in items:
@@ -730,10 +737,20 @@ def serialize(self):
                         for item_part in getattr(item, "%s_list" % content):
                             collection.add(item_part)
                         break
-            return collection.serialize()
+            try:
+                result = collection.serialize()
+            except:
+                self.logger.error("VCALENDAR collection serializing broken: %s (%s)", self._filesystem_path, e)
+                if self.configuration.getboolean("logging", "exceptions"):
+                    self.logger.exception("Exception details:")
         elif self.get_meta("tag") == "VADDRESSBOOK":
-            return "".join([item.serialize() for item in items])
-        return ""
+            try:
+                result = "".join([item.serialize() for item in items])
+            except:
+                self.logger.error("VADDRESSBOOK collection serializing broken: %s (%s)", self._filesystem_path, e)
+                if self.configuration.getboolean("logging", "exceptions"):
+                    self.logger.exception("Exception details:")
+        return result
 
     _lock = threading.Lock()
     _waiters = []

radicale/xmlutils.py

@@ -679,7 +679,7 @@ def _propfind_response(base_prefix, path, item, props, user, write=False,
             element.append(privilege)
         elif tag == _tag("D", "supported-report-set"):
             for report_name in (
-                    "principal-property-search", "sync-collection",
+                    "principal-property-search",
                     "expand-property", "principal-search-property-set"):
                 supported = ET.Element(_tag("D", "supported-report"))
                 report_tag = ET.Element(_tag("D", "report"))