Merge pull request #1825 from pbiering/add-trace-logging-feature

Add trace logging feature

.gitignore

@@ -23,3 +23,5 @@ coverage.xml
 .vscode
 .sass-cache
 Gemfile.lock
+
+pytestdebug.log

CHANGELOG.md

@@ -8,6 +8,7 @@
 * Feature: add hook for server-side e-mail notification
 * Fix: logging ignores not retrievable get_native_id if not supported by OS
 * Fix: report with enabled expand honors now provided filter proper
+* Improve: add options [logging] trace_on_debug and trace_filter for supporting trace logging
 
 ## 3.5.4
 * Improve: item filter enhanced for 3rd level supporting VALARM and honoring TRIGGER (offset or absolute)

DOCUMENTATION.md

@@ -1420,6 +1420,24 @@ Available levels: **debug**, **info**, **warning**, **error**, **critical**
 
 Default: `warning` _(< 3.2.0)_ `info` _(>= 3.2.0)_
 
+##### trace_on_debug
+
+_(> 3.5.4)_
+
+Do not filter debug messages starting with 'TRACE'
+
+Default: `False`
+
+##### trace_filter
+
+_(> 3.5.4)_
+
+Filter debug messages starting with 'TRACE/<TOKEN>'
+
+Precondition: `trace_on_debug = True`
+
+Default: (empty)
+
 ##### mask_passwords
 
 Don't include passwords in logs.

config

@@ -272,6 +272,12 @@
 # Value: debug | info | warning | error | critical
 #level = info
 
+# do not filter debug messages starting with 'TRACE'
+#trace_on_debug = False
+
+# filter debug messages starting with 'TRACE/<TOKEN>'
+#trace_filter = ""
+
 # Don't include passwords in logs
 #mask_passwords = True
 

radicale/__init__.py

@@ -52,7 +52,10 @@ def _get_application_instance(config_path: str, wsgi_errors: types.ErrorStream
                 configuration = config.load(config.parse_compound_paths(
                     config.DEFAULT_CONFIG_PATH,
                     config_path))
-                log.set_level(cast(str, configuration.get("logging", "level")), configuration.get("logging", "backtrace_on_debug"))
+                log.set_level(cast(str, configuration.get("logging", "level")),
+                              configuration.get("logging", "backtrace_on_debug"),
+                              configuration.get("logging", "trace_on_debug"),
+                              configuration.get("logging", "trace_filter"))
                 # Log configuration after logger is configured
                 default_config_active = True
                 for source, miss in configuration.sources():

radicale/__main__.py

@@ -165,7 +165,10 @@ def run() -> None:
         sys.exit(1)
 
     # Configure logging
-    log.set_level(cast(str, configuration.get("logging", "level")), configuration.get("logging", "backtrace_on_debug"))
+    log.set_level(cast(str, configuration.get("logging", "level")),
+                  configuration.get("logging", "backtrace_on_debug"),
+                  configuration.get("logging", "trace_on_debug"),
+                  configuration.get("logging", "trace_filter"))
 
     # Log configuration after logger is configured
     default_config_active = True

radicale/config.py

@@ -509,6 +509,14 @@ This is an automated message. Please do not reply.""",
             "value": "info",
             "help": "threshold for the logger",
             "type": logging_level}),
+        ("trace_on_debug", {
+            "value": "False",
+            "help": "do not filter debug messages starting with 'TRACE'",
+            "type": bool}),
+        ("trace_filter", {
+            "value": "",
+            "help": "filter debug messages starting with 'TRACE/<TOKEN>'",
+            "type": str}),
         ("bad_put_request_content", {
             "value": "False",
             "help": "log bad PUT request content",

radicale/log.py

@@ -57,8 +57,35 @@ class RemoveTracebackFilter(logging.Filter):
         return True
 
 
+class RemoveTRACEFilter(logging.Filter):
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if record.msg.startswith("TRACE"):
+            return False
+        else:
+            return True
+
+
+class PassTRACETOKENFilter(logging.Filter):
+    def __init__(self, trace_filter: str):
+        super().__init__()
+        self.trace_filter = trace_filter
+        self.prefix = "TRACE/" + self.trace_filter
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if record.msg.startswith("TRACE"):
+            if record.msg.startswith(self.prefix):
+                return True
+            else:
+                return False
+        else:
+            return True
+
+
 REMOVE_TRACEBACK_FILTER: logging.Filter = RemoveTracebackFilter()
 
+REMOVE_TRACE_FILTER: logging.Filter = RemoveTRACEFilter()
+
 
 class IdentLogRecordFactory:
     """LogRecordFactory that adds ``ident`` attribute."""
@@ -231,7 +258,7 @@ logger_display_backtrace_disabled: bool = False
 logger_display_backtrace_enabled: bool = False
 
 
-def set_level(level: Union[int, str], backtrace_on_debug: bool) -> None:
+def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_on_debug: bool = False, trace_filter: str = "") -> None:
     """Set logging level for global logger."""
     global logger_display_backtrace_disabled
     global logger_display_backtrace_enabled
@@ -255,3 +282,14 @@ def set_level(level: Union[int, str], backtrace_on_debug: bool) -> None:
                 logger.debug("Logging of backtrace is enabled by option in this loglevel")
                 logger_display_backtrace_enabled = True
             logger.removeFilter(REMOVE_TRACEBACK_FILTER)
+        if trace_on_debug:
+            if trace_filter != "":
+                logger.debug("Logging messages starting with 'TRACE/%s' enabled", trace_filter)
+                logger.addFilter(PassTRACETOKENFilter(trace_filter))
+                logger.removeFilter(REMOVE_TRACE_FILTER)
+            else:
+                logger.debug("Logging messages starting with 'TRACE' enabled")
+                logger.removeFilter(REMOVE_TRACE_FILTER)
+        else:
+            logger.debug("Logging messages starting with 'TRACE' disabled")
+            logger.addFilter(REMOVE_TRACE_FILTER)

radicale/server.py

@@ -340,6 +340,8 @@ def serve(configuration: config.Configuration,
             select_timeout = 1.0
         max_connections: int = configuration.get("server", "max_connections")
         logger.info("Radicale server ready")
+        logger.debug("TRACE: Radicale server ready ('logging/trace_on_debug' is active)")
+        logger.debug("TRACE/SERVER: Radicale server ready ('logging/trace_on_debug' is active - either with 'SERVER' or empty filter)")
         while True:
             rlist: List[socket.socket] = []
             # Wait for finished clients