From 3382d23d85c9cdaae049453f3e414ada757b6431 Mon Sep 17 00:00:00 2001 From: s3lph Date: Sat, 14 Jul 2018 00:15:19 +0200 Subject: [PATCH] Basic logging implementation; still undocumented. --- matemat/webserver/config.py | 34 +++++++- matemat/webserver/httpd.py | 77 +++++++++++++++---- matemat/webserver/test/abstract_httpd_test.py | 7 ++ matemat/webserver/test/test_serve.py | 4 +- 4 files changed, 103 insertions(+), 19 deletions(-) diff --git a/matemat/webserver/config.py b/matemat/webserver/config.py index c2e1c5f..222f431 100644 --- a/matemat/webserver/config.py +++ b/matemat/webserver/config.py @@ -1,10 +1,35 @@ -from typing import Any, Dict, Iterable, List, Union +from typing import Any, Dict, Iterable, List, Tuple, Union import os +import io +import sys +import logging from configparser import ConfigParser +def parse_logging(symbolic_level: str, symbolic_target: str) -> Tuple[int, Union[str, io.TextIOWrapper]]: + level: int = logging.NOTSET + try: + level = int(symbolic_level) + except ValueError: + try: + level = int(logging.getLevelName(symbolic_level)) + except KeyError: + pass + except ValueError: + pass + if symbolic_target == 'stderr': + target: Union[str, io.TextIOWrapper] = sys.stderr + elif symbolic_target == 'stdout': + target = sys.stdout + elif symbolic_target == 'none': + target = None + else: + target = os.path.abspath(os.path.expanduser(symbolic_target)) + return level, target + + def parse_config_file(paths: Union[str, Iterable[str]]) -> Dict[str, Any]: """ Parse the configuration file at the given path. @@ -22,6 +47,10 @@ def parse_config_file(paths: Union[str, Iterable[str]]) -> Dict[str, Any]: 'staticroot': '/var/matemat/static', # Root directory of Jinja2 templates 'templateroot': '/var/matemat/templates', + # Log level + 'loglevel': logging.INFO, + # Log target: An IO stream (stderr, stdout, ...) or a filename + 'logtarget': sys.stderr, # Variables passed to pagelets 'pagelet_variables': dict() } @@ -47,6 +76,9 @@ def parse_config_file(paths: Union[str, Iterable[str]]) -> Dict[str, Any]: config['listen'] = parser['Matemat'].get('Address', config['listen']) config['port'] = int(parser['Matemat'].get('Port', config['port'])) config['staticroot'] = parser['Matemat'].get('StaticPath', os.path.expanduser(config['staticroot'])) + config['loglevel'], config['logtarget'] =\ + parse_logging(parser['Matemat'].get('LogLevel', config['loglevel']), + parser['Matemat'].get('LogTarget', config['logtarget'])) config['templateroot'] = parser['Matemat'].get('TemplatePath', os.path.expanduser(config['templateroot'])) # Read all values from the [Pagelets] section, if present. These values are passed to pagelet functions diff --git a/matemat/webserver/httpd.py b/matemat/webserver/httpd.py index 2d5194d..34da277 100644 --- a/matemat/webserver/httpd.py +++ b/matemat/webserver/httpd.py @@ -1,8 +1,9 @@ from typing import Any, Callable, Dict, Tuple, Type, Union -import traceback - +from io import TextIOWrapper +import logging +import sys import os import socket import mimetypes @@ -25,9 +26,6 @@ from matemat.webserver.util import parse_args # Enable IPv6 support (IPv6/IPv4 dual-stack support should be implicitly enabled) TCPServer.address_family = socket.AF_INET6 -# Redirect internal logging to somewhere else, or, for now, silently discard (TODO: logger will come later) -BaseHTTPRequestHandler.log_request = lambda self, code='-', size='-': None -BaseHTTPRequestHandler.log_error = lambda self, fstring='', *args: None # Dictionary to hold registered pagelet paths and their handler functions _PAGELET_PATHS: Dict[str, Callable[[str, # HTTP method (GET, POST, ...) @@ -107,6 +105,8 @@ class MatematHTTPServer(HTTPServer): staticroot: str, templateroot: str, pagelet_variables: Dict[str, str], + log_level: int = logging.INFO, + log_target: Union[str, TextIOWrapper] = sys.stderr, bind_and_activate: bool = True) -> None: super().__init__(server_address, handler, bind_and_activate) # Resolve webroot directory @@ -119,6 +119,19 @@ class MatematHTTPServer(HTTPServer): self.jinja_env: jinja2.Environment = jinja2.Environment( loader=jinja2.FileSystemLoader(os.path.abspath(templateroot)) ) + # Set up logger + self.logger: logging.Logger = logging.getLogger('matemat.webserver') + self.logger.setLevel(log_level) + # Set up log handler that logs to + sh: logging.Handler = logging.StreamHandler(sys.stderr) + if log_target is None: + sh: logging.Handler = logging.NullHandler() + elif isinstance(log_target, TextIOWrapper): + sh = logging.StreamHandler(log_target) + elif isinstance(log_target, str): + sh = logging.FileHandler(log_target) + sh.setFormatter(logging.Formatter('%(asctime)s @ %(name)s [%(levelname)s]: %(message)s')) + self.logger.addHandler(sh) class MatematWebserver(object): @@ -141,7 +154,9 @@ class MatematWebserver(object): port: int, staticroot: str, templateroot: str, - pagelet_variables: Dict[str, str]) -> None: + pagelet_variables: Dict[str, str], + loglevel: int, + logtarget: Union[str, TextIOWrapper]) -> None: """ Instantiate a MatematWebserver. @@ -150,13 +165,21 @@ class MatematWebserver(object): :param staticroot: Path to the static webroot directory. :param templateroot: Path to the Jinja2 templates root directory. :param pagelet_variables: Dictionary of variables to pass to pagelet functions. + :param loglevel: The log level, as defined in the builtin logging module. + :param logtarget: The logging target. """ # IPv4 address detection heuristic if ':' not in listen and '.' in listen: # Rewrite IPv4 address to IPv6-mapped form listen = f'::ffff:{listen}' # Create the http server - self._httpd = MatematHTTPServer((listen, port), HttpHandler, staticroot, templateroot, pagelet_variables) + self._httpd = MatematHTTPServer((listen, port), + HttpHandler, + staticroot, + templateroot, + pagelet_variables, + loglevel, + logtarget) def start(self) -> None: """ @@ -198,10 +221,12 @@ class HttpHandler(BaseHTTPRequestHandler): # If there is no active session, create a new session ID if session_id is None or session_id not in self.server.session_vars: session_id = str(uuid4()) + self.server.logger.debug('Started session %s', session_id) # Check for session timeout if session_id in self.server.session_vars and self.server.session_vars[session_id][0] < now: self._end_session(session_id) + self.server.logger.debug('Session %s timed out', session_id) raise TimeoutError('Session timed out.') # Update or initialize the session timeout if session_id not in self.server.session_vars: @@ -362,15 +387,21 @@ class HttpHandler(BaseHTTPRequestHandler): # Special handling for some errors except HttpException as e: self.send_error(e.status, e.title, e.message) - except PermissionError: + if 500 <= e.status < 600: + self.send_error(500, 'Internal Server Error') + self.server.logger.exception('', exc_info=e) + else: + self.server.logger.debug('', exc_info=e) + except PermissionError as e: self.send_error(403, 'Forbidden') - except ValueError: + self.server.logger.debug('', exc_info=e) + except ValueError as e: self.send_error(400, 'Bad Request') + self.server.logger.debug('', exc_info=e) except BaseException as e: # Generic error handling self.send_error(500, 'Internal Server Error') - print(e) - traceback.print_tb(e.__traceback__) + self.server.logger.exception('', e.args, e) # noinspection PyPep8Naming def do_POST(self) -> None: @@ -389,16 +420,21 @@ class HttpHandler(BaseHTTPRequestHandler): self._handle('POST', path, args) # Special handling for some errors except HttpException as e: - self.send_error(e.status, e.title, e.message) - except PermissionError: + if 500 <= e.status < 600: + self.send_error(500, 'Internal Server Error') + self.server.logger.exception('', exc_info=e) + else: + self.server.logger.debug('', exc_info=e) + except PermissionError as e: self.send_error(403, 'Forbidden') - except ValueError: + self.server.logger.debug('', exc_info=e) + except ValueError as e: self.send_error(400, 'Bad Request') + self.server.logger.debug('', exc_info=e) except BaseException as e: # Generic error handling self.send_error(500, 'Internal Server Error') - print(e) - traceback.print_tb(e.__traceback__) + self.server.logger.exception('', e.args, e) @property def session_vars(self) -> Dict[str, Any]: @@ -408,3 +444,12 @@ class HttpHandler(BaseHTTPRequestHandler): :return: Dictionary of named session variables. """ return self.server.session_vars[self.session_id][1] + + def log_request(self, code='-', size='-'): + self.server.logger.info('%s %s from %s', self.requestline, code, self.client_address) + + def log_error(self, fmt: str, *args): + self.server.logger.warning(f'{self.requestline} from {self.client_address}: {fmt}', *args) + + def log_message(self, fmt, *args): + self.server.logger.info(fmt, *args) diff --git a/matemat/webserver/test/abstract_httpd_test.py b/matemat/webserver/test/abstract_httpd_test.py index 4b61417..d691caa 100644 --- a/matemat/webserver/test/abstract_httpd_test.py +++ b/matemat/webserver/test/abstract_httpd_test.py @@ -9,6 +9,7 @@ from abc import ABC from datetime import datetime from http.server import HTTPServer +import logging import jinja2 from matemat.webserver import pagelet, RequestArguments @@ -115,6 +116,12 @@ class MockServer: self.jinja_env = jinja2.Environment( loader=jinja2.DictLoader({'test.txt': 'Hello, {{ what }}!'}) ) + # Set up logger + self.logger: logging.Logger = logging.getLogger('matemat unit test') + self.logger.setLevel(0) + sh: logging.StreamHandler = logging.StreamHandler() + sh.setFormatter(logging.Formatter('%(asctime)s @ %(name)s [%(levelname)s]: %(message)s')) + self.logger.addHandler(sh) class MockSocket(bytes): diff --git a/matemat/webserver/test/test_serve.py b/matemat/webserver/test/test_serve.py index 32853de..5db53b3 100644 --- a/matemat/webserver/test/test_serve.py +++ b/matemat/webserver/test/test_serve.py @@ -61,7 +61,7 @@ def serve_test_pagelet_fail(method: str, pagelet_variables: Dict[str, str]) -> Union[bytes, str, PageletResponse]: session_vars['test'] = 'hello, world!' headers['Content-Type'] = 'text/plain' - raise HttpException() + raise HttpException(599, 'Error expected during unit testing') class TestServe(AbstractHttpdTest): @@ -111,7 +111,7 @@ class TestServe(AbstractHttpdTest): packet = self.client_sock.get_response() # Make sure an error is raised - self.assertEqual(500, packet.statuscode) + self.assertEqual(599, packet.statuscode) def test_serve_pagelet_redirect(self): # Call the test pagelet that redirects to another path