Merge pull request #1935 from pbiering/improve-profiling

Improve profiling and logging

CHANGELOG.md

@@ -6,6 +6,8 @@
 * Extend: [auth] imap: add fallback support for LOGIN towards remote IMAP server (replaced in 3.5.0)
 * Fix: improper detection of HTTP_X_FORWARDED_PORT on MOVE
 * Extend: [logging] with profiling log per reqest or regular per request method
+* New: [logging] option to log response header on debug loglevel
+* Adjust: [logging] header/content debug log indended by space to be skipped by logwatch
 
 ## 3.5.9
 * Extend: [auth] add support for type http_remote_user

DOCUMENTATION.md

@@ -1654,7 +1654,7 @@ Default: `False`
 
 _(>= 3.2.2)_
 
-Log request on `level = debug`
+Log request header on `level = debug`
 
 Default: `False`
 
@@ -1662,7 +1662,15 @@ Default: `False`
 
 _(>= 3.2.2)_
 
-Log request on `level = debug`
+Log request content (body) on `level = debug`
+
+Default: `False`
+
+##### response_header_on_debug
+
+_(>= 3.5.10)_
+
+Log response header on `level = debug`
 
 Default: `False`
 
@@ -1670,7 +1678,7 @@ Default: `False`
 
 _(>= 3.2.2)_
 
-Log response on `level = debug`
+Log response content (body) on `level = debug`
 
 Default: `False`
 
@@ -1711,6 +1719,22 @@ Log profiling data per request minimum duration (seconds) before logging, otherw
 
 Default: `3`
 
+##### profiling_per_request_header
+
+_(>= 3.5.10)_
+
+Log profiling request header (if passing minimum duration)
+
+Default: `False`
+
+##### profiling_per_request_xml
+
+_(>= 3.5.10)_
+
+Log profiling request XML (if passing minimum duration)
+
+Default: `False`
+
 ##### profiling_per_request_method_interval
 
 _(>= 3.5.10)_

config

@@ -312,6 +312,9 @@
 # Log request content on level=debug
 #request_content_on_debug = False
 
+# Log response header on level=debug
+#response_header_on_debug = False
+
 # Log response content on level=debug
 #response_content_on_debug = False
 
@@ -325,9 +328,15 @@
 # Value: per_request | per_request_method | none
 #profiling = none
 
-# Log profiling data per request minium duration (seconds)
+# Log profiling data per request minimum duration (seconds)
 #profiling_per_request_min_duration = 3
 
+# Log profiling request header (if passing minimum duration)
+#profiling_per_request_header = False
+
+# Log profiling request XML (if passing minimum duration)
+#profiling_per_request_xml = False
+
 # Log profiling data per request method interval (seconds)
 #profiling_per_request_method_interval = 600
 

radicale/app/__init__.py

@@ -38,7 +38,7 @@ import zlib
 from http import client
 from typing import Iterable, List, Mapping, Tuple, Union
 
-from radicale import config, httputils, log, pathutils, types
+from radicale import config, httputils, log, pathutils, types, utils
 from radicale.app.base import ApplicationBase
 from radicale.app.delete import ApplicationPartDelete
 from radicale.app.get import ApplicationPartGet
@@ -96,8 +96,15 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
         super().__init__(configuration)
         self._mask_passwords = configuration.get("logging", "mask_passwords")
         self._bad_put_request_content = configuration.get("logging", "bad_put_request_content")
+        logger.info("log bad put request content: %s", self._bad_put_request_content)
         self._request_header_on_debug = configuration.get("logging", "request_header_on_debug")
+        self._request_content_on_debug = configuration.get("logging", "request_content_on_debug")
+        self._response_header_on_debug = configuration.get("logging", "response_header_on_debug")
         self._response_content_on_debug = configuration.get("logging", "response_content_on_debug")
+        logger.debug("log request  header  on debug: %s", self._request_header_on_debug)
+        logger.debug("log request  content on debug: %s", self._request_content_on_debug)
+        logger.debug("log response header  on debug: %s", self._response_header_on_debug)
+        logger.debug("log response content on debug: %s", self._response_content_on_debug)
         self._auth_delay = configuration.get("auth", "delay")
         self._auth_type = configuration.get("auth", "type")
         self._web_type = configuration.get("web", "type")
