From 1dfd62f2efa9dbeb1ff80ce6423b77dbdd7a4cf1 Mon Sep 17 00:00:00 2001
From: Matthew Evans <git@ml-evs.science>
Date: Sun, 12 Mar 2023 11:55:53 +0000
Subject: [PATCH] Refactor of logging

- Tweak logging of config to avoid circular imports

- Put the production access log in the main stdout logger

- Print exc traceback in logger
---
 .docker/server_dockerfile     |  2 +-
 pydatalab/pydatalab/config.py | 10 --------
 pydatalab/pydatalab/logger.py | 48 +++++++++++++++++++++++------------
 pydatalab/pydatalab/main.py   |  8 +++++-
 4 files changed, 40 insertions(+), 28 deletions(-)

diff --git a/.docker/server_dockerfile b/.docker/server_dockerfile
index 850d20521..5aaf403e4 100644
--- a/.docker/server_dockerfile
+++ b/.docker/server_dockerfile
@@ -27,7 +27,7 @@ CMD ["pipenv", "run", \
      "gunicorn", \
      "-w", "2", \
      "--error-logfile", "/logs/pydatalab_error.log", \
-     "--access-logfile", "/logs/pydatalab_access.log", \
+     "--access-logfile", "-", \
      "-b", "0.0.0.0:5001", \
      "pydatalab.main:create_app()" \
 ]
diff --git a/pydatalab/pydatalab/config.py b/pydatalab/pydatalab/config.py
index 11036900e..cb6c12d3a 100644
--- a/pydatalab/pydatalab/config.py
+++ b/pydatalab/pydatalab/config.py
@@ -138,13 +138,3 @@ def update(self, mapping):
 
 
 CONFIG = ServerConfig()
-
-
-def log_config():
-    """Adds the current server configuration to the log."""
-    from pydatalab.logger import LOGGER
-
-    LOGGER.info("Loaded config with options: %s", CONFIG.dict())
-
-
-log_config()
diff --git a/pydatalab/pydatalab/logger.py b/pydatalab/pydatalab/logger.py
index e2fff96f5..7136d8387 100644
--- a/pydatalab/pydatalab/logger.py
+++ b/pydatalab/pydatalab/logger.py
@@ -1,6 +1,6 @@
 import logging
 from functools import wraps
-from typing import Callable
+from typing import Callable, Optional
 
 
 class AnsiColorHandler(logging.StreamHandler):
@@ -11,10 +11,10 @@ class AnsiColorHandler(logging.StreamHandler):
     """
 
     LOGLEVEL_COLORS = {
-        logging.DEBUG: "38;20m",
-        logging.INFO: "46;30m",
-        logging.WARNING: "43;30m",
-        logging.ERROR: "41;30m",
+        logging.DEBUG: "36m",
+        logging.INFO: "32m",
+        logging.WARNING: "33m",
+        logging.ERROR: "1;91m",
         logging.CRITICAL: "101;30m",
     }
 
@@ -34,29 +34,37 @@ def format(self, record: logging.LogRecord) -> str:
         if len(message) > self.max_width:
             message = message[: self.max_width] + "[...]"
         color = self.LOGLEVEL_COLORS[record.levelno]
-        message = f"{prefix} \x1b[{color}{message}\x1b[0m"
+        message = f"\x1b[{color} {prefix} {message}\x1b[0m"
         return message
 
 
-def setup_log():
-    """Creates a logger for pydatalab with a simple
-    stdout output.
+def setup_log(log_name: str = "pydatalab", log_level: Optional[int] = None) -> logging.Logger:
+    """Creates a logger a simple coloured stdout output.
 
-    Verbosity is set in the config file via
-    the DEBUG option.
+    Verbosity can be set to debug in the config file via
+    the DEBUG option, or passed the the function.
+
+    Parameters:
+        log_name: The name of the logger.
+        log_level: The logging level to use.
+
+    Returns:
+        The logger object.
 
     """
     from pydatalab.config import CONFIG
 
-    logger = logging.getLogger("pydatalab")
+    logger = logging.getLogger(log_name)
     logger.handlers = []
     logger.propagate = False
     handler = AnsiColorHandler()
     logger.addHandler(handler)
+    if log_level is None:
+        log_level = logging.INFO
+
+        if CONFIG.DEBUG:
+            log_level = logging.DEBUG
 
-    log_level = logging.INFO
-    if CONFIG.DEBUG:
-        log_level = logging.DEBUG
     logger.setLevel(log_level)
     return logger
 
@@ -97,7 +105,15 @@ def wrapped_logged_route(*args, **kwargs):
             )
             return result
         except Exception as exc:
-            LOGGER.error("%s errored with %s %s", fn.__name__, exc.__class__.__name__, exc)
+            import traceback
+
+            LOGGER.error(
+                "%s errored with %s %s %s",
+                fn.__name__,
+                exc.__class__.__name__,
+                exc,
+                traceback.print_tb(exc.__traceback__),
+            )
             raise exc
 
     return wrapped_logged_route
diff --git a/pydatalab/pydatalab/main.py b/pydatalab/pydatalab/main.py
index 7509e58bf..49fd531b1 100644
--- a/pydatalab/pydatalab/main.py
+++ b/pydatalab/pydatalab/main.py
@@ -1,4 +1,5 @@
 import datetime
+import logging
 from typing import Any, Dict
 
 from dotenv import dotenv_values
@@ -10,7 +11,7 @@
 
 import pydatalab.mongo
 from pydatalab.config import CONFIG
-from pydatalab.logger import logged_route
+from pydatalab.logger import LOGGER, logged_route, setup_log
 from pydatalab.login import LOGIN_MANAGER
 from pydatalab.utils import CustomJSONEncoder
 
@@ -28,6 +29,8 @@ def create_app(config_override: Dict[str, Any] = None) -> Flask:
         The `Flask` app with all associated endpoints.
 
     """
+    setup_log("werkzeug", log_level=logging.INFO)
+    setup_log("", log_level=logging.INFO)
 
     app = Flask(__name__, instance_relative_config=True)
 
@@ -37,6 +40,9 @@ def create_app(config_override: Dict[str, Any] = None) -> Flask:
     app.config.update(CONFIG.dict())
     app.config.update(dotenv_values())
 
+    LOGGER.info("Starting app with Flask app.config: %s", app.config)
+    LOGGER.info("Datalab config: %s", CONFIG.dict())
+
     if CONFIG.BEHIND_REVERSE_PROXY:
         # Fix headers for reverse proxied app:
         # https://flask.palletsprojects.com/en/2.2.x/deploying/proxy_fix/