From 8021848bcf38e51dcd2a65cfd222039e0066cd0e Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:44:21 +0100 Subject: [PATCH 01/14] clarify description --- DOCUMENTATION.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 71670c68..7c9e59f4 100644 --- a/DOCUMENTATION.md +++ b/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,7 @@ Default: `False` _(>= 3.2.2)_ -Log request on `level = debug` +Log request content (body) on `level = debug` Default: `False` @@ -1670,7 +1670,7 @@ Default: `False` _(>= 3.2.2)_ -Log response on `level = debug` +Log response content (body) on `level = debug` Default: `False` From 1cbcc4099468855d37e717021530a318e6448f73 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:45:47 +0100 Subject: [PATCH 02/14] fix typo --- config | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config b/config index 781c4edf..e10ce295 100644 --- a/config +++ b/config @@ -325,7 +325,7 @@ # 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 data per request method interval (seconds) From b819febeb21303d8d09c0a944515fed2f8ddae84 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:47:09 +0100 Subject: [PATCH 03/14] new option [logging] response_header_on_debug --- DOCUMENTATION.md | 8 ++++++++ config | 3 +++ radicale/config.py | 4 ++++ 3 files changed, 15 insertions(+) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 7c9e59f4..0f03668f 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1666,6 +1666,14 @@ Log request content (body) on `level = debug` Default: `False` +##### response_header_on_debug + +_(>= 3.5.10)_ + +Log response header on `level = debug` + +Default: `False` + ##### response_content_on_debug _(>= 3.2.2)_ diff --git a/config b/config index e10ce295..91b12e0f 100644 --- a/config +++ b/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 diff --git a/radicale/config.py b/radicale/config.py index cf59bcd1..e4af0a8f 100644 --- a/radicale/config.py +++ b/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", From dfb932a44859dc9382db1e90c65c081d767d3d2d Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:48:05 +0100 Subject: [PATCH 04/14] new options [logging] profiling_per_request_header profiling_per_request_xml --- DOCUMENTATION.md | 16 ++++++++++++++++ config | 6 ++++++ radicale/config.py | 8 ++++++++ 3 files changed, 30 insertions(+) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 0f03668f..0a8760df 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1719,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)_ diff --git a/config b/config index 91b12e0f..75a314e8 100644 --- a/config +++ b/config @@ -331,6 +331,12 @@ # 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 diff --git a/radicale/config.py b/radicale/config.py index e4af0a8f..abe7e465 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -601,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)", From 97875b951450e6058ef22d421cf0b13ea4cbc424 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:50:20 +0100 Subject: [PATCH 05/14] log status of new/existing log/profile header/content options on startup --- radicale/app/__init__.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 51d87cfc..e790d71a 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -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 From bac608a37accaefbfcb948d398ac5b3643ff20c7 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 17:52:54 +0100 Subject: [PATCH 06/14] add support for empty argument on pretty_xml --- radicale/xmlutils.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/radicale/xmlutils.py b/radicale/xmlutils.py index 4b9c51bf..17fbf961 100644 --- a/radicale/xmlutils.py +++ b/radicale/xmlutils.py @@ -26,7 +26,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 +56,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 +71,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 '\n%s' % ET.tostring(element, "unicode") From 183e55614407e232c7f0f9e8de4332d6241063f7 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:01:14 +0100 Subject: [PATCH 07/14] Adjust: [logging] header/content debug log indended by space to be skipped by logwatch --- radicale/app/__init__.py | 8 ++++---- radicale/app/base.py | 6 +++--- radicale/app/put.py | 6 +++--- radicale/httputils.py | 4 ++-- radicale/utils.py | 14 ++++++++++++++ 5 files changed, 26 insertions(+), 12 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index e790d71a..0bcded6d 100644 --- a/radicale/app/__init__.py +++ b/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 @@ -177,7 +177,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, s = io.StringIO() 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()) + 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], 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) @@ -238,7 +238,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 @@ -329,7 +329,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") diff --git a/radicale/app/base.py b/radicale/app/base.py index 6e3a7cd3..229f0f65 100644 --- a/radicale/app/base.py +++ b/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() diff --git a/radicale/app/put.py b/radicale/app/put.py index daec6339..89a401a8 100644 --- a/radicale/app/put.py +++ b/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 diff --git a/radicale/httputils.py b/radicale/httputils.py index 23f10ec1..d97d0513 100644 --- a/radicale/httputils.py +++ b/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): @@ -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 diff --git a/radicale/utils.py b/radicale/utils.py index ba5c69ff..16540bde 100644 --- a/radicale/utils.py +++ b/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) From 64f5e58549a162f80448fd71ebfd1a61123db567 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:09:04 +0100 Subject: [PATCH 08/14] add support for logging XML request conditionally for profiling --- radicale/app/__init__.py | 16 +++++++++------- radicale/app/base.py | 2 +- radicale/app/delete.py | 2 +- radicale/app/get.py | 2 +- radicale/app/mkcalendar.py | 2 +- radicale/app/mkcol.py | 2 +- radicale/app/move.py | 2 +- radicale/app/options.py | 2 +- radicale/app/propfind.py | 2 +- radicale/app/proppatch.py | 2 +- radicale/app/put.py | 4 ++-- radicale/app/report.py | 4 ++-- radicale/httputils.py | 30 +++++++++++++++--------------- radicale/tests/custom/web.py | 4 ++-- radicale/types.py | 2 +- radicale/web/none.py | 2 +- 16 files changed, 41 insertions(+), 39 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 0bcded6d..98123cd6 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -204,7 +204,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") @@ -224,12 +224,14 @@ class Application(ApplicationPartDelete, ApplicationPartHead, unsafe_path = environ.get("PATH_INFO", "") https = environ.get("HTTPS", "") profiler = None + 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" @@ -468,7 +470,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, elif self._profiling_per_request_method: self.profiler_per_request_method[request_method].enable() - status, headers, answer = function( + status, headers, answer, xml_request = function( environ, base_prefix, path, user, remote_host, remote_useragent) # Profiling @@ -478,13 +480,13 @@ class Application(ApplicationPartDelete, ApplicationPartHead, elif self._profiling_per_request_method: 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") @@ -494,4 +496,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) diff --git a/radicale/app/base.py b/radicale/app/base.py index 229f0f65..18a68b95 100644 --- a/radicale/app/base.py +++ b/radicale/app/base.py @@ -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: diff --git a/radicale/app/delete.py b/radicale/app/delete.py index 61fe6c43..2201e998 100644 --- a/radicale/app/delete.py +++ b/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 diff --git a/radicale/app/get.py b/radicale/app/get.py index b8adb39a..2eac58f1 100644 --- a/radicale/app/get.py +++ b/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 diff --git a/radicale/app/mkcalendar.py b/radicale/app/mkcalendar.py index db14bfdc..53abcdbd 100644 --- a/radicale/app/mkcalendar.py +++ b/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) diff --git a/radicale/app/mkcol.py b/radicale/app/mkcol.py index 72d5aa2b..45ad7c4a 100644 --- a/radicale/app/mkcol.py +++ b/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) diff --git a/radicale/app/move.py b/radicale/app/move.py index ac4fcab4..b65f6600 100644 --- a/radicale/app/move.py +++ b/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 diff --git a/radicale/app/options.py b/radicale/app/options.py index a869e2ab..9e347de2 100644 --- a/radicale/app/options.py +++ b/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 diff --git a/radicale/app/propfind.py b/radicale/app/propfind.py index b546c5e1..d79d0269 100644 --- a/radicale/app/propfind.py +++ b/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) diff --git a/radicale/app/proppatch.py b/radicale/app/proppatch.py index 9d6dc221..caaf7b7a 100644 --- a/radicale/app/proppatch.py +++ b/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) diff --git a/radicale/app/put.py b/radicale/app/put.py index 89a401a8..bd049158 100644 --- a/radicale/app/put.py +++ b/radicale/app/put.py @@ -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 diff --git a/radicale/app/report.py b/radicale/app/report.py index dda4ba10..2bad1924 100644 --- a/radicale/app/report.py +++ b/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) diff --git a/radicale/httputils.py b/radicale/httputils.py index d97d0513..30c6a7a0 100644 --- a/radicale/httputils.py +++ b/radicale/httputils.py @@ -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" @@ -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( diff --git a/radicale/tests/custom/web.py b/radicale/tests/custom/web.py index 695bbe81..2570fec0 100644 --- a/radicale/tests/custom/web.py +++ b/radicale/tests/custom/web.py @@ -28,9 +28,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 diff --git a/radicale/types.py b/radicale/types.py index 6899a755..6c7a7198 100644 --- a/radicale/types.py +++ b/radicale/types.py @@ -20,7 +20,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] diff --git a/radicale/web/none.py b/radicale/web/none.py index 263992ec..15e255c7 100644 --- a/radicale/web/none.py +++ b/radicale/web/none.py @@ -32,4 +32,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 From a60e86671be6ffeb7a7c857708b9a8ddacdbbd21 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:10:51 +0100 Subject: [PATCH 09/14] extend copyright --- radicale/tests/custom/web.py | 3 ++- radicale/types.py | 3 ++- radicale/web/none.py | 3 ++- radicale/xmlutils.py | 3 ++- 4 files changed, 8 insertions(+), 4 deletions(-) diff --git a/radicale/tests/custom/web.py b/radicale/tests/custom/web.py index 2570fec0..ee8bc6e6 100644 --- a/radicale/tests/custom/web.py +++ b/radicale/tests/custom/web.py @@ -1,5 +1,6 @@ # This file is part of Radicale - CalDAV and CardDAV server -# Copyright © 2017-2018 Unrud +# Copyright © 2017-2021 Unrud +# Copyright © 2025-2025 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 diff --git a/radicale/types.py b/radicale/types.py index 6c7a7198..175869d7 100644 --- a/radicale/types.py +++ b/radicale/types.py @@ -1,5 +1,6 @@ # This file is part of Radicale - CalDAV and CardDAV server -# Copyright © 2020 Unrud +# Copyright © 2020-2023 Unrud +# Copyright © 2024-2025 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 diff --git a/radicale/web/none.py b/radicale/web/none.py index 15e255c7..59cc341e 100644 --- a/radicale/web/none.py +++ b/radicale/web/none.py @@ -1,5 +1,6 @@ # This file is part of Radicale - CalDAV and CardDAV server -# Copyright © 2017-2018 Unrud +# Copyright © 2017-2022 Unrud +# Copyright © 2025-2025 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 diff --git a/radicale/xmlutils.py b/radicale/xmlutils.py index 17fbf961..becfecca 100644 --- a/radicale/xmlutils.py +++ b/radicale/xmlutils.py @@ -2,7 +2,8 @@ # Copyright © 2008 Nicolas Kandel # Copyright © 2008 Pascal Halter # Copyright © 2008-2015 Guillaume Ayoub -# Copyright © 2017-2018 Unrud +# Copyright © 2017-2021 Unrud +# Copyright © 2025-2025 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 From 2b2c417b1be3fe490ff8323bfe1518dfaea8e526 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:11:20 +0100 Subject: [PATCH 10/14] implement log of response header --- radicale/app/__init__.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 98123cd6..fc7e1981 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -262,6 +262,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() From f015b8e7a1829023c539a8c56dfac8950ae321be Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:12:08 +0100 Subject: [PATCH 11/14] avoid raise condition with parallel running profilers --- radicale/app/__init__.py | 21 +++++++++++++++++---- 1 file changed, 17 insertions(+), 4 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index fc7e1981..df02d14b 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -224,6 +224,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, unsafe_path = environ.get("PATH_INFO", "") https = environ.get("HTTPS", "") profiler = None + profiler_active = False xml_request = None context = AuthContext() @@ -471,9 +472,19 @@ 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, xml_request = function( environ, base_prefix, path, user, remote_host, remote_useragent) @@ -481,9 +492,11 @@ class Application(ApplicationPartDelete, ApplicationPartHead, # 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, xml_request) == httputils.NOT_ALLOWED: logger.info("Access to %r denied for %s", path, From c0af7bf1ba04a37391ec0a3e0ee8bd62454e860a Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:21:21 +0100 Subject: [PATCH 12/14] extend profiling by logging header and XML request in case min duration exceeded --- radicale/app/__init__.py | 37 +++++++++++++++++++++++++++---------- 1 file changed, 27 insertions(+), 10 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index df02d14b..63fe561e 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -175,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], utils.textwrap_str(s.getvalue(), -1)) + 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) @@ -284,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 From 12c37af1db7c041828f599e4afd6dd9c72e7441e Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:21:57 +0100 Subject: [PATCH 13/14] update changelog --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 599a108e..c4fd54a8 100644 --- a/CHANGELOG.md +++ b/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 From f879bd5c5d1dac51c5f5a7e699f16d2eaae4b38b Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:34:22 +0100 Subject: [PATCH 14/14] bugfix --- radicale/xmlutils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/radicale/xmlutils.py b/radicale/xmlutils.py index becfecca..4c31bbb1 100644 --- a/radicale/xmlutils.py +++ b/radicale/xmlutils.py @@ -57,7 +57,7 @@ for short, url in NAMESPACES.items(): ET.register_namespace("" if short == "D" else short, url) -def pretty_xml(element: Union[ET.Element | None]) -> 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 * " "