@@ -130,6 +137,8 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
         # Profiling options
         self._profiling = configuration.get("logging", "profiling")
         self._profiling_per_request_min_duration = configuration.get("logging", "profiling_per_request_min_duration")
+        self._profiling_per_request_header = configuration.get("logging", "profiling_per_request_header")
+        self._profiling_per_request_xml = configuration.get("logging", "profiling_per_request_xml")
         self._profiling_per_request_method_interval = configuration.get("logging", "profiling_per_request_method_interval")
         self._profiling_top_x_functions = configuration.get("logging", "profiling_top_x_functions")
         if self._profiling in config.PROFILING:
@@ -142,6 +151,8 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
             logger.info("profiling top X functions: %d", self._profiling_top_x_functions)
         if self._profiling_per_request:
             logger.info("profiling per request minimum duration: %d (below are skipped)", self._profiling_per_request_min_duration)
+            logger.info("profiling per request header: %s", self._profiling_per_request_header)
+            logger.info("profiling per request xml   : %s", self._profiling_per_request_xml)
         if self._profiling_per_request_method:
             logger.info("profiling per request method interval: %d seconds", self._profiling_per_request_method_interval)
         # Profiling per request method initialization
@@ -164,9 +175,11 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
         for method in REQUEST_METHODS:
             if self.profiler_per_request_method_counter[method] > 0:
                 s = io.StringIO()
+                s.write("**Profiling statistics BEGIN**\n")
                 stats = pstats.Stats(self.profiler_per_request_method[method], stream=s).sort_stats('cumulative')
                 stats.print_stats(self._profiling_top_x_functions)  # Print top X functions
-                logger.info("Profiling data per request method %s after %d seconds and %d requests: %s", method, profiler_timedelta_start, self.profiler_per_request_method_counter[method], s.getvalue())
+                s.write("**Profiling statistics END**\n")
+                logger.info("Profiling data per request method %s after %d seconds and %d requests:\n%s", method, profiler_timedelta_start, self.profiler_per_request_method_counter[method], utils.textwrap_str(s.getvalue(), -1))
             else:
                 if shutdown:
                     logger.info("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start)
@@ -193,7 +206,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
                              "%s", environ.get("REQUEST_METHOD", "unknown"),
                              environ.get("PATH_INFO", ""), e, exc_info=True)
                 # Make minimal response
-                status, raw_headers, raw_answer = (
+                status, raw_headers, raw_answer, xml_request = (
                     httputils.INTERNAL_SERVER_ERROR)
                 assert isinstance(raw_answer, str)
                 answer = raw_answer.encode("ascii")
@@ -213,12 +226,15 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
         unsafe_path = environ.get("PATH_INFO", "")
         https = environ.get("HTTPS", "")
         profiler = None
+        profiler_active = False
+        xml_request = None
 
         context = AuthContext()
 
         """Manage a request."""
         def response(status: int, headers: types.WSGIResponseHeaders,
-                     answer: Union[None, str, bytes]) -> _IntermediateResponse:
+                     answer: Union[None, str, bytes],
+                     xml_request: Union[None, str] = None) -> _IntermediateResponse:
             """Helper to create response from internal types.WSGIResponse"""
             headers = dict(headers)
             content_encoding = "plain"
@@ -227,7 +243,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
             if answer is not None:
                 if isinstance(answer, str):
                     if self._response_content_on_debug:
-                        logger.debug("Response content:\n%s", answer)
+                        logger.debug("Response content (nonXML):\n%s", utils.textwrap_str(answer))
                     else:
                         logger.debug("Response content: suppressed by config/option [logging] response_content_on_debug")
                     headers["Content-Type"] += "; charset=%s" % self._encoding
@@ -249,6 +265,11 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
             # Add extra headers set in configuration
             headers.update(self._extra_headers)
 
