diff --git a/CHANGELOG.md b/CHANGELOG.md index de942739..d72e62b5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ## 3.7.1.dev * Fix: share address book collection as birthday calendar not working on non-DEBUG level * Extension: share accept now PATH and USER for matching email addresses as well +* Adjustment: replace logging/trace_on_debug by new log level "trace" ## 3.7.0 diff --git a/DOCUMENTATION.md b/DOCUMENTATION.md index f03c2895..dce0af63 100644 --- a/DOCUMENTATION.md +++ b/DOCUMENTATION.md @@ -1674,17 +1674,20 @@ Default: `internal` Set the logging level. Available levels are: +* `trace` _(>= 3.7.1)_ * `debug` * `info` +* `notice` _(>= 3.7.1)_ * `warning` * `error` * `critical` +* `alert` _(>= 3.7.1)_ Default: `warning` _(< 3.2.0)_ / `info` _(>= 3.2.0)_ ##### limit_content -_(> 3.7.0)_ +_(>= 3.7.0)_ Limit content of wrapped text (chars) @@ -1692,7 +1695,7 @@ Default: `3000` ##### trace_on_debug -_(> 3.5.4)_ +_(> 3.5.4)_ && _(< 3.7.1)_ Do not filter debug messages starting with 'TRACE' @@ -1700,12 +1703,18 @@ Default: `False` ##### trace_filter -_(> 3.5.4)_ +_(> 3.5.4)_ && _(< 3.7.1)_ Filter debug messages starting with 'TRACE/' Prerequisite: `trace_on_debug = True` +_(>= 3.7.1)_ + +Filter trace messages starting with '' + +Prerequisite: `level = trace` + Default: (empty) ##### mask_passwords diff --git a/config b/config index 63fc0072..01a76596 100644 --- a/config +++ b/config @@ -359,16 +359,13 @@ [logging] # Threshold for the logger -# Value: debug | info | warning | error | critical +# Value: trace | debug | info | notice | warning | error | critical | alert #level = info # Limit content of wrapped text (chars) #limit_content = 3000 -# do not filter debug messages starting with 'TRACE' -#trace_on_debug = False - -# filter debug messages starting with 'TRACE/' +# filter debug messages starting with '' #trace_filter = "" # Don't include passwords in logs diff --git a/pyproject.toml b/pyproject.toml index 2b2de192..cc3eeb91 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -55,7 +55,7 @@ build-backend = "setuptools.build_meta" [tool.tox] min_version = "4.0" -envlist = ["py_loglevel_info", "py_radicale_loglevel_info", "py", "flake8", "isort", "mypy", "integ_test", "html5validator"] +envlist = ["py_loglevel_info", "py_radicale_loglevel_info", "py_radicale_loglevel_trace", "py", "flake8", "isort", "mypy", "integ_test", "html5validator"] [tool.tox.env.py] extras = ["test"] @@ -80,6 +80,14 @@ deps = [ ] commands = [["pytest", "-r", "s", "--log-level", "INFO", "."]] +[tool.tox.env.py_radicale_loglevel_trace] +extras = ["test"] +setenv = { PYTEST_RADICALE_LOGLEVEL = "trace" } +deps = [ + "pytest" +] +commands = [["pytest", "-r", "s", "--log-level", "5", "."]] + [tool.tox.env.flake8] deps = ["flake8==7.1.0"] commands = [["flake8", "."]] diff --git a/radicale/__init__.py b/radicale/__init__.py index 8924d507..60148152 100644 --- a/radicale/__init__.py +++ b/radicale/__init__.py @@ -54,7 +54,6 @@ def _get_application_instance(config_path: str, wsgi_errors: types.ErrorStream config_path)) 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/__main__.py b/radicale/__main__.py index f5a76a92..de11db6c 100644 --- a/radicale/__main__.py +++ b/radicale/__main__.py @@ -172,7 +172,6 @@ def run() -> None: # Configure logging 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 diff --git a/radicale/app/propfind.py b/radicale/app/propfind.py index 238dd39a..41ba6ef9 100644 --- a/radicale/app/propfind.py +++ b/radicale/app/propfind.py @@ -20,7 +20,6 @@ import collections import itertools -import logging import posixpath import socket import xml.etree.ElementTree as ET @@ -76,8 +75,7 @@ def xml_propfind( # Writing answer multistatus = ET.Element(xmlutils.make_clark("D:multistatus")) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind: shares=%r", shares) + logger.trace("PROPFIND/xml_propfind: shares=%r", shares) for item, permission, raw_permissions, conversion in allowed_items: write = permission == "w" @@ -141,19 +139,15 @@ def xml_propfind_response( # lookup share share = None - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind: conversion=%r item.path=%r", conversion, uri) + logger.trace("PROPFIND/xml_propfind: conversion=%r item.path=%r", conversion, uri) for entry in shares: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind: check entry=%r", entry) + logger.trace("PROPFIND/xml_propfind: check entry=%r", entry) if entry is not None: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind: PathMapped=%r uri=%r", shares[entry]['PathMapped'], uri) + logger.trace("PROPFIND/xml_propfind: PathMapped=%r uri=%r", shares[entry]['PathMapped'], uri) if uri.startswith(shares[entry]['PathMapped']): if conversion is not None and shares[entry]['Conversion'] == conversion: share = shares[entry] - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind: found share=%r", share) + logger.trace("PROPFIND/xml_propfind: found share=%r", share) break share_bday_automap = False @@ -307,8 +301,7 @@ def xml_propfind_response( elif tag == xmlutils.make_clark("D:current-user-privilege-set"): privileges = ["D:read"] if share: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind_response/current-user-privilege-set: raw_permissions=%r share[Permissions]=%r permit_properties_overlay=%s", raw_permissions, share['Permissions'], self._sharing.permit_properties_overlay) + logger.trace("PROPFIND/xml_propfind_response/current-user-privilege-set: raw_permissions=%r share[Permissions]=%r permit_properties_overlay=%s", raw_permissions, share['Permissions'], self._sharing.permit_properties_overlay) if write: if "w" in share['Permissions']: if not share_bday_automap: @@ -321,8 +314,7 @@ def xml_propfind_response( "p" in share['Permissions'] or ("p" in raw_permissions and "P" not in share['Permissions']) or (self._sharing.permit_properties_overlay and "P" not in raw_permissions and "P" not in share['Permissions'])): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind_response/current-user-privilege-set: add D:write-properties") + logger.trace("PROPFIND/xml_propfind_response/current-user-privilege-set: add D:write-properties") privileges.append("D:write-properties") elif write: privileges.append("D:all") @@ -367,8 +359,7 @@ def xml_propfind_response( elif tag == xmlutils.make_clark("D:getcontentlength"): if not is_collection or is_leaf: if collection.tag == "VADDRESSBOOK" and share_bday_automap and isinstance(item, storage.BaseCollection): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind_response/getcontentlength: start bday automap handling") + logger.trace("PROPFIND/xml_propfind_response/getcontentlength: start bday automap handling") length = 0 for entry in item.get_all(): item_ics = entry.convert_vcf_to_ics() @@ -435,8 +426,7 @@ def xml_propfind_response( # Only for internal use by the web interface if isinstance(item, storage.BaseCollection) and not collection.is_principal: if collection.tag == "VADDRESSBOOK" and share_bday_automap: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/xml_propfind_response/getcontentcount: start bday automap handling") + logger.trace("PROPFIND/xml_propfind_response/getcontentcount: start bday automap handling") items = [] for entry in item.get_all(): item_ics = entry.convert_vcf_to_ics() @@ -528,8 +518,7 @@ class ApplicationPartPropfind(ApplicationBase): if isinstance(item, storage.BaseCollection): path = pathutils.unstrip_path(item.path, True) raw_permissions = self._rights.authorization(user, path) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND/_collect_allowed_items/BaseCollection: path=%r user=%r raw_permissions=%r", path, user, raw_permissions) + logger.trace("PROPFIND/_collect_allowed_items/BaseCollection: path=%r user=%r raw_permissions=%r", path, user, raw_permissions) if item.tag: permissions = rights.intersect(raw_permissions, "rw") target = "collection with tag %r" % item.path @@ -586,8 +575,7 @@ class ApplicationPartPropfind(ApplicationBase): logger.debug("Client timed out", exc_info=True) return httputils.REQUEST_TIMEOUT with self._storage.acquire_lock("r", user): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND: discover path=%r depth=%s", path, http_depth) + logger.trace("PROPFIND: discover path=%r depth=%s", path, http_depth) items_iter = iter(self._storage.discover( path, http_depth, None, self._rights._user_groups)) @@ -609,8 +597,7 @@ class ApplicationPartPropfind(ApplicationBase): allowed_items.append((item, permission, raw_permissions, None)) if self._sharing._enabled: if http_depth == "1": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND: get shared collections") + logger.trace("PROPFIND: get shared collections") # check for shared collections related to user, Enabled and not Hidden collections_share_list = self._sharing.sharing_collection_list(User=user, Enabled=True, Hidden=False) if collections_share_list: @@ -619,15 +606,12 @@ class ApplicationPartPropfind(ApplicationBase): c_path = share['PathMapped'] c_user = share['Owner'] c_permissions_filter = share['Permissions'] - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND: test shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter) + logger.trace("PROPFIND: test shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter) c_access = Access(self._rights, c_user, c_path, c_permissions_filter) if not c_access.check("r"): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND: skip shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r (permissions not matching)", c_share, c_path, c_user, c_permissions_filter) + logger.trace("PROPFIND: skip shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r (permissions not matching)", c_share, c_path, c_user, c_permissions_filter) continue - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPFIND: append shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter) + logger.trace("PROPFIND: append shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter) with self._storage.acquire_lock("r", c_user): c_items_iter = iter(self._storage.discover(c_path, "0")) c_allowed_items = list(self._collect_allowed_items(c_items_iter, c_user)) diff --git a/radicale/app/proppatch.py b/radicale/app/proppatch.py index b2e654cb..462f3a0e 100644 --- a/radicale/app/proppatch.py +++ b/radicale/app/proppatch.py @@ -20,7 +20,6 @@ # along with Radicale. If not, see . import errno -import logging import re import socket import xml.etree.ElementTree as ET @@ -65,14 +64,14 @@ def xml_proppatch(base_prefix: str, path: str, props_with_remove = xmlutils.props_from_request(xml_request) if share and share_overlay: # PROPPATCH overlay adjustment - logger.debug("TRACE/PROPPATCH/xml_proppatch: share+share_overlay is active: %r", share) + logger.trace("PROPPATCH/xml_proppatch: share+share_overlay is active: %r", share) if share['Properties'] is not None: all_props_with_remove = cast(Dict[str, Optional[str]], radicale_item.check_and_sanitize_props(share['Properties'])) else: all_props_with_remove = {} all_props_with_remove.update(props_with_remove) all_props = radicale_item.check_and_sanitize_props(all_props_with_remove) - logger.debug("TRACE/PROPPATCH/xml_proppatch: share+share_overlay result: %r", all_props) + logger.trace("PROPPATCH/xml_proppatch: share+share_overlay result: %r", all_props) else: if collection is not None: # always the case, but makes mypy happy @@ -115,11 +114,10 @@ class ApplicationPartProppatch(ApplicationBase): access = Access(self._rights, user, path, permissions_filter) raw_permissions = self._rights.authorization(user, path) if not access.check("w"): - logger.debug("TRACE/PROPPATCH/xml_proppatch: no native write-access: %r", path) + logger.trace("PROPPATCH/xml_proppatch: no native write-access: %r", path) if share: # priority share->rights->global - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/PROPPATCH/share: raw_permissions=%r share[Permissions]=%r permit_properties_overlay=%s enforce_properties_overlay=%s", raw_permissions, share['Permissions'], self._sharing.permit_properties_overlay, self._sharing.enforce_properties_overlay) + logger.trace("PROPPATCH/share: raw_permissions=%r share[Permissions]=%r permit_properties_overlay=%s enforce_properties_overlay=%s", raw_permissions, share['Permissions'], self._sharing.permit_properties_overlay, self._sharing.enforce_properties_overlay) if ("P" in share['Permissions'] or ("P" in raw_permissions and "p" not in share['Permissions']) or (self._sharing.permit_properties_overlay and "p" not in raw_permissions and "p" not in share['Permissions']) @@ -140,10 +138,10 @@ class ApplicationPartProppatch(ApplicationBase): else: return httputils.NOT_ALLOWED else: - logger.debug("TRACE/PROPPATCH/xml_proppatch: write-access: %r", path) + logger.trace("PROPPATCH/xml_proppatch: write-access: %r", path) if share: # write access -> check for enforced properties overlay - logger.debug("TRACE/PROPPATCH/xml_proppatch: write-access/sharing: %r", path_orig) + logger.trace("PROPPATCH/xml_proppatch: write-access/sharing: %r", path_orig) if self._sharing.enforce_properties_overlay: if permissions_filter is not None and "e" in permissions_filter: logger.info("PROPPATCH request on shared %r: write-permissions, overlay enforced, but disabled by share permission 'e'", path_orig) diff --git a/radicale/app/report.py b/radicale/app/report.py index dba007be..030e8bae 100644 --- a/radicale/app/report.py +++ b/radicale/app/report.py @@ -25,7 +25,6 @@ import contextlib import copy import datetime -import logging import posixpath import socket import xml.etree.ElementTree as ET @@ -157,14 +156,12 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], Read rfc3253-3.6 for info. """ - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: base_prefix=%r path=%r", base_prefix, path) + logger.trace("REPORT/xml_report: base_prefix=%r path=%r", base_prefix, path) share_bday_automap = False if share and share['Conversion'] == "bday": share_bday_automap = True - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report(1): share=%r", share) + logger.trace("REPORT/xml_report(1): share=%r", share) multistatus = ET.Element(xmlutils.make_clark("D:multistatus")) if xml_request is None: @@ -246,8 +243,7 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], filter_copy = copy.deepcopy(filter_) if expand is not None: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: expand") + logger.trace("REPORT/xml_report: expand") for comp_filter in filter_copy.findall(".//" + xmlutils.make_clark("C:comp-filter")): if comp_filter.get("name", "").upper() == "VCALENDAR": continue @@ -276,10 +272,9 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], item_ics.href = item.href retrieved_items_vcf_to_ics.append((item_ics, flag)) retrieved_items = retrieved_items_vcf_to_ics - logging.debug("TRACE/REPORT/retrieved_items: %r", retrieved_items) + logger.trace("REPORT/retrieved_items: %r", retrieved_items) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report(2): share=%r", share) + logger.trace("REPORT/xml_report(2): share=%r", share) n_vevents = 0 while retrieved_items: @@ -348,16 +343,13 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element], n_vevents += n_vev if prop.tag == xmlutils.make_clark("D:getetag"): if n_vev > 0: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: getetag/expanded element") + logger.trace("REPORT/xml_report: getetag/expanded element") element.text = item.etag found_props.append(element) else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: getetag/no expanded element") + logger.trace("REPORT/xml_report: getetag/no expanded element") else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: default") + logger.trace("REPORT/xml_report: default") found_props.append(expanded_element) else: if prop.tag == xmlutils.make_clark("D:getetag"): @@ -736,8 +728,7 @@ def xml_item_response(base_prefix: str, href: str, response = ET.Element(xmlutils.make_clark("D:response")) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_item_response: found=%s share=%r", found_item, share) + logger.trace("REPORT/xml_item_response: found=%s share=%r", found_item, share) share_bday_automap = False if share and share['Conversion'] == "bday": @@ -745,16 +736,14 @@ def xml_item_response(base_prefix: str, href: str, href_element = ET.Element(xmlutils.make_clark("D:href")) href_element.text = xmlutils.make_href(base_prefix, href) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: href=%r", href_element.text) + logger.trace("REPORT/xml_report: href=%r", href_element.text) if share: # backmap if href_element.text.startswith(share['PathMapped']): href_element.text = str(share['PathOrToken']) + href_element.text.removeprefix(share['PathMapped']) if share_bday_automap and href_element.text.endswith(".vcf"): href_element.text = href_element.text.removesuffix(".vcf") + ".ics" - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: href=%r (backmapped)", href_element.text) + logger.trace("REPORT/xml_report: href=%r (backmapped)", href_element.text) response.append(href_element) if found_item: @@ -793,8 +782,7 @@ def retrieve_items( gets set to ``True``.""" nonlocal collection_requested for hreference in hreferences: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: hreference=%r", hreference) + logger.trace("REPORT/xml_report: hreference=%r", hreference) if share: # map back to owner if hreference.startswith(share['PathOrToken']): @@ -802,8 +790,7 @@ def retrieve_items( if share['Conversion'] == "bday": if hreference.endswith(".ics"): hreference = hreference.removesuffix(".ics") + ".vcf" - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/xml_report: hreference=%r (backmapped)", hreference) + logger.trace("REPORT/xml_report: hreference=%r (backmapped)", hreference) try: name = pathutils.name_from_path(hreference, collection) except ValueError as e: @@ -828,8 +815,7 @@ def retrieve_items( else: yield item, False if collection_requested: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/REPORT/retrieve_items: get_filtered") + logger.trace("REPORT/retrieve_items: get_filtered") yield from collection.get_filtered(filters) diff --git a/radicale/config.py b/radicale/config.py index 594bee29..f7179bad 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -37,7 +37,8 @@ from configparser import RawConfigParser from typing import (Any, Callable, ClassVar, Iterable, List, Optional, Sequence, Tuple, TypeVar, Union) -from radicale import auth, hook, rights, sharing, storage, types, utils, web +from radicale import (auth, hook, log, rights, sharing, storage, types, utils, + web) from radicale.hook import email from radicale.item import check_and_sanitize_props @@ -78,7 +79,7 @@ def rights_permission(value: Any) -> str: def logging_level(value: Any) -> str: - if value not in ("debug", "info", "warning", "error", "critical"): + if value not in log.LOG_LEVEL_OPTIONS: raise ValueError("unsupported level: %r" % value) return value @@ -622,13 +623,9 @@ This is an automated message. Please do not reply.""", "value": str(utils.DEFAULT_LIMIT_CONTENT), "help": "limit content of wrapped text (chars)", "type": positive_int}), - ("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/'", + "help": "filter trace messages starting with ''", "type": str}), ("bad_put_request_content", { "value": "False", diff --git a/radicale/item/__init__.py b/radicale/item/__init__.py index cef24d15..edbe008d 100644 --- a/radicale/item/__init__.py +++ b/radicale/item/__init__.py @@ -27,7 +27,6 @@ Module for address books and calendar entries (see ``Item``). import binascii import contextlib import datetime -import logging import math import os import re @@ -506,32 +505,26 @@ class Item: self._vobject_item = orig_vobject_item def convert_vcf_to_ics(self) -> Union["Item", None]: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: convert VCF to ICS (href): %r", self.href) - logger.debug("TRACE/item/convert_vcf_to_ics: convert VCF to ICS (vobject): %r", self.vobject_item) + logger.trace("item/convert_vcf_to_ics: convert VCF to ICS (href): %r", self.href) + logger.trace("item/convert_vcf_to_ics: convert VCF to ICS (vobject): %r", self.vobject_item) if self.vobject_item.name != "VCARD": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: item is not a VCARD (skip): %r", self.href) + logger.trace("item/convert_vcf_to_ics: item is not a VCARD (skip): %r", self.href) return None else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: item is a VCARD (ok): %r", self.href) + logger.trace("item/convert_vcf_to_ics: item is a VCARD (ok): %r", self.href) if not hasattr(self.vobject_item, "bday"): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: miss bday (skip): %r", self.href) + logger.trace("item/convert_vcf_to_ics: miss bday (skip): %r", self.href) return None else: pass bday = self.vobject_item.bday - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: has bday (ok): %r -> %r", self.href, bday.value) + logger.trace("item/convert_vcf_to_ics: has bday (ok): %r -> %r", self.href, bday.value) pattern = re.compile('^([0-9]{4})-?([0-9]{2})-?([0-9]{2})$') match = pattern.match(bday.value) if not match: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: has unsupported bday: %r -> %r", self.href, bday.value) + logger.trace("item/convert_vcf_to_ics: has unsupported bday: %r -> %r", self.href, bday.value) return None else: pass @@ -550,8 +543,7 @@ class Item: elif hasattr(self.vobject_item, "nickname"): name = self.vobject_item.nickname.value else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/item/convert_vcf_to_ics: has bday but neither FN or N or NICKNAME (skip): %r", self.href) + logger.trace("item/convert_vcf_to_ics: has bday but neither FN or N or NICKNAME (skip): %r", self.href) return None # create VCALENDAR @@ -612,10 +604,9 @@ class Item: href=href, vobject_item=item_ics) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/storage: item generated/vobject: %r", item_ics.serialize()) - logger.debug("TRACE/storage: item orig /etag : %r", self.etag) - logger.debug("TRACE/storage: item generated/etag : %r", item_new.etag) - logger.debug("TRACE/storage: item generated/href : %r", item_new.href) + logger.trace("storage: item generated/vobject: %r", item_ics.serialize()) + logger.trace("storage: item orig /etag : %r", self.etag) + logger.trace("storage: item generated/etag : %r", item_new.etag) + logger.trace("storage: item generated/href : %r", item_new.href) return item_new diff --git a/radicale/item/filter.py b/radicale/item/filter.py index a1329988..5f990075 100644 --- a/radicale/item/filter.py +++ b/radicale/item/filter.py @@ -99,7 +99,7 @@ def comp_match(item: "item.Item", filter_: ET.Element, level: int = 0) -> bool: # HACK: the filters are tested separately against all components name = filter_.get("name", "").upper() - logger.debug("TRACE/ITEM/FILTER/comp_match: name=%s level=%d", name, level) + logger.trace("ITEM/FILTER/comp_match: name=%s level=%d", name, level) if level == 0: tag = item.name @@ -144,12 +144,12 @@ def comp_match(item: "item.Item", filter_: ET.Element, level: int = 0) -> bool: trigger = subcomp.trigger.value for child in filter_: if child.tag == xmlutils.make_clark("C:prop-filter"): - logger.debug("TRACE/ITEM/FILTER/comp_match: prop-filter level=%d", level) + logger.trace("ITEM/FILTER/comp_match: prop-filter level=%d", level) if not any(prop_match(comp, child, "C") for comp in components): return False elif child.tag == xmlutils.make_clark("C:time-range"): - logger.debug("TRACE/ITEM/FILTER/comp_match: time-range level=%d tag=%s", level, tag) + logger.trace("ITEM/FILTER/comp_match: time-range level=%d tag=%s", level, tag) if (level == 0) and (name == "VCALENDAR"): for name_try in ("VTODO", "VEVENT", "VJOURNAL"): try: @@ -161,7 +161,7 @@ def comp_match(item: "item.Item", filter_: ET.Element, level: int = 0) -> bool: if not time_range_match(item.vobject_item, filter_[0], tag, trigger): return False elif child.tag == xmlutils.make_clark("C:comp-filter"): - logger.debug("TRACE/ITEM/FILTER/comp_match: comp-filter level=%d", level) + logger.trace("ITEM/FILTER/comp_match: comp-filter level=%d", level) if not comp_match(item, child, level=level + 1): return False else: @@ -246,7 +246,7 @@ def time_range_match(vobject_item: vobject.base.Component, def infinity_fn(start: datetime) -> bool: return False - logger.debug("TRACE/ITEM/FILTER/time_range_match: start=(%s) end=(%s) child_name=%s", start, end, child_name) + logger.trace("ITEM/FILTER/time_range_match: start=(%s) end=(%s) child_name=%s", start, end, child_name) visit_time_ranges(vobject_item, child_name, range_fn, infinity_fn) return matched @@ -303,7 +303,7 @@ def visit_time_ranges(vobject_item: vobject.base.Component, child_name: str, # recurrences too. This is not respected and client don't seem to bother # either. - logger.debug("TRACE/ITEM/FILTER/visit_time_ranges: child_name=%s", child_name) + logger.trace("ITEM/FILTER/visit_time_ranges: child_name=%s", child_name) def getrruleset(child: vobject.base.Component, ignore: Sequence[date] ) -> Tuple[Iterable[date], bool]: @@ -378,11 +378,11 @@ def visit_time_ranges(vobject_item: vobject.base.Component, child_name: str, if dtstart.tzinfo is None and dtend.tzinfo is not None: dtstart_orig = dtstart dtstart = date_to_datetime(dtstart, dtend.astimezone().tzinfo) - logger.debug("TRACE/ITEM/FILTER/get_children: overtake missing tzinfo on dtstart from dtend: '%s' -> '%s'", dtstart_orig, dtstart) + logger.trace("ITEM/FILTER/get_children: overtake missing tzinfo on dtstart from dtend: '%s' -> '%s'", dtstart_orig, dtstart) elif dtstart.tzinfo is not None and dtend.tzinfo is None: dtend_orig = dtend dtend = date_to_datetime(dtend, dtstart.astimezone().tzinfo) - logger.debug("TRACE/ITEM/FILTER/get_children: overtake missing tzinfo on dtend from dtstart: '%s' -> '%s'", dtend_orig, dtend) + logger.trace("ITEM/FILTER/get_children: overtake missing tzinfo on dtend from dtstart: '%s' -> '%s'", dtend_orig, dtend) original_duration = (dtend - dtstart).total_seconds() dtend = date_to_datetime(dtend) @@ -550,7 +550,7 @@ def visit_time_ranges(vobject_item: vobject.base.Component, child_name: str, else: # Match a property - logger.debug("TRACE/ITEM/FILTER/get_children: child_name=%s property match", child_name) + logger.trace("ITEM/FILTER/get_children: child_name=%s property match", child_name) child = getattr(vobject_item, child_name.lower()) if isinstance(child.value, date): child_is_datetime = isinstance(child.value, datetime) @@ -640,7 +640,7 @@ def simplify_prefilters(filters: Iterable[ET.Element], collection_tag: str """ flat_filters = list(chain.from_iterable(filters)) simple = len(flat_filters) <= 1 - logger.debug("TRACE/ITEM/FILTER/simplify_prefilters: collection_tag=%s", collection_tag) + logger.trace("ITEM/FILTER/simplify_prefilters: collection_tag=%s", collection_tag) for col_filter in flat_filters: if collection_tag != "VCALENDAR": simple = False @@ -651,14 +651,14 @@ def simplify_prefilters(filters: Iterable[ET.Element], collection_tag: str continue simple &= len(col_filter) <= 1 for comp_filter in col_filter: - logger.debug("TRACE/ITEM/FILTER/simplify_prefilters: filter.tag=%s simple=%s", comp_filter.tag, simple) + logger.trace("ITEM/FILTER/simplify_prefilters: filter.tag=%s simple=%s", comp_filter.tag, simple) if comp_filter.tag == xmlutils.make_clark("C:time-range") and simple is True: # time-filter found on level 0 start, end = time_range_timestamps(comp_filter) - logger.debug("TRACE/ITEM/FILTER/simplify_prefilters: found time-filter on level 0 start=%r(%d) end=%r(%d) simple=%s", format_ut(start), start, format_ut(end), end, simple) + logger.trace("ITEM/FILTER/simplify_prefilters: found time-filter on level 0 start=%r(%d) end=%r(%d) simple=%s", format_ut(start), start, format_ut(end), end, simple) return None, start, end, simple if comp_filter.tag != xmlutils.make_clark("C:comp-filter"): - logger.debug("TRACE/ITEM/FILTER/simplify_prefilters: no comp-filter on level 0") + logger.trace("ITEM/FILTER/simplify_prefilters: no comp-filter on level 0") simple = False continue tag = comp_filter.get("name", "").upper() @@ -675,7 +675,7 @@ def simplify_prefilters(filters: Iterable[ET.Element], collection_tag: str simple = False continue start, end = time_range_timestamps(time_filter) - logger.debug("TRACE/ITEM/FILTER/simplify_prefilters: found time-filter on level 1 tag=%s start=%d end=%d simple=%s", tag, start, end, simple) + logger.trace("ITEM/FILTER/simplify_prefilters: found time-filter on level 1 tag=%s start=%d end=%d simple=%s", tag, start, end, simple) return tag, start, end, simple return tag, TIMESTAMP_MIN, TIMESTAMP_MAX, simple return None, TIMESTAMP_MIN, TIMESTAMP_MAX, simple diff --git a/radicale/log.py b/radicale/log.py index 7f7df5e3..408f7f62 100644 --- a/radicale/log.py +++ b/radicale/log.py @@ -35,8 +35,9 @@ import struct import sys import threading import time -from typing import (Any, Callable, ClassVar, Dict, Iterator, Mapping, Optional, - Tuple, Union, cast) +from functools import partial, partialmethod +from typing import (TYPE_CHECKING, Any, Callable, ClassVar, Dict, Iterator, + Mapping, Optional, Tuple, Union, cast) from radicale import types @@ -47,34 +48,69 @@ LOGGER_FORMATS: Mapping[str, str] = { } DATE_FORMAT: str = "%Y-%m-%d %H:%M:%S %z" -logger: logging.Logger = logging.getLogger(LOGGER_NAME) +LOG_LEVEL_OPTIONS: list = ["trace", "debug", "info", "notice", "warning", "error", "critical", "alert"] + +LOG_LEVEL_TRACE: int = 5 +LOG_LEVEL_NOTICE: int = 25 +LOG_LEVEL_ALERT: int = 55 + +logging.addLevelName(LOG_LEVEL_TRACE, "TRACE") +logging.addLevelName(LOG_LEVEL_NOTICE, "NOTICE") +logging.addLevelName(LOG_LEVEL_ALERT, "ALERT") + +setattr(logging, "TRACE", LOG_LEVEL_TRACE) +setattr(logging, "NOTICE", LOG_LEVEL_NOTICE) +setattr(logging, "ALERT", LOG_LEVEL_ALERT) + +logging.__all__ += ['TRACE', 'NOTICE', 'ALERT'] + +setattr(logging, "trace", partial(logging.log, LOG_LEVEL_TRACE)) +setattr(logging, "notice", partial(logging.log, LOG_LEVEL_NOTICE)) +setattr(logging, "alert", partial(logging.log, LOG_LEVEL_ALERT)) + +setattr(logging.getLoggerClass(), "trace", partialmethod(logging.Logger.log, LOG_LEVEL_TRACE)) +setattr(logging.getLoggerClass(), "notice", partialmethod(logging.Logger.log, LOG_LEVEL_NOTICE)) +setattr(logging.getLoggerClass(), "alert", partialmethod(logging.Logger.log, LOG_LEVEL_ALERT)) + + +class RadicaleLogger(logging.Logger): + if TYPE_CHECKING: + pass + # reuse similar types + trace = logging.Logger.debug + notice = logging.Logger.info + alert = logging.Logger.critical + else: + def trace(self, msg, *args, **kwargs): + if self.isEnabledFor(LOG_LEVEL_TRACE): + self._log(LOG_LEVEL_TRACE, msg, args, **kwargs) + + def notice(self, msg, *args, **kwargs): + if self.isEnabledFor(LOG_LEVEL_NOTICE): + self._log(LOG_LEVEL_NOTICE, msg, args, **kwargs) + + def alert(self, msg, *args, **kwargs): + if self.isEnabledFor(LOG_LEVEL_ALERT): + self._log(LOG_LEVEL_ALERT, msg, args, **kwargs) + + +logger = cast(RadicaleLogger, logging.getLogger(LOGGER_NAME)) class RemoveTracebackFilter(logging.Filter): - def filter(self, record: logging.LogRecord) -> bool: record.exc_info = None 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): + if record.levelno == LOG_LEVEL_TRACE: + if record.msg.startswith(self.trace_filter): return True else: return False @@ -84,8 +120,6 @@ class PassTRACETOKENFilter(logging.Filter): REMOVE_TRACEBACK_FILTER: logging.Filter = RemoveTracebackFilter() -REMOVE_TRACE_FILTER: logging.Filter = RemoveTRACEFilter() - class IdentLogRecordFactory: """LogRecordFactory that adds ``ident`` attribute.""" @@ -191,11 +225,14 @@ class ThreadedStreamHandler(logging.Handler): return False self._journal_socket = journal_socket - priority = {"DEBUG": 7, + priority = {"TRACE": 7, + "DEBUG": 7, "INFO": 6, + "NOTICE": 5, "WARNING": 4, "ERROR": 3, - "CRITICAL": 2}.get(record.levelname, 4) + "CRITICAL": 2, + "ALERT": 1}.get(record.levelname, 4) timestamp = time.strftime("%Y-%m-%dT%H:%M:%S.%%03dZ", time.gmtime(record.created)) % record.msecs data = {"PRIORITY": priority, @@ -258,7 +295,7 @@ logger_display_backtrace_disabled: bool = False logger_display_backtrace_enabled: bool = False -def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_on_debug: bool = False, trace_filter: str = "") -> None: +def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_filter: str = "") -> None: """Set logging level for global logger.""" global logger_display_backtrace_disabled global logger_display_backtrace_enabled @@ -266,6 +303,7 @@ def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_on_debug: level = getattr(logging, level.upper()) assert isinstance(level, int) logger.setLevel(level) + logger.log(level, "Logging level set to: %r", logging.getLevelName(level)) if level > logging.DEBUG: if logger_display_backtrace_disabled is False: logger.info("Logging of backtrace is disabled in this loglevel") @@ -282,14 +320,9 @@ def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_on_debug: 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) + if level < logging.DEBUG: + if trace_filter != "": + logger.trace("Logging messages on 'trace' level enabled but filtered by prefix: %r", trace_filter) + logger.addFilter(PassTRACETOKENFilter(trace_filter)) else: - logger.debug("Logging messages starting with 'TRACE' disabled") - logger.addFilter(REMOVE_TRACE_FILTER) + logger.trace("Logging messages on 'trace' level enabled") diff --git a/radicale/server.py b/radicale/server.py index 1dc3dee4..8df83ab2 100644 --- a/radicale/server.py +++ b/radicale/server.py @@ -341,8 +341,6 @@ def serve(configuration: config.Configuration, max_connections: int = configuration.get("server", "max_connections") logger.info("Maximum parallel connections: %d", 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 diff --git a/radicale/sharing/__init__.py b/radicale/sharing/__init__.py index 9c0bf99e..dc926022 100644 --- a/radicale/sharing/__init__.py +++ b/radicale/sharing/__init__.py @@ -18,7 +18,6 @@ import base64 import io import json -import logging import re import socket import uuid @@ -362,8 +361,7 @@ class BaseSharing: sharing_collection_list = [] if not self.sharing_collection_by_map: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map: not active") + logger.trace("sharing/map: not active") else: # retrieve collections depending on filter sharing_collection_list += self.database_list_sharing( @@ -382,7 +380,7 @@ class BaseSharing: # resolves a path to a share def sharing_collection_resolver(self, path: str, user: str) -> Union[dict, None]: """ returning dict with PathMapped, Owner, Permissions or None if not found""" - logger.debug("TRACE/sharing/resolver: lookup path=%r user=%r", path, user) + logger.trace("sharing/resolver: lookup path=%r user=%r", path, user) share = None if path == "/": @@ -395,8 +393,7 @@ class BaseSharing: if share is not None and 'error' in share: return None else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token: not active") + logger.trace("sharing/token: not active") if self.sharing_collection_by_map: if share is None: @@ -404,23 +401,21 @@ class BaseSharing: if share is not None and 'error' in share: return None else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map: not active") + logger.trace("sharing/map: not active") return share # adjust a share def sharing_collection_update(self, ShareType: str, PathOrToken: str, OwnerOrUser: str, Properties: dict) -> None: """ returning dict with PathMapped, Owner, Permissions or None if not found""" - logger.info("Sharing/collection/update: ShareType=%r PathOrToken=%r OwnerOrUser=%r", ShareType, PathOrToken, OwnerOrUser) + logger.info("sharing/collection/update: ShareType=%r PathOrToken=%r OwnerOrUser=%r", ShareType, PathOrToken, OwnerOrUser) # Filter properies for permitted ones properties_filtered: dict = {} for prop in Properties: if prop in OVERLAY_PROPERTIES_WHITELIST: properties_filtered[prop] = Properties[prop] else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/collection_update: silent discard unsupported property: %r", prop) + logger.trace("sharing/collection_update: silent discard unsupported property: %r", prop) self.database_update_sharing(ShareType=ShareType, PathOrToken=PathOrToken, @@ -435,51 +430,43 @@ class BaseSharing: def sharing_collection_by_token_resolver(self, path) -> Union[dict, None]: """ returning dict with PathMapped, Owner, Permissions or None if invalid""" if self.sharing_collection_by_token: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/resolver: check path: %r", path) + logger.trace("sharing/token/resolver: check path: %r", path) if path.startswith("/.token/"): pattern = re.compile('^(/\\.token/' + TOKEN_PATTERN_V1 + '/)$') match = pattern.match(path) if not match: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/resolver: unsupported token: %r", path) + logger.trace("sharing/token/resolver: unsupported token: %r", path) return {'error': 'token-not-supported'} else: # TODO add token validity checks - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/resolver: supported token: %r", path) + logger.trace("sharing/token/resolver: supported token: %r", path) result = self.database_get_sharing( ShareType="token", OnlyEnabled=False, PathOrToken=match[1]) if result is None: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/resolver: supported token not found: %r", path) + logger.trace("sharing/token/resolver: supported token not found: %r", path) return {'error': 'token-not-found'} if result['EnabledByOwner'] is not True: - logger.info("Sharing/%s: resolved path %r->%r, User=%r not enabled by owner", "token", path, result['PathMapped'], result['Owner']) + logger.info("sharing/%s: resolved path %r->%r, User=%r not enabled by owner", "token", path, result['PathMapped'], result['Owner']) return {'error': 'token-not-enabled'} - logger.info("Sharing/%s: resolved %r->%r, User=%r, Permissions=%r Conversion=%r", "token", path, result['PathMapped'], result['Owner'], result['Permissions'], result['Conversion']) + logger.info("sharing/%s: resolved %r->%r, User=%r, Permissions=%r Conversion=%r", "token", path, result['PathMapped'], result['Owner'], result['Permissions'], result['Conversion']) return result else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/resolver: no supported prefix found in path: %r", path) + logger.trace("sharing/token/resolver: no supported prefix found in path: %r", path) return None else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token: not active") + logger.trace("sharing/token: not active") return None # resolves a map "path" to a share def sharing_collection_by_map_resolver(self, path: str, user: str) -> Union[dict, None]: """ returning dict with PathMapped, Owner, Permissions or None if invalid""" if self.sharing_collection_by_map: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map/resolver: check path: %r", path) - + logger.trace("sharing/map/resolver: check path: %r", path) result = self.database_get_sharing( ShareType="map", PathOrToken=path, @@ -489,8 +476,7 @@ class BaseSharing: if not result: # fallback to parent path parent_path = pathutils.parent_path(path) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map/resolver: check parent path: %r", parent_path) + logger.trace("sharing/map/resolver: check parent path: %r", parent_path) result = self.database_get_sharing( ShareType="map", PathOrToken=parent_path, @@ -498,28 +484,25 @@ class BaseSharing: User=user) if result: result['PathMapped'] = path.replace(parent_path, result['PathMapped']) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map/resolver: PathMapped=%r Permissions=%r by parent_path=%r", result['PathMapped'], result['Permissions'], parent_path) + logger.trace("sharing/map/resolver: PathMapped=%r Permissions=%r by parent_path=%r", result['PathMapped'], result['Permissions'], parent_path) else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map/resolver: not found") + logger.trace("sharing/map/resolver: not found") return None if result: if result['EnabledByOwner'] is not True: - logger.info("Sharing/%s: resolved path %r->%r, user %r->%r not enabled by owner", "map", path, result['PathMapped'], user, result['Owner']) + logger.info("sharing/%s: resolved path %r->%r, user %r->%r not enabled by owner", "map", path, result['PathMapped'], user, result['Owner']) return {'error': 'map-not-enabled'} if result['EnabledByUser'] is not True: - logger.info("Sharing/%s: resolved path %r->%r, user %r->%r not enabled by user", "map", path, result['PathMapped'], user, result['Owner']) + logger.info("sharing/%s: resolved path %r->%r, user %r->%r not enabled by user", "map", path, result['PathMapped'], user, result['Owner']) return {'error': 'map-not-enabled'} - logger.info("Sharing/%s: resolved path %r->%r, user %r->%r, Permissions=%r Conversion=%r", "map", path, result['PathMapped'], user, result['Owner'], result['Permissions'], result['Conversion']) + logger.info("sharing/%s: resolved path %r->%r, user %r->%r, Permissions=%r Conversion=%r", "map", path, result['PathMapped'], user, result['Owner'], result['Permissions'], result['Conversion']) return result return None else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map: not active") + logger.trace("sharing/map: not active") return None # *** POST API *** @@ -570,7 +553,7 @@ class BaseSharing: """ # initial log prefix - api_info = "Sharing/API/POST" + api_info = "sharing/API/POST" if not self._enabled: # API is not enabled @@ -590,8 +573,7 @@ class BaseSharing: ShareType_action = path.removeprefix("/.sharing/v1/") match = re.search('([a-z]+)/([a-z]+)$', ShareType_action) if not match: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: ShareType/action not extractable: %r", ShareType_action) + logger.trace("sharing/API: ShareType/action not extractable: %r", ShareType_action) return httputils.NOT_FOUND else: ShareType = match.group(1) @@ -603,8 +585,7 @@ class BaseSharing: # check for valid ShareTypes if ShareType: if ShareType not in SHARE_TYPES: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: ShareType not whitelisted: %r", ShareType) + logger.trace("sharing/API: ShareType not whitelisted: %r", ShareType) return httputils.NOT_FOUND # check for enabled ShareTypes @@ -620,15 +601,13 @@ class BaseSharing: # check for valid API hooks if action not in API_HOOKS_V1: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: action not whitelisted: %r", action) + logger.trace("sharing/API: action not whitelisted: %r", action) return httputils.NOT_FOUND # append action api_info = api_info + "/" + action - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: called by authenticated user: %r", user) + logger.trace("sharing/API: called by authenticated user: %r", user) # read POST data try: request_body = httputils.read_request_body(self.configuration, environ) @@ -654,8 +633,7 @@ class BaseSharing: if type(request_data[key]) is not bool: logger.warning(api_info + ": unsupported (non-boolean) " + key + ": " + request_data[key]) return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_data[key]) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + " (json): %r", f"{request_data}") + logger.trace(api_info + " (json): %r", f"{request_data}") elif 'application/x-www-form-urlencoded' in content_type: input_format = "form" output_format = "plain" # default @@ -667,8 +645,7 @@ class BaseSharing: # Properties key value parser properties_dict: dict = {} for entry in request_parsed[key]: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: parse property %r", entry) + logger.trace("sharing/API: parse property %r", entry) if entry == "": continue m = re.search('^([^=]+)=([^=]+)$', entry) @@ -677,8 +654,7 @@ class BaseSharing: token = m.group(1).lstrip('"\'').rstrip('"\'') value = m.group(2).lstrip('"\'').rstrip('"\'') properties_dict[token] = value - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API: converted Properties from form into dict: %r", properties_dict) + logger.trace("sharing/API: converted Properties from form into dict: %r", properties_dict) request_data[key] = properties_dict if len(request_data[key]) == 0: # empty @@ -691,11 +667,9 @@ class BaseSharing: return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_parsed[key][0]) else: request_data[key] = request_parsed[key][0] - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + " (form): %r", f"{request_data}") + logger.trace("" + api_info + " (form): %r", f"{request_data}") else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": no supported content data") + logger.trace("" + api_info + ": no supported content data") return httputils.bad_request("Content-type not supported") # check for requested output type @@ -840,12 +814,10 @@ class BaseSharing: # action: list if action == "list": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": start") + logger.trace("" + api_info + ": start") if PathOrToken is not None: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": filter: %r", PathOrToken) + logger.trace("" + api_info + ": filter: %r", PathOrToken) if ShareType != "all": result_array = self.database_list_sharing( @@ -874,8 +846,7 @@ class BaseSharing: # action: create elif action == "create": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": start") + logger.trace("" + api_info + ": start") if PathMapped is None: logger.warning(api_info + ": missing PathMapped") @@ -955,8 +926,7 @@ class BaseSharing: # v1: create uuid token with 2x 16 bytes + separator = 264 bit with base64 encoding resulting in 56 chars without '=' padding token = "/.token/v1/" + str(base64.urlsafe_b64encode(uuid.uuid4().bytes + b"\0" + uuid.uuid4().bytes), 'utf-8') + "/" - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": %r (Permissions=%r token=%r)", PathMapped, Permissions, token) + logger.trace("" + api_info + ": %r (Permissions=%r token=%r)", PathMapped, Permissions, token) result = self.database_create_sharing( ShareType=ShareType, @@ -975,8 +945,7 @@ class BaseSharing: Actions=Actions, ) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": result=%r", result) + logger.trace("" + api_info + ": result=%r", result) elif ShareType == "map": # check preconditions @@ -1031,8 +1000,7 @@ class BaseSharing: logger.warning(api_info + ": PathOrToken=%r already exists as real collection for User=%r", PathOrToken, User) return httputils.CONFLICT - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": %r (Permissions=%r PathOrToken=%r Owner=%r User=%r)", PathMapped, Permissions, PathOrToken, user, User) + logger.trace("" + api_info + ": %r (Permissions=%r PathOrToken=%r Owner=%r User=%r)", PathMapped, Permissions, PathOrToken, user, User) result = self.database_create_sharing( ShareType=ShareType, @@ -1054,8 +1022,7 @@ class BaseSharing: else: logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) return httputils.bad_request("Invalid share type") - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": result=%r", result) + logger.trace("" + api_info + ": result=%r", result) # result handling if result['status'] == "conflict": return httputils.CONFLICT @@ -1078,8 +1045,7 @@ class BaseSharing: # action: update elif action == "update": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": start") + logger.trace("" + api_info + ": start") if ShareType not in SHARE_TYPES_V1: logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) @@ -1105,17 +1071,14 @@ class BaseSharing: elif share['Properties'] is not None: # replace properties for prop in share['Properties']: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": check for existing property %r", prop) + logger.trace("" + api_info + ": check for existing property %r", prop) if prop not in Properties: # overtake - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": overtake property %r", prop) + logger.trace("" + api_info + ": overtake property %r", prop) Properties[prop] = share['Properties'][prop] elif Properties[prop] == '': # unset, do nothing - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": clear property %r", prop) + logger.trace("" + api_info + ": clear property %r", prop) del Properties[prop] if user == share['Owner']: @@ -1160,8 +1123,7 @@ class BaseSharing: logger.warning(api_info + ": access to %r not allowed for user %r to adjust anything beside: %s", PathOrToken, user, " ".join(DB_FIELDS_V1_USER_PERMITTED)) return httputils.NOT_ALLOWED if 'Properties' in request_data: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API/update: permit_properties_overlay=%s Permissions=%r", self.permit_properties_overlay, share['Permissions']) + logger.trace("sharing/API/update: permit_properties_overlay=%s Permissions=%r", self.permit_properties_overlay, share['Permissions']) if self.permit_properties_overlay: if share['Permissions'] is not None and "p" in str(share['Permissions']): logger.warning(api_info + ": %r properties overlay permitted by option, but denied by permission 'p'", PathOrToken) @@ -1204,8 +1166,7 @@ class BaseSharing: # action: delete elif action == "delete": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/" + api_info + ": start") + logger.trace("" + api_info + ": start") if ShareType not in SHARE_TYPES_V1: logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) @@ -1260,8 +1221,7 @@ class BaseSharing: # action: TOGGLE elif action in API_SHARE_TOGGLES_V1: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API/POST/" + action) + logger.trace("sharing/API/POST/" + action) if ShareType not in SHARE_TYPES_V1: logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) @@ -1338,9 +1298,8 @@ class BaseSharing: return httputils.bad_request("Invalid action") # output handler - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/API/POST output format: %r", output_format) - logger.debug("TRACE/sharing/API/POST answer: %r", answer) + logger.trace("sharing/API/POST output format: %r", output_format) + logger.trace("sharing/API/POST answer: %r", answer) if output_format == "csv" or output_format == "plain": answer_array = [] if output_format == "plain": diff --git a/radicale/sharing/csv.py b/radicale/sharing/csv.py index ccfd448c..d045d585 100644 --- a/radicale/sharing/csv.py +++ b/radicale/sharing/csv.py @@ -17,7 +17,6 @@ import csv import json -import logging import os from typing import Union @@ -97,8 +96,7 @@ class Sharing(sharing.BaseSharing): User: Union[str, None] = None) -> Union[dict, None]: """ retrieve sharing target and attributes by map """ # Lookup - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing: lookup ShareType=%r PathOrToken=%r User=%r OnlyEnabled=%s)", ShareType, PathOrToken, User, OnlyEnabled) + logger.trace("sharing: lookup ShareType=%r PathOrToken=%r User=%r OnlyEnabled=%s)", ShareType, PathOrToken, User, OnlyEnabled) index = 0 found = False @@ -107,8 +105,7 @@ class Sharing(sharing.BaseSharing): # skip fieldnames pass else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing: check row: %r", row) + logger.trace("sharing: check row: %r", row) if row['ShareType'] != ShareType: pass elif row['PathOrToken'] != PathOrToken: @@ -174,33 +171,27 @@ class Sharing(sharing.BaseSharing): result = [] with self._storage.acquire_lock("r", path=self._sharing_db_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/called: ShareType=%r OwnerOrUser=%r User=%r PathOrToken=%r PathMapped=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s Conversion=%r", ShareType, OwnerOrUser, User, PathOrToken, PathMapped, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser, Conversion) + logger.trace("sharing/list/called: ShareType=%r OwnerOrUser=%r User=%r PathOrToken=%r PathMapped=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s Conversion=%r", ShareType, OwnerOrUser, User, PathOrToken, PathMapped, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser, Conversion) for row in self._sharing_cache: if index == 0: # skip fieldnames pass else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: test: %r", row) + logger.trace("sharing/list/row: test: %r", row) if ShareType is not None and row['ShareType'] != ShareType: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by ShareType") + logger.trace("sharing/list/row: skip by ShareType") pass elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser): pass elif User is not None and row['User'] != User: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by User") + logger.trace("sharing/list/row: skip by User") pass elif PathOrToken is not None and row['PathOrToken'] != PathOrToken: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by PathOrToken") + logger.trace("sharing/list/row: skip by PathOrToken") pass elif PathMapped is not None and row['PathMapped'] != PathMapped: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by PathMapped") + logger.trace("sharing/list/row: skip by PathMapped") pass elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner: pass @@ -213,8 +204,7 @@ class Sharing(sharing.BaseSharing): elif Conversion is not None and row['Conversion'] != Conversion: pass else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: add : %r", row) + logger.trace("sharing/list/row: add : %r", row) result.append(row) index += 1 return result @@ -235,11 +225,9 @@ class Sharing(sharing.BaseSharing): row: dict with self._storage.acquire_lock("w", path=self._sharing_db_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing: ShareType=%r", ShareType) + logger.trace("sharing: ShareType=%r", ShareType) if ShareType == "token": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/token/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions) + logger.trace("sharing/token/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions) # check for duplicate token entry for row in self._sharing_cache: if row['ShareType'] != "token": @@ -249,8 +237,7 @@ class Sharing(sharing.BaseSharing): logger.error("sharing/token/create: PathOrToken already exists: PathOrToken=%r", PathOrToken) return {"status": "conflict"} elif ShareType == "map": - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/map/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions) + logger.trace("sharing/map/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions) # check for duplicate map entry for row in self._sharing_cache: if row['ShareType'] != "map": @@ -279,13 +266,11 @@ class Sharing(sharing.BaseSharing): "Actions": Actions, } - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/*/create: add row: %r", row) + logger.trace("sharing/*/create: add row: %r", row) self._sharing_cache.append(row) if self._write_csv(self._sharing_db_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/create: write CSV done", ShareType) + logger.trace("sharing/%s/create: write CSV done", ShareType) return {"status": "success"} logger.error("sharing/%s/create: cannot update CSV database", ShareType) @@ -308,8 +293,7 @@ class Sharing(sharing.BaseSharing): Actions: Union[dict, None] = None, ) -> dict: """ update sharing """ - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: PathOrToken=%r OwnerOrUser=%r PathMapped=%r Properties=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s", ShareType, PathOrToken, OwnerOrUser, PathMapped, Properties, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser) + logger.trace("sharing/%s/update: PathOrToken=%r OwnerOrUser=%r PathMapped=%r Properties=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s", ShareType, PathOrToken, OwnerOrUser, PathMapped, Properties, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser) with self._storage.acquire_lock("w", path=self._sharing_db_file): # lookup token @@ -329,8 +313,7 @@ class Sharing(sharing.BaseSharing): index += 1 if found: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: orig row[%d]=%r", ShareType, index, row) + logger.trace("sharing/%s/update: orig row[%d]=%r", ShareType, index, row) # CSV: remove+adjust+readd if PathMapped is not None: @@ -356,12 +339,10 @@ class Sharing(sharing.BaseSharing): # update timestamp self._sharing_cache[index]["TimestampUpdated"] = Timestamp - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: adj row[%d]=%r", ShareType, index, self._sharing_cache[index]) + logger.trace("sharing/%s/update: adj row[%d]=%r", ShareType, index, self._sharing_cache[index]) if self._write_csv(self._sharing_db_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: write CSV done", ShareType) + logger.trace("sharing/%s/update: write CSV done", ShareType) return {"status": "success"} logger.error("sharing/%s/update: cannot update CSV database", ShareType) @@ -374,16 +355,14 @@ class Sharing(sharing.BaseSharing): PathOrToken: str, User: str) -> dict: """ delete sharing """ - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken) + logger.trace("sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken) with self._storage.acquire_lock("w", User, path=self._sharing_db_file): # lookup token found = False index = 0 for row in self._sharing_cache: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/delete: check: %r", ShareType, row) + logger.trace("sharing/%s/delete: check: %r", ShareType, row) if index == 0: # skip fieldnames pass @@ -397,15 +376,11 @@ class Sharing(sharing.BaseSharing): index += 1 if found: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/delete: found index=%d", ShareType, index) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/delete: PathOrToken=%r Owner=%r index=%d", ShareType, PathOrToken, row['Owner'], index) + logger.trace("sharing/%s/delete: PathOrToken=%r Owner=%r index=%d", ShareType, PathOrToken, row['Owner'], index) self._sharing_cache.pop(index) if self._write_csv(self._sharing_db_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing_by_token: write CSV done") + logger.trace("sharing/%s/delete: write CSV done", ShareType) return {"status": "success"} logger.error("sharing/%s/delete: cannot update CSV database", ShareType) @@ -440,8 +415,7 @@ class Sharing(sharing.BaseSharing): # convert txt to bool or int if self._lines > 0: for fieldname in row: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/_load: test fieldname=%r", fieldname) + logger.trace("sharing/_load_csv: test fieldname=%r", fieldname) if fieldname not in sharing.DB_TYPES_V1: logger.error("sharing database row error, unsupported fieldname found: %r", fieldname) return False diff --git a/radicale/sharing/files.py b/radicale/sharing/files.py index 06b999d1..8f87745e 100644 --- a/radicale/sharing/files.py +++ b/radicale/sharing/files.py @@ -14,7 +14,6 @@ # You should have received a copy of the GNU General Public License # along with Radicale. If not, see . -import logging import os import pickle import urllib @@ -93,8 +92,7 @@ class Sharing(sharing.BaseSharing): User: Union[str, None] = None) -> Union[dict, None]: """ retrieve sharing target and attributes by map """ # Lookup - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/get: PathOrToken=%r User=%r)", ShareType, PathOrToken, User) + logger.trace("sharing/%s/get: PathOrToken=%r User=%r)", ShareType, PathOrToken, User) sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken)) @@ -132,8 +130,7 @@ class Sharing(sharing.BaseSharing): Conversion = row['Conversion'] if 'Actions' in row: Actions = row['Actions'] - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing: map %r to %r (Owner=%r User=%r Permissions=%r Hidden=%s Properties=%r)", PathOrToken, PathMapped, Owner, UserShare, Permissions, Hidden, Properties) + logger.trace("sharing: map %r to %r (Owner=%r User=%r Permissions=%r Hidden=%s Properties=%r)", PathOrToken, PathMapped, Owner, UserShare, Permissions, Hidden, Properties) return { "mapped": True, "ShareType": ShareType, @@ -167,8 +164,7 @@ class Sharing(sharing.BaseSharing): """ retrieve sharing """ result = [] - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/called: ShareType=%r OwnerOrUser=%r User=%r PathOrToken=%r PathMapped=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s Conversion=%r", ShareType, OwnerOrUser, User, PathOrToken, PathMapped, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser, Conversion) + logger.trace("sharing/list/called: ShareType=%r OwnerOrUser=%r User=%r PathOrToken=%r PathMapped=%r EnabledByOwner=%s EnabledByUser=%s HiddenByOwner=%s HiddenByUser=%s Conversion=%r", ShareType, OwnerOrUser, User, PathOrToken, PathMapped, EnabledByOwner, EnabledByUser, HiddenByOwner, HiddenByUser, Conversion) for _ShareType in sharing.SHARE_TYPES_V1: if ShareType is not None and _ShareType != ShareType: @@ -181,8 +177,7 @@ class Sharing(sharing.BaseSharing): if not entry.is_file(): continue - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list: check file: %r", entry.name) + logger.trace("sharing/list: check file: %r", entry.name) # read file with open(entry, "rb") as fb: (version, row) = pickle.load(fb) @@ -191,25 +186,20 @@ class Sharing(sharing.BaseSharing): # skip continue - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: test: %r", row) + logger.trace("sharing/list/row: test: %r", row) if ShareType is not None and row['ShareType'] != ShareType: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by ShareType") + logger.trace("sharing/list/row: skip by ShareType") pass elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser): pass elif User is not None and row['User'] != User: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by User") + logger.trace("sharing/list/row: skip by User") pass elif PathOrToken is not None and row['PathOrToken'] != PathOrToken: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by PathOrToken") + logger.trace("sharing/list/row: skip by PathOrToken") pass elif PathMapped is not None and row['PathMapped'] != PathMapped: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: skip by PathMapped") + logger.trace("sharing/list/row: skip by PathMapped") pass elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner: pass @@ -222,8 +212,7 @@ class Sharing(sharing.BaseSharing): elif Conversion is not None and row['Conversion'] != Conversion: pass else: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/list/row: add: %r", row) + logger.trace("sharing/list/row: add: %r", row) result.append(row) return result @@ -245,9 +234,8 @@ class Sharing(sharing.BaseSharing): sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken)) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/create: sharing_config_file=%r", ShareType, sharing_config_file) - logger.debug("TRACE/sharing/%s/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", ShareType, PathOrToken, Owner, PathMapped, User, Permissions) + logger.trace("sharing/%s/create: sharing_config_file=%r", ShareType, sharing_config_file) + logger.trace("sharing/%s/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", ShareType, PathOrToken, Owner, PathMapped, User, Permissions) if os.path.isfile(sharing_config_file): return {"status": "conflict"} @@ -272,13 +260,11 @@ class Sharing(sharing.BaseSharing): try: with self._storage.acquire_lock("w", Owner, path=sharing_config_file): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/create: store share-config: %r into file %r", ShareType, row, sharing_config_file) + logger.trace("sharing/%s/create: store share-config: %r into file %r", ShareType, row, sharing_config_file) # write file with open(sharing_config_file, "wb") as fb: pickle.dump((version, row), fb) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/*/create: share-config file stored: %r", sharing_config_file) + logger.trace("sharing/*/create: share-config file stored: %r", sharing_config_file) return {"status": "success"} except Exception as e: logger.error("sharing/%s/create: cannot store share-config: %r (%r)", ShareType, sharing_config_file, e) @@ -301,8 +287,7 @@ class Sharing(sharing.BaseSharing): Actions: Union[dict, None] = None, ) -> dict: """ update sharing """ - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: PathOrToken=%r OwnerOrUser=%r User=%r Properties=%r", ShareType, PathOrToken, OwnerOrUser, User, Properties) + logger.trace("sharing/%s/update: PathOrToken=%r OwnerOrUser=%r User=%r Properties=%r", ShareType, PathOrToken, OwnerOrUser, User, Properties) sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken)) @@ -318,11 +303,7 @@ class Sharing(sharing.BaseSharing): if version != DB_VERSION: return {"status": "error"} - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: check: %r", ShareType, row) - - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/update: orig row=%r", ShareType, row) + logger.trace("sharing/%s/update: orig row=%r", ShareType, row) if PathMapped is not None: row["PathMapped"] = PathMapped @@ -347,14 +328,13 @@ class Sharing(sharing.BaseSharing): # update timestamp row["TimestampUpdated"] = Timestamp - logger.debug("TRACE/sharing/%s/update: adj row=%r", ShareType, row) + logger.trace("sharing/%s/update: adj row=%r", ShareType, row) try: # write file with open(sharing_config_file, "wb") as fb: pickle.dump((version, row), fb) - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/create: share-config file stored: %r", ShareType, sharing_config_file) + logger.trace("sharing/%s/create: share-config file stored: %r", ShareType, sharing_config_file) return {"status": "success"} except Exception as e: logger.error("sharing/%s/create: cannot store share-config: %r (%r)", ShareType, sharing_config_file, e) @@ -365,8 +345,7 @@ class Sharing(sharing.BaseSharing): PathOrToken: str, User: str) -> dict: """ delete sharing """ - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken) + logger.trace("sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken) sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken)) diff --git a/radicale/sharing/none.py b/radicale/sharing/none.py index 1264602a..b4f87442 100644 --- a/radicale/sharing/none.py +++ b/radicale/sharing/none.py @@ -29,10 +29,10 @@ class Sharing(sharing.BaseSharing): def get_sharing_collection_by_token(self, token: str) -> Union[dict, None]: """ retrieve target and attributs by token """ # default - logger.debug("TRACE/sharing_by_token: 'none' cannot provide any map for token: %r", token) + logger.trace("sharing/collection_by_token: 'none' cannot provide any map for token: %r", token) return None def get_sharing_collection_by_map(self, path) -> Union[dict, None]: """ retrieve target and attributs by map """ - logger.debug("TRACE/sharing_by_map: 'none' cannot provide any map for path: %r", path) + logger.trace("sharing/collection_by_map: 'none' cannot provide any map for path: %r", path) return {"mapped": False} diff --git a/radicale/storage/__init__.py b/radicale/storage/__init__.py index 1e0b16bf..21b9a24a 100644 --- a/radicale/storage/__init__.py +++ b/radicale/storage/__init__.py @@ -25,7 +25,6 @@ Take a look at the class ``BaseCollection`` if you want to implement your own. """ import json -import logging import xml.etree.ElementTree as ET from hashlib import sha256 from typing import (Callable, ContextManager, Dict, Iterable, Iterator, List, @@ -157,17 +156,17 @@ class BaseCollection: return tag, start, end, simple = radicale_filter.simplify_prefilters( filters, self.tag) - logger.debug("TRACE/STORAGE/get_filtered: prefilter tag=%s start=%s end=%s simple=%s", tag, format_ut(start), format_ut(end), simple) + logger.trace("STORAGE/get_filtered: prefilter tag=%s start=%s end=%s simple=%s", tag, format_ut(start), format_ut(end), simple) for item in self.get_all(): - logger.debug("TRACE/STORAGE/get_filtered: component_name=%s tag=%s", item.component_name, tag) + logger.trace("STORAGE/get_filtered: component_name=%s tag=%s", item.component_name, tag) if tag is not None and tag != item.component_name: continue istart, iend = item.time_range - logger.debug("TRACE/STORAGE/get_filtered: istart=%s iend=%s", format_ut(istart), format_ut(iend)) + logger.trace("STORAGE/get_filtered: istart=%s iend=%s", format_ut(istart), format_ut(iend)) if istart >= end or iend <= start: - logger.debug("TRACE/STORAGE/get_filtered: skip iuid=%s", item.uid) + logger.trace("STORAGE/get_filtered: skip iuid=%s", item.uid) continue - logger.debug("TRACE/STORAGE/get_filtered: add iuid=%s", item.uid) + logger.trace("STORAGE/get_filtered: add iuid=%s", item.uid) yield item, simple and (start <= istart or iend <= end) def has_uid(self, uid: str) -> bool: @@ -284,13 +283,11 @@ class BaseCollection: template[template_insert_pos:]) if self.tag == "VADDRESSBOOK": if vcf_to_ics: - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/storage: convert VCF to ICS") + logger.trace("storage: convert VCF to ICS") items = [] for item in self.get_all(): - if logger.isEnabledFor(logging.DEBUG): - logger.debug("TRACE/storage/convert VCF to ICS: %r:", item) + logger.trace("storage/convert VCF to ICS: %r:", item) item_ics = item.convert_vcf_to_ics() if item_ics is None: continue