diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 6556f3f..b1eaddb 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -37,4 +37,4 @@ staging: name: staging url: https://matemat.kernelpanic.lol/ only: - - staging-unstable \ No newline at end of file + - staging-unstable diff --git a/doc b/doc index d5dc5f7..c68df9d 160000 --- a/doc +++ b/doc @@ -1 +1 @@ -Subproject commit d5dc5f794ad1b959b9d4dce47eeb6068e5a75115 +Subproject commit c68df9d86af1d8d0ebb6b6609efeef14f7103761 diff --git a/matemat/webserver/config.py b/matemat/webserver/config.py index c2e1c5f..1913c4a 100644 --- a/matemat/webserver/config.py +++ b/matemat/webserver/config.py @@ -1,10 +1,50 @@ -from typing import Any, Dict, Iterable, List, Union +from typing import Any, Dict, Iterable, List, Tuple, Union import os +import sys +import logging from configparser import ConfigParser +def parse_logging(symbolic_level: str, symbolic_target: str) -> Tuple[int, logging.Handler]: + """ + Parse the LogLevel and LogTarget from configuration. + The LogLevel value may be either an integer or a log level literal defined in the Python builtin logging module. + The LogTarget value may be one of the following: + - `stderr` to log to error output (default) + - `stdout` to log to standard output + - `none` to disable logging + - Any other value is interpreted as a filename + + :param symbolic_level: The value for the LogLevel key. + :param symbolic_target: The value for the LogTarget key. + :return: A tuple of the log level (as an int) and the logging.Handler derived from the log target string. + """ + try: + # Attempt to cast the log level into an int + level: int = int(symbolic_level) + except ValueError: + try: + # If this fails, look up the name in the logging class + level = int(logging.getLevelName(symbolic_level)) + except ValueError: + # LogLevel value was neither an int nor a known literal + raise ValueError(f'Unknown log level: {symbolic_level}') + # Special handling of the strings "stderr", "stdout" and "none" + if symbolic_target == 'stderr': + target: logging.Handler = logging.StreamHandler(sys.stderr) + elif symbolic_target == 'stdout': + target = logging.StreamHandler(sys.stdout) + elif symbolic_target == 'none': + target = logging.NullHandler() + else: + # Fallback: Interpret string as filename + target = logging.FileHandler(os.path.abspath(os.path.expanduser(symbolic_target))) + # Return log level and log 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 +62,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 + 'log_level': logging.INFO, + # Log target: An IO stream (stderr, stdout, ...) or a filename + 'log_handler': logging.StreamHandler(), # Variables passed to pagelets 'pagelet_variables': dict() } @@ -47,6 +91,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['log_level'], config['log_handler'] =\ + parse_logging(parser['Matemat'].get('LogLevel', config['log_level']), + parser['Matemat'].get('LogTarget', 'stderr')) 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 bbfd5b8..0cf3d80 100644 --- a/matemat/webserver/httpd.py +++ b/matemat/webserver/httpd.py @@ -1,8 +1,7 @@ from typing import Any, Callable, Dict, Tuple, Type, Union -import traceback - +import logging import os import socket import mimetypes @@ -25,9 +24,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 +103,8 @@ class MatematHTTPServer(HTTPServer): staticroot: str, templateroot: str, pagelet_variables: Dict[str, str], + log_level: int, + log_handler: logging.Handler, bind_and_activate: bool = True) -> None: super().__init__(server_address, handler, bind_and_activate) # Resolve webroot directory @@ -119,6 +117,12 @@ 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 the log handler's (obtained from config parsing) format string + log_handler.setFormatter(logging.Formatter('%(asctime)s %(name)s [%(levelname)s]: %(message)s')) + self.logger.addHandler(log_handler) class MatematWebserver(object): @@ -141,7 +145,9 @@ class MatematWebserver(object): port: int, staticroot: str, templateroot: str, - pagelet_variables: Dict[str, str]) -> None: + pagelet_variables: Dict[str, str], + log_level: int, + log_handler: logging.Handler) -> None: """ Instantiate a MatematWebserver. @@ -150,13 +156,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 log_level: The log level, as defined in the builtin logging module. + :param log_handler: The logging handler. """ # 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, + log_level, + log_handler) def start(self) -> None: """ @@ -198,10 +212,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,21 +378,21 @@ class HttpHandler(BaseHTTPRequestHandler): # Special handling for some errors except HttpException as e: self.send_error(e.status, e.title, e.message) - print(e) - traceback.print_tb(e.__traceback__) + 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') - print(e) - traceback.print_tb(e.__traceback__) + self.server.logger.debug('', exc_info=e) except ValueError as e: self.send_error(400, 'Bad Request') - print(e) - traceback.print_tb(e.__traceback__) + 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: @@ -395,22 +411,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) - print(e) - traceback.print_tb(e.__traceback__) + 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') - print(e) - traceback.print_tb(e.__traceback__) + self.server.logger.debug('', exc_info=e) except ValueError as e: self.send_error(400, 'Bad Request') - print(e) - traceback.print_tb(e.__traceback__) + 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]: @@ -420,3 +435,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..0817d41 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,13 @@ 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) + # Initalize a log handler to stderr and set the log format + 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_config.py b/matemat/webserver/test/test_config.py index 2d37635..517bc29 100644 --- a/matemat/webserver/test/test_config.py +++ b/matemat/webserver/test/test_config.py @@ -5,6 +5,8 @@ from unittest import TestCase from unittest.mock import patch from io import StringIO +import logging +import sys from matemat.webserver import parse_config_file @@ -19,6 +21,9 @@ Port = 8080 StaticPath =/var/test/static TemplatePath= /var/test/templates +LogLevel = CRITICAL +LogTarget = /tmp/log/matemat_test.log + [Pagelets] Name=Matemat (Unit Test) @@ -34,6 +39,29 @@ Port=443 Name=Matemat (Unit Test 2) ''' +_LOG_NONE_CONFIG = ''' +[Matemat] +LogTarget=none +''' + +_LOG_STDOUT_CONFIG = ''' +[Matemat] +LogTarget=stdout +''' + +_LOG_STDERR_CONFIG = ''' +[Matemat] +LogTarget=stderr +''' + +_LOG_GARBAGE_PORT = ''' +[Matemat] +Port=iwanttobeavalidporttoo''' + +_LOG_GARBAGE_LOGLEVEL = ''' +[Matemat] +LogLevel=thisisnotaloglevel''' + class IterOpenMock: """ @@ -59,7 +87,7 @@ class IterOpenMock: class TestConfig(TestCase): - def test_parse_config_empty_defualt_values(self): + def test_parse_config_empty_default_values(self): """ Test that default values are set when reading an empty config file. """ @@ -72,12 +100,17 @@ class TestConfig(TestCase): self.assertIn('port', config) self.assertIn('staticroot', config) self.assertIn('templateroot', config) + self.assertIn('log_level', config) + self.assertIn('log_handler', config) self.assertIn('pagelet_variables', config) # Make sure all mandatory values are set to their default self.assertEqual('::', config['listen']) self.assertEqual(80, config['port']) self.assertEqual('/var/matemat/static', config['staticroot']) self.assertEqual('/var/matemat/templates', config['templateroot']) + self.assertEqual(logging.INFO, config['log_level']) + self.assertIsInstance(config['log_handler'], logging.StreamHandler) + self.assertEqual(sys.stderr, config['log_handler'].stream) self.assertIsInstance(config['pagelet_variables'], dict) self.assertEqual(0, len(config['pagelet_variables'])) @@ -94,6 +127,8 @@ class TestConfig(TestCase): self.assertIn('port', config) self.assertIn('staticroot', config) self.assertIn('templateroot', config) + self.assertIn('log_level', config) + self.assertIn('log_handler', config) self.assertIn('pagelet_variables', config) self.assertIn('Name', config['pagelet_variables']) self.assertIn('UploadDir', config['pagelet_variables']) @@ -103,6 +138,9 @@ class TestConfig(TestCase): self.assertEqual(8080, config['port']) self.assertEqual('/var/test/static', config['staticroot']) self.assertEqual('/var/test/templates', config['templateroot']) + self.assertEqual(logging.CRITICAL, config['log_level']) + self.assertIsInstance(config['log_handler'], logging.FileHandler) + self.assertEqual('/tmp/log/matemat_test.log', config['log_handler'].baseFilename) self.assertEqual('Matemat\n(Unit Test)', config['pagelet_variables']['Name']) self.assertEqual('/var/test/static/upload', config['pagelet_variables']['UploadDir']) self.assertEqual('/var/test/db/test.db', config['pagelet_variables']['DatabaseFile']) @@ -134,3 +172,55 @@ class TestConfig(TestCase): self.assertEqual('Matemat (Unit Test 2)', config['pagelet_variables']['Name']) self.assertEqual('/var/test/static/upload', config['pagelet_variables']['UploadDir']) self.assertEqual('/var/test/db/test.db', config['pagelet_variables']['DatabaseFile']) + + def test_parse_config_logging_none(self): + """ + Test that "LogTaget=none" disables logging. + """ + # Mock the open() function to return a config file example with disabled logging + with patch('builtins.open', return_value=StringIO(_LOG_NONE_CONFIG)): + # The filename is only a placeholder, file content is determined by mocking open + config = parse_config_file('test') + # Make sure the returned log handler is a null handler + self.assertIsInstance(config['log_handler'], logging.NullHandler) + + def test_parse_config_logging_stdout(self): + """ + Test that "LogTaget=stdout" logs to sys.stdout. + """ + # Mock the open() function to return a config file example with stdout logging + with patch('builtins.open', return_value=StringIO(_LOG_STDOUT_CONFIG)): + # The filename is only a placeholder, file content is determined by mocking open + config = parse_config_file('test') + # Make sure the returned log handler is a stdout handler + self.assertIsInstance(config['log_handler'], logging.StreamHandler) + self.assertEqual(sys.stdout, config['log_handler'].stream) + + def test_parse_config_logging_stderr(self): + """ + Test that "LogTaget=stderr" logs to sys.stderr. + """ + # Mock the open() function to return a config file example with stdout logging + with patch('builtins.open', return_value=StringIO(_LOG_STDERR_CONFIG)): + # The filename is only a placeholder, file content is determined by mocking open + config = parse_config_file('test') + # Make sure the returned log handler is a stdout handler + self.assertIsInstance(config['log_handler'], logging.StreamHandler) + self.assertEqual(sys.stderr, config['log_handler'].stream) + + def test_parse_config_garbage(self): + """ + Test that garbage config raises ValueErrors. + """ + # Mock the open() function to return a config file example with a non-numeric port + with patch('builtins.open', return_value=StringIO(_LOG_GARBAGE_PORT)): + # Make sure a ValueError is raised + with self.assertRaises(ValueError): + # The filename is only a placeholder, file content is determined by mocking open + parse_config_file('test') + # Mock the open() function to return a config file example with a non-numeric log level with invalid symbol + with patch('builtins.open', return_value=StringIO(_LOG_GARBAGE_LOGLEVEL)): + # Make sure a ValueError is raised + with self.assertRaises(ValueError): + # The filename is only a placeholder, file content is determined by mocking open + parse_config_file('test') 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