+            if self._response_header_on_debug:
+                logger.debug("Response header:\n%s", utils.textwrap_str(pprint.pformat(headers)))
+            else:
+                logger.debug("Response header: suppressed by config/option [logging] response_header_on_debug")
+
             # Start response
             time_end = datetime.datetime.now()
             time_delta_seconds = (time_end - time_begin).total_seconds()
@@ -265,17 +286,32 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
 
             # Profiling end
             if self._profiling_per_request:
-                if profiler is not None:
-                    # Profiling per request
-                    if time_delta_seconds < self._profiling_per_request_min_duration:
-                        logger.debug("Profiling data per request %s for %r%s: (suppressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration)
+                if profiler_active is True:
+                    if profiler is not None:
+                        # Profiling per request
+                        if time_delta_seconds < self._profiling_per_request_min_duration:
+                            logger.debug("Profiling data per request %s for %r%s: (suppressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration)
+                        else:
+                            s = io.StringIO()
+                            s.write("**Profiling statistics BEGIN**\n")
+                            stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative')
+                            stats.print_stats(self._profiling_top_x_functions)  # Print top X functions
+                            s.write("**Profiling statistics END**\n")
+                            if self._profiling_per_request_header:
+                                s.write("**Profiling request header BEGIN**\n")
+                                s.write(pprint.pformat(self._scrub_headers(environ)))
+                                s.write("\n**Profiling request header END**")
+                            if self._profiling_per_request_xml:
+                                if xml_request is not None:
+                                    s.write("\n**Profiling request content (XML) BEGIN**\n")
+                                    if xml_request is not None:
+                                        s.write(xml_request)
+                                    s.write("**Profiling request content (XML) END**")
+                            logger.info("Profiling data per request %s for %r%s:\n%s", request_method, unsafe_path, depthinfo, utils.textwrap_str(s.getvalue(), -1))
                     else:
-                        s = io.StringIO()
-                        stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative')
-                        stats.print_stats(self._profiling_top_x_functions)  # Print top X functions
-                        logger.info("Profiling data per request %s for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue())
+                        logger.debug("Profiling data per request %s for %r%s: (suppressed because of no data)", request_method, unsafe_path, depthinfo)
                 else:
-                    logger.debug("Profiling data per request %s for %r%s: (suppressed because of no data)", request_method, unsafe_path, depthinfo)
+                    logger.info("Profiling data per request %s for %r%s: (not available because of concurrent running profiling request)", request_method, unsafe_path, depthinfo)
             elif self._profiling_per_request_method:
                 self.profiler_per_request_method[request_method].disable()
                 self.profiler_per_request_method_counter[request_method] += 1
@@ -318,7 +354,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
                     remote_host, remote_useragent, https_info)
         if self._request_header_on_debug:
             logger.debug("Request header:\n%s",
-                         pprint.pformat(self._scrub_headers(environ)))
+                         utils.textwrap_str(pprint.pformat(self._scrub_headers(environ))))
         else:
             logger.debug("Request header: suppressed by config/option [logging] request_header_on_debug")
 
@@ -453,27 +489,39 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
             # Profiling
             if self._profiling_per_request:
                 profiler = cProfile.Profile()
-                profiler.enable()
+                try:
+                    profiler.enable()
+                except ValueError:
+                    profiler_active = False
+                else:
+                    profiler_active = True
             elif self._profiling_per_request_method:
-                self.profiler_per_request_method[request_method].enable()
+                try:
+                    self.profiler_per_request_method[request_method].enable()
+                except ValueError:
+                    profiler_active = False
+                else:
+                    profiler_active = True
 
-            status, headers, answer = function(
+            status, headers, answer, xml_request = function(
                 environ, base_prefix, path, user, remote_host, remote_useragent)
 
             # Profiling
             if self._profiling_per_request:
                 if profiler is not None:
-                    profiler.disable()
+                    if profiler_active is True:
+                        profiler.disable()
             elif self._profiling_per_request_method:
-                self.profiler_per_request_method[request_method].disable()
+                if profiler_active is True:
+                    self.profiler_per_request_method[request_method].disable()
 
-            if (status, headers, answer) == httputils.NOT_ALLOWED:
+            if (status, headers, answer, xml_request) == httputils.NOT_ALLOWED:
                 logger.info("Access to %r denied for %s", path,
                             repr(user) if user else "anonymous user")
         else:
-            status, headers, answer = httputils.NOT_ALLOWED
+            status, headers, answer, xml_request = httputils.NOT_ALLOWED
 
-        if ((status, headers, answer) == httputils.NOT_ALLOWED and not user and
+        if ((status, headers, answer, xml_request) == httputils.NOT_ALLOWED and not user and
                 not external_login):
             # Unknown or unauthorized user
             logger.debug("Asking client for authentication")
@@ -483,4 +531,4 @@ class Application(ApplicationPartDelete, ApplicationPartHead,
                 "WWW-Authenticate":
                 "Basic realm=\"%s\"" % self._auth_realm})
 
-        return response(status, headers, answer)
+        return response(status, headers, answer, xml_request)

radicale/app/base.py

@@ -23,7 +23,7 @@ import xml.etree.ElementTree as ET
 from typing import Optional
 
 from radicale import (auth, config, hook, httputils, pathutils, rights,
-                      storage, types, web, xmlutils)
+                      storage, types, utils, web, xmlutils)
 from radicale.log import logger
 
 # HACK: https://github.com/tiran/defusedxml/issues/54
@@ -71,7 +71,7 @@ class ApplicationBase:
         if logger.isEnabledFor(logging.DEBUG):
             if self._request_content_on_debug:
                 logger.debug("Request content (XML):\n%s",
-                             xmlutils.pretty_xml(xml_content))
+                             utils.textwrap_str(xmlutils.pretty_xml(xml_content)))
             else:
                 logger.debug("Request content (XML): suppressed by config/option [logging] request_content_on_debug")
         return xml_content
