From 54b9995e22c7d30d3cd5c99ecd98a5f3ba103b2b Mon Sep 17 00:00:00 2001 From: Unrud Date: Thu, 16 Aug 2018 07:59:55 +0200 Subject: [PATCH] Use module-wide logger and remove logging config --- config | 8 +- logging | 52 ------------ radicale/__init__.py | 148 ++++++++++++++++------------------ radicale/__main__.py | 41 ++++------ radicale/auth.py | 13 +-- radicale/config.py | 4 - radicale/log.py | 65 +++++++-------- radicale/rights.py | 27 +++---- radicale/storage.py | 47 +++++------ radicale/tests/__init__.py | 9 --- radicale/tests/test_auth.py | 8 +- radicale/tests/test_base.py | 4 +- radicale/tests/test_rights.py | 2 +- radicale/web.py | 16 ++-- radicale/xmlutils.py | 6 +- 15 files changed, 176 insertions(+), 274 deletions(-) delete mode 100644 logging diff --git a/config b/config index fc37502..b700882 100644 --- a/config +++ b/config @@ -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) diff --git a/logging b/logging deleted file mode 100644 index 72f40db..0000000 --- a/logging +++ /dev/null @@ -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 diff --git a/radicale/__init__.py b/radicale/__init__.py index 20d8a8c..2b705c8 100644 --- a/radicale/__init__.py +++ b/radicale/__init__.py @@ -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,8 +135,8 @@ 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 " - "can cause network connection failures") + logger.warning("Using server.timeout with Python < 3.5.2 " + "can cause network connection failures") def get_request(self): # Set timeout for client @@ -148,10 +147,10 @@ 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", - sys.exc_info()[1], exc_info=True) + logger.error("An exception occurred during request: %s", + sys.exc_info()[1], exc_info=True) class HTTPSServer(HTTPServer): @@ -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,8 +334,8 @@ class Application: path = str(environ.get("PATH_INFO", "")) except Exception: path = "" - self.logger.error("An exception occurred during %s request on %r: " - "%s", method, path, e, exc_info=True) + 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") status = "%d %s" % ( @@ -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,30 +398,30 @@ 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", - unsafe_base_prefix) + logger.debug("Script name overwritten by client: %r", + unsafe_base_prefix) else: # SCRIPT_NAME is already removed from PATH_INFO, according to the # WSGI specification. 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,12 +477,12 @@ class Application: try: self.Collection.create_collection(principal_path) except ValueError as e: - self.logger.warning("Failed to create principal " - "collection %r: %s", user, e) + logger.warning("Failed to create principal " + "collection %r: %s", user, e) user = "" else: - self.logger.warning("Access to principal path %r denied by " - "rights backend", principal_path) + logger.warning("Access to principal path %r denied by " + "rights backend", principal_path) # Verify content length content_length = int(environ.get("CONTENT_LENGTH") or 0) @@ -495,23 +490,22 @@ 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, - repr(user) if user else "anonymous user") + logger.info("Access to %r denied for %s", path, + repr(user) if user else "anonymous user") else: status, headers, answer = NOT_ALLOWED 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,17 +551,17 @@ 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", - xmlutils.pretty_xml(xml_content)) + 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", - xmlutils.pretty_xml(xml_content)) + 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, xml_declaration=True) @@ -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): diff --git a/radicale/__main__.py b/radicale/__main__.py index 510078d..be1697e 100644 --- a/radicale/__main__.py +++ b/radicale/__main__.py @@ -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: diff --git a/radicale/auth.py b/radicale/auth.py index 16704bb..119cdad 100644 --- a/radicale/auth.py +++ b/radicale/auth.py @@ -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") diff --git a/radicale/config.py b/radicale/config.py index 7f94d5a..2f9d585 100644 --- a/radicale/config.py +++ b/radicale/config.py @@ -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", diff --git a/radicale/log.py b/radicale/log.py index e803a19..3e28188 100644 --- a/radicale/log.py +++ b/radicale/log.py @@ -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) +removeTracebackFilter = RemoveTracebackFilter() + + +def get_default_handler(): + handler = logging.StreamHandler(sys.stderr) + 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: - 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 - handler = logging.StreamHandler(sys.stderr) - handler.setFormatter( - logging.Formatter("[%(thread)x] %(levelname)s: %(message)s")) - logger.addHandler(handler) - return logger + root_logger.setLevel(logging.WARNING) + logger.setLevel(logging.WARNING) + logger.addFilter(removeTracebackFilter) diff --git a/radicale/rights.py b/radicale/rights.py index 4e1e69a..6881c3d 100644 --- a/radicale/rights.py +++ b/radicale/rights.py @@ -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", - user, sane_path, re_user_pattern, - re_collection_pattern, section) + 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, - re_collection_pattern, section) - self.logger.info( - "Rights: %r:%r doesn't match any section", user, sane_path) + logger.debug("Rule %r:%r doesn't match %r:%r from section %r", + user, sane_path, re_user_pattern, + re_collection_pattern, section) + logger.info("Rights: %r:%r doesn't match any section", user, sane_path) return False diff --git a/radicale/storage.py b/radicale/storage.py index 14faec1..30621c4 100644 --- a/radicale/storage.py +++ b/radicale/storage.py @@ -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,8 +883,8 @@ 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", - sane_path, e, exc_info=True) + logger.debug("Unsafe path %r requested from storage: %s", + sane_path, e, exc_info=True) return # Check if the path exists and if it leads to a collection or an item @@ -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,9 +1354,8 @@ 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", - href, self.path, e, exc_info=True) + 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 def _clean_item_cache(self): @@ -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) diff --git a/radicale/tests/__init__.py b/radicale/tests/__init__.py index bb8e586..9381938 100644 --- a/radicale/tests/__init__.py +++ b/radicale/tests/__init__.py @@ -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.""" diff --git a/radicale/tests/test_auth.py b/radicale/tests/test_auth.py index a70693b..7c8b36d 100644 --- a/radicale/tests/test_auth.py +++ b/radicale/tests/test_auth.py @@ -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", "/", """ @@ -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", "/", """ @@ -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()) diff --git a/radicale/tests/test_base.py b/radicale/tests/test_base.py index 1d3941c..dcd902f 100644 --- a/radicale/tests/test_base.py +++ b/radicale/tests/test_base.py @@ -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) diff --git a/radicale/tests/test_rights.py b/radicale/tests/test_rights.py index dfe196b..b8bbf9f 100644 --- a/radicale/tests/test_rights.py +++ b/radicale/tests/test_rights.py @@ -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" % diff --git a/radicale/web.py b/radicale/web.py index d6778ce..74dba9f 100644 --- a/radicale/web.py +++ b/radicale/web.py @@ -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,8 +99,8 @@ 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", - path, e, exc_info=True) + 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("/"): location = posixpath.basename(path) + "/" diff --git a/radicale/xmlutils.py b/radicale/xmlutils.py index 2d311e3..d7dac0a 100644 --- a/radicale/xmlutils.py +++ b/radicale/xmlutils.py @@ -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