Avii/Radicale
1
0
Fork 0
Code Issues Pull Requests Actions 2 Packages Projects Releases Wiki Activity

Merge pull request #2075 from pbiering/logging-trace

Browse Source 
Add trace log level
This commit is contained in:
Peter Bieringer
2026-04-09 07:28:07 +02:00
committed by GitHub
parent 35a09300a6 1f3675c618
commit c78da9f9d3
19 changed files with 252 additions and 343 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
CHANGELOG.md
View File

@@ -3,6 +3,7 @@
## 3.7.1.dev ## 3.7.1.dev
* Fix: share address book collection as birthday calendar not working on non-DEBUG level * 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 * 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 ## 3.7.0

15
DOCUMENTATION.md
View File

@@ -1674,17 +1674,20 @@ Default: `internal`
Set the logging level. Set the logging level.
Available levels are: Available levels are:
* `trace` _(>= 3.7.1)_
* `debug` * `debug`
* `info` * `info`
* `notice` _(>= 3.7.1)_
* `warning` * `warning`
* `error` * `error`
* `critical` * `critical`
* `alert` _(>= 3.7.1)_
Default: `warning` _(< 3.2.0)_ / `info` _(>= 3.2.0)_ Default: `warning` _(< 3.2.0)_ / `info` _(>= 3.2.0)_
##### limit_content ##### limit_content
_(> 3.7.0)_ _(>= 3.7.0)_
Limit content of wrapped text (chars) Limit content of wrapped text (chars)
@@ -1692,7 +1695,7 @@ Default: `3000`
##### trace_on_debug ##### trace_on_debug
_(> 3.5.4)_ _(> 3.5.4)_ && _(< 3.7.1)_
Do not filter debug messages starting with 'TRACE' Do not filter debug messages starting with 'TRACE'
@@ -1700,12 +1703,18 @@ Default: `False`
##### trace_filter ##### trace_filter
_(> 3.5.4)_ _(> 3.5.4)_ && _(< 3.7.1)_
Filter debug messages starting with 'TRACE/<TOKEN>' Filter debug messages starting with 'TRACE/<TOKEN>'
Prerequisite: `trace_on_debug = True` Prerequisite: `trace_on_debug = True`
_(>= 3.7.1)_
Filter trace messages starting with '<TOKEN>'
Prerequisite: `level = trace`
Default: (empty) Default: (empty)
##### mask_passwords ##### mask_passwords

7
config
View File

@@ -359,16 +359,13 @@
[logging] [logging]
# Threshold for the logger # Threshold for the logger
# Value: debug | info | warning | error | critical # Value: trace | debug | info | notice | warning | error | critical | alert
#level = info #level = info
# Limit content of wrapped text (chars) # Limit content of wrapped text (chars)
#limit_content = 3000 #limit_content = 3000
# do not filter debug messages starting with 'TRACE' # filter debug messages starting with '<TOKEN>'
#trace_on_debug = False
# filter debug messages starting with 'TRACE/<TOKEN>'
#trace_filter = "" #trace_filter = ""
# Don't include passwords in logs # Don't include passwords in logs

10
pyproject.toml
View File

@@ -55,7 +55,7 @@ build-backend = "setuptools.build_meta"
[tool.tox] [tool.tox]
min_version = "4.0" 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] [tool.tox.env.py]
extras = ["test"] extras = ["test"]
@@ -80,6 +80,14 @@ deps = [
] ]
commands = [["pytest", "-r", "s", "--log-level", "INFO", "."]] 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] [tool.tox.env.flake8]
deps = ["flake8==7.1.0"] deps = ["flake8==7.1.0"]
commands = [["flake8", "."]] commands = [["flake8", "."]]

1
radicale/__init__.py
View File

@@ -54,7 +54,6 @@ def _get_application_instance(config_path: str, wsgi_errors: types.ErrorStream
config_path)) config_path))
log.set_level(cast(str, configuration.get("logging", "level")), log.set_level(cast(str, configuration.get("logging", "level")),
configuration.get("logging", "backtrace_on_debug"), configuration.get("logging", "backtrace_on_debug"),
configuration.get("logging", "trace_on_debug"),
configuration.get("logging", "trace_filter")) configuration.get("logging", "trace_filter"))
# Log configuration after logger is configured # Log configuration after logger is configured
default_config_active = True default_config_active = True

1
radicale/__main__.py
View File

@@ -172,7 +172,6 @@ def run() -> None:
# Configure logging # Configure logging
log.set_level(cast(str, configuration.get("logging", "level")), log.set_level(cast(str, configuration.get("logging", "level")),
configuration.get("logging", "backtrace_on_debug"), configuration.get("logging", "backtrace_on_debug"),
configuration.get("logging", "trace_on_debug"),
configuration.get("logging", "trace_filter")) configuration.get("logging", "trace_filter"))
# Log configuration after logger is configured # Log configuration after logger is configured

46
radicale/app/propfind.py
View File