@@ -80,7 +80,7 @@ class ApplicationBase:
         if logger.isEnabledFor(logging.DEBUG):
             if self._response_content_on_debug:
                 logger.debug("Response content (XML):\n%s",
-                             xmlutils.pretty_xml(xml_content))
+                             utils.textwrap_str(xmlutils.pretty_xml(xml_content)))
             else:
                 logger.debug("Response content (XML): suppressed by config/option [logging] response_content_on_debug")
         f = io.BytesIO()
@@ -93,7 +93,7 @@ class ApplicationBase:
         """Generate XML error response."""
         headers = {"Content-Type": "text/xml; charset=%s" % self._encoding}
         content = self._xml_response(xmlutils.webdav_error(human_tag))
-        return status, headers, content
+        return status, headers, content, None
 
 
 class Access:

radicale/app/delete.py

@@ -110,4 +110,4 @@ class ApplicationPartDelete(ApplicationBase):
             for notification_item in hook_notification_item_list:
                 self._hook.notify(notification_item)
             headers = {"Content-Type": "text/xml; charset=%s" % self._encoding}
-            return client.OK, headers, self._xml_response(xml_answer)
+            return client.OK, headers, self._xml_response(xml_answer), None

radicale/app/get.py

@@ -109,4 +109,4 @@ class ApplicationPartGet(ApplicationBase):
             if content_disposition:
                 headers["Content-Disposition"] = content_disposition
             answer = item.serialize()
-            return client.OK, headers, answer
+            return client.OK, headers, answer, None

radicale/app/mkcalendar.py

@@ -89,4 +89,4 @@ class ApplicationPartMkcalendar(ApplicationBase):
                     logger.warning(
                         "Bad MKCALENDAR request on %r: %s", path, e, exc_info=True)
                     return httputils.BAD_REQUEST
-            return client.CREATED, {}, None
+            return client.CREATED, {}, None, xmlutils.pretty_xml(xml_content)

radicale/app/mkcol.py

@@ -94,4 +94,4 @@ class ApplicationPartMkcol(ApplicationBase):
                         "Bad MKCOL request on %r (type:%s): %s", path, collection_type, e, exc_info=True)
                     return httputils.BAD_REQUEST
             logger.info("MKCOL request %r (type:%s): %s", path, collection_type, "successful")
