Basic logging implementation; still undocumented.

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

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)
+            self.server.logger.exception('', e.args, e)
-            traceback.print_tb(e.__traceback__)
 
     # 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)
+            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 +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)

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

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