From 183e55614407e232c7f0f9e8de4332d6241063f7 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Wed, 10 Dec 2025 18:01:14 +0100 Subject: [PATCH] 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)