-            return client.CREATED, {}, None
+            return client.CREATED, {}, None, xmlutils.pretty_xml(xml_content)

radicale/app/move.py

@@ -127,4 +127,4 @@ class ApplicationPartMove(ApplicationBase):
                     logger.warning(
                         "Bad MOVE request on %r: %s", path, e, exc_info=True)
                     return httputils.BAD_REQUEST
-            return client.NO_CONTENT if to_item else client.CREATED, {}, None
+            return client.NO_CONTENT if to_item else client.CREATED, {}, None, None

radicale/app/options.py

@@ -33,4 +33,4 @@ class ApplicationPartOptions(ApplicationBase):
             "Allow": ", ".join(
                 name[3:] for name in dir(self) if name.startswith("do_")),
             "DAV": httputils.DAV_HEADERS}
-        return client.OK, headers, None
+        return client.OK, headers, None, None

radicale/app/propfind.py

@@ -410,4 +410,4 @@ class ApplicationPartPropfind(ApplicationBase):
                                       allowed_items, user, self._encoding)
             if xml_answer is None:
                 return httputils.NOT_ALLOWED
-            return client.MULTI_STATUS, headers, self._xml_response(xml_answer)
+            return client.MULTI_STATUS, headers, self._xml_response(xml_answer), xmlutils.pretty_xml(xml_content)

radicale/app/proppatch.py

@@ -131,4 +131,4 @@ class ApplicationPartProppatch(ApplicationBase):
                     logger.warning(
                         "Bad PROPPATCH request on %r: %s", path, e, exc_info=True)
                     return httputils.BAD_REQUEST
-            return client.MULTI_STATUS, headers, self._xml_response(xml_answer)
+            return client.MULTI_STATUS, headers, self._xml_response(xml_answer), xmlutils.pretty_xml(xml_content)

radicale/app/put.py

@@ -99,7 +99,7 @@ def prepare(vobject_items: List[vobject.base.Component], path: str,
                                 content = vobject_item
                             else:
                                 content = item._text
-                            logger.warning("Problem during prepare item with UID '%s' (content below): %s\n%s", item.uid, e, content)
+                            logger.warning("Problem during prepare item with UID '%s' (content below): %s\n%s", item.uid, e, utils.textwrap_str(content))
                         else:
                             logger.warning("Problem during prepare item with UID '%s' (content suppressed in this loglevel): %s", item.uid, e)
                         raise
@@ -117,7 +117,7 @@ def prepare(vobject_items: List[vobject.base.Component], path: str,
                                 content = vobject_item
                             else:
                                 content = item._text
-                            logger.warning("Problem during prepare item with UID '%s' (content below): %s\n%s", item.uid, e, content)
+                            logger.warning("Problem during prepare item with UID '%s' (content below): %s\n%s", item.uid, e, utils.textwrap_str(content))
                         else:
                             logger.warning("Problem during prepare item with UID '%s' (content suppressed in this loglevel): %s", item.uid, e)
                         raise
@@ -180,7 +180,7 @@ class ApplicationPartPut(ApplicationBase):
             logger.warning(
                 "Bad PUT request on %r (read_components): %s", path, e, exc_info=True)
             if self._log_bad_put_request_content:
-                logger.warning("Bad PUT request content of %r:\n%s", path, content)
+                logger.warning("Bad PUT request content of %r:\n%s", path, utils.textwrap_str(content))
             else:
                 logger.debug("Bad PUT request content: suppressed by config/option [logging] bad_put_request_content")
             return httputils.BAD_REQUEST
@@ -334,7 +334,7 @@ class ApplicationPartPut(ApplicationBase):
                 if (item and item.uid == prepared_item.uid):
                     logger.debug("PUT request updated existing item %r", path)
                     headers = {"ETag": etag}
-                    return client.NO_CONTENT, headers, None
+                    return client.NO_CONTENT, headers, None, None
 
             headers = {"ETag": etag}
-            return client.CREATED, headers, None
+            return client.CREATED, headers, None, None

radicale/app/report.py

@@ -815,7 +815,7 @@ class ApplicationPartReport(ApplicationBase):
                         "Bad REPORT request on %r: %s", path, e, exc_info=True)
                     return httputils.BAD_REQUEST
                 headers = {"Content-Type": "text/calendar; charset=%s" % self._encoding}
-                return status, headers, str(body)
+                return status, headers, str(body), xmlutils.pretty_xml(xml_content)
             else:
                 try:
                     status, xml_answer = xml_report(
@@ -826,4 +826,4 @@ class ApplicationPartReport(ApplicationBase):
                         "Bad REPORT request on %r: %s", path, e, exc_info=True)
                     return httputils.BAD_REQUEST
                 headers = {"Content-Type": "text/xml; charset=%s" % self._encoding}
-                return status, headers, self._xml_response(xml_answer)
+                return status, headers, self._xml_response(xml_answer), xmlutils.pretty_xml(xml_content)

radicale/config.py

@@ -577,6 +577,10 @@ This is an automated message. Please do not reply.""",
             "value": "False",
             "help": "log request content on level=debug",
             "type": bool}),
+        ("response_header_on_debug", {
+            "value": "False",
+            "help": "log response header on level=debug",
+            "type": bool}),
         ("response_content_on_debug", {
             "value": "False",
             "help": "log response content on level=debug",
@@ -597,6 +601,14 @@ This is an automated message. Please do not reply.""",
             "value": "3",
             "help": "log profiling data per request minimum duration (seconds)",
             "type": int}),
