Pbiering testing

config

@@ -111,6 +111,11 @@
 # Example: git add -A && (git diff --cached --quiet || git commit -m "Changes by "%(user)s)
 #hook =
 
+# Caching of Items files in memory
+cache_items = False
+# Caching of Props files in memory
+cache_props = False
+
 
 [logging]
 
@@ -120,15 +125,43 @@
 # 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 = 0xffff
+# 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
+
+# Include regular cache performance statistics in logs on info level
+# 0: on each request
+# >0: minimum interval in seconds
+cache_statistics_interval = 300
+
 
 [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-storage-check.py

@@ -0,0 +1,57 @@
+#!/usr/bin/python3.4 -s
+#
+# This file is a tool for the Radicale Server - Calendar Server
+# Copyright © 2016 Peter Bieringer
+#
+# This library is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with Radicale.  If not, see <http://www.gnu.org/licenses/>.
+
+import sys
+import traceback
+import vobject
+
+## Main
+if len(sys.argv) < 2:
+    print ('Missing file names as arguments')
+
+i = 1
+while i < len(sys.argv):
+    path = sys.argv[i]
+    print ('Analyze file:', path)
+    i += 1
+    with open(path, encoding="utf-8", newline="") as f:
+        print ('Read file:', path)
+        text = f.read()
+        print ("Parse file contents:", path)
+        try:
+            item = vobject.readOne(text)
+            print ("Parse file contents successful:", path)
+        except Exception as e:
+            print ("Parse file contents ERROR", path)
+            print ("Unexpected error:", e)
+            traceback.print_exc(file=sys.stdout)
+            exit(1);
+
+        # check whether vobject likes the VCARD item
+        try:
+            print ("Serialize file contents:", path)
+            item_ser = item.serialize()
+            print ("Serialize file contents successful:", path)
+            print ("=== CONTENTS BEGIN ===")
+            print (str(item_ser))
+            print ("=== CONTENTS END ===")
+        except Exception as e:
+            print ("Serialize file contents ERROR", path)
+            print ("Unexpected error:", e)
+            traceback.print_exc(file=sys.stdout)
+            exit(1);

radicale/__init__.py

@@ -42,6 +42,7 @@
 import wsgiref.simple_server
 import zlib
 import datetime
+from hashlib import md5
 from http import client
 from urllib.parse import unquote, urlparse
 
@@ -205,6 +206,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 +264,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 +292,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 [%s]:\n%s", self.request_token, answer)
                 answer = answer.encode(self.encoding)
                 accept_encoding = [
                     encoding.strip() for encoding in
@@ -308,14 +314,25 @@ def response(status, headers=(), answer=None):
                     headers[key] = self.configuration.get("headers", key)
 
             # Start response
-            time_end = datetime.datetime.now()
             status = "%i %s" % (
                 status, client.responses.get(status, "Unknown"))
+            start_response(status, list(headers.items()))
+            time_end = datetime.datetime.now()
+            sizeinfo = ""
+            if answer:
+                sizeinfo = sizeinfo + str(len(str(answer))) + " bytes"
+            if "Content-Encoding" in headers:
+                if len(sizeinfo) > 0:
+                    sizeinfo = sizeinfo + " "
+                sizeinfo = sizeinfo + headers["Content-Encoding"]
+            if len(sizeinfo) > 0:
+                sizeinfo = " (" + sizeinfo + ")"
             self.logger.info(
-                "%s answer status for %s in %s sec: %s",
-                environ["REQUEST_METHOD"], environ["PATH_INFO"] + depthinfo,
+                "[%s] %s response status for %s in %.3f sec status: %s",
+                self.request_token,
+                environ["REQUEST_METHOD"], environ["PATH_INFO"] + depthinfo + sizeinfo,
                 (time_end - time_begin).total_seconds(), status)
-            start_response(status, list(headers.items()))
+            storage.cache_log_statistics_overall(self)
             # Return response content
             return [answer] if answer else []
 
@@ -334,12 +351,20 @@ def response(status, headers=(), answer=None):
         if environ.get("HTTP_DEPTH"):
             depthinfo = " with depth " + environ["HTTP_DEPTH"]
         time_begin = datetime.datetime.now()
+
+        # Create an unique request token
+        request_token = md5((environ["PATH_INFO"] + depthinfo + remote_host + remote_useragent +str(time_begin)).encode('utf-8')).hexdigest()[1:8]
+        # store token for header/request/response logging
+        self.request_token = request_token
+
         self.logger.info(
-            "%s request for %s received from %s using \"%s\"",
+            "[%s] %s request  for %s received from %s using \"%s\"",
+            self.request_token,
             environ["REQUEST_METHOD"], environ["PATH_INFO"] + depthinfo,
             remote_host, remote_useragent)
-        headers = pprint.pformat(self.headers_log(environ))
-        self.logger.debug("Request headers:\n%s", headers)
+        if self.debug and not (self.debug_filter & 0x0001):
+            headers = pprint.pformat(self.headers_log(environ))
+            self.logger.debug("Request headers [%s]:\n%s", self.request_token, headers)
 
         # Let reverse proxies overwrite SCRIPT_NAME
         if "HTTP_X_SCRIPT_NAME" in environ:
@@ -354,7 +379,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 +476,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 [%s]:\n%s", self.request_token, content.strip())
         else:
             content = None
         return content
@@ -672,6 +699,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

@@ -34,7 +34,7 @@
 
 from . import (
   VERSION, Application, RequestHandler, ThreadedHTTPServer,
-  ThreadedHTTPSServer, config, log)
+  ThreadedHTTPSServer, config, log, storage)
 
 
 def run():
@@ -142,13 +142,14 @@ def serve(configuration, logger):
     # Register exit function
     def cleanup():
         """Remove the PID files."""
-        logger.debug("Cleaning up")
+        logger.info("Cleaning up 'main'")
         # Remove PID file
         if (configuration.get("server", "pid") and
                 configuration.getboolean("server", "daemon")):
             os.unlink(configuration.get("server", "pid"))
 
     atexit.register(cleanup)
+    atexit.register(storage.cleanup, logger)
     logger.info("Starting Radicale")
 
     # Create collection servers
@@ -188,10 +189,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 +225,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

@@ -115,6 +115,12 @@
         ("filesystem_close_lock_file", {
             "value": "False",
             "help": "close the lock file when no more clients are waiting"}),
+        ("cache_items", {
+            "value": "False",
+            "help": "enable item file caching in memory"}),
+        ("cache_props", {
+            "value": "False",
+            "help": "enable props file caching in memory"}),
         ("hook", {
             "value": "",
             "help": "command that is run after changes to storage"})])),
@@ -126,9 +132,21 @@
             "value": "False",
             "help": "print debug information",
             "aliases": ["-D", "--debug"]}),
+        ("debug_filter", {
+            "value": "0xffff",
+            "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"}),
+        ("cache_statistics_interval", {
+            "value": "300",
+            "help": "log interval of item/props cache statistics on info level"}),
         ("mask_passwords", {
             "value": "True",
             "help": "mask passwords in logs"})]))])