Avii/Radicale
1
0
Fork 0
Code Issues Pull Requests Actions 2 Packages Projects Releases Wiki Activity

log on_notice_condition: implementation

Browse Source
This commit is contained in:
Peter Bieringer
2026-05-12 08:29:59 +02:00
parent b6805177f7
commit b9ec1c223f
21 changed files with 263 additions and 70 deletions
Download Patch File Download Diff File Expand all files Collapse all files

59
radicale/app/__init__.py
View File

@@ -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)

50
radicale/app/base.py
View File

@@ -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

4
radicale/app/delete.py
View File

@@ -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

4
radicale/app/get.py
View File

@@ -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:

4
radicale/app/head.py
View File

@@ -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)

6
radicale/app/mkcalendar.py
View File

@@ -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:

4
radicale/app/mkcol.py
View File

@@ -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)

4
radicale/app/move.py
View File

@@ -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)

2
radicale/app/options.py
View File

@@ -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(

6
radicale/app/post.py
View File

@@ -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

7
radicale/app/propfind.py
View File

@@ -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)

11
radicale/app/proppatch.py
View File

@@ -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)

7
radicale/app/put.py
View File

@@ -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:

16
radicale/app/report.py
View File

@@ -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)