+        ("profiling_per_request_header", {
+            "value": "False",
+            "help": "Log profiling request body (if passing minimum duration)",
+            "type": bool}),
+        ("profiling_per_request_xml", {
+            "value": "False",
+            "help": "Log profiling request XML (if passing minimum duration)",
+            "type": bool}),
         ("profiling_per_request_method_interval", {
             "value": "600",
             "help": "log profiling data per request method interval (seconds)",

radicale/httputils.py

@@ -31,7 +31,7 @@ import time
 from http import client
 from typing import List, Mapping, Union, cast
 
-from radicale import config, pathutils, types
+from radicale import config, pathutils, types, utils
 from radicale.log import logger
 
 if sys.version_info < (3, 9):
@@ -49,42 +49,42 @@ else:
 
 NOT_ALLOWED: types.WSGIResponse = (
     client.FORBIDDEN, (("Content-Type", "text/plain"),),
-    "Access to the requested resource forbidden.")
+    "Access to the requested resource forbidden.", None)
 FORBIDDEN: types.WSGIResponse = (
     client.FORBIDDEN, (("Content-Type", "text/plain"),),
-    "Action on the requested resource refused.")
+    "Action on the requested resource refused.", None)
 BAD_REQUEST: types.WSGIResponse = (
-    client.BAD_REQUEST, (("Content-Type", "text/plain"),), "Bad Request")
+    client.BAD_REQUEST, (("Content-Type", "text/plain"),), "Bad Request", None)
 NOT_FOUND: types.WSGIResponse = (
     client.NOT_FOUND, (("Content-Type", "text/plain"),),
-    "The requested resource could not be found.")
+    "The requested resource could not be found.", None)
 CONFLICT: types.WSGIResponse = (
     client.CONFLICT, (("Content-Type", "text/plain"),),
-    "Conflict in the request.")
+    "Conflict in the request.", None)
 METHOD_NOT_ALLOWED: types.WSGIResponse = (
     client.METHOD_NOT_ALLOWED, (("Content-Type", "text/plain"),),
-    "The method is not allowed on the requested resource.")
+    "The method is not allowed on the requested resource.", None)
 PRECONDITION_FAILED: types.WSGIResponse = (
     client.PRECONDITION_FAILED,
-    (("Content-Type", "text/plain"),), "Precondition failed.")
+    (("Content-Type", "text/plain"),), "Precondition failed.", None)
 REQUEST_TIMEOUT: types.WSGIResponse = (
     client.REQUEST_TIMEOUT, (("Content-Type", "text/plain"),),
-    "Connection timed out.")
+    "Connection timed out.", None)
 REQUEST_ENTITY_TOO_LARGE: types.WSGIResponse = (
     client.REQUEST_ENTITY_TOO_LARGE, (("Content-Type", "text/plain"),),
-    "Request body too large.")
+    "Request body too large.", None)
 REMOTE_DESTINATION: types.WSGIResponse = (
     client.BAD_GATEWAY, (("Content-Type", "text/plain"),),
-    "Remote destination not supported.")
+    "Remote destination not supported.", None)
 DIRECTORY_LISTING: types.WSGIResponse = (
     client.FORBIDDEN, (("Content-Type", "text/plain"),),
-    "Directory listings are not supported.")
+    "Directory listings are not supported.", None)
 INSUFFICIENT_STORAGE: types.WSGIResponse = (
     client.INSUFFICIENT_STORAGE, (("Content-Type", "text/plain"),),
-    "Insufficient Storage.  Please contact the administrator.")
+    "Insufficient Storage.  Please contact the administrator.", None)
 INTERNAL_SERVER_ERROR: types.WSGIResponse = (
     client.INTERNAL_SERVER_ERROR, (("Content-Type", "text/plain"),),
-    "A server error occurred.  Please contact the administrator.")
+    "A server error occurred.  Please contact the administrator.", None)
 
 DAV_HEADERS: str = "1, 2, 3, calendar-access, addressbook, extended-mkcol"
 
