diff --git a/CHANGELOG.md b/CHANGELOG.md index 920df43b..599a108e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ * Add: logging of broken contact items during PUT * Extend: [auth] imap: add fallback support for LOGIN towards remote IMAP server (replaced in 3.5.0) * Fix: improper detection of HTTP_X_FORWARDED_PORT on MOVE +* Extend: [logging] with profiling log per reqest or regular per request method ## 3.5.9 * Extend: [auth] add support for type http_remote_user diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index 855c671a..71670c68 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1690,6 +1690,44 @@ Log storage cache actions on `level = debug` Default: `False` +##### profiling_per_request + +_(>= 3.5.10)_ + +Log profiling data on level=info + +Default: `none` + +One of +* `none` (disabled) +* `per_request` (above minimum duration) +* `per_request_method` (regular interval) + +##### profiling_per_request_min_duration + +_(>= 3.5.10)_ + +Log profiling data per request minimum duration (seconds) before logging, otherwise skip + +Default: `3` + +##### profiling_per_request_method_interval + +_(>= 3.5.10)_ + +Log profiling data per method interval (seconds) +Triggered by request, not active on idle systems + +Default: `600` + +##### profiling_top_x_functions + +_(>= 3.5.10)_ + +Log profiling top X functions (limit) + +Default: `10` + #### [headers] This section can be used to specify additional HTTP headers that will be sent to clients. diff --git a/config b/config index 93291650..781c4edf 100644 --- a/config +++ b/config @@ -321,6 +321,20 @@ # Log storage cache actions on level=debug #storage_cache_actions_on_debug = False +# Log profiling data on level=info +# Value: per_request | per_request_method | none +#profiling = none + +# Log profiling data per request minium duration (seconds) +#profiling_per_request_min_duration = 3 + +# Log profiling data per request method interval (seconds) +#profiling_per_request_method_interval = 600 + +# Log profiling top X functions (limit) +#profiling_top_x_functions = 10 + + [headers] # Additional HTTP headers diff --git a/contrib/logwatch/radicale b/contrib/logwatch/radicale index 7cc1b1b8..1cdddc30 100644 --- a/contrib/logwatch/radicale +++ b/contrib/logwatch/radicale @@ -126,11 +126,35 @@ while (defined($ThisLine = )) { elsif ( $ThisLine =~ / (Failed login attempt) /o ) { $OtherEvents{$1}++; } + elsif ( $ThisLine =~ / (Profiling data per request method \S+) /o ) { + my $info = $1; + if ( $ThisLine =~ /(no request seen so far)/o ) { + $OtherEvents{$info . " - " . $1}++; + } else { + $OtherEvents{$info}++; + }; + } + elsif ( $ThisLine =~ / (Profiling data per request \S+) /o ) { + my $info = $1; + if ( $ThisLine =~ /(suppressed because duration below minimum|suppressed because of no data)/o ) { + $OtherEvents{$info . " - " . $1}++; + } else { + $OtherEvents{$info}++; + }; + } elsif ( $ThisLine =~ /\[(DEBUG|INFO)\] /o ) { # skip if DEBUG+INFO } else { # Report any unmatched entries... + if ($ThisLine =~ /^({\'| )/o) { + # skip profiling or raw header data + next; + }; + if ($ThisLine =~ /^$/o) { + # skip empty line + next; + }; $ThisLine =~ s/^\[\d+(\/Thread-\d+)?\] //; # remove process/Thread ID chomp($ThisLine); $OtherList{$ThisLine}++; diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 940d15b5..9b3c9ba3 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -27,8 +27,11 @@ the built-in server (see ``radicale.server`` module). """ import base64 +import cProfile import datetime +import io import pprint +import pstats import random import time import zlib @@ -55,6 +58,8 @@ from radicale.log import logger # Combination of types.WSGIStartResponse and WSGI application return value _IntermediateResponse = Tuple[str, List[Tuple[str, str]], Iterable[bytes]] +REQUEST_METHODS = ["DELETE", "GET", "HEAD", "MKCALENDAR", "MKCOL", "MOVE", "OPTIONS", "POST", "PROPFIND", "PROPPATCH", "PUT", "REPORT"] + class Application(ApplicationPartDelete, ApplicationPartHead, ApplicationPartGet, ApplicationPartMkcalendar, @@ -73,6 +78,12 @@ class Application(ApplicationPartDelete, ApplicationPartHead, _web_type: str _script_name: str _extra_headers: Mapping[str, str] + _profiling_per_request: bool = False + _profiling_per_request_method: bool = False + profiler_per_request_method: dict[str, cProfile.Profile] = {} + profiler_per_request_method_counter: dict[str, int] = {} + profiler_per_request_method_starttime: datetime.datetime + profiler_per_request_method_logtime: datetime.datetime def __init__(self, configuration: config.Configuration) -> None: """Initialize Application. @@ -116,6 +127,51 @@ class Application(ApplicationPartDelete, ApplicationPartHead, self._extra_headers[key] = configuration.get("headers", key) self._strict_preconditions = configuration.get("storage", "strict_preconditions") logger.info("strict preconditions check: %s", self._strict_preconditions) + # Profiling options + self._profiling = configuration.get("logging", "profiling") + self._profiling_per_request_min_duration = configuration.get("logging", "profiling_per_request_min_duration") + self._profiling_per_request_method_interval = configuration.get("logging", "profiling_per_request_method_interval") + self._profiling_top_x_functions = configuration.get("logging", "profiling_top_x_functions") + if self._profiling in config.PROFILING: + logger.info("profiling: %s", self._profiling) + if self._profiling == "per_request": + self._profiling_per_request = True + elif self._profiling == "per_request_method": + self._profiling_per_request_method = True + if self._profiling_per_request or self._profiling_per_request_method: + logger.info("profiling top X functions: %d", self._profiling_top_x_functions) + if self._profiling_per_request: + logger.info("profiling per request minimum duration: %d (below are skipped)", self._profiling_per_request_min_duration) + if self._profiling_per_request_method: + logger.info("profiling per request method interval: %d seconds", self._profiling_per_request_method_interval) + # Profiling per request method initialization + if self._profiling_per_request_method: + for method in REQUEST_METHODS: + self.profiler_per_request_method[method] = cProfile.Profile() + self.profiler_per_request_method_counter[method] = False + self.profiler_per_request_method_starttime = datetime.datetime.now() + self.profiler_per_request_method_logtime = self.profiler_per_request_method_starttime + + def __del__(self) -> None: + """Shutdown application.""" + if self._profiling_per_request_method: + # Profiling since startup + self._profiler_per_request_method(True) + + def _profiler_per_request_method(self, shutdown: bool = False) -> None: + """Display profiler data per method.""" + profiler_timedelta_start = (datetime.datetime.now() - self.profiler_per_request_method_starttime).total_seconds() + for method in REQUEST_METHODS: + if self.profiler_per_request_method_counter[method] > 0: + 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()) + else: + if shutdown: + logger.info("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start) + else: + logger.debug("Profiling data per request method %s after %d seconds: (no request seen so far)", method, profiler_timedelta_start) def _scrub_headers(self, environ: types.WSGIEnviron) -> types.WSGIEnviron: """Mask passwords and cookies.""" @@ -156,6 +212,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, request_method = environ["REQUEST_METHOD"].upper() unsafe_path = environ.get("PATH_INFO", "") https = environ.get("HTTPS", "") + profiler = None context = AuthContext() @@ -194,6 +251,7 @@ class Application(ApplicationPartDelete, ApplicationPartHead, # Start response time_end = datetime.datetime.now() + time_delta_seconds = (time_end - time_begin).total_seconds() status_text = "%d %s" % ( status, client.responses.get(status, "Unknown")) if answer is not None: @@ -203,7 +261,29 @@ class Application(ApplicationPartDelete, ApplicationPartHead, else: logger.info("%s response status for %r%s in %.3f seconds: %s", request_method, unsafe_path, depthinfo, - (time_end - time_begin).total_seconds(), status_text) + time_delta_seconds, status_text) + + # Profiling end + if self._profiling_per_request: + if profiler is not None: + # Profiling per request + if time_delta_seconds < self._profiling_per_request_min_duration: + logger.debug("Profiling data per request %s for %r%s: (suppressed because duration below minimum %.3f < %.3f)", request_method, unsafe_path, depthinfo, time_delta_seconds, self._profiling_per_request_min_duration) + else: + s = io.StringIO() + stats = pstats.Stats(profiler, stream=s).sort_stats('cumulative') + stats.print_stats(self._profiling_top_x_functions) # Print top X functions + logger.info("Profiling data per request %s for %r%s: %s", request_method, unsafe_path, depthinfo, s.getvalue()) + else: + logger.debug("Profiling data per request %s for %r%s: (suppressed because of no data)", request_method, unsafe_path, depthinfo) + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].disable() + self.profiler_per_request_method_counter[request_method] += 1 + profiler_timedelta = (datetime.datetime.now() - self.profiler_per_request_method_logtime).total_seconds() + if profiler_timedelta > self._profiling_per_request_method_interval: + self._profiler_per_request_method() + self.profiler_per_request_method_logtime = datetime.datetime.now() + # Return response content return status_text, list(headers.items()), answers @@ -370,8 +450,23 @@ class Application(ApplicationPartDelete, ApplicationPartHead, return response(*httputils.REQUEST_ENTITY_TOO_LARGE) if not login or user: + # Profiling + if self._profiling_per_request: + profiler = cProfile.Profile() + profiler.enable() + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].enable() + status, headers, answer = function( environ, base_prefix, path, user, remote_host, remote_useragent) + + # Profiling + if self._profiling_per_request: + if profiler is not None: + profiler.disable() + elif self._profiling_per_request_method: + self.profiler_per_request_method[request_method].disable() + if (status, headers, answer) == httputils.NOT_ALLOWED: logger.info("Access to %r denied for %s", path, repr(user) if user else "anonymous user") diff --git a/radicale/config.py b/radicale/config.py index a4ba6610..cf59bcd1 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -45,6 +45,8 @@ DEFAULT_CONFIG_PATH: str = os.pathsep.join([ "?/etc/radicale/config", "?~/.config/radicale/config"]) +PROFILING: Sequence[str] = ("per_request", "per_request_method", "none") + def positive_int(value: Any) -> int: value = int(value) @@ -70,6 +72,12 @@ def logging_level(value: Any) -> str: return value +def profiling(value: Any) -> str: + if value not in PROFILING: + raise ValueError("unsupported profiling: %r" % value) + return value + + def filepath(value: Any) -> str: if not value: return "" @@ -581,6 +589,22 @@ This is an automated message. Please do not reply.""", "value": "False", "help": "log storage cache action on level=debug", "type": bool}), + ("profiling", { + "value": "none", + "help": "log profiling data level=info", + "type": profiling}), + ("profiling_per_request_min_duration", { + "value": "3", + "help": "log profiling data per request minimum duration (seconds)", + "type": int}), + ("profiling_per_request_method_interval", { + "value": "600", + "help": "log profiling data per request method interval (seconds)", + "type": int}), + ("profiling_top_x_functions", { + "value": "10", + "help": "log profiling top X functions (limit)", + "type": int}), ("mask_passwords", { "value": "True", "help": "mask passwords in logs",