Adjust: [logging] header/content debug log indended by space to be skipped by logwatch

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

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

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

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

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)