@@ -150,7 +150,7 @@ def read_request_body(configuration: "config.Configuration",
     content = decode_request(configuration, environ,
                              read_raw_request_body(configuration, environ))
     if configuration.get("logging", "request_content_on_debug"):
-        logger.debug("Request content:\n%s", content)
+        logger.debug("Request content:\n%s", utils.textwrap_str(content))
     else:
         logger.debug("Request content: suppressed by config/option [logging] request_content_on_debug")
     return content
@@ -159,7 +159,7 @@ def read_request_body(configuration: "config.Configuration",
 def redirect(location: str, status: int = client.FOUND) -> types.WSGIResponse:
     return (status,
             {"Location": location, "Content-Type": "text/plain"},
-            "Redirected to %s" % location)
+            "Redirected to %s" % location, None)
 
 
 def _serve_traversable(
@@ -214,7 +214,7 @@ def _serve_traversable(
         # adjust on the fly default main.js of InfCloud installation
         logger.debug("Adjust on-the-fly default InfCloud main.js in served page: %r", path)
         answer = answer.replace(b"'InfCloud - the open source CalDAV/CardDAV web client'", b"'InfCloud - the open source CalDAV/CardDAV web client - served through Radicale CalDAV/CardDAV server'")
-    return client.OK, headers, answer
+    return client.OK, headers, answer, None
 
 
 def serve_resource(

radicale/tests/custom/web.py

@@ -1,5 +1,6 @@
 # This file is part of Radicale - CalDAV and CardDAV server
-# Copyright © 2017-2018 Unrud <unrud@outlook.com>
+# Copyright © 2017-2021 Unrud <unrud@outlook.com>
+# Copyright © 2025-2025 Peter Bieringer <pb@bieringer.de>
 #
 # 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
@@ -28,9 +29,9 @@ class Web(web.BaseWeb):
 
     def get(self, environ: types.WSGIEnviron, base_prefix: str, path: str,
             user: str) -> types.WSGIResponse:
-        return client.OK, {"Content-Type": "text/plain"}, "custom"
+        return client.OK, {"Content-Type": "text/plain"}, "custom", None
 
     def post(self, environ: types.WSGIEnviron, base_prefix: str, path: str,
              user: str) -> types.WSGIResponse:
         content = httputils.read_request_body(self.configuration, environ)
-        return client.OK, {"Content-Type": "text/plain"}, "echo:" + content
+        return client.OK, {"Content-Type": "text/plain"}, "echo:" + content, None

radicale/types.py

@@ -1,5 +1,6 @@
 # This file is part of Radicale - CalDAV and CardDAV server
-# Copyright © 2020 Unrud <unrud@outlook.com>
+# Copyright © 2020-2023 Unrud <unrud@outlook.com>
+# Copyright © 2024-2025 Peter Bieringer <pb@bieringer.de>
 #
 # 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
@@ -20,7 +21,7 @@ from typing import (Any, Callable, ContextManager, Iterator, List, Mapping,
                     runtime_checkable)
 
 WSGIResponseHeaders = Union[Mapping[str, str], Sequence[Tuple[str, str]]]
-WSGIResponse = Tuple[int, WSGIResponseHeaders, Union[None, str, bytes]]
+WSGIResponse = Tuple[int, WSGIResponseHeaders, Union[None, str, bytes], Union[None, str]]
 WSGIEnviron = Mapping[str, Any]
 WSGIStartResponse = Callable[[str, List[Tuple[str, str]]], Any]
 

radicale/utils.py

@@ -21,6 +21,7 @@ import datetime
 import os
 import ssl
 import sys
+import textwrap
 from importlib import import_module, metadata
 from typing import Callable, Sequence, Tuple, Type, TypeVar, Union
 
@@ -291,3 +292,16 @@ def format_ut(unixtime: int) -> str:
             dt = datetime.datetime.fromtimestamp(unixtime, datetime.UTC)
         r = str(unixtime) + "(" + dt.strftime('%Y-%m-%dT%H:%M:%SZ') + ")"
     return r
+
+
+def limit_str(content: str, limit: int) -> str:
+    length = len(content)
+    if limit > 0 and length >= limit:
+        return content[:limit] + ("...(shortened because original length %d > limit %d)" % (length, limit))
+    else:
+        return content
+
+
+def textwrap_str(content: str, limit: int = 2000) -> str:
+    # TODO: add support for config option and prefix
+    return textwrap.indent(limit_str(content, limit), " ", lambda line: True)

radicale/web/none.py

@@ -1,5 +1,6 @@
 # This file is part of Radicale - CalDAV and CardDAV server
-# Copyright © 2017-2018 Unrud <unrud@outlook.com>
+# Copyright © 2017-2022 Unrud <unrud@outlook.com>
+# Copyright © 2025-2025 Peter Bieringer <pb@bieringer.de>
 #
 # 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
@@ -32,4 +33,4 @@ class Web(web.BaseWeb):
         assert pathutils.sanitize_path(path) == path
         if path != "/.web":
             return httputils.redirect(base_prefix + "/.web")
-        return client.OK, {"Content-Type": "text/plain"}, "Radicale works!"
+        return client.OK, {"Content-Type": "text/plain"}, "Radicale works!", None

radicale/xmlutils.py

@@ -2,7 +2,8 @@
 # Copyright © 2008 Nicolas Kandel
 # Copyright © 2008 Pascal Halter
 # Copyright © 2008-2015 Guillaume Ayoub
-# Copyright © 2017-2018 Unrud <unrud@outlook.com>
+# Copyright © 2017-2021 Unrud <unrud@outlook.com>
+# Copyright © 2025-2025 Peter Bieringer <pb@bieringer.de>
 #
 # 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
@@ -26,7 +27,7 @@ import copy
 import xml.etree.ElementTree as ET
 from collections import OrderedDict
 from http import client
-from typing import Dict, Mapping, Optional
+from typing import Dict, Mapping, Optional, Union
 from urllib.parse import quote
 
 from radicale import item, pathutils
@@ -56,7 +57,7 @@ for short, url in NAMESPACES.items():
     ET.register_namespace("" if short == "D" else short, url)
 
 
-def pretty_xml(element: ET.Element) -> str:
+def pretty_xml(element: Union[ET.Element, None]) -> str:
     """Indent an ElementTree ``element`` and its children."""
     def pretty_xml_recursive(element: ET.Element, level: int) -> None:
         indent = "\n" + level * "  "
@@ -71,6 +72,9 @@ def pretty_xml(element: ET.Element) -> str:
                 sub_element.tail = indent
         elif level > 0 and not (element.tail or "").strip():
             element.tail = indent
+
+    if element is None:
+        return ""
     element = copy.deepcopy(element)
     pretty_xml_recursive(element, 0)
     return '<?xml version="1.0"?>\n%s' % ET.tostring(element, "unicode")