Merge branch '6-unified-logging' into 'master'

Resolve "Unified Logging"

Closes #6

See merge request s3lph/matemat!12

.gitignore

@@ -10,3 +10,4 @@
 *.sqlite3
 *.db
 **/matemat.conf
+static/upload/

doc

@@ -1 +1 @@
-Subproject commit d5dc5f794ad1b959b9d4dce47eeb6068e5a75115
+Subproject commit c68df9d86af1d8d0ebb6b6609efeef14f7103761

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

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,15 +378,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)
+            self.server.logger.exception('', e.args, e)
-            traceback.print_tb(e.__traceback__)
 
     # noinspection PyPep8Naming
     def do_POST(self) -> None:
@@ -389,16 +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)
+            if 500 <= e.status < 600:
-        except PermissionError:
+                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)
+            self.server.logger.exception('', e.args, e)
-            traceback.print_tb(e.__traceback__)
 
     @property
     def session_vars(self) -> Dict[str, Any]:
@@ -408,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)

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):

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')

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