diff --git a/.gitignore b/.gitignore index 5a0363a0..87b83643 100644 --- a/.gitignore +++ b/.gitignore @@ -23,3 +23,5 @@ coverage.xml .vscode .sass-cache Gemfile.lock + +pytestdebug.log diff --git a/CHANGELOG.md b/CHANGELOG.md index f78f5d6a..ec1b5eeb 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index be7fe021..d00cd01a 100644 --- a/DOCUMENTATION.md +++ b/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/' + +Precondition: `trace_on_debug = True` + +Default: (empty) + ##### mask_passwords Don't include passwords in logs. diff --git a/config b/config index ab2ea7eb..51e5324c 100644 --- a/config +++ b/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/' +#trace_filter = "" + # Don't include passwords in logs #mask_passwords = True diff --git a/radicale/__init__.py b/radicale/__init__.py index 2554e5b2..8924d507 100644 --- a/radicale/__init__.py +++ b/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(): diff --git a/radicale/__main__.py b/radicale/__main__.py index 25d2b853..b3576a60 100644 --- a/radicale/__main__.py +++ b/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 diff --git a/radicale/config.py b/radicale/config.py index 15405063..7deee5ca 100644 --- a/radicale/config.py +++ b/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/'", + "type": str}), ("bad_put_request_content", { "value": "False", "help": "log bad PUT request content", diff --git a/radicale/log.py b/radicale/log.py index 1dde25d2..7f7df5e3 100644 --- a/radicale/log.py +++ b/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) diff --git a/radicale/server.py b/radicale/server.py index e437286a..55e112e2 100644 --- a/radicale/server.py +++ b/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