tobias/radicale
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Use module-wide logger and remove logging config

Browse Source
This commit is contained in:
Unrud 2018-08-16 07:59:55 +02:00
parent 6c9299cf16
commit 54b9995e22
15 changed files with 176 additions and 274 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
config
View File

@ -136,13 +136,7 @@
[logging]
# Logging configuration file
# If no config is given, simple information is printed on the standard output
# For more information about the syntax of the configuration file, see:
# http://docs.python.org/library/logging.config.html
#config =
# Set the default logging level to debug
# Set the logging level to debug
#debug = False
# Store all environment variables (including those set in the shell)

52
logging
View File

@ -1,52 +0,0 @@
# -*- mode: conf -*-
# vim:ft=cfg
# Logging config file for Radicale - A simple calendar server
#
# The recommended path for this file is /etc/radicale/logging
# The path must be specified in the logging section of the configuration file
#
# Some examples are included in Radicale's documentation, see:
# http://radicale.org/logging/
#
# Other handlers are available. For more information, see:
# http://docs.python.org/library/logging.config.html
# Loggers, handlers and formatters keys
[loggers]
# Loggers names, main configuration slots
keys = root
[handlers]
# Logging handlers, defining logging output methods
keys = console
[formatters]
# Logging formatters
keys = simple
# Loggers
[logger_root]
# Root logger
level = WARNING
handlers = console
# Handlers
[handler_console]
# Console handler
class = StreamHandler
args = (sys.stderr,)
formatter = simple
# Formatters
[formatter_simple]
# Simple output format
format = [%(thread)x] %(levelname)s: %(message)s

130
radicale/__init__.py
View File

