From b9ec1c223f3c013f1dd4cb417f03105f8cb338d8 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Tue, 12 May 2026 08:29:59 +0200 Subject: [PATCH] log on_notice_condition: implementation --- radicale/app/__init__.py | 59 ++++++++++++++++---- radicale/app/base.py | 50 ++++++++++++----- radicale/app/delete.py | 4 +- radicale/app/get.py | 4 +- radicale/app/head.py | 4 +- radicale/app/mkcalendar.py | 6 +-- radicale/app/mkcol.py | 4 +- radicale/app/move.py | 4 +- radicale/app/options.py | 2 +- radicale/app/post.py | 6 +-- radicale/app/propfind.py | 7 +-- radicale/app/proppatch.py | 11 ++-- radicale/app/put.py | 7 +-- radicale/app/report.py | 16 +++--- radicale/httputils.py | 25 ++++++--- radicale/log.py | 102 +++++++++++++++++++++++++++++++++++ radicale/sharing/__init__.py | 4 +- radicale/tests/custom/web.py | 6 +-- radicale/web/__init__.py | 8 ++- radicale/web/internal.py | 2 +- radicale/web/none.py | 2 +- 21 files changed, 263 insertions(+), 70 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 6655233a..2e9bb96d 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -282,7 +282,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, """Manage a request.""" def response(status: int, headers: types.WSGIResponseHeaders, answer: Union[None, str, bytes], - xml_request: Union[None, str] = None) -> _IntermediateResponse: + xml_request: Union[None, str] = None, request_info: dict = {}) -> _IntermediateResponse: """Helper to create response from internal types.WSGIResponse""" headers = dict(headers) content_encoding = "plain" @@ -294,8 +294,16 @@ class Application(ApplicationPartDelete, ApplicationPartHead, if logger.isEnabledFor(logging.DEBUG): logger.debug("Response content (nonXML):\n%s", utils.textwrap_str(answer, self._limit_content)) else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("Response content: suppressed by config/option [logging] response_content_on_debug") + if self._response_content_on_notice_condition != {}: + if log.log_conditional( + "response-content", + condition=self._response_content_on_notice_condition, + value=request_info, + ): + logger.notice("Response content (nonXML, log condition passed):\n%s", utils.textwrap_str(answer, self._limit_content)) + else: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Response content: suppressed by config/option [logging] response_content_on_debug") headers["Content-Type"] += "; charset=%s" % self._encoding answer = answer.encode(self._encoding) accept_encoding = [ @@ -315,12 +323,22 @@ class Application(ApplicationPartDelete, ApplicationPartHead, # Add extra headers set in configuration headers.update(self._extra_headers) + request_info["status"] = status + if self._response_header_on_debug: if logger.isEnabledFor(logging.DEBUG): logger.debug("Response header:\n%s", utils.textwrap_str(pprint.pformat(headers), self._limit_content)) else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("Response header: suppressed by config/option [logging] response_header_on_debug") + if self._response_header_on_notice_condition != {}: + if log.log_conditional( + "response-header", + condition=self._response_header_on_notice_condition, + value=request_info, + ): + logger.notice("Response header (log condition passed):\n%s", utils.textwrap_str(pprint.pformat(headers), self._limit_content)) + else: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Response header: suppressed by config/option [logging] response_header_on_debug") # Start response # delay on error @@ -436,8 +454,10 @@ class Application(ApplicationPartDelete, ApplicationPartHead, if environ.get("HTTP_X_FORWARDED_HOST") or environ.get("HTTP_X_FORWARDED_PROTO") or environ.get("HTTP_X_FORWARDED_SERVER"): reverse_proxy = True remote_useragent = "" + remote_useragent_txt = "" if environ.get("HTTP_USER_AGENT"): - remote_useragent = " using %r" % environ["HTTP_USER_AGENT"] + remote_useragent = environ["HTTP_USER_AGENT"] + remote_useragent_txt = " using %r" % environ["HTTP_USER_AGENT"] depthinfo = "" if environ.get("HTTP_DEPTH"): depthinfo = " with depth %r" % environ["HTTP_DEPTH"] @@ -447,12 +467,14 @@ class Application(ApplicationPartDelete, ApplicationPartHead, https_info = "" logger.info("%s request for %r%s received from %s%s%s", request_method, unsafe_path, depthinfo, - remote_host, remote_useragent, https_info) + remote_host, remote_useragent_txt, https_info) if self._request_header_on_debug: logger.debug("Request header:\n%s", utils.textwrap_str(pprint.pformat(self._scrub_headers(environ)), self._limit_content)) else: - logger.debug("Request header: suppressed by config/option [logging] request_header_on_debug") + if not self._request_header_on_notice_condition != {}: + # conditional request header logging is later + logger.debug("Request header: suppressed by config/option [logging] request_header_on_debug") # SCRIPT_NAME is already removed from PATH_INFO, according to the # WSGI specification. @@ -535,6 +557,23 @@ class Application(ApplicationPartDelete, ApplicationPartHead, self._rights._user_groups = self._auth._ldap_groups except AttributeError: pass + + request_info: dict = { + "method": request_method, + "login": login, # not 'user' in this step + "path": path, + "useragent": remote_useragent, + "host": remote_host, + } + + if not self._request_header_on_debug and self._request_header_on_notice_condition != {}: + if log.log_conditional( + "request-header", + condition=self._request_header_on_notice_condition, + value=request_info, + ): + logger.notice("Request header (log condition passed):\n%s", utils.textwrap_str(pprint.pformat(self._scrub_headers(environ)), self._limit_content)) + if user and login == user: logger.info("Successful login: %r (%s)", user, info) elif user: @@ -619,7 +658,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, try: status, headers, answer, xml_request = function( - environ, base_prefix, path, user, remote_host, remote_useragent) + environ, base_prefix, path, user, request_info) except PermissionError as e: logger.error("PermissionError: %s", e) status, headers, answer, xml_request = httputils.INTERNAL_SERVER_ERROR @@ -656,4 +695,4 @@ class Application(ApplicationPartDelete, ApplicationPartHead, "WWW-Authenticate": "Basic realm=\"%s\"" % self._auth_realm}) - return response(status, headers, answer, xml_request) + return response(status, headers, answer, xml_request, request_info) diff --git a/radicale/app/base.py b/radicale/app/base.py index 63993a9a..cd64e253 100644 --- a/radicale/app/base.py +++ b/radicale/app/base.py @@ -23,7 +23,7 @@ import unicodedata import xml.etree.ElementTree as ET from typing import Optional, Union -from radicale import (auth, config, hook, httputils, pathutils, rights, +from radicale import (auth, config, hook, httputils, log, pathutils, rights, sharing, storage, types, utils, web, xmlutils) from radicale.log import logger from radicale.rights import intersect @@ -137,12 +137,16 @@ class ApplicationBase: self._log_bad_put_request_content = configuration.get("logging", "bad_put_request_content") self._response_content_on_debug = configuration.get("logging", "response_content_on_debug") self._request_content_on_debug = configuration.get("logging", "request_content_on_debug") + self._response_content_on_notice_condition = configuration.get("logging", "response_content_on_notice_condition") + self._request_content_on_notice_condition = configuration.get("logging", "request_content_on_notice_condition") self._limit_content = configuration.get("logging", "limit_content") self._validate_user_value = configuration.get("server", "validate_user_value") self._validate_path_value = configuration.get("server", "validate_path_value") self._hook = hook.load(configuration) - def _read_xml_request_body(self, environ: types.WSGIEnviron + def _read_xml_request_body(self, + environ: types.WSGIEnviron, + request_info: dict, ) -> Optional[ET.Element]: content = httputils.decode_request( self.configuration, environ, @@ -154,19 +158,41 @@ class ApplicationBase: except ET.ParseError as e: logger.debug("Request content (Invalid XML):\n%s", content) raise RuntimeError("Failed to parse XML: %s" % e) from e - if logger.isEnabledFor(logging.DEBUG): - if self._request_content_on_debug: - logger.debug("Request content (XML):\n%s", - utils.textwrap_str(xmlutils.pretty_xml(xml_content))) + if self._request_content_on_debug: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Request content (XML):\n%s", utils.textwrap_str(xmlutils.pretty_xml(xml_content))) + else: + if self._request_content_on_notice_condition != {}: + if log.log_conditional( + "request-content", + condition=self._request_content_on_notice_condition, + value=request_info, + ): + logger.notice("Request content (XML, log condition passed):\n%s", utils.textwrap_str(xmlutils.pretty_xml(xml_content))) + else: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Request content (XML, log condition skipped): suppressed") else: - logger.debug("Request content (XML): suppressed by config/option [logging] request_content_on_debug") + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Request content (XML): suppressed by config/option [logging] request_content_on_debug") return xml_content - def _xml_response(self, xml_content: ET.Element) -> bytes: - if logger.isEnabledFor(logging.DEBUG): - if self._response_content_on_debug: + def _xml_response(self, xml_content: ET.Element, request_info: dict) -> bytes: + if self._response_content_on_debug: + if logger.isEnabledFor(logging.DEBUG): logger.debug("Response content (XML):\n%s", utils.textwrap_str(xmlutils.pretty_xml(xml_content), self._limit_content)) + else: + if self._response_content_on_notice_condition != {}: + if log.log_conditional( + "response-content", + condition=self._response_content_on_notice_condition, + value=request_info, + ): + logger.notice("Response content (XML, log condition passed):\n%s", utils.textwrap_str(xmlutils.pretty_xml(xml_content))) + else: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Response content (XML, log condition skipped): suppressed") else: logger.debug("Response content (XML): suppressed by config/option [logging] response_content_on_debug") f = io.BytesIO() @@ -174,11 +200,11 @@ class ApplicationBase: xml_declaration=True) return f.getvalue() - def _webdav_error_response(self, status: int, human_tag: str + def _webdav_error_response(self, status: int, human_tag: str, request_info: dict ) -> types.WSGIResponse: """Generate XML error response.""" headers = {"Content-Type": "text/xml; charset=%s" % self._encoding} - content = self._xml_response(xmlutils.webdav_error(human_tag)) + content = self._xml_response(xmlutils.webdav_error(human_tag), request_info) return status, headers, content, None diff --git a/radicale/app/delete.py b/radicale/app/delete.py index 5388e86d..38357f61 100644 --- a/radicale/app/delete.py +++ b/radicale/app/delete.py @@ -55,7 +55,7 @@ def xml_delete(base_prefix: str, path: str, collection: storage.BaseCollection, class ApplicationPartDelete(ApplicationBase): def do_DELETE(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage DELETE request.""" actor = user permissions_filter = None @@ -126,4 +126,4 @@ class ApplicationPartDelete(ApplicationBase): for notification_item in hook_notification_item_list: # Will be empty if hook not enabled self._hook.notify(notification_item) headers = {"Content-Type": "text/xml; charset=%s" % self._encoding} - return client.OK, headers, self._xml_response(xml_answer), None + return client.OK, headers, self._xml_response(xml_answer, request_info), None diff --git a/radicale/app/get.py b/radicale/app/get.py index a0139560..21bd0349 100644 --- a/radicale/app/get.py +++ b/radicale/app/get.py @@ -68,7 +68,7 @@ class ApplicationPartGet(ApplicationBase): return value def do_GET(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: """Manage GET request.""" # Redirect to /.web if the root path is requested if not pathutils.strip_path(path): @@ -84,7 +84,7 @@ class ApplicationPartGet(ApplicationBase): base_prefix + unsafe_path, location) return httputils.redirect(location, client.MOVED_PERMANENTLY) # Dispatch /.web path to web module - return self._web.get(environ, base_prefix, path, user) + return self._web.get(environ, base_prefix, path, user, request_info) permissions_filter = None share = None if self._sharing._enabled: diff --git a/radicale/app/head.py b/radicale/app/head.py index eec68bb5..2dfb6f3f 100644 --- a/radicale/app/head.py +++ b/radicale/app/head.py @@ -26,7 +26,7 @@ from radicale.app.get import ApplicationPartGet class ApplicationPartHead(ApplicationPartGet, ApplicationBase): def do_HEAD(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: """Manage HEAD request.""" # Body is dropped in `Application.__call__` for HEAD requests - return self.do_GET(environ, base_prefix, path, user, remote_host, remote_useragent) + return self.do_GET(environ, base_prefix, path, user, request_info) diff --git a/radicale/app/mkcalendar.py b/radicale/app/mkcalendar.py index 6932fa50..266998c5 100644 --- a/radicale/app/mkcalendar.py +++ b/radicale/app/mkcalendar.py @@ -32,12 +32,12 @@ from radicale.log import logger class ApplicationPartMkcalendar(ApplicationBase): def do_MKCALENDAR(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage MKCALENDAR request.""" if "w" not in self._rights.authorization(user, path): return httputils.NOT_ALLOWED try: - xml_content = self._read_xml_request_body(environ) + xml_content = self._read_xml_request_body(environ, request_info) except RuntimeError as e: logger.warning( "Bad MKCALENDAR request on %r: %s", path, e, exc_info=True) @@ -67,7 +67,7 @@ class ApplicationPartMkcalendar(ApplicationBase): item = next(iter(self._storage.discover(path)), None) if item: return self._webdav_error_response( - client.CONFLICT, "D:resource-must-be-null") + client.CONFLICT, "D:resource-must-be-null", request_info) parent_path = pathutils.parent_path(path) parent_item = next(iter(self._storage.discover(parent_path)), None) if not parent_item: diff --git a/radicale/app/mkcol.py b/radicale/app/mkcol.py index 77d81e22..26de7bd0 100644 --- a/radicale/app/mkcol.py +++ b/radicale/app/mkcol.py @@ -32,13 +32,13 @@ from radicale.log import logger class ApplicationPartMkcol(ApplicationBase): def do_MKCOL(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage MKCOL request.""" permissions = self._rights.authorization(user, path) if not rights.intersect(permissions, "Ww"): return httputils.NOT_ALLOWED try: - xml_content = self._read_xml_request_body(environ) + xml_content = self._read_xml_request_body(environ, request_info) except RuntimeError as e: logger.warning( "Bad MKCOL request on %r: %s", path, e, exc_info=True) diff --git a/radicale/app/move.py b/radicale/app/move.py index f16368f4..1d84c58b 100644 --- a/radicale/app/move.py +++ b/radicale/app/move.py @@ -49,7 +49,7 @@ def get_server_netloc(environ: types.WSGIEnviron, force_port: bool = False): class ApplicationPartMove(ApplicationBase): def do_MOVE(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage MOVE request.""" raw_dest = environ.get("HTTP_DESTINATION", "") @@ -136,7 +136,7 @@ class ApplicationPartMove(ApplicationBase): to_collection.has_uid(item.uid)): return self._webdav_error_response( client.CONFLICT, "%s:no-uid-conflict" % ( - "C" if collection_tag == "VCALENDAR" else "CR")) + "C" if collection_tag == "VCALENDAR" else "CR"), request_info) to_href = posixpath.basename(pathutils.strip_path(to_path)) try: self._storage.move(item, to_collection, to_href) diff --git a/radicale/app/options.py b/radicale/app/options.py index bcb3663e..2e81b45a 100644 --- a/radicale/app/options.py +++ b/radicale/app/options.py @@ -28,7 +28,7 @@ from radicale.app.base import ApplicationBase class ApplicationPartOptions(ApplicationBase): def do_OPTIONS(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage OPTIONS request.""" headers = { "Allow": ", ".join( diff --git a/radicale/app/post.py b/radicale/app/post.py index a70fc736..b2f44a89 100644 --- a/radicale/app/post.py +++ b/radicale/app/post.py @@ -26,10 +26,10 @@ from radicale.app.base import ApplicationBase class ApplicationPartPost(ApplicationBase): def do_POST(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage POST request.""" if path == "/.web" or path.startswith("/.web/"): - return self._web.post(environ, base_prefix, path, user) + return self._web.post(environ, base_prefix, path, user, request_info) elif path == "/.sharing" or path.startswith("/.sharing/"): - return self._sharing.post(environ, base_prefix, path, user) + return self._sharing.post(environ, base_prefix, path, user, request_info) return httputils.METHOD_NOT_ALLOWED diff --git a/radicale/app/propfind.py b/radicale/app/propfind.py index 9424547c..151577f4 100644 --- a/radicale/app/propfind.py +++ b/radicale/app/propfind.py @@ -574,7 +574,7 @@ class ApplicationPartPropfind(ApplicationBase): yield item, permission, raw_permissions def do_PROPFIND(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage PROPFIND request.""" http_depth = environ.get("HTTP_DEPTH", "0") permissions_filter = None @@ -594,7 +594,7 @@ class ApplicationPartPropfind(ApplicationBase): if not access.check("r"): return httputils.NOT_ALLOWED try: - xml_content = self._read_xml_request_body(environ) + xml_content = self._read_xml_request_body(environ, request_info) except RuntimeError as e: logger.warning( "Bad PROPFIND request on %r: %s", path, e, exc_info=True) @@ -659,4 +659,5 @@ class ApplicationPartPropfind(ApplicationBase): allowed_items, user, self._encoding, max_resource_size=self._max_resource_size, shares=shares) if xml_answer is None: return httputils.NOT_ALLOWED - return client.MULTI_STATUS, headers, self._xml_response(xml_answer), xmlutils.pretty_xml(xml_content) + request_info["status"] = client.MULTI_STATUS + return client.MULTI_STATUS, headers, self._xml_response(xml_answer, request_info), xmlutils.pretty_xml(xml_content) diff --git a/radicale/app/proppatch.py b/radicale/app/proppatch.py index f97d4737..90145329 100644 --- a/radicale/app/proppatch.py +++ b/radicale/app/proppatch.py @@ -97,7 +97,7 @@ def xml_proppatch(base_prefix: str, path: str, class ApplicationPartProppatch(ApplicationBase): def do_PROPPATCH(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage PROPPATCH request.""" actor = user permissions_filter = None @@ -155,7 +155,8 @@ class ApplicationPartProppatch(ApplicationBase): logger.info("PROPPATCH request on shared %r: write-permissions, overlay not enforced, but enforced by permission 'E'", path_orig) share_overlay = True try: - xml_content = self._read_xml_request_body(environ) + xml_content = self._read_xml_request_body(environ, request_info) + except RuntimeError as e: logger.warning( "Bad PROPPATCH request on %r: %s", path, e, exc_info=True) @@ -193,7 +194,8 @@ 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), xmlutils.pretty_xml(xml_content) + request_info["status"] = client.MULTI_STATUS + return client.MULTI_STATUS, headers, self._xml_response(xml_answer, request_info), xmlutils.pretty_xml(xml_content) with self._storage.acquire_lock("w", user, path=path, request="PROPPATCH"): item = next(iter(self._storage.discover(path)), None) @@ -242,4 +244,5 @@ 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), xmlutils.pretty_xml(xml_content) + request_info["status"] = client.MULTI_STATUS + return client.MULTI_STATUS, headers, self._xml_response(xml_answer, request_info), xmlutils.pretty_xml(xml_content) diff --git a/radicale/app/put.py b/radicale/app/put.py index 7d14955e..1536c127 100644 --- a/radicale/app/put.py +++ b/radicale/app/put.py @@ -179,7 +179,7 @@ def prepare(vobject_items: List[vobject.base.Component], path: str, class ApplicationPartPut(ApplicationBase): def do_PUT(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage PUT request.""" actor = user permissions_filter = None @@ -196,7 +196,7 @@ class ApplicationPartPut(ApplicationBase): if not access.check("w"): return httputils.NOT_ALLOWED try: - content = httputils.read_request_body(self.configuration, environ) + content = httputils.read_request_body(self.configuration, environ, request_info) except RuntimeError as e: logger.warning("Bad PUT request on %r (read_request_body): %s", path, e, exc_info=True) return httputils.BAD_REQUEST @@ -344,9 +344,10 @@ class ApplicationPartPut(ApplicationBase): prepared_item, = prepared_items if (item and item.uid != prepared_item.uid or not item and parent_item.has_uid(prepared_item.uid)): + request_info["status"] = client.CONFLICT return self._webdav_error_response( client.CONFLICT, "%s:no-uid-conflict" % ( - "C" if tag == "VCALENDAR" else "CR")) + "C" if tag == "VCALENDAR" else "CR"), request_info) href = posixpath.basename(pathutils.strip_path(path)) try: diff --git a/radicale/app/report.py b/radicale/app/report.py index f9b4defd..93461e2e 100644 --- a/radicale/app/report.py +++ b/radicale/app/report.py @@ -149,7 +149,7 @@ def free_busy_report(base_prefix: str, path: str, xml_request: Optional[ET.Eleme def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], collection: storage.BaseCollection, encoding: str, unlock_storage_fn: Callable[[], None], - max_occurrence: int = 0, user: str = "", remote_addr: str = "", remote_useragent: str = "", + max_occurrence: int = 0, user: str = "", request_info: dict = {}, share: Union[dict, None] = None) -> Tuple[int, ET.Element]: """Read and answer REPORT requests that return XML. @@ -216,8 +216,11 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], sync_token, names = collection.sync(old_sync_token) except ValueError as e: # Invalid sync token + remote_useragent_txt = "" + if request_info["useragent"] != "": + remote_useragent_txt = " using %r" % request_info["useragent"] logger.warning("Client provided invalid sync token for path %r (user %r from %s%s): %s", - path, user, remote_addr, remote_useragent, e, exc_info=True) + path, user, request_info["host"], remote_useragent_txt, e, exc_info=True) # client.CONFLICT doesn't work with some clients (e.g. InfCloud) return (client.FORBIDDEN, xmlutils.webdav_error("D:valid-sync-token")) @@ -851,7 +854,7 @@ def test_filter(collection_tag: str, item: radicale_item.Item, class ApplicationPartReport(ApplicationBase): def do_REPORT(self, environ: types.WSGIEnviron, base_prefix: str, - path: str, user: str, remote_host: str, remote_useragent: str) -> types.WSGIResponse: + path: str, user: str, request_info: dict) -> types.WSGIResponse: """Manage REPORT request.""" permissions_filter = None share = None @@ -867,7 +870,7 @@ class ApplicationPartReport(ApplicationBase): if not access.check("r"): return httputils.NOT_ALLOWED try: - xml_content = self._read_xml_request_body(environ) + xml_content = self._read_xml_request_body(environ, request_info) except RuntimeError as e: logger.warning("Bad REPORT request on %r: %s", path, e, exc_info=True) @@ -905,10 +908,11 @@ class ApplicationPartReport(ApplicationBase): try: status, xml_answer = xml_report( base_prefix, path, xml_content, collection, self._encoding, - lock_stack.close, max_occurrence, user, remote_host, remote_useragent, share=share) + lock_stack.close, max_occurrence, user, request_info, share=share) except ValueError as e: logger.warning( "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), xmlutils.pretty_xml(xml_content) + request_info["status"] = status + return status, headers, self._xml_response(xml_answer, request_info), xmlutils.pretty_xml(xml_content) diff --git a/radicale/httputils.py b/radicale/httputils.py index 424f178e..e030cdce 100644 --- a/radicale/httputils.py +++ b/radicale/httputils.py @@ -32,7 +32,7 @@ import time from http import client from typing import List, Mapping, Union, cast -from radicale import config, pathutils, types, utils +from radicale import config, log, pathutils, types, utils from radicale.log import logger if sys.version_info < (3, 9): @@ -151,16 +151,29 @@ def read_raw_request_body(configuration: "config.Configuration", def read_request_body(configuration: "config.Configuration", - environ: types.WSGIEnviron) -> str: + environ: types.WSGIEnviron, request_info: dict) -> str: content = decode_request(configuration, environ, read_raw_request_body(configuration, environ)) - if logger.isEnabledFor(logging.DEBUG): - if configuration.get("logging", "request_content_on_debug"): - _limit_content = configuration.get("logging", "limit_content") + _limit_content = configuration.get("logging", "limit_content") + if configuration.get("logging", "request_content_on_debug"): + if logger.isEnabledFor(logging.DEBUG): logger.debug("Request content (sha256sum): %s", utils.sha256_str(content)) logger.debug("Request content:\n%s", utils.textwrap_str(content, _limit_content)) + else: + _request_content_on_notice_condition = configuration.get("logging", "request_content_on_notice_condition") + if _request_content_on_notice_condition != {}: + if log.log_conditional( + "request-content", + condition=_request_content_on_notice_condition, + value=request_info, + ): + logger.notice("Request content (log condition passed):\n%s", utils.textwrap_str(content, _limit_content)) + else: + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Request content (log condition skipped): suppressed") else: - logger.debug("Request content: suppressed by config/option [logging] request_content_on_debug") + if logger.isEnabledFor(logging.DEBUG): + logger.debug("Request content: suppressed by config/option [logging] request_content_on_debug") return content diff --git a/radicale/log.py b/radicale/log.py index 408f7f62..1436166c 100644 --- a/radicale/log.py +++ b/radicale/log.py @@ -28,8 +28,10 @@ Log messages are sent to the first available target of: import contextlib import io +import ipaddress import logging import os +import re import socket import struct import sys @@ -48,6 +50,19 @@ LOGGER_FORMATS: Mapping[str, str] = { } DATE_FORMAT: str = "%Y-%m-%d %H:%M:%S %z" +LOG_CONDITION_TOKEN: dict = {"method": "str", + "path": "str", + "useragent": "str", + "host": "ipaddress", + "login": "str", + "status": "int", + } +LOG_CONDITION_CONDITION: list = ["match", "value"] +LOG_CONDITION_MATCH_STR: list = ["startswith", "endswith", "equal", "re", "==", "="] +LOG_CONDITION_MATCH_INT: list = ["=", ">", "<", "<=", ">=", "equal", "==", "<>", "!="] +LOG_CONDITION_MATCH_IPADDRESS: list = ["==", "equal", "=", "<>", "!="] +LOG_CONDITION_MATCH_IPNETWORK: list = ["included", "excluded", "incl", "excl"] + LOG_LEVEL_OPTIONS: list = ["trace", "debug", "info", "notice", "warning", "error", "critical", "alert"] LOG_LEVEL_TRACE: int = 5 @@ -326,3 +341,90 @@ def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_filter: st logger.addFilter(PassTRACETOKENFilter(trace_filter)) else: logger.trace("Logging messages on 'trace' level enabled") + + +def log_conditional(name: str, condition: dict, value: dict) -> bool: + logger.trace("log/conditional/%s/CHECK : condition=%r value=%r", name, condition, value) + # "and" combination + condition_active = False + for token in condition: + condition_active = True + if LOG_CONDITION_TOKEN[token] == "str": + logger.trace("log/conditional/%s/%s/string/CHECK : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + if condition[token]["match"] in ["equal", "==", "="]: + if not condition[token]["value"] == value[token]: + return False + elif condition[token]["match"] in ["startswith"]: + if not value[token].startswith(condition[token]["value"]): + return False + elif condition[token]["match"] in ["endswith"]: + if not value[token].endswith(condition[token]["value"]): + return False + elif condition[token]["match"] in ["re"]: + if not re.search(condition[token]["value"], value[token]): + return False + logger.trace("log/conditional/%s/%s/string/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + + elif LOG_CONDITION_TOKEN[token] == "int": + condition[token]["value"] = int(condition[token]["value"]) + logger.trace("log/conditional/%s/%s/integer/CHECK : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + if condition[token]["match"] in ["equal", "==", "="]: + if not condition[token]["value"] == value[token]: + return False + elif condition[token]["match"] in ["<"]: + if not condition[token]["value"] < value[token]: + return False + elif condition[token]["match"] in ["<="]: + if not condition[token]["value"] <= value[token]: + return False + elif condition[token]["match"] in [">"]: + if not condition[token]["value"] > value[token]: + return False + elif condition[token]["match"] in [">="]: + if not condition[token]["value"] >= value[token]: + return False + elif condition[token]["match"] in ["<>", "!="]: + if not condition[token]["value"] != value[token]: + return False + logger.trace("log/conditional/%s/%s/integer/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + + elif LOG_CONDITION_TOKEN[token] == "ipaddress": + logger.trace("log/conditional/%s/%s/ip/CHECK : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + # simple IP address check + if condition[token]["match"] in ["equal", "==", "="]: + if not condition[token]["value"] == value[token]: + return False + elif condition[token]["match"] in ["<>", "!="]: + if not condition[token]["value"] != value[token]: + return False + elif condition[token]["match"] in ["included", "incl", "excluded", "excl"]: + if condition[token]["match"] in ["included", "incl"]: + if value[token] == "unknown": + return False + else: + ip_net = ipaddress.ip_network(value[token]) + ip = ipaddress.ip_network(condition[token]["value"]) + if type(ip_net) is ipaddress.IPv4Network and type(ip) is ipaddress.IPv4Network: + if not ip_net.subnet_of(ip): + return False + elif type(ip_net) is ipaddress.IPv6Network and type(ip) is ipaddress.IPv6Network: + if not ip_net.subnet_of(ip): + return False + else: + return False + elif condition[token]["match"] in ["excluded", "excl"]: + if value[token] != "unknown": + ip_net = ipaddress.ip_network(value[token]) + if type(ip_net) is ipaddress.IPv4Network and type(ip) is ipaddress.IPv4Network: + if ip_net.subnet_of(ip): + return False + elif type(ip_net) is ipaddress.IPv6Network and type(ip) is ipaddress.IPv6Network: + if ip_net.subnet_of(ip): + return False + logger.trace("log/conditional/%s/%s/ip/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + else: + logger.trace("log/conditional/%s/%s/ip/SKIPPED: %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token]) + + # only return 'True' if at least one condition was found + logger.trace("log/conditional/%s/PASSED: condition=%r value=%r", name, condition, value) + return condition_active diff --git a/radicale/sharing/__init__.py b/radicale/sharing/__init__.py index b1b1078e..fb162ffc 100644 --- a/radicale/sharing/__init__.py +++ b/radicale/sharing/__init__.py @@ -511,7 +511,7 @@ class BaseSharing: return None # *** POST API *** - def post(self, environ: types.WSGIEnviron, base_prefix: str, path: str, user: str) -> types.WSGIResponse: + def post(self, environ: types.WSGIEnviron, base_prefix: str, path: str, user: str, request_info: dict) -> types.WSGIResponse: # Late import to avoid circular dependency in config from radicale.app import base as app_base from radicale.app.base import Access @@ -616,7 +616,7 @@ class BaseSharing: logger.trace("sharing/API: called by authenticated user: %r", user) # read POST data try: - request_body = httputils.read_request_body(self.configuration, environ) + request_body = httputils.read_request_body(self.configuration, environ, request_info) except RuntimeError as e: logger.warning("Bad POST request on %r (read_request_body): %s", path, e, exc_info=True) return httputils.bad_request("Failed read POST request body") diff --git a/radicale/tests/custom/web.py b/radicale/tests/custom/web.py index ee8bc6e6..7afdd510 100644 --- a/radicale/tests/custom/web.py +++ b/radicale/tests/custom/web.py @@ -28,10 +28,10 @@ from radicale import httputils, types, web class Web(web.BaseWeb): def get(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: 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) + user: str, request_info: dict) -> types.WSGIResponse: + content = httputils.read_request_body(self.configuration, environ, request_info) return client.OK, {"Content-Type": "text/plain"}, "echo:" + content, None diff --git a/radicale/web/__init__.py b/radicale/web/__init__.py index a8f2b731..526452aa 100644 --- a/radicale/web/__init__.py +++ b/radicale/web/__init__.py @@ -49,7 +49,7 @@ class BaseWeb: self.configuration = configuration def get(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: """GET request. ``base_prefix`` is sanitized and never ends with "/". @@ -58,11 +58,13 @@ class BaseWeb: ``user`` is empty for anonymous users. + ``request_info`` dict of additional information + """ return httputils.METHOD_NOT_ALLOWED def post(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: """POST request. ``base_prefix`` is sanitized and never ends with "/". @@ -71,6 +73,8 @@ class BaseWeb: ``user`` is empty for anonymous users. + ``request_info`` dict of additional information + Use ``httputils.read*_request_body(self.configuration, environ)`` to read the body. diff --git a/radicale/web/internal.py b/radicale/web/internal.py index 01516b5b..312ad961 100644 --- a/radicale/web/internal.py +++ b/radicale/web/internal.py @@ -34,6 +34,6 @@ FALLBACK_MIMETYPE = httputils.FALLBACK_MIMETYPE # deprecated class Web(web.BaseWeb): def get(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: return httputils.serve_resource("radicale.web", "internal_data", base_prefix, path) diff --git a/radicale/web/none.py b/radicale/web/none.py index 59cc341e..7f6b4bba 100644 --- a/radicale/web/none.py +++ b/radicale/web/none.py @@ -28,7 +28,7 @@ from radicale import httputils, pathutils, types, web class Web(web.BaseWeb): def get(self, environ: types.WSGIEnviron, base_prefix: str, path: str, - user: str) -> types.WSGIResponse: + user: str, request_info: dict) -> types.WSGIResponse: assert path == "/.web" or path.startswith("/.web/") assert pathutils.sanitize_path(path) == path if path != "/.web":