@@ -20,7 +20,6 @@
import collections import collections
import itertools import itertools
import logging
import posixpath import posixpath
import socket import socket
import xml.etree.ElementTree as ET import xml.etree.ElementTree as ET
@@ -76,8 +75,7 @@ def xml_propfind(
# Writing answer # Writing answer
multistatus = ET.Element(xmlutils.make_clark("D:multistatus")) multistatus = ET.Element(xmlutils.make_clark("D:multistatus"))
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind: shares=%r", shares)
logger.debug("TRACE/PROPFIND/xml_propfind: shares=%r", shares)
for item, permission, raw_permissions, conversion in allowed_items: for item, permission, raw_permissions, conversion in allowed_items:
write = permission == "w" write = permission == "w"
@@ -141,19 +139,15 @@ def xml_propfind_response(
# lookup share # lookup share
share = None share = None
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind: conversion=%r item.path=%r", conversion, uri)
logger.debug("TRACE/PROPFIND/xml_propfind: conversion=%r item.path=%r", conversion, uri)
for entry in shares: for entry in shares:
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind: check entry=%r", entry)
logger.debug("TRACE/PROPFIND/xml_propfind: check entry=%r", entry)
if entry is not None: if entry is not None:
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind: PathMapped=%r uri=%r", shares[entry]['PathMapped'], uri)
logger.debug("TRACE/PROPFIND/xml_propfind: PathMapped=%r uri=%r", shares[entry]['PathMapped'], uri)
if uri.startswith(shares[entry]['PathMapped']): if uri.startswith(shares[entry]['PathMapped']):
if conversion is not None and shares[entry]['Conversion'] == conversion: if conversion is not None and shares[entry]['Conversion'] == conversion:
share = shares[entry] share = shares[entry]
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind: found share=%r", share)
logger.debug("TRACE/PROPFIND/xml_propfind: found share=%r", share)
break break
share_bday_automap = False share_bday_automap = False
@@ -307,8 +301,7 @@ def xml_propfind_response(
elif tag == xmlutils.make_clark("D:current-user-privilege-set"): elif tag == xmlutils.make_clark("D:current-user-privilege-set"):
privileges = ["D:read"] privileges = ["D:read"]
if share: if share:
if logger.isEnabledFor(logging.DEBUG): 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)
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)
if write: if write:
if "w" in share['Permissions']: if "w" in share['Permissions']:
if not share_bday_automap: if not share_bday_automap:
@@ -321,8 +314,7 @@ def xml_propfind_response(
"p" in share['Permissions'] or "p" in share['Permissions'] or
("p" in raw_permissions and "P" not 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'])): (self._sharing.permit_properties_overlay and "P" not in raw_permissions and "P" not in share['Permissions'])):
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind_response/current-user-privilege-set: add D:write-properties")
logger.debug("TRACE/PROPFIND/xml_propfind_response/current-user-privilege-set: add D:write-properties")
privileges.append("D:write-properties") privileges.append("D:write-properties")
elif write: elif write:
privileges.append("D:all") privileges.append("D:all")
@@ -367,8 +359,7 @@ def xml_propfind_response(
elif tag == xmlutils.make_clark("D:getcontentlength"): elif tag == xmlutils.make_clark("D:getcontentlength"):
if not is_collection or is_leaf: if not is_collection or is_leaf:
if collection.tag == "VADDRESSBOOK" and share_bday_automap and isinstance(item, storage.BaseCollection): if collection.tag == "VADDRESSBOOK" and share_bday_automap and isinstance(item, storage.BaseCollection):
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind_response/getcontentlength: start bday automap handling")
logger.debug("TRACE/PROPFIND/xml_propfind_response/getcontentlength: start bday automap handling")
length = 0 length = 0
for entry in item.get_all(): for entry in item.get_all():
item_ics = entry.convert_vcf_to_ics() item_ics = entry.convert_vcf_to_ics()
@@ -435,8 +426,7 @@ def xml_propfind_response(
# Only for internal use by the web interface # Only for internal use by the web interface
if isinstance(item, storage.BaseCollection) and not collection.is_principal: if isinstance(item, storage.BaseCollection) and not collection.is_principal:
if collection.tag == "VADDRESSBOOK" and share_bday_automap: if collection.tag == "VADDRESSBOOK" and share_bday_automap:
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/xml_propfind_response/getcontentcount: start bday automap handling")
logger.debug("TRACE/PROPFIND/xml_propfind_response/getcontentcount: start bday automap handling")
items = [] items = []
for entry in item.get_all(): for entry in item.get_all():
item_ics = entry.convert_vcf_to_ics() item_ics = entry.convert_vcf_to_ics()
@@ -528,8 +518,7 @@ class ApplicationPartPropfind(ApplicationBase):
if isinstance(item, storage.BaseCollection): if isinstance(item, storage.BaseCollection):
path = pathutils.unstrip_path(item.path, True) path = pathutils.unstrip_path(item.path, True)
raw_permissions = self._rights.authorization(user, path) raw_permissions = self._rights.authorization(user, path)
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND/_collect_allowed_items/BaseCollection: path=%r user=%r raw_permissions=%r", path, user, raw_permissions)
logger.debug("TRACE/PROPFIND/_collect_allowed_items/BaseCollection: path=%r user=%r raw_permissions=%r", path, user, raw_permissions)
if item.tag: if item.tag:
permissions = rights.intersect(raw_permissions, "rw") permissions = rights.intersect(raw_permissions, "rw")
target = "collection with tag %r" % item.path target = "collection with tag %r" % item.path
@@ -586,8 +575,7 @@ class ApplicationPartPropfind(ApplicationBase):
logger.debug("Client timed out", exc_info=True) logger.debug("Client timed out", exc_info=True)
return httputils.REQUEST_TIMEOUT return httputils.REQUEST_TIMEOUT
with self._storage.acquire_lock("r", user): with self._storage.acquire_lock("r", user):
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND: discover path=%r depth=%s", path, http_depth)
logger.debug("TRACE/PROPFIND: discover path=%r depth=%s", path, http_depth)
items_iter = iter(self._storage.discover( items_iter = iter(self._storage.discover(
path, http_depth, path, http_depth,
None, self._rights._user_groups)) None, self._rights._user_groups))
@@ -609,8 +597,7 @@ class ApplicationPartPropfind(ApplicationBase):
allowed_items.append((item, permission, raw_permissions, None)) allowed_items.append((item, permission, raw_permissions, None))
if self._sharing._enabled: if self._sharing._enabled:
if http_depth == "1": if http_depth == "1":
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND: get shared collections")
logger.debug("TRACE/PROPFIND: get shared collections")
# check for shared collections related to user, Enabled and not Hidden # 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) collections_share_list = self._sharing.sharing_collection_list(User=user, Enabled=True, Hidden=False)
if collections_share_list: if collections_share_list:
@@ -619,15 +606,12 @@ class ApplicationPartPropfind(ApplicationBase):
c_path = share['PathMapped'] c_path = share['PathMapped']
c_user = share['Owner'] c_user = share['Owner']
c_permissions_filter = share['Permissions'] c_permissions_filter = share['Permissions']
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND: test shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter)
logger.debug("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) c_access = Access(self._rights, c_user, c_path, c_permissions_filter)
if not c_access.check("r"): if not c_access.check("r"):
if logger.isEnabledFor(logging.DEBUG): 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)
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)
continue continue
if logger.isEnabledFor(logging.DEBUG): logger.trace("PROPFIND: append shared collection: PathOrToken=%r PathMapped=%r Owner=%r Permissions=%r", c_share, c_path, c_user, c_permissions_filter)
logger.debug("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): with self._storage.acquire_lock("r", c_user):
c_items_iter = iter(self._storage.discover(c_path, "0")) c_items_iter = iter(self._storage.discover(c_path, "0"))
c_allowed_items = list(self._collect_allowed_items(c_items_iter, c_user)) c_allowed_items = list(self._collect_allowed_items(c_items_iter, c_user))

14
radicale/app/proppatch.py
View File

@@ -20,7 +20,6 @@
# along with Radicale. If not, see <http://www.gnu.org/licenses/>. # along with Radicale. If not, see <http://www.gnu.org/licenses/>.
import errno import errno
import logging
import re import re
import socket import socket
import xml.etree.ElementTree as ET 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) props_with_remove = xmlutils.props_from_request(xml_request)
if share and share_overlay: if share and share_overlay:
# PROPPATCH overlay adjustment # 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: if share['Properties'] is not None:
all_props_with_remove = cast(Dict[str, Optional[str]], radicale_item.check_and_sanitize_props(share['Properties'])) all_props_with_remove = cast(Dict[str, Optional[str]], radicale_item.check_and_sanitize_props(share['Properties']))
else: else:
all_props_with_remove = {} all_props_with_remove = {}
all_props_with_remove.update(props_with_remove) all_props_with_remove.update(props_with_remove)
all_props = radicale_item.check_and_sanitize_props(all_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: else:
if collection is not None: if collection is not None:
# always the case, but makes mypy happy # always the case, but makes mypy happy
@@ -115,11 +114,10 @@ class ApplicationPartProppatch(ApplicationBase):
access = Access(self._rights, user, path, permissions_filter) access = Access(self._rights, user, path, permissions_filter)
raw_permissions = self._rights.authorization(user, path) raw_permissions = self._rights.authorization(user, path)
if not access.check("w"): 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: if share:
# priority share->rights->global # priority share->rights->global
if logger.isEnabledFor(logging.DEBUG): 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)
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)
if ("P" in share['Permissions'] or if ("P" in share['Permissions'] or
("P" in raw_permissions and "p" not 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']) (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: else:
return httputils.NOT_ALLOWED return httputils.NOT_ALLOWED
else: else:
logger.debug("TRACE/PROPPATCH/xml_proppatch: write-access: %r", path) logger.trace("PROPPATCH/xml_proppatch: write-access: %r", path)
if share: if share:
# write access -> check for enforced properties overlay # 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 self._sharing.enforce_properties_overlay:
if permissions_filter is not None and "e" in permissions_filter: 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) logger.info("PROPPATCH request on shared %r: write-permissions, overlay enforced, but disabled by share permission 'e'", path_orig)

42
radicale/app/report.py
View File

@@ -25,7 +25,6 @@
import contextlib import contextlib
import copy import copy
import datetime import datetime
import logging
import posixpath import posixpath
import socket import socket
import xml.etree.ElementTree as ET 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. Read rfc3253-3.6 for info.
""" """
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: base_prefix=%r path=%r", base_prefix, path)
logger.debug("TRACE/REPORT/xml_report: base_prefix=%r path=%r", base_prefix, path)
share_bday_automap = False share_bday_automap = False
if share and share['Conversion'] == "bday": if share and share['Conversion'] == "bday":
share_bday_automap = True share_bday_automap = True
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report(1): share=%r", share)
logger.debug("TRACE/REPORT/xml_report(1): share=%r", share)
multistatus = ET.Element(xmlutils.make_clark("D:multistatus")) multistatus = ET.Element(xmlutils.make_clark("D:multistatus"))
if xml_request is None: 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_) filter_copy = copy.deepcopy(filter_)
if expand is not None: if expand is not None:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: expand")
logger.debug("TRACE/REPORT/xml_report: expand")
for comp_filter in filter_copy.findall(".//" + xmlutils.make_clark("C:comp-filter")): for comp_filter in filter_copy.findall(".//" + xmlutils.make_clark("C:comp-filter")):
if comp_filter.get("name", "").upper() == "VCALENDAR": if comp_filter.get("name", "").upper() == "VCALENDAR":
continue continue
@@ -276,10 +272,9 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element],
item_ics.href = item.href item_ics.href = item.href
retrieved_items_vcf_to_ics.append((item_ics, flag)) retrieved_items_vcf_to_ics.append((item_ics, flag))
retrieved_items = retrieved_items_vcf_to_ics 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.trace("REPORT/xml_report(2): share=%r", share)
logger.debug("TRACE/REPORT/xml_report(2): share=%r", share)
n_vevents = 0 n_vevents = 0
while retrieved_items: while retrieved_items:
@@ -348,16 +343,13 @@ def xml_report(base_prefix: str, path: str, xml_request: Optional[ET.Element],
n_vevents += n_vev n_vevents += n_vev
if prop.tag == xmlutils.make_clark("D:getetag"): if prop.tag == xmlutils.make_clark("D:getetag"):
if n_vev > 0: if n_vev > 0:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: getetag/expanded element")
logger.debug("TRACE/REPORT/xml_report: getetag/expanded element")
element.text = item.etag element.text = item.etag
found_props.append(element) found_props.append(element)
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: getetag/no expanded element")
logger.debug("TRACE/REPORT/xml_report: getetag/no expanded element")
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: default")
logger.debug("TRACE/REPORT/xml_report: default")
found_props.append(expanded_element) found_props.append(expanded_element)
else: else:
if prop.tag == xmlutils.make_clark("D:getetag"): 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")) response = ET.Element(xmlutils.make_clark("D:response"))
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_item_response: found=%s share=%r", found_item, share)
logger.debug("TRACE/REPORT/xml_item_response: found=%s share=%r", found_item, share)
share_bday_automap = False share_bday_automap = False
if share and share['Conversion'] == "bday": 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 = ET.Element(xmlutils.make_clark("D:href"))
href_element.text = xmlutils.make_href(base_prefix, href) href_element.text = xmlutils.make_href(base_prefix, href)
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: href=%r", href_element.text)
logger.debug("TRACE/REPORT/xml_report: href=%r", href_element.text)
if share: if share:
# backmap # backmap
if href_element.text.startswith(share['PathMapped']): if href_element.text.startswith(share['PathMapped']):
href_element.text = str(share['PathOrToken']) + href_element.text.removeprefix(share['PathMapped']) href_element.text = str(share['PathOrToken']) + href_element.text.removeprefix(share['PathMapped'])
if share_bday_automap and href_element.text.endswith(".vcf"): if share_bday_automap and href_element.text.endswith(".vcf"):
href_element.text = href_element.text.removesuffix(".vcf") + ".ics" href_element.text = href_element.text.removesuffix(".vcf") + ".ics"
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: href=%r (backmapped)", href_element.text)
logger.debug("TRACE/REPORT/xml_report: href=%r (backmapped)", href_element.text)
response.append(href_element) response.append(href_element)
if found_item: if found_item:
@@ -793,8 +782,7 @@ def retrieve_items(
gets set to ``True``.""" gets set to ``True``."""
nonlocal collection_requested nonlocal collection_requested
for hreference in hreferences: for hreference in hreferences:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: hreference=%r", hreference)
logger.debug("TRACE/REPORT/xml_report: hreference=%r", hreference)
if share: if share:
# map back to owner # map back to owner
if hreference.startswith(share['PathOrToken']): if hreference.startswith(share['PathOrToken']):
@@ -802,8 +790,7 @@ def retrieve_items(
if share['Conversion'] == "bday": if share['Conversion'] == "bday":
if hreference.endswith(".ics"): if hreference.endswith(".ics"):
hreference = hreference.removesuffix(".ics") + ".vcf" hreference = hreference.removesuffix(".ics") + ".vcf"
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/xml_report: hreference=%r (backmapped)", hreference)
logger.debug("TRACE/REPORT/xml_report: hreference=%r (backmapped)", hreference)
try: try:
name = pathutils.name_from_path(hreference, collection) name = pathutils.name_from_path(hreference, collection)
except ValueError as e: except ValueError as e:
@@ -828,8 +815,7 @@ def retrieve_items(
else: else:
yield item, False yield item, False
if collection_requested: if collection_requested:
if logger.isEnabledFor(logging.DEBUG): logger.trace("REPORT/retrieve_items: get_filtered")
logger.debug("TRACE/REPORT/retrieve_items: get_filtered")
yield from collection.get_filtered(filters) yield from collection.get_filtered(filters)

11
radicale/config.py
View File

@@ -37,7 +37,8 @@ from configparser import RawConfigParser
from typing import (Any, Callable, ClassVar, Iterable, List, Optional, from typing import (Any, Callable, ClassVar, Iterable, List, Optional,
Sequence, Tuple, TypeVar, Union) 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.hook import email
from radicale.item import check_and_sanitize_props from radicale.item import check_and_sanitize_props
@@ -78,7 +79,7 @@ def rights_permission(value: Any) -> str:
def logging_level(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) raise ValueError("unsupported level: %r" % value)
return value return value
@@ -622,13 +623,9 @@ This is an automated message. Please do not reply.""",
"value": str(utils.DEFAULT_LIMIT_CONTENT), "value": str(utils.DEFAULT_LIMIT_CONTENT),
"help": "limit content of wrapped text (chars)", "help": "limit content of wrapped text (chars)",
"type": positive_int}), "type": positive_int}),
("trace_on_debug", {
"value": "False",
"help": "do not filter debug messages starting with 'TRACE'",
"type": bool}),
("trace_filter", { ("trace_filter", {
"value": "", "value": "",
"help": "filter debug messages starting with 'TRACE/<TOKEN>'", "help": "filter trace messages starting with '<TOKEN>'",
"type": str}), "type": str}),
("bad_put_request_content", { ("bad_put_request_content", {
"value": "False", "value": "False",

33
radicale/item/__init__.py
View File

@@ -27,7 +27,6 @@ Module for address books and calendar entries (see ``Item``).
import binascii import binascii
import contextlib import contextlib
import datetime import datetime
import logging
import math import math
import os import os
import re import re
@@ -506,32 +505,26 @@ class Item:
self._vobject_item = orig_vobject_item self._vobject_item = orig_vobject_item
def convert_vcf_to_ics(self) -> Union["Item", None]: def convert_vcf_to_ics(self) -> Union["Item", None]:
if logger.isEnabledFor(logging.DEBUG): logger.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 (href): %r", self.href) logger.trace("item/convert_vcf_to_ics: convert VCF to ICS (vobject): %r", self.vobject_item)
logger.debug("TRACE/item/convert_vcf_to_ics: convert VCF to ICS (vobject): %r", self.vobject_item)
if self.vobject_item.name != "VCARD": if self.vobject_item.name != "VCARD":
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: item is not a VCARD (skip): %r", self.href)
logger.debug("TRACE/item/convert_vcf_to_ics: item is not a VCARD (skip): %r", self.href)
return None return None
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: item is a VCARD (ok): %r", self.href)
logger.debug("TRACE/item/convert_vcf_to_ics: item is a VCARD (ok): %r", self.href)
if not hasattr(self.vobject_item, "bday"): if not hasattr(self.vobject_item, "bday"):
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: miss bday (skip): %r", self.href)
logger.debug("TRACE/item/convert_vcf_to_ics: miss bday (skip): %r", self.href)
return None return None
else: else:
pass pass
bday = self.vobject_item.bday bday = self.vobject_item.bday
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: has bday (ok): %r -> %r", self.href, bday.value)
logger.debug("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})$') pattern = re.compile('^([0-9]{4})-?([0-9]{2})-?([0-9]{2})$')
match = pattern.match(bday.value) match = pattern.match(bday.value)
if not match: if not match:
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: has unsupported bday: %r -> %r", self.href, bday.value)
logger.debug("TRACE/item/convert_vcf_to_ics: has unsupported bday: %r -> %r", self.href, bday.value)
return None return None
else: else:
pass pass
@@ -550,8 +543,7 @@ class Item:
elif hasattr(self.vobject_item, "nickname"): elif hasattr(self.vobject_item, "nickname"):
name = self.vobject_item.nickname.value name = self.vobject_item.nickname.value
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("item/convert_vcf_to_ics: has bday but neither FN or N or NICKNAME (skip): %r", self.href)
logger.debug("TRACE/item/convert_vcf_to_ics: has bday but neither FN or N or NICKNAME (skip): %r", self.href)
return None return None
# create VCALENDAR # create VCALENDAR
@@ -612,10 +604,9 @@ class Item:
href=href, href=href,
vobject_item=item_ics) vobject_item=item_ics)
if logger.isEnabledFor(logging.DEBUG): logger.trace("storage: item generated/vobject: %r", item_ics.serialize())
logger.debug("TRACE/storage: item generated/vobject: %r", item_ics.serialize()) logger.trace("storage: item orig /etag : %r", self.etag)
logger.debug("TRACE/storage: item orig /etag : %r", self.etag) logger.trace("storage: item generated/etag : %r", item_new.etag)
logger.debug("TRACE/storage: item generated/etag : %r", item_new.etag) logger.trace("storage: item generated/href : %r", item_new.href)
logger.debug("TRACE/storage: item generated/href : %r", item_new.href)
return item_new return item_new

28
radicale/item/filter.py
View File

@@ -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 # HACK: the filters are tested separately against all components
name = filter_.get("name", "").upper() 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: if level == 0:
tag = item.name tag = item.name
@@ -144,12 +144,12 @@ def comp_match(item: "item.Item", filter_: ET.Element, level: int = 0) -> bool:
trigger = subcomp.trigger.value trigger = subcomp.trigger.value
for child in filter_: for child in filter_:
if child.tag == xmlutils.make_clark("C:prop-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") if not any(prop_match(comp, child, "C")
for comp in components): for comp in components):
return False return False
elif child.tag == xmlutils.make_clark("C:time-range"): 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"): if (level == 0) and (name == "VCALENDAR"):
for name_try in ("VTODO", "VEVENT", "VJOURNAL"): for name_try in ("VTODO", "VEVENT", "VJOURNAL"):
try: 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): if not time_range_match(item.vobject_item, filter_[0], tag, trigger):
return False return False
elif child.tag == xmlutils.make_clark("C:comp-filter"): 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): if not comp_match(item, child, level=level + 1):
return False return False
else: else:
@@ -246,7 +246,7 @@ def time_range_match(vobject_item: vobject.base.Component,
def infinity_fn(start: datetime) -> bool: def infinity_fn(start: datetime) -> bool:
return False 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) visit_time_ranges(vobject_item, child_name, range_fn, infinity_fn)
return matched 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 # recurrences too. This is not respected and client don't seem to bother
# either. # 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] def getrruleset(child: vobject.base.Component, ignore: Sequence[date]
) -> Tuple[Iterable[date], bool]: ) -> 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: if dtstart.tzinfo is None and dtend.tzinfo is not None:
dtstart_orig = dtstart dtstart_orig = dtstart
dtstart = date_to_datetime(dtstart, dtend.astimezone().tzinfo) 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: elif dtstart.tzinfo is not None and dtend.tzinfo is None:
dtend_orig = dtend dtend_orig = dtend
dtend = date_to_datetime(dtend, dtstart.astimezone().tzinfo) 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() original_duration = (dtend - dtstart).total_seconds()
dtend = date_to_datetime(dtend) dtend = date_to_datetime(dtend)
@@ -550,7 +550,7 @@ def visit_time_ranges(vobject_item: vobject.base.Component, child_name: str,
else: else:
# Match a property # 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()) child = getattr(vobject_item, child_name.lower())
if isinstance(child.value, date): if isinstance(child.value, date):
child_is_datetime = isinstance(child.value, datetime) 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)) flat_filters = list(chain.from_iterable(filters))
simple = len(flat_filters) <= 1 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: for col_filter in flat_filters:
if collection_tag != "VCALENDAR": if collection_tag != "VCALENDAR":
simple = False simple = False
@@ -651,14 +651,14 @@ def simplify_prefilters(filters: Iterable[ET.Element], collection_tag: str
continue continue
simple &= len(col_filter) <= 1 simple &= len(col_filter) <= 1
for comp_filter in col_filter: 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: if comp_filter.tag == xmlutils.make_clark("C:time-range") and simple is True:
# time-filter found on level 0 # time-filter found on level 0
start, end = time_range_timestamps(comp_filter) 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 return None, start, end, simple
if comp_filter.tag != xmlutils.make_clark("C:comp-filter"): 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 simple = False
continue continue
tag = comp_filter.get("name", "").upper() tag = comp_filter.get("name", "").upper()
@@ -675,7 +675,7 @@ def simplify_prefilters(filters: Iterable[ET.Element], collection_tag: str
simple = False simple = False
continue continue
start, end = time_range_timestamps(time_filter) 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, start, end, simple
return tag, TIMESTAMP_MIN, TIMESTAMP_MAX, simple return tag, TIMESTAMP_MIN, TIMESTAMP_MAX, simple
return None, TIMESTAMP_MIN, TIMESTAMP_MAX, simple return None, TIMESTAMP_MIN, TIMESTAMP_MAX, simple

95
radicale/log.py
View File

@@ -35,8 +35,9 @@ import struct
import sys import sys
import threading import threading
import time import time
from typing import (Any, Callable, ClassVar, Dict, Iterator, Mapping, Optional, from functools import partial, partialmethod
Tuple, Union, cast) from typing import (TYPE_CHECKING, Any, Callable, ClassVar, Dict, Iterator,
Mapping, Optional, Tuple, Union, cast)
from radicale import types from radicale import types
@@ -47,34 +48,69 @@ LOGGER_FORMATS: Mapping[str, str] = {
} }
DATE_FORMAT: str = "%Y-%m-%d %H:%M:%S %z" 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): class RemoveTracebackFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool: def filter(self, record: logging.LogRecord) -> bool:
record.exc_info = None record.exc_info = None
return True 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): class PassTRACETOKENFilter(logging.Filter):
def __init__(self, trace_filter: str): def __init__(self, trace_filter: str):
super().__init__() super().__init__()
self.trace_filter = trace_filter self.trace_filter = trace_filter
self.prefix = "TRACE/" + self.trace_filter
def filter(self, record: logging.LogRecord) -> bool: def filter(self, record: logging.LogRecord) -> bool:
if record.msg.startswith("TRACE"): if record.levelno == LOG_LEVEL_TRACE:
if record.msg.startswith(self.prefix): if record.msg.startswith(self.trace_filter):
return True return True
else: else:
return False return False
@@ -84,8 +120,6 @@ class PassTRACETOKENFilter(logging.Filter):
REMOVE_TRACEBACK_FILTER: logging.Filter = RemoveTracebackFilter() REMOVE_TRACEBACK_FILTER: logging.Filter = RemoveTracebackFilter()
REMOVE_TRACE_FILTER: logging.Filter = RemoveTRACEFilter()
class IdentLogRecordFactory: class IdentLogRecordFactory:
"""LogRecordFactory that adds ``ident`` attribute.""" """LogRecordFactory that adds ``ident`` attribute."""
@@ -191,11 +225,14 @@ class ThreadedStreamHandler(logging.Handler):
return False return False
self._journal_socket = journal_socket self._journal_socket = journal_socket
priority = {"DEBUG": 7, priority = {"TRACE": 7,
"DEBUG": 7,
"INFO": 6, "INFO": 6,
"NOTICE": 5,
"WARNING": 4, "WARNING": 4,
"ERROR": 3, "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", timestamp = time.strftime("%Y-%m-%dT%H:%M:%S.%%03dZ",
time.gmtime(record.created)) % record.msecs time.gmtime(record.created)) % record.msecs
data = {"PRIORITY": priority, data = {"PRIORITY": priority,
@@ -258,7 +295,7 @@ logger_display_backtrace_disabled: bool = False
logger_display_backtrace_enabled: 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.""" """Set logging level for global logger."""
global logger_display_backtrace_disabled global logger_display_backtrace_disabled
global logger_display_backtrace_enabled 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()) level = getattr(logging, level.upper())
assert isinstance(level, int) assert isinstance(level, int)
logger.setLevel(level) logger.setLevel(level)
logger.log(level, "Logging level set to: %r", logging.getLevelName(level))
if level > logging.DEBUG: if level > logging.DEBUG:
if logger_display_backtrace_disabled is False: if logger_display_backtrace_disabled is False:
logger.info("Logging of backtrace is disabled in this loglevel") 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.debug("Logging of backtrace is enabled by option in this loglevel")
logger_display_backtrace_enabled = True logger_display_backtrace_enabled = True
logger.removeFilter(REMOVE_TRACEBACK_FILTER) logger.removeFilter(REMOVE_TRACEBACK_FILTER)
if trace_on_debug: if level < logging.DEBUG:
if trace_filter != "": if trace_filter != "":
logger.debug("Logging messages starting with 'TRACE/%s' enabled", trace_filter) logger.trace("Logging messages on 'trace' level enabled but filtered by prefix: %r", trace_filter)
logger.addFilter(PassTRACETOKENFilter(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: else:
logger.debug("Logging messages starting with 'TRACE' disabled") logger.trace("Logging messages on 'trace' level enabled")
logger.addFilter(REMOVE_TRACE_FILTER)

2
radicale/server.py
View File

@@ -341,8 +341,6 @@ def serve(configuration: config.Configuration,
max_connections: int = configuration.get("server", "max_connections") max_connections: int = configuration.get("server", "max_connections")
logger.info("Maximum parallel connections: %d", max_connections) logger.info("Maximum parallel connections: %d", max_connections)
logger.info("Radicale server ready") 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: while True:
rlist: List[socket.socket] = [] rlist: List[socket.socket] = []
# Wait for finished clients # Wait for finished clients

137
radicale/sharing/__init__.py
View File

@@ -18,7 +18,6 @@
import base64 import base64
import io import io
import json import json
import logging
import re import re
import socket import socket
import uuid import uuid
@@ -362,8 +361,7 @@ class BaseSharing:
sharing_collection_list = [] sharing_collection_list = []
if not self.sharing_collection_by_map: if not self.sharing_collection_by_map:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map: not active")
logger.debug("TRACE/sharing/map: not active")
else: else:
# retrieve collections depending on filter # retrieve collections depending on filter
sharing_collection_list += self.database_list_sharing( sharing_collection_list += self.database_list_sharing(
@@ -382,7 +380,7 @@ class BaseSharing:
# resolves a path to a share # resolves a path to a share
def sharing_collection_resolver(self, path: str, user: str) -> Union[dict, None]: def sharing_collection_resolver(self, path: str, user: str) -> Union[dict, None]:
""" returning dict with PathMapped, Owner, Permissions or None if not found""" """ 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 share = None
if path == "/": if path == "/":
@@ -395,8 +393,7 @@ class BaseSharing:
if share is not None and 'error' in share: if share is not None and 'error' in share:
return None return None
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token: not active")
logger.debug("TRACE/sharing/token: not active")
if self.sharing_collection_by_map: if self.sharing_collection_by_map:
if share is None: if share is None:
@@ -404,23 +401,21 @@ class BaseSharing:
if share is not None and 'error' in share: if share is not None and 'error' in share:
return None return None
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map: not active")
logger.debug("TRACE/sharing/map: not active")
return share return share
# adjust a share # adjust a share
def sharing_collection_update(self, ShareType: str, PathOrToken: str, OwnerOrUser: str, Properties: dict) -> None: 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""" """ 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 # Filter properies for permitted ones
properties_filtered: dict = {} properties_filtered: dict = {}
for prop in Properties: for prop in Properties:
if prop in OVERLAY_PROPERTIES_WHITELIST: if prop in OVERLAY_PROPERTIES_WHITELIST:
properties_filtered[prop] = Properties[prop] properties_filtered[prop] = Properties[prop]
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/collection_update: silent discard unsupported property: %r", prop)
logger.debug("TRACE/sharing/collection_update: silent discard unsupported property: %r", prop)
self.database_update_sharing(ShareType=ShareType, self.database_update_sharing(ShareType=ShareType,
PathOrToken=PathOrToken, PathOrToken=PathOrToken,
@@ -435,51 +430,43 @@ class BaseSharing:
def sharing_collection_by_token_resolver(self, path) -> Union[dict, None]: def sharing_collection_by_token_resolver(self, path) -> Union[dict, None]:
""" returning dict with PathMapped, Owner, Permissions or None if invalid""" """ returning dict with PathMapped, Owner, Permissions or None if invalid"""
if self.sharing_collection_by_token: if self.sharing_collection_by_token:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/resolver: check path: %r", path)
logger.debug("TRACE/sharing/token/resolver: check path: %r", path)
if path.startswith("/.token/"): if path.startswith("/.token/"):
pattern = re.compile('^(/\\.token/' + TOKEN_PATTERN_V1 + '/)$') pattern = re.compile('^(/\\.token/' + TOKEN_PATTERN_V1 + '/)$')
match = pattern.match(path) match = pattern.match(path)
if not match: if not match:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/resolver: unsupported token: %r", path)
logger.debug("TRACE/sharing/token/resolver: unsupported token: %r", path)
return {'error': 'token-not-supported'} return {'error': 'token-not-supported'}
else: else:
# TODO add token validity checks # TODO add token validity checks
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/resolver: supported token: %r", path)
logger.debug("TRACE/sharing/token/resolver: supported token: %r", path)
result = self.database_get_sharing( result = self.database_get_sharing(
ShareType="token", ShareType="token",
OnlyEnabled=False, OnlyEnabled=False,
PathOrToken=match[1]) PathOrToken=match[1])
if result is None: if result is None:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/resolver: supported token not found: %r", path)
logger.debug("TRACE/sharing/token/resolver: supported token not found: %r", path)
return {'error': 'token-not-found'} return {'error': 'token-not-found'}
if result['EnabledByOwner'] is not True: 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'} 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 return result
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/resolver: no supported prefix found in path: %r", path)
logger.debug("TRACE/sharing/token/resolver: no supported prefix found in path: %r", path)
return None return None
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token: not active")
logger.debug("TRACE/sharing/token: not active")
return None return None
# resolves a map "path" to a share # resolves a map "path" to a share
def sharing_collection_by_map_resolver(self, path: str, user: str) -> Union[dict, None]: def sharing_collection_by_map_resolver(self, path: str, user: str) -> Union[dict, None]:
""" returning dict with PathMapped, Owner, Permissions or None if invalid""" """ returning dict with PathMapped, Owner, Permissions or None if invalid"""
if self.sharing_collection_by_map: if self.sharing_collection_by_map:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map/resolver: check path: %r", path)
logger.debug("TRACE/sharing/map/resolver: check path: %r", path)
result = self.database_get_sharing( result = self.database_get_sharing(
ShareType="map", ShareType="map",
PathOrToken=path, PathOrToken=path,
@@ -489,8 +476,7 @@ class BaseSharing:
if not result: if not result:
# fallback to parent path # fallback to parent path
parent_path = pathutils.parent_path(path) parent_path = pathutils.parent_path(path)
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map/resolver: check parent path: %r", parent_path)
logger.debug("TRACE/sharing/map/resolver: check parent path: %r", parent_path)
result = self.database_get_sharing( result = self.database_get_sharing(
ShareType="map", ShareType="map",
PathOrToken=parent_path, PathOrToken=parent_path,
@@ -498,28 +484,25 @@ class BaseSharing:
User=user) User=user)
if result: if result:
result['PathMapped'] = path.replace(parent_path, result['PathMapped']) result['PathMapped'] = path.replace(parent_path, result['PathMapped'])
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map/resolver: PathMapped=%r Permissions=%r by parent_path=%r", result['PathMapped'], result['Permissions'], parent_path)
logger.debug("TRACE/sharing/map/resolver: PathMapped=%r Permissions=%r by parent_path=%r", result['PathMapped'], result['Permissions'], parent_path)
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map/resolver: not found")
logger.debug("TRACE/sharing/map/resolver: not found")
return None return None
if result: if result:
if result['EnabledByOwner'] is not True: 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'} return {'error': 'map-not-enabled'}
if result['EnabledByUser'] is not True: 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'} 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 result
return None return None
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map: not active")
logger.debug("TRACE/sharing/map: not active")
return None return None
# *** POST API *** # *** POST API ***
@@ -570,7 +553,7 @@ class BaseSharing:
""" """
# initial log prefix # initial log prefix
api_info = "Sharing/API/POST" api_info = "sharing/API/POST"
if not self._enabled: if not self._enabled:
# API is not enabled # API is not enabled
@@ -590,8 +573,7 @@ class BaseSharing:
ShareType_action = path.removeprefix("/.sharing/v1/") ShareType_action = path.removeprefix("/.sharing/v1/")
match = re.search('([a-z]+)/([a-z]+)$', ShareType_action) match = re.search('([a-z]+)/([a-z]+)$', ShareType_action)
if not match: if not match:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: ShareType/action not extractable: %r", ShareType_action)
logger.debug("TRACE/sharing/API: ShareType/action not extractable: %r", ShareType_action)
return httputils.NOT_FOUND return httputils.NOT_FOUND
else: else:
ShareType = match.group(1) ShareType = match.group(1)
@@ -603,8 +585,7 @@ class BaseSharing:
# check for valid ShareTypes # check for valid ShareTypes
if ShareType: if ShareType:
if ShareType not in SHARE_TYPES: if ShareType not in SHARE_TYPES:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: ShareType not whitelisted: %r", ShareType)
logger.debug("TRACE/sharing/API: ShareType not whitelisted: %r", ShareType)
return httputils.NOT_FOUND return httputils.NOT_FOUND
# check for enabled ShareTypes # check for enabled ShareTypes
@@ -620,15 +601,13 @@ class BaseSharing:
# check for valid API hooks # check for valid API hooks
if action not in API_HOOKS_V1: if action not in API_HOOKS_V1:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: action not whitelisted: %r", action)
logger.debug("TRACE/sharing/API: action not whitelisted: %r", action)
return httputils.NOT_FOUND return httputils.NOT_FOUND
# append action # append action
api_info = api_info + "/" + action api_info = api_info + "/" + action
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: called by authenticated user: %r", user)
logger.debug("TRACE/sharing/API: called by authenticated user: %r", user)
# read POST data # read POST data
try: try:
request_body = httputils.read_request_body(self.configuration, environ) request_body = httputils.read_request_body(self.configuration, environ)
@@ -654,8 +633,7 @@ class BaseSharing:
if type(request_data[key]) is not bool: if type(request_data[key]) is not bool:
logger.warning(api_info + ": unsupported (non-boolean) " + key + ": " + request_data[key]) logger.warning(api_info + ": unsupported (non-boolean) " + key + ": " + request_data[key])
return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_data[key]) return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_data[key])
if logger.isEnabledFor(logging.DEBUG): logger.trace(api_info + " (json): %r", f"{request_data}")
logger.debug("TRACE/" + api_info + " (json): %r", f"{request_data}")
elif 'application/x-www-form-urlencoded' in content_type: elif 'application/x-www-form-urlencoded' in content_type:
input_format = "form" input_format = "form"
output_format = "plain" # default output_format = "plain" # default
@@ -667,8 +645,7 @@ class BaseSharing:
# Properties key value parser # Properties key value parser
properties_dict: dict = {} properties_dict: dict = {}
for entry in request_parsed[key]: for entry in request_parsed[key]:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: parse property %r", entry)
logger.debug("TRACE/sharing/API: parse property %r", entry)
if entry == "": if entry == "":
continue continue
m = re.search('^([^=]+)=([^=]+)$', entry) m = re.search('^([^=]+)=([^=]+)$', entry)
@@ -677,8 +654,7 @@ class BaseSharing:
token = m.group(1).lstrip('"\'').rstrip('"\'') token = m.group(1).lstrip('"\'').rstrip('"\'')
value = m.group(2).lstrip('"\'').rstrip('"\'') value = m.group(2).lstrip('"\'').rstrip('"\'')
properties_dict[token] = value properties_dict[token] = value
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API: converted Properties from form into dict: %r", properties_dict)
logger.debug("TRACE/sharing/API: converted Properties from form into dict: %r", properties_dict)
request_data[key] = properties_dict request_data[key] = properties_dict
if len(request_data[key]) == 0: if len(request_data[key]) == 0:
# empty # empty
@@ -691,11 +667,9 @@ class BaseSharing:
return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_parsed[key][0]) return httputils.bad_request("Invalid non-boolean value for " + key + ": " + request_parsed[key][0])
else: else:
request_data[key] = request_parsed[key][0] request_data[key] = request_parsed[key][0]
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + " (form): %r", f"{request_data}")
logger.debug("TRACE/" + api_info + " (form): %r", f"{request_data}")
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": no supported content data")
logger.debug("TRACE/" + api_info + ": no supported content data")
return httputils.bad_request("Content-type not supported") return httputils.bad_request("Content-type not supported")
# check for requested output type # check for requested output type
@@ -840,12 +814,10 @@ class BaseSharing:
# action: list # action: list
if action == "list": if action == "list":
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": start")
logger.debug("TRACE/" + api_info + ": start")
if PathOrToken is not None: if PathOrToken is not None:
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": filter: %r", PathOrToken)
logger.debug("TRACE/" + api_info + ": filter: %r", PathOrToken)
if ShareType != "all": if ShareType != "all":
result_array = self.database_list_sharing( result_array = self.database_list_sharing(
@@ -874,8 +846,7 @@ class BaseSharing:
# action: create # action: create
elif action == "create": elif action == "create":
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": start")
logger.debug("TRACE/" + api_info + ": start")
if PathMapped is None: if PathMapped is None:
logger.warning(api_info + ": missing PathMapped") 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 # 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') + "/" token = "/.token/v1/" + str(base64.urlsafe_b64encode(uuid.uuid4().bytes + b"\0" + uuid.uuid4().bytes), 'utf-8') + "/"
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": %r (Permissions=%r token=%r)", PathMapped, Permissions, token)
logger.debug("TRACE/" + api_info + ": %r (Permissions=%r token=%r)", PathMapped, Permissions, token)
result = self.database_create_sharing( result = self.database_create_sharing(
ShareType=ShareType, ShareType=ShareType,
@@ -975,8 +945,7 @@ class BaseSharing:
Actions=Actions, Actions=Actions,
) )
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": result=%r", result)
logger.debug("TRACE/" + api_info + ": result=%r", result)
elif ShareType == "map": elif ShareType == "map":
# check preconditions # check preconditions
@@ -1031,8 +1000,7 @@ class BaseSharing:
logger.warning(api_info + ": PathOrToken=%r already exists as real collection for User=%r", PathOrToken, User) logger.warning(api_info + ": PathOrToken=%r already exists as real collection for User=%r", PathOrToken, User)
return httputils.CONFLICT return httputils.CONFLICT
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": %r (Permissions=%r PathOrToken=%r Owner=%r User=%r)", PathMapped, Permissions, PathOrToken, user, User)
logger.debug("TRACE/" + api_info + ": %r (Permissions=%r PathOrToken=%r Owner=%r User=%r)", PathMapped, Permissions, PathOrToken, user, User)
result = self.database_create_sharing( result = self.database_create_sharing(
ShareType=ShareType, ShareType=ShareType,
@@ -1054,8 +1022,7 @@ class BaseSharing:
else: else:
logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) logger.warning(api_info + ": unsupported for ShareType=%r", ShareType)
return httputils.bad_request("Invalid share type") return httputils.bad_request("Invalid share type")
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": result=%r", result)
logger.debug("TRACE/" + api_info + ": result=%r", result)
# result handling # result handling
if result['status'] == "conflict": if result['status'] == "conflict":
return httputils.CONFLICT return httputils.CONFLICT
@@ -1078,8 +1045,7 @@ class BaseSharing:
# action: update # action: update
elif action == "update": elif action == "update":
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": start")
logger.debug("TRACE/" + api_info + ": start")
if ShareType not in SHARE_TYPES_V1: if ShareType not in SHARE_TYPES_V1:
logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) logger.warning(api_info + ": unsupported for ShareType=%r", ShareType)
@@ -1105,17 +1071,14 @@ class BaseSharing:
elif share['Properties'] is not None: elif share['Properties'] is not None:
# replace properties # replace properties
for prop in share['Properties']: for prop in share['Properties']:
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": check for existing property %r", prop)
logger.debug("TRACE/" + api_info + ": check for existing property %r", prop)
if prop not in Properties: if prop not in Properties:
# overtake # overtake
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": overtake property %r", prop)
logger.debug("TRACE/" + api_info + ": overtake property %r", prop)
Properties[prop] = share['Properties'][prop] Properties[prop] = share['Properties'][prop]
elif Properties[prop] == '': elif Properties[prop] == '':
# unset, do nothing # unset, do nothing
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": clear property %r", prop)
logger.debug("TRACE/" + api_info + ": clear property %r", prop)
del Properties[prop] del Properties[prop]
if user == share['Owner']: 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)) 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 return httputils.NOT_ALLOWED
if 'Properties' in request_data: if 'Properties' in request_data:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API/update: permit_properties_overlay=%s Permissions=%r", self.permit_properties_overlay, share['Permissions'])
logger.debug("TRACE/sharing/API/update: permit_properties_overlay=%s Permissions=%r", self.permit_properties_overlay, share['Permissions'])
if self.permit_properties_overlay: if self.permit_properties_overlay:
if share['Permissions'] is not None and "p" in str(share['Permissions']): 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) logger.warning(api_info + ": %r properties overlay permitted by option, but denied by permission 'p'", PathOrToken)
@@ -1204,8 +1166,7 @@ class BaseSharing:
# action: delete # action: delete
elif action == "delete": elif action == "delete":
if logger.isEnabledFor(logging.DEBUG): logger.trace("" + api_info + ": start")
logger.debug("TRACE/" + api_info + ": start")
if ShareType not in SHARE_TYPES_V1: if ShareType not in SHARE_TYPES_V1:
logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) logger.warning(api_info + ": unsupported for ShareType=%r", ShareType)
@@ -1260,8 +1221,7 @@ class BaseSharing:
# action: TOGGLE # action: TOGGLE
elif action in API_SHARE_TOGGLES_V1: elif action in API_SHARE_TOGGLES_V1:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API/POST/" + action)
logger.debug("TRACE/sharing/API/POST/" + action)
if ShareType not in SHARE_TYPES_V1: if ShareType not in SHARE_TYPES_V1:
logger.warning(api_info + ": unsupported for ShareType=%r", ShareType) logger.warning(api_info + ": unsupported for ShareType=%r", ShareType)
@@ -1338,9 +1298,8 @@ class BaseSharing:
return httputils.bad_request("Invalid action") return httputils.bad_request("Invalid action")
# output handler # output handler
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/API/POST output format: %r", output_format)
logger.debug("TRACE/sharing/API/POST output format: %r", output_format) logger.trace("sharing/API/POST answer: %r", answer)
logger.debug("TRACE/sharing/API/POST answer: %r", answer)
if output_format == "csv" or output_format == "plain": if output_format == "csv" or output_format == "plain":
answer_array = [] answer_array = []
if output_format == "plain": if output_format == "plain":

72
radicale/sharing/csv.py
View File

@@ -17,7 +17,6 @@
import csv import csv
import json import json
import logging
import os import os
from typing import Union from typing import Union
@@ -97,8 +96,7 @@ class Sharing(sharing.BaseSharing):
User: Union[str, None] = None) -> Union[dict, None]: User: Union[str, None] = None) -> Union[dict, None]:
""" retrieve sharing target and attributes by map """ """ retrieve sharing target and attributes by map """
# Lookup # Lookup
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing: lookup ShareType=%r PathOrToken=%r User=%r OnlyEnabled=%s)", ShareType, PathOrToken, User, OnlyEnabled)
logger.debug("TRACE/sharing: lookup ShareType=%r PathOrToken=%r User=%r OnlyEnabled=%s)", ShareType, PathOrToken, User, OnlyEnabled)
index = 0 index = 0
found = False found = False
@@ -107,8 +105,7 @@ class Sharing(sharing.BaseSharing):
# skip fieldnames # skip fieldnames
pass pass
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing: check row: %r", row)
logger.debug("TRACE/sharing: check row: %r", row)
if row['ShareType'] != ShareType: if row['ShareType'] != ShareType:
pass pass
elif row['PathOrToken'] != PathOrToken: elif row['PathOrToken'] != PathOrToken:
@@ -174,33 +171,27 @@ class Sharing(sharing.BaseSharing):
result = [] result = []
with self._storage.acquire_lock("r", path=self._sharing_db_file): with self._storage.acquire_lock("r", path=self._sharing_db_file):
if logger.isEnabledFor(logging.DEBUG): 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)
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)
for row in self._sharing_cache: for row in self._sharing_cache:
if index == 0: if index == 0:
# skip fieldnames # skip fieldnames
pass pass
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: test: %r", row)
logger.debug("TRACE/sharing/list/row: test: %r", row)
if ShareType is not None and row['ShareType'] != ShareType: if ShareType is not None and row['ShareType'] != ShareType:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by ShareType")
logger.debug("TRACE/sharing/list/row: skip by ShareType")
pass pass
elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser): elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser):
pass pass
elif User is not None and row['User'] != User: elif User is not None and row['User'] != User:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by User")
logger.debug("TRACE/sharing/list/row: skip by User")
pass pass
elif PathOrToken is not None and row['PathOrToken'] != PathOrToken: elif PathOrToken is not None and row['PathOrToken'] != PathOrToken:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by PathOrToken")
logger.debug("TRACE/sharing/list/row: skip by PathOrToken")
pass pass
elif PathMapped is not None and row['PathMapped'] != PathMapped: elif PathMapped is not None and row['PathMapped'] != PathMapped:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by PathMapped")
logger.debug("TRACE/sharing/list/row: skip by PathMapped")
pass pass
elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner: elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner:
pass pass
@@ -213,8 +204,7 @@ class Sharing(sharing.BaseSharing):
elif Conversion is not None and row['Conversion'] != Conversion: elif Conversion is not None and row['Conversion'] != Conversion:
pass pass
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: add : %r", row)
logger.debug("TRACE/sharing/list/row: add : %r", row)
result.append(row) result.append(row)
index += 1 index += 1
return result return result
@@ -235,11 +225,9 @@ class Sharing(sharing.BaseSharing):
row: dict row: dict
with self._storage.acquire_lock("w", path=self._sharing_db_file): with self._storage.acquire_lock("w", path=self._sharing_db_file):
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing: ShareType=%r", ShareType)
logger.debug("TRACE/sharing: ShareType=%r", ShareType)
if ShareType == "token": if ShareType == "token":
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/token/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions)
logger.debug("TRACE/sharing/token/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions)
# check for duplicate token entry # check for duplicate token entry
for row in self._sharing_cache: for row in self._sharing_cache:
if row['ShareType'] != "token": if row['ShareType'] != "token":
@@ -249,8 +237,7 @@ class Sharing(sharing.BaseSharing):
logger.error("sharing/token/create: PathOrToken already exists: PathOrToken=%r", PathOrToken) logger.error("sharing/token/create: PathOrToken already exists: PathOrToken=%r", PathOrToken)
return {"status": "conflict"} return {"status": "conflict"}
elif ShareType == "map": elif ShareType == "map":
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/map/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions)
logger.debug("TRACE/sharing/map/create: PathOrToken=%r Owner=%r PathMapped=%r User=%r Permissions=%r", PathOrToken, Owner, PathMapped, User, Permissions)
# check for duplicate map entry # check for duplicate map entry
for row in self._sharing_cache: for row in self._sharing_cache:
if row['ShareType'] != "map": if row['ShareType'] != "map":
@@ -279,13 +266,11 @@ class Sharing(sharing.BaseSharing):
"Actions": Actions, "Actions": Actions,
} }
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/*/create: add row: %r", row)
logger.debug("TRACE/sharing/*/create: add row: %r", row)
self._sharing_cache.append(row) self._sharing_cache.append(row)
if self._write_csv(self._sharing_db_file): if self._write_csv(self._sharing_db_file):
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/create: write CSV done", ShareType)
logger.debug("TRACE/sharing/%s/create: write CSV done", ShareType)
return {"status": "success"} return {"status": "success"}
logger.error("sharing/%s/create: cannot update CSV database", ShareType) logger.error("sharing/%s/create: cannot update CSV database", ShareType)
@@ -308,8 +293,7 @@ class Sharing(sharing.BaseSharing):
Actions: Union[dict, None] = None, Actions: Union[dict, None] = None,
) -> dict: ) -> dict:
""" update sharing """ """ update sharing """
if logger.isEnabledFor(logging.DEBUG): 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)
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)
with self._storage.acquire_lock("w", path=self._sharing_db_file): with self._storage.acquire_lock("w", path=self._sharing_db_file):
# lookup token # lookup token
@@ -329,8 +313,7 @@ class Sharing(sharing.BaseSharing):
index += 1 index += 1
if found: if found:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/update: orig row[%d]=%r", ShareType, index, row)
logger.debug("TRACE/sharing/%s/update: orig row[%d]=%r", ShareType, index, row)
# CSV: remove+adjust+readd # CSV: remove+adjust+readd
if PathMapped is not None: if PathMapped is not None:
@@ -356,12 +339,10 @@ class Sharing(sharing.BaseSharing):
# update timestamp # update timestamp
self._sharing_cache[index]["TimestampUpdated"] = Timestamp self._sharing_cache[index]["TimestampUpdated"] = Timestamp
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/update: adj row[%d]=%r", ShareType, index, self._sharing_cache[index])
logger.debug("TRACE/sharing/%s/update: adj row[%d]=%r", ShareType, index, self._sharing_cache[index])
if self._write_csv(self._sharing_db_file): if self._write_csv(self._sharing_db_file):
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/update: write CSV done", ShareType)
logger.debug("TRACE/sharing/%s/update: write CSV done", ShareType)
return {"status": "success"} return {"status": "success"}
logger.error("sharing/%s/update: cannot update CSV database", ShareType) logger.error("sharing/%s/update: cannot update CSV database", ShareType)
@@ -374,16 +355,14 @@ class Sharing(sharing.BaseSharing):
PathOrToken: str, PathOrToken: str,
User: str) -> dict: User: str) -> dict:
""" delete sharing """ """ delete sharing """
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken)
logger.debug("TRACE/sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken)
with self._storage.acquire_lock("w", User, path=self._sharing_db_file): with self._storage.acquire_lock("w", User, path=self._sharing_db_file):
# lookup token # lookup token
found = False found = False
index = 0 index = 0
for row in self._sharing_cache: for row in self._sharing_cache:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/delete: check: %r", ShareType, row)
logger.debug("TRACE/sharing/%s/delete: check: %r", ShareType, row)
if index == 0: if index == 0:
# skip fieldnames # skip fieldnames
pass pass
@@ -397,15 +376,11 @@ class Sharing(sharing.BaseSharing):
index += 1 index += 1
if found: if found:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/delete: PathOrToken=%r Owner=%r index=%d", ShareType, PathOrToken, row['Owner'], index)
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)
self._sharing_cache.pop(index) self._sharing_cache.pop(index)
if self._write_csv(self._sharing_db_file): if self._write_csv(self._sharing_db_file):
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/delete: write CSV done", ShareType)
logger.debug("TRACE/sharing_by_token: write CSV done")
return {"status": "success"} return {"status": "success"}
logger.error("sharing/%s/delete: cannot update CSV database", ShareType) logger.error("sharing/%s/delete: cannot update CSV database", ShareType)
@@ -440,8 +415,7 @@ class Sharing(sharing.BaseSharing):
# convert txt to bool or int # convert txt to bool or int
if self._lines > 0: if self._lines > 0:
for fieldname in row: for fieldname in row:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/_load_csv: test fieldname=%r", fieldname)
logger.debug("TRACE/sharing/_load: test fieldname=%r", fieldname)
if fieldname not in sharing.DB_TYPES_V1: if fieldname not in sharing.DB_TYPES_V1:
logger.error("sharing database row error, unsupported fieldname found: %r", fieldname) logger.error("sharing database row error, unsupported fieldname found: %r", fieldname)
return False return False

59
radicale/sharing/files.py
View File

@@ -14,7 +14,6 @@
# You should have received a copy of the GNU General Public License # You should have received a copy of the GNU General Public License
# along with Radicale. If not, see <http://www.gnu.org/licenses/>. # along with Radicale. If not, see <http://www.gnu.org/licenses/>.
import logging
import os import os
import pickle import pickle
import urllib import urllib
@@ -93,8 +92,7 @@ class Sharing(sharing.BaseSharing):
User: Union[str, None] = None) -> Union[dict, None]: User: Union[str, None] = None) -> Union[dict, None]:
""" retrieve sharing target and attributes by map """ """ retrieve sharing target and attributes by map """
# Lookup # Lookup
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/get: PathOrToken=%r User=%r)", ShareType, PathOrToken, User)
logger.debug("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)) 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'] Conversion = row['Conversion']
if 'Actions' in row: if 'Actions' in row:
Actions = row['Actions'] Actions = row['Actions']
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing: map %r to %r (Owner=%r User=%r Permissions=%r Hidden=%s Properties=%r)", PathOrToken, PathMapped, Owner, UserShare, Permissions, Hidden, Properties)
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)
return { return {
"mapped": True, "mapped": True,
"ShareType": ShareType, "ShareType": ShareType,
@@ -167,8 +164,7 @@ class Sharing(sharing.BaseSharing):
""" retrieve sharing """ """ retrieve sharing """
result = [] result = []
if logger.isEnabledFor(logging.DEBUG): 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)
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)
for _ShareType in sharing.SHARE_TYPES_V1: for _ShareType in sharing.SHARE_TYPES_V1:
if ShareType is not None and _ShareType != ShareType: if ShareType is not None and _ShareType != ShareType:
@@ -181,8 +177,7 @@ class Sharing(sharing.BaseSharing):
if not entry.is_file(): if not entry.is_file():
continue continue
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list: check file: %r", entry.name)
logger.debug("TRACE/sharing/list: check file: %r", entry.name)
# read file # read file
with open(entry, "rb") as fb: with open(entry, "rb") as fb:
(version, row) = pickle.load(fb) (version, row) = pickle.load(fb)
@@ -191,25 +186,20 @@ class Sharing(sharing.BaseSharing):
# skip # skip
continue continue
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: test: %r", row)
logger.debug("TRACE/sharing/list/row: test: %r", row)
if ShareType is not None and row['ShareType'] != ShareType: if ShareType is not None and row['ShareType'] != ShareType:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by ShareType")
logger.debug("TRACE/sharing/list/row: skip by ShareType")
pass pass
elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser): elif OwnerOrUser is not None and (row['Owner'] != OwnerOrUser and row['User'] != OwnerOrUser):
pass pass
elif User is not None and row['User'] != User: elif User is not None and row['User'] != User:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by User")
logger.debug("TRACE/sharing/list/row: skip by User")
pass pass
elif PathOrToken is not None and row['PathOrToken'] != PathOrToken: elif PathOrToken is not None and row['PathOrToken'] != PathOrToken:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by PathOrToken")
logger.debug("TRACE/sharing/list/row: skip by PathOrToken")
pass pass
elif PathMapped is not None and row['PathMapped'] != PathMapped: elif PathMapped is not None and row['PathMapped'] != PathMapped:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: skip by PathMapped")
logger.debug("TRACE/sharing/list/row: skip by PathMapped")
pass pass
elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner: elif EnabledByOwner is not None and row['EnabledByOwner'] != EnabledByOwner:
pass pass
@@ -222,8 +212,7 @@ class Sharing(sharing.BaseSharing):
elif Conversion is not None and row['Conversion'] != Conversion: elif Conversion is not None and row['Conversion'] != Conversion:
pass pass
else: else:
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/list/row: add: %r", row)
logger.debug("TRACE/sharing/list/row: add: %r", row)
result.append(row) result.append(row)
return result 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)) sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken))
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/create: sharing_config_file=%r", ShareType, sharing_config_file)
logger.debug("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)
logger.debug("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): if os.path.isfile(sharing_config_file):
return {"status": "conflict"} return {"status": "conflict"}
@@ -272,13 +260,11 @@ class Sharing(sharing.BaseSharing):
try: try:
with self._storage.acquire_lock("w", Owner, path=sharing_config_file): with self._storage.acquire_lock("w", Owner, path=sharing_config_file):
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/create: store share-config: %r into file %r", ShareType, row, sharing_config_file)
logger.debug("TRACE/sharing/%s/create: store share-config: %r into file %r", ShareType, row, sharing_config_file)
# write file # write file
with open(sharing_config_file, "wb") as fb: with open(sharing_config_file, "wb") as fb:
pickle.dump((version, row), fb) pickle.dump((version, row), fb)
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/*/create: share-config file stored: %r", sharing_config_file)
logger.debug("TRACE/sharing/*/create: share-config file stored: %r", sharing_config_file)
return {"status": "success"} return {"status": "success"}
except Exception as e: except Exception as e:
logger.error("sharing/%s/create: cannot store share-config: %r (%r)", ShareType, sharing_config_file, 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, Actions: Union[dict, None] = None,
) -> dict: ) -> dict:
""" update sharing """ """ update sharing """
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/update: PathOrToken=%r OwnerOrUser=%r User=%r Properties=%r", ShareType, PathOrToken, OwnerOrUser, User, Properties)
logger.debug("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)) 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: if version != DB_VERSION:
return {"status": "error"} return {"status": "error"}
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/update: orig row=%r", ShareType, row)
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)
if PathMapped is not None: if PathMapped is not None:
row["PathMapped"] = PathMapped row["PathMapped"] = PathMapped
@@ -347,14 +328,13 @@ class Sharing(sharing.BaseSharing):
# update timestamp # update timestamp
row["TimestampUpdated"] = 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: try:
# write file # write file
with open(sharing_config_file, "wb") as fb: with open(sharing_config_file, "wb") as fb:
pickle.dump((version, row), fb) pickle.dump((version, row), fb)
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/create: share-config file stored: %r", ShareType, sharing_config_file)
logger.debug("TRACE/sharing/%s/create: share-config file stored: %r", ShareType, sharing_config_file)
return {"status": "success"} return {"status": "success"}
except Exception as e: except Exception as e:
logger.error("sharing/%s/create: cannot store share-config: %r (%r)", ShareType, sharing_config_file, 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, PathOrToken: str,
User: str) -> dict: User: str) -> dict:
""" delete sharing """ """ delete sharing """
if logger.isEnabledFor(logging.DEBUG): logger.trace("sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken)
logger.debug("TRACE/sharing/%s/delete: PathOrToken=%r", ShareType, PathOrToken)
sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken)) sharing_config_file = os.path.join(self._sharing_database_path_ShareType[ShareType], self._encode_path(PathOrToken))

4
radicale/sharing/none.py
View File

@@ -29,10 +29,10 @@ class Sharing(sharing.BaseSharing):
def get_sharing_collection_by_token(self, token: str) -> Union[dict, None]: def get_sharing_collection_by_token(self, token: str) -> Union[dict, None]:
""" retrieve target and attributs by token """ """ retrieve target and attributs by token """
# default # 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 return None
def get_sharing_collection_by_map(self, path) -> Union[dict, None]: def get_sharing_collection_by_map(self, path) -> Union[dict, None]:
""" retrieve target and attributs by map """ """ 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} return {"mapped": False}

17
radicale/storage/__init__.py
View File

@@ -25,7 +25,6 @@ Take a look at the class ``BaseCollection`` if you want to implement your own.
""" """
import json import json
import logging
import xml.etree.ElementTree as ET import xml.etree.ElementTree as ET
from hashlib import sha256 from hashlib import sha256
from typing import (Callable, ContextManager, Dict, Iterable, Iterator, List, from typing import (Callable, ContextManager, Dict, Iterable, Iterator, List,
@@ -157,17 +156,17 @@ class BaseCollection:
return return
tag, start, end, simple = radicale_filter.simplify_prefilters( tag, start, end, simple = radicale_filter.simplify_prefilters(
filters, self.tag) 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(): 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: if tag is not None and tag != item.component_name:
continue continue
istart, iend = item.time_range 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: 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 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) yield item, simple and (start <= istart or iend <= end)
def has_uid(self, uid: str) -> bool: def has_uid(self, uid: str) -> bool:
@@ -284,13 +283,11 @@ class BaseCollection:
template[template_insert_pos:]) template[template_insert_pos:])
if self.tag == "VADDRESSBOOK": if self.tag == "VADDRESSBOOK":
if vcf_to_ics: if vcf_to_ics:
if logger.isEnabledFor(logging.DEBUG): logger.trace("storage: convert VCF to ICS")
logger.debug("TRACE/storage: convert VCF to ICS")
items = [] items = []
for item in self.get_all(): for item in self.get_all():
if logger.isEnabledFor(logging.DEBUG): logger.trace("storage/convert VCF to ICS: %r:", item)
logger.debug("TRACE/storage/convert VCF to ICS: %r:", item)
item_ics = item.convert_vcf_to_ics() item_ics = item.convert_vcf_to_ics()
if item_ics is None: if item_ics is None:
continue continue