@ -52,7 +52,7 @@ from xml.etree import ElementTree as ET
import vobject
from radicale import auth, config, log, rights, storage, web, xmlutils
from radicale.log import logger
VERSION = pkg_resources.get_distribution('radicale').version
@ -104,7 +104,6 @@ class HTTPServer(wsgiref.simple_server.WSGIServer):
# These class attributes must be set before creating instance
client_timeout = None
max_connections = None
logger = None
def __init__(self, address, handler, bind_and_activate=True):
"""Create server."""
@ -136,7 +135,7 @@ class HTTPServer(wsgiref.simple_server.WSGIServer):
raise
if self.client_timeout and sys.version_info < (3, 5, 2):
self.logger.warning("Using server.timeout with Python < 3.5.2 "
logger.warning("Using server.timeout with Python < 3.5.2 "
"can cause network connection failures")
def get_request(self):
@ -148,9 +147,9 @@ class HTTPServer(wsgiref.simple_server.WSGIServer):
def handle_error(self, request, client_address):
if issubclass(sys.exc_info()[0], socket.timeout):
self.logger.info("client timed out", exc_info=True)
logger.info("client timed out", exc_info=True)
else:
self.logger.error("An exception occurred during request: %s",
logger.error("An exception occurred during request: %s",
sys.exc_info()[1], exc_info=True)
@ -208,9 +207,6 @@ class ThreadedHTTPSServer(socketserver.ThreadingMixIn, HTTPSServer):
class RequestHandler(wsgiref.simple_server.WSGIRequestHandler):
"""HTTP requests handler."""
# These class attributes must be set before creating instance
logger = None
def __init__(self, *args, **kwargs):
# Store exception for logging
self.error_stream = io.StringIO()
@ -236,22 +232,21 @@ class RequestHandler(wsgiref.simple_server.WSGIRequestHandler):
# Log exception
error = self.error_stream.getvalue().strip("\n")
if error:
self.logger.error(
logger.error(
"An unhandled exception occurred during request:\n%s" % error)
class Application:
"""WSGI application managing collections."""
def __init__(self, configuration, logger):
def __init__(self, configuration):
"""Initialize application."""
super().__init__()
self.configuration = configuration
self.logger = logger
self.Auth = auth.load(configuration, logger)
self.Collection = storage.load(configuration, logger)
self.Rights = rights.load(configuration, logger)
self.Web = web.load(configuration, logger)
self.Auth = auth.load(configuration)
self.Collection = storage.load(configuration)
self.Rights = rights.load(configuration)
self.Web = web.load(configuration)
self.encoding = configuration.get("encoding", "request")
def headers_log(self, environ):
@ -321,7 +316,7 @@ class Application:
if can_write:
text_status.append("write")
write_allowed_items.append(item)
self.logger.debug(
logger.debug(
"%s has %s access to %s",
repr(user) if user else "anonymous user",
" and ".join(text_status) if text_status else "NO", target)
@ -339,7 +334,7 @@ class Application:
path = str(environ.get("PATH_INFO", ""))
except Exception:
path = ""
self.logger.error("An exception occurred during %s request on %r: "
logger.error("An exception occurred during %s request on %r: "
"%s", method, path, e, exc_info=True)
status, headers, answer = INTERNAL_SERVER_ERROR
answer = answer.encode("ascii")
@ -357,7 +352,7 @@ class Application:
# Set content length
if answer:
if hasattr(answer, "encode"):
self.logger.debug("Response content:\n%s", answer)
logger.debug("Response content:\n%s", answer)
headers["Content-Type"] += "; charset=%s" % self.encoding
answer = answer.encode(self.encoding)
accept_encoding = [
@ -381,7 +376,7 @@ class Application:
time_end = datetime.datetime.now()
status = "%d %s" % (
status, client.responses.get(status, "Unknown"))
self.logger.info(
logger.info(
"%s response status for %r%s in %.3f seconds: %s",
environ["REQUEST_METHOD"], environ.get("PATH_INFO", ""),
depthinfo, (time_end - time_begin).total_seconds(), status)
@ -403,18 +398,18 @@ class Application:
if environ.get("HTTP_DEPTH"):
depthinfo = " with depth %r" % environ["HTTP_DEPTH"]
time_begin = datetime.datetime.now()
self.logger.info(
logger.info(
"%s request for %r%s received from %s%s",
environ["REQUEST_METHOD"], environ.get("PATH_INFO", ""), depthinfo,
remote_host, remote_useragent)
headers = pprint.pformat(self.headers_log(environ))
self.logger.debug("Request headers:\n%s", headers)
logger.debug("Request headers:\n%s", headers)
# Let reverse proxies overwrite SCRIPT_NAME
if "HTTP_X_SCRIPT_NAME" in environ:
# script_name must be removed from PATH_INFO by the client.
unsafe_base_prefix = environ["HTTP_X_SCRIPT_NAME"]
self.logger.debug("Script name overwritten by client: %r",
logger.debug("Script name overwritten by client: %r",
unsafe_base_prefix)
else:
# SCRIPT_NAME is already removed from PATH_INFO, according to the
@ -422,11 +417,11 @@ class Application:
unsafe_base_prefix = environ.get("SCRIPT_NAME", "")
# Sanitize base prefix
base_prefix = storage.sanitize_path(unsafe_base_prefix).rstrip("/")
self.logger.debug("Sanitized script name: %r", base_prefix)
logger.debug("Sanitized script name: %r", base_prefix)
# Sanitize request URI (a WSGI server indicates with an empty path,
# that the URL targets the application root without a trailing slash)
path = storage.sanitize_path(environ.get("PATH_INFO", ""))
self.logger.debug("Sanitized path: %r", path)
logger.debug("Sanitized path: %r", path)
# Get function corresponding to method
function = getattr(self, "do_%s" % environ["REQUEST_METHOD"].upper())
@ -452,21 +447,21 @@ class Application:
user = self.Auth.login(login, password) or "" if login else ""
if user and login == user:
self.logger.info("Successful login: %r", user)
logger.info("Successful login: %r", user)
elif user:
self.logger.info("Successful login: %r -> %r", login, user)
logger.info("Successful login: %r -> %r", login, user)
elif login:
self.logger.info("Failed login attempt: %r", login)
logger.info("Failed login attempt: %r", login)
# Random delay to avoid timing oracles and bruteforce attacks
delay = self.configuration.getfloat("auth", "delay")
if delay > 0:
random_delay = delay * (0.5 + random.random())
self.logger.debug("Sleeping %.3f seconds", random_delay)
logger.debug("Sleeping %.3f seconds", random_delay)
time.sleep(random_delay)
if user and not storage.is_safe_path_component(user):
# Prevent usernames like "user/calendar.ics"
self.logger.info("Refused unsafe username: %r", user)
logger.info("Refused unsafe username: %r", user)
user = ""
# Create principal collection
@ -482,11 +477,11 @@ class Application:
try:
self.Collection.create_collection(principal_path)
except ValueError as e:
self.logger.warning("Failed to create principal "
logger.warning("Failed to create principal "
"collection %r: %s", user, e)
user = ""
else:
self.logger.warning("Access to principal path %r denied by "
logger.warning("Access to principal path %r denied by "
"rights backend", principal_path)
# Verify content length
@ -495,15 +490,14 @@ class Application:
max_content_length = self.configuration.getint(
"server", "max_content_length")
if max_content_length and content_length > max_content_length:
self.logger.info(
"Request body too large: %d", content_length)
logger.info("Request body too large: %d", content_length)
return response(*REQUEST_ENTITY_TOO_LARGE)
if not login or user:
status, headers, answer = function(
environ, base_prefix, path, user)
if (status, headers, answer) == NOT_ALLOWED:
self.logger.info("Access to %r denied for %s", path,
logger.info("Access to %r denied for %s", path,
repr(user) if user else "anonymous user")
else:
status, headers, answer = NOT_ALLOWED
@ -511,7 +505,7 @@ class Application:
if ((status, headers, answer) == NOT_ALLOWED and not user and
not external_login):
# Unknown or unauthorized user
self.logger.debug("Asking client for authentication")
logger.debug("Asking client for authentication")
status = client.UNAUTHORIZED
realm = self.configuration.get("server", "realm")
headers = dict(headers)
@ -547,7 +541,7 @@ class Application:
def _read_content(self, environ):
content = self.decode(self._read_raw_content(environ), environ)
self.logger.debug("Request content:\n%s", content)
logger.debug("Request content:\n%s", content)
return content
def _read_xml_content(self, environ):
@ -557,16 +551,16 @@ class Application:
try:
xml_content = ET.fromstring(content)
except ET.ParseError as e:
self.logger.debug("Request content (Invalid XML):\n%s", content)
logger.debug("Request content (Invalid XML):\n%s", content)
raise RuntimeError("Failed to parse XML: %s" % e) from e
if self.logger.isEnabledFor(logging.DEBUG):
self.logger.debug("Request content:\n%s",
if logger.isEnabledFor(logging.DEBUG):
logger.debug("Request content:\n%s",
xmlutils.pretty_xml(xml_content))
return xml_content
def _write_xml_content(self, xml_content):
if self.logger.isEnabledFor(logging.DEBUG):
self.logger.debug("Response content:\n%s",
if logger.isEnabledFor(logging.DEBUG):
logger.debug("Response content:\n%s",
xmlutils.pretty_xml(xml_content))
f = io.BytesIO()
ET.ElementTree(xml_content).write(f, encoding=self.encoding,
@ -652,11 +646,11 @@ class Application:
try:
xml_content = self._read_xml_content(environ)
except RuntimeError as e:
self.logger.warning(
logger.warning(
"Bad MKCALENDAR request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("w", user):
item = next(self.Collection.discover(path), None)
@ -679,7 +673,7 @@ class Application:
storage.check_and_sanitize_props(props)
self.Collection.create_collection(path, props=props)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad MKCALENDAR request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
return client.CREATED, {}, None
@ -691,11 +685,11 @@ class Application:
try:
xml_content = self._read_xml_content(environ)
except RuntimeError as e:
self.logger.warning(
logger.warning(
"Bad MKCOL request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("w", user):
item = next(self.Collection.discover(path), None)
@ -714,7 +708,7 @@ class Application:
storage.check_and_sanitize_props(props)
self.Collection.create_collection(path, props=props)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad MKCOL request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
return client.CREATED, {}, None
@ -724,15 +718,15 @@ class Application:
raw_dest = environ.get("HTTP_DESTINATION", "")
to_url = urlparse(raw_dest)
if to_url.netloc != environ["HTTP_HOST"]:
self.logger.info("Unsupported destination address: %r", raw_dest)
logger.info("Unsupported destination address: %r", raw_dest)
# Remote destination server, not supported
return REMOTE_DESTINATION
if not self._access(user, path, "w"):
return NOT_ALLOWED
to_path = storage.sanitize_path(to_url.path)
if not (to_path + "/").startswith(base_prefix + "/"):
self.logger.warning("Destination %r from MOVE request on %r does"
"n't start with base prefix", to_path, path)
logger.warning("Destination %r from MOVE request on %r doesn't "
"start with base prefix", to_path, path)
return NOT_ALLOWED
to_path = to_path[len(base_prefix):]
if not self._access(user, to_path, "w"):
@ -774,7 +768,7 @@ class Application:
try:
self.Collection.move(item, to_collection, to_href)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad MOVE request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
return client.NO_CONTENT if to_item else client.CREATED, {}, None
@ -794,11 +788,11 @@ class Application:
try:
xml_content = self._read_xml_content(environ)
except RuntimeError as e:
self.logger.warning(
logger.warning(
"Bad PROPFIND request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("r", user):
items = self.Collection.discover(
@ -827,11 +821,11 @@ class Application:
try:
xml_content = self._read_xml_content(environ)
except RuntimeError as e:
self.logger.warning(
logger.warning(
"Bad PROPPATCH request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("w", user):
item = next(self.Collection.discover(path), None)
@ -845,7 +839,7 @@ class Application:
xml_answer = xmlutils.proppatch(base_prefix, path, xml_content,
item)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad PROPPATCH request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
return (client.MULTI_STATUS, headers,
@ -858,11 +852,10 @@ class Application:
try:
content = self._read_content(environ)
except RuntimeError as e:
self.logger.warning(
"Bad PUT request on %r: %s", path, e, exc_info=True)
logger.warning("Bad PUT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("w", user):
parent_path = storage.sanitize_path(
@ -917,7 +910,7 @@ class Application:
if not write_whole_collection and item else None,
tag=tag)
except Exception as e:
self.logger.warning(
logger.warning(
"Bad PUT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
@ -939,7 +932,7 @@ class Application:
new_item = self.Collection.create_collection(
path, items, props)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad PUT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
else:
@ -952,7 +945,7 @@ class Application:
parent_item.set_meta_all(new_props)
new_item = parent_item.upload(href, items[0])
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad PUT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
headers = {"ETag": new_item.etag}
@ -965,11 +958,11 @@ class Application:
try:
xml_content = self._read_xml_content(environ)
except RuntimeError as e:
self.logger.warning(
logger.warning(
"Bad REPORT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
except socket.timeout as e:
self.logger.debug("client timed out", exc_info=True)
logger.debug("client timed out", exc_info=True)
return REQUEST_TIMEOUT
with self.Collection.acquire_lock("r", user):
item = next(self.Collection.discover(path), None)
@ -986,7 +979,7 @@ class Application:
status, xml_answer = xmlutils.report(
base_prefix, path, xml_content, collection)
except ValueError as e:
self.logger.warning(
logger.warning(
"Bad REPORT request on %r: %s", path, e, exc_info=True)
return BAD_REQUEST
return (status, headers, self._write_xml_content(xml_answer))
@ -1002,13 +995,12 @@ def _init_application(config_path):
with _application_lock:
if _application is not None:
return
log.setup()
_application_config_path = config_path
configuration = config.load([config_path] if config_path else [],
ignore_missing_paths=False)
filename = os.path.expanduser(configuration.get("logging", "config"))
debug = configuration.getboolean("logging", "debug")
logger = log.start("radicale", filename, debug)
_application = Application(configuration, logger)
log.set_debug(configuration.getboolean("logging", "debug"))
_application = Application(configuration)
def application(environ, start_response):

41
radicale/__main__.py
View File

@ -34,10 +34,13 @@ from wsgiref.simple_server import make_server
from radicale import (VERSION, Application, RequestHandler, ThreadedHTTPServer,
ThreadedHTTPSServer, config, log, storage)
from radicale.log import logger
def run():
"""Run Radicale as a standalone server."""
log.setup()
# Get command-line arguments
parser = argparse.ArgumentParser(usage="radicale [OPTIONS]")
@ -79,6 +82,10 @@ def run():
group.add_argument(*args, **kwargs)
args = parser.parse_args()
# Preliminary configure logging
log.set_debug(args.logging_debug)
if args.config is not None:
config_paths = [args.config] if args.config else []
ignore_missing_paths = False
@ -92,9 +99,7 @@ def run():
configuration = config.load(config_paths,
ignore_missing_paths=ignore_missing_paths)
except Exception as e:
print("ERROR: Invalid configuration: %s" % e, file=sys.stderr)
if args.logging_debug:
raise
log.error("Invalid configuration: %s", e, exc_info=True)
exit(1)
# Update Radicale configuration according to arguments
@ -105,25 +110,13 @@ def run():
if value is not None:
configuration.set(section, action.split('_', 1)[1], value)
if args.verify_storage:
# Write to stderr when storage verification is requested
configuration["logging"]["config"] = ""
# Start logging
filename = os.path.expanduser(configuration.get("logging", "config"))
debug = configuration.getboolean("logging", "debug")
try:
logger = log.start("radicale", filename, debug)
except Exception as e:
print("ERROR: Failed to start logger: %s" % e, file=sys.stderr)
if debug:
raise
exit(1)
# Configure logging
log.set_debug(configuration.getboolean("logging", "debug"))
if args.verify_storage:
logger.info("Verifying storage")
try:
Collection = storage.load(configuration, logger)
Collection = storage.load(configuration)
with Collection.acquire_lock("r"):
if not Collection.verify():
logger.error("Storage verifcation failed")
@ -135,14 +128,14 @@ def run():
return
try:
serve(configuration, logger)
serve(configuration)
except Exception as e:
logger.error("An exception occurred during server startup: %s", e,
exc_info=True)
exit(1)
def daemonize(configuration, logger):
def daemonize(configuration):
"""Fork and decouple if Radicale is configured as daemon."""
# Check and create PID file in a race-free manner
if configuration.get("server", "pid"):
@ -181,7 +174,7 @@ def daemonize(configuration, logger):
os.dup2(null_out.fileno(), sys.stderr.fileno())
def serve(configuration, logger):
def serve(configuration):
"""Serve radicale from configuration."""
logger.info("Starting Radicale")
@ -211,9 +204,7 @@ def serve(configuration, logger):
server_class.client_timeout = configuration.getint("server", "timeout")
server_class.max_connections = configuration.getint(
"server", "max_connections")
server_class.logger = logger
RequestHandler.logger = logger
if not configuration.getboolean("server", "dns_lookup"):
RequestHandler.address_string = lambda self: self.client_address[0]
@ -226,7 +217,7 @@ def serve(configuration, logger):
except ValueError as e:
raise RuntimeError(
"Failed to parse address %r: %s" % (host, e)) from e
application = Application(configuration, logger)
application = Application(configuration)
try:
server = make_server(
address, port, application, server_class, RequestHandler)
@ -270,7 +261,7 @@ def serve(configuration, logger):
# Fallback to busy waiting. (select.select blocks SIGINT on Windows.)
select_timeout = 1.0
if configuration.getboolean("server", "daemon"):
daemonize(configuration, logger)
daemonize(configuration)
logger.info("Radicale server ready")
while not shutdown_program:
try:

13
radicale/auth.py
View File

@ -60,11 +60,13 @@ import hmac
import os
from importlib import import_module
from radicale.log import logger
INTERNAL_TYPES = ("None", "none", "remote_user", "http_x_remote_user",
"htpasswd")
def load(configuration, logger):
def load(configuration):
"""Load the authentication manager chosen in configuration."""
auth_type = configuration.get("auth", "type")
if auth_type in ("None", "none"): # DEPRECATED: use "none"
@ -82,13 +84,12 @@ def load(configuration, logger):
raise RuntimeError("Failed to load authentication module %r: %s" %
(auth_type, e)) from e
logger.info("Authentication type is %r", auth_type)
return class_(configuration, logger)
return class_(configuration)
class BaseAuth:
def __init__(self, configuration, logger):
def __init__(self, configuration):
self.configuration = configuration
self.logger = logger
def get_external_login(self, environ):
"""Optionally provide the login and password externally.
@ -149,8 +150,8 @@ class NoneAuth(BaseAuth):
class Auth(BaseAuth):
def __init__(self, configuration, logger):
super().__init__(configuration, logger)
def __init__(self, configuration):
super().__init__(configuration)
self.filename = os.path.expanduser(
configuration.get("auth", "htpasswd_filename"))
self.encryption = configuration.get("auth", "htpasswd_encryption")

4
radicale/config.py
View File

@ -192,10 +192,6 @@ INITIAL_CONFIG = OrderedDict([
"type": str,
"internal": web.INTERNAL_TYPES})])),
("logging", OrderedDict([
("config", {
"value": "",
"help": "logging configuration file",
"type": str}),
("debug", {
"value": "False",
"help": "print debug information",

69
radicale/log.py
View File

@ -23,18 +23,15 @@ http://docs.python.org/library/logging.config.html
"""
import logging
import logging.config
import signal
import sys
import threading
def configure_from_file(logger, filename, debug):
logging.config.fileConfig(filename, disable_existing_loggers=False)
if debug:
logger.setLevel(logging.DEBUG)
for handler in logger.handlers:
handler.setLevel(logging.DEBUG)
return logger
LOGGER_NAME = "radicale"
LOGGER_FORMAT = "[%(processName)s/%(threadName)s] %(levelname)s: %(message)s"
root_logger = logging.getLogger()
logger = logging.getLogger(LOGGER_NAME)
class RemoveTracebackFilter(logging.Filter):
@ -43,33 +40,29 @@ class RemoveTracebackFilter(logging.Filter):
return True
def start(name="radicale", filename=None, debug=False):
"""Start the logging according to the configuration."""
logger = logging.getLogger(name)
if debug:
logger.setLevel(logging.DEBUG)
else:
logger.addFilter(RemoveTracebackFilter())
if filename:
# Configuration taken from file
try:
configure_from_file(logger, filename, debug)
except Exception as e:
raise RuntimeError("Failed to load logging configuration file %r: "
"%s" % (filename, e)) from e
# Reload config on SIGHUP (UNIX only)
if hasattr(signal, "SIGHUP"):
def handler(signum, frame):
try:
configure_from_file(logger, filename, debug)
except Exception as e:
logger.error("Failed to reload logging configuration file "
"%r: %s", filename, e, exc_info=True)
signal.signal(signal.SIGHUP, handler)
else:
# Default configuration, standard output
removeTracebackFilter = RemoveTracebackFilter()
def get_default_handler():
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(
logging.Formatter("[%(thread)x] %(levelname)s: %(message)s"))
logger.addHandler(handler)
return logger
return handler
def setup():
"""Set global logging up."""
global register_stream, unregister_stream
handler = get_default_handler()
logging.basicConfig(format=LOGGER_FORMAT, handlers=[handler])
set_debug(True)
def set_debug(debug):
"""Set debug mode for global logger."""
if debug:
root_logger.setLevel(logging.DEBUG)
logger.setLevel(logging.DEBUG)
logger.removeFilter(removeTracebackFilter)
else:
root_logger.setLevel(logging.WARNING)
logger.setLevel(logging.WARNING)
logger.addFilter(removeTracebackFilter)

21
radicale/rights.py
View File

@ -44,12 +44,13 @@ import re
from importlib import import_module
from radicale import storage
from radicale.log import logger
INTERNAL_TYPES = ("None", "none", "authenticated", "owner_write", "owner_only",
"from_file")
def load(configuration, logger):
def load(configuration):
"""Load the rights manager chosen in configuration."""
rights_type = configuration.get("rights", "type")
if configuration.get("auth", "type") in ("None", "none"): # DEPRECATED
@ -71,13 +72,12 @@ def load(configuration, logger):
raise RuntimeError("Failed to load rights module %r: %s" %
(rights_type, e)) from e
logger.info("Rights type is %r", rights_type)
return rights_class(configuration, logger)
return rights_class(configuration)
class BaseRights:
def __init__(self, configuration, logger):
def __init__(self, configuration):
self.configuration = configuration
self.logger = logger
def authorized(self, user, path, permission):
"""Check if the user is allowed to read or write the collection.
@ -131,8 +131,8 @@ class OwnerOnlyRights(BaseRights):
class Rights(BaseRights):
def __init__(self, configuration, logger):
super().__init__(configuration, logger)
def __init__(self, configuration):
super().__init__(configuration)
self.filename = os.path.expanduser(configuration.get("rights", "file"))
def authorized(self, user, path, permission):
@ -163,14 +163,13 @@ class Rights(BaseRights):
raise RuntimeError("Error in section %r of rights file %r: "
"%s" % (section, self.filename, e)) from e
if user_match and collection_match:
self.logger.debug("Rule %r:%r matches %r:%r from section %r",
logger.debug("Rule %r:%r matches %r:%r from section %r",
user, sane_path, re_user_pattern,
re_collection_pattern, section)
return permission in regex.get(section, "permission")
else:
self.logger.debug("Rule %r:%r doesn't match %r:%r from section"
" %r", user, sane_path, re_user_pattern,
logger.debug("Rule %r:%r doesn't match %r:%r from section %r",
user, sane_path, re_user_pattern,
re_collection_pattern, section)
self.logger.info(
"Rights: %r:%r doesn't match any section", user, sane_path)
logger.info("Rights: %r:%r doesn't match any section", user, sane_path)
return False

43
radicale/storage.py
View File

@ -47,6 +47,8 @@ from tempfile import NamedTemporaryFile, TemporaryDirectory
import vobject
from radicale.log import logger
if sys.version_info >= (3, 5):
# HACK: Avoid import cycle for Python < 3.5
from radicale import xmlutils
@ -93,7 +95,7 @@ elif os.name == "posix":
INTERNAL_TYPES = ("multifilesystem",)
def load(configuration, logger):
def load(configuration):
"""Load the storage manager chosen in configuration."""
if sys.version_info < (3, 5):
# HACK: Avoid import cycle for Python < 3.5
@ -113,7 +115,6 @@ def load(configuration, logger):
class CollectionCopy(collection_class):
"""Collection copy, avoids overriding the original class attributes."""
CollectionCopy.configuration = configuration
CollectionCopy.logger = logger
CollectionCopy.static_init()
return CollectionCopy
@ -429,7 +430,6 @@ class BaseCollection:
# Overriden on copy by the "load" function
configuration = None
logger = None
# Properties of instance
"""The sanitized path of the collection without leading or trailing ``/``.
@ -883,7 +883,7 @@ class Collection(BaseCollection):
filesystem_path = path_to_filesystem(folder, sane_path)
except ValueError as e:
# Path is unsafe
cls.logger.debug("Unsafe path %r requested from storage: %s",
logger.debug("Unsafe path %r requested from storage: %s",
sane_path, e, exc_info=True)
return
@ -915,8 +915,8 @@ class Collection(BaseCollection):
for href in scandir(filesystem_path, only_dirs=True):
if not is_safe_filesystem_path_component(href):
if not href.startswith(".Radicale"):
cls.logger.debug("Skipping collection %r in %r", href,
sane_path)
logger.debug("Skipping collection %r in %r",
href, sane_path)
continue
child_path = posixpath.join(sane_path, href)
with child_context_manager(child_path):
@ -938,12 +938,12 @@ class Collection(BaseCollection):
else:
collection_errors += 1
name = "collection %r" % path.strip("/")
cls.logger.error("Invalid %s: %s", name, e, exc_info=True)
logger.error("Invalid %s: %s", name, e, exc_info=True)
remaining_paths = [""]
while remaining_paths:
path = remaining_paths.pop(0)
cls.logger.debug("Verifying collection %r", path)
logger.debug("Verifying collection %r", path)
with exception_cm(path):
saved_item_errors = item_errors
collection = None
@ -955,8 +955,7 @@ class Collection(BaseCollection):
if isinstance(item, BaseCollection):
remaining_paths.append(item.path)
else:
cls.logger.debug("Verified item %r in %r",
item.href, path)
logger.debug("Verified item %r in %r", item.href, path)
if item_errors == saved_item_errors:
collection.sync()
return item_errors == 0 and collection_errors == 0
@ -1107,7 +1106,7 @@ class Collection(BaseCollection):
continue
if mtime > age_limit:
continue
cls.logger.debug("Found expired item in cache: %r", name)
logger.debug("Found expired item in cache: %r", name)
# Race: Another process might have deleted or locked the
# file.
try:
@ -1133,7 +1132,7 @@ class Collection(BaseCollection):
cache_etag, history_etag = pickle.load(f)
except (FileNotFoundError, pickle.UnpicklingError, ValueError) as e:
if isinstance(e, (pickle.UnpicklingError, ValueError)):
self.logger.warning(
logger.warning(
"Failed to load history cache entry %r in %r: %s",
href, self.path, e, exc_info=True)
cache_etag = ""
@ -1225,7 +1224,7 @@ class Collection(BaseCollection):
except (FileNotFoundError, pickle.UnpicklingError,
ValueError) as e:
if isinstance(e, (pickle.UnpicklingError, ValueError)):
self.logger.warning(
logger.warning(
"Failed to load stored sync token %r in %r: %s",
old_token_name, self.path, e, exc_info=True)
# Delete the damaged file
@ -1273,8 +1272,7 @@ class Collection(BaseCollection):
for href in scandir(self._filesystem_path, only_files=True):
if not is_safe_filesystem_path_component(href):
if not href.startswith(".Radicale"):
self.logger.debug(
"Skipping item %r in %r", href, self.path)
logger.debug("Skipping item %r in %r", href, self.path)
continue
yield href
@ -1356,8 +1354,7 @@ class Collection(BaseCollection):
except FileNotFoundError as e:
pass
except (pickle.UnpicklingError, ValueError) as e:
self.logger.warning(
"Failed to load item cache entry %r in %r: %s",
logger.warning("Failed to load item cache entry %r in %r: %s",
href, self.path, e, exc_info=True)
return cache_hash, uid, etag, text, name, tag, start, end
@ -1378,7 +1375,7 @@ class Collection(BaseCollection):
raise UnsafePathError(href)
path = path_to_filesystem(self._filesystem_path, href)
except ValueError as e:
self.logger.debug(
logger.debug(
"Can't translate name %r safely to filesystem in %r: %s",
href, self.path, e, exc_info=True)
return None, None
@ -1452,7 +1449,7 @@ class Collection(BaseCollection):
path = os.path.join(self._filesystem_path, href)
if (not is_safe_filesystem_path_component(href) or
href not in files and os.path.lexists(path)):
self.logger.debug(
logger.debug(
"Can't translate name safely to filesystem: %r", href)
yield (href, None)
else:
@ -1570,8 +1567,8 @@ class Collection(BaseCollection):
if mode == "w" and hook:
folder = os.path.expanduser(cls.configuration.get(
"storage", "filesystem_folder"))
cls.logger.debug("Running hook")
debug = cls.logger.isEnabledFor(logging.DEBUG)
logger.debug("Running hook")
debug = logger.isEnabledFor(logging.DEBUG)
p = subprocess.Popen(
hook % {"user": shlex.quote(user or "Anonymous")},
stdin=subprocess.DEVNULL,
@ -1580,9 +1577,9 @@ class Collection(BaseCollection):
shell=True, universal_newlines=True, cwd=folder)
stdout_data, stderr_data = p.communicate()
if stdout_data:
cls.logger.debug("Captured stdout hook:\n%s", stdout_data)
logger.debug("Captured stdout hook:\n%s", stdout_data)
if stderr_data:
cls.logger.debug("Captured stderr hook:\n%s", stderr_data)
logger.debug("Captured stderr hook:\n%s", stderr_data)
if p.returncode != 0:
raise subprocess.CalledProcessError(p.returncode, p.args)

9
radicale/tests/__init__.py
View File

@ -19,24 +19,15 @@ Tests for Radicale.
"""
import logging
import os
import sys
from io import BytesIO
sys.path.insert(0, os.path.dirname(os.path.dirname(__file__)))
logger = logging.getLogger("radicale_test")
if not logger.hasHandlers():
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
class BaseTest:
"""Base class for tests."""
logger = logger
def request(self, method, path, data=None, **args):
"""Send a request."""

8
radicale/tests/test_auth.py
View File

@ -61,7 +61,7 @@ class TestBaseAuthRequests(BaseTest):
self.configuration["auth"]["type"] = "htpasswd"
self.configuration["auth"]["htpasswd_filename"] = htpasswd_file_path
self.configuration["auth"]["htpasswd_encryption"] = htpasswd_encryption
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
if test_matrix is None:
test_matrix = (
("tmp", "bepo", 207), ("tmp", "tmp", 401), ("tmp", "", 401),
@ -131,7 +131,7 @@ class TestBaseAuthRequests(BaseTest):
def test_remote_user(self):
self.configuration["auth"]["type"] = "remote_user"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
status, _, answer = self.request(
"PROPFIND", "/",
"""<?xml version="1.0" encoding="utf-8"?>
@ -145,7 +145,7 @@ class TestBaseAuthRequests(BaseTest):
def test_http_x_remote_user(self):
self.configuration["auth"]["type"] = "http_x_remote_user"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
status, _, answer = self.request(
"PROPFIND", "/",
"""<?xml version="1.0" encoding="utf-8"?>
@ -160,7 +160,7 @@ class TestBaseAuthRequests(BaseTest):
def test_custom(self):
"""Custom authentication."""
self.configuration["auth"]["type"] = "tests.custom.auth"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
status, _, answer = self.request(
"PROPFIND", "/tmp", HTTP_AUTHORIZATION="Basic %s" %
base64.b64encode(("tmp:").encode()).decode())

4
radicale/tests/test_base.py
View File

@ -1396,7 +1396,7 @@ class BaseRequestsMixIn:
self.configuration["auth"]["htpasswd_filename"] = os.devnull
self.configuration["auth"]["htpasswd_encryption"] = "plain"
self.configuration["rights"]["type"] = "owner_only"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
status, headers, _ = self.request("MKCOL", "/user/")
assert status in (401, 403)
assert headers.get("WWW-Authenticate")
@ -1479,7 +1479,7 @@ class BaseFileSystemTest(BaseTest):
self.configuration["storage"]["filesystem_fsync"] = "False"
# Required on Windows, doesn't matter on Unix
self.configuration["storage"]["filesystem_close_lock_file"] = "True"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
def teardown(self):
shutil.rmtree(self.colpath)

2
radicale/tests/test_rights.py
View File

@ -53,7 +53,7 @@ class TestBaseAuthRequests(BaseTest):
self.configuration["auth"]["type"] = "htpasswd"
self.configuration["auth"]["htpasswd_filename"] = htpasswd_file_path
self.configuration["auth"]["htpasswd_encryption"] = "plain"
self.application = Application(self.configuration, self.logger)
self.application = Application(self.configuration)
for u in ("tmp", "other"):
status, _, _ = self.request(
"PROPFIND", "/%s" % u, HTTP_AUTHORIZATION="Basic %s" %

14
radicale/web.py
View File

@ -23,6 +23,7 @@ from importlib import import_module
import pkg_resources
from radicale import storage
from radicale.log import logger
NOT_FOUND = (
client.NOT_FOUND, (("Content-Type", "text/plain"),),
@ -47,7 +48,7 @@ FALLBACK_MIMETYPE = "application/octet-stream"
INTERNAL_TYPES = ("None", "none", "internal")
def load(configuration, logger):
def load(configuration):
"""Load the web module chosen in configuration."""
web_type = configuration.get("web", "type")
if web_type in ("None", "none"): # DEPRECATED: use "none"
@ -61,13 +62,12 @@ def load(configuration, logger):
raise RuntimeError("Failed to load web module %r: %s" %
(web_type, e)) from e
logger.info("Web type is %r", web_type)
return web_class(configuration, logger)
return web_class(configuration)
class BaseWeb:
def __init__(self, configuration, logger):
def __init__(self, configuration):
self.configuration = configuration
self.logger = logger
def get(self, environ, base_prefix, path, user):
"""GET request.
@ -90,8 +90,8 @@ class NoneWeb(BaseWeb):
class Web(BaseWeb):
def __init__(self, configuration, logger):
super().__init__(configuration, logger)
def __init__(self, configuration):
super().__init__(configuration)
self.folder = pkg_resources.resource_filename(__name__, "web")
def get(self, environ, base_prefix, path, user):
@ -99,7 +99,7 @@ class Web(BaseWeb):
filesystem_path = storage.path_to_filesystem(
self.folder, path[len("/.web"):])
except ValueError as e:
self.logger.debug("Web content with unsafe path %r requested: %s",
logger.debug("Web content with unsafe path %r requested: %s",
path, e, exc_info=True)
return NOT_FOUND
if os.path.isdir(filesystem_path) and not path.endswith("/"):

6
radicale/xmlutils.py
View File

@ -38,6 +38,7 @@ from itertools import chain
from urllib.parse import quote, unquote, urlparse
from radicale import storage
from radicale.log import logger
MIMETYPES = {
"VADDRESSBOOK": "text/vcard",
@ -173,7 +174,7 @@ def _comp_match(item, filter_, level=0):
elif level == 1:
tag = item.component_name
else:
item.collection.logger.warning(
logger.warning(
"Filters with three levels of comp-filter are not supported")
return True
if not tag:
@ -190,7 +191,7 @@ def _comp_match(item, filter_, level=0):
return False
if (level == 0 and name != "VCALENDAR" or
level == 1 and name not in ("VTODO", "VEVENT", "VJOURNAL")):
item.collection.logger.warning("Filtering %s is not supported" % name)
logger.warning("Filtering %s is not supported" % name)
return True
# Point #3 and #4 of rfc4791-9.7.1
components = ([item.item] if level == 0
@ -1131,7 +1132,6 @@ def report(base_prefix, path, xml_request, collection):
Read rfc3253-3.6 for info.
"""
logger = collection.logger
multistatus = ET.Element(_tag("D", "multistatus"))
if xml_request is None:
return client.MULTI_STATUS, multistatus