Add logging to start.py

b05a498 Now that the logging configuration is being loaded by start.py, this commit will add logger messages to the functions in start.py. Note that I'm not currently seeing log messages from prestart.py or gunicorn_conf.py, so these modules include simple `print()` statements.
br3ndonland · Aug 18, 2020 · e9b27ce · e9b27ce
1 parent b05a498
commit e9b27ce
Show file tree

Hide file tree

Showing 3 changed files with 59 additions and 41 deletions.
diff --git a/inboard/app/prestart.py b/inboard/app/prestart.py
@@ -1,3 +1,7 @@
 #!/usr/bin/env python3
+from pathlib import Path
 
-print("Running prestart.py. Add database migrations and other scripts here.")
+print(
+    f"[{Path(__file__).stem}] Hello World, from prestart.py!",
+    "Add database migrations and other scripts here.",
+)
diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py
@@ -1,6 +1,7 @@
 import json
 import multiprocessing
 import os
+from pathlib import Path
 
 workers_per_core_str = os.getenv("WORKERS_PER_CORE", "1")
 max_workers_str = os.getenv("MAX_WORKERS")
@@ -43,8 +44,13 @@
 timeout = int(timeout_str)
 keepalive = int(keepalive_str)
 
-# For debugging and testing
 log_data = {
+    # General
+    "host": host,
+    "port": port,
+    "use_max_workers": use_max_workers,
+    "workers_per_core": workers_per_core,
+    # Gunicorn
     "loglevel": loglevel,
     "workers": workers,
     "bind": bind,
@@ -53,10 +59,6 @@
     "keepalive": keepalive,
     "errorlog": errorlog,
     "accesslog": accesslog,
-    # Additional, non-gunicorn variables
-    "workers_per_core": workers_per_core,
-    "use_max_workers": use_max_workers,
-    "host": host,
-    "port": port,
 }
-print(json.dumps(log_data))
+
+print(f"[{Path(__file__).stem}] Gunicorn configuration:", json.dumps(log_data))
diff --git a/inboard/start.py b/inboard/start.py
@@ -1,29 +1,16 @@
 #!/usr/bin/env python3
 import importlib.util
+import logging
 import logging.config
 import os
 import subprocess
+from logging import Logger
 from pathlib import Path
 
 import uvicorn  # type: ignore
 import yaml
 
 
-def set_app_module() -> str:
-    """Set the name of the Python module with the app instance to run."""
-    if Path("/app/main.py").is_file():
-        default_module_name = "main"
-    elif Path("/app/app/main.py").is_file():
-        default_module_name = "app.main"
-    else:
-        default_module_name = "base.main"
-    module_name = os.getenv("MODULE_NAME", default_module_name)
-    variable_name = os.getenv("VARIABLE_NAME", "app")
-    app_module = os.getenv("APP_MODULE", f"{module_name}:{variable_name}")
-    os.environ["APP_MODULE"] = app_module
-    return app_module
-
-
 def set_conf_path(module: str) -> Path:
     """Set the path to a configuration file."""
     conf_var = str(os.getenv(f"{module.upper()}_CONF"))
@@ -39,7 +26,9 @@ def set_conf_path(module: str) -> Path:
     return Path(conf_path)
 
 
-def configure_logging(logging_conf: Path = Path("/logging_conf.py")) -> str:
+def configure_logging(
+    logger: Logger = logging.getLogger(), logging_conf: Path = Path("/logging_conf.py")
+) -> str:
     """Configure Python logging based on a path to a logging configuration file."""
     try:
         if logging_conf.suffix == ".py":
@@ -68,30 +57,54 @@ def configure_logging(logging_conf: Path = Path("/logging_conf.py")) -> str:
             raise ImportError(f"Unable to configure logging with {logging_conf.name}.")
     except Exception as e:
         message = f"Error when configuring logging: {e}"
-    # TODO: print statements will be replaced by logger messages
-    print(message)
+    logger.debug(f"[{Path(__file__).stem}] {message}")
     return message
 
 
-def run_pre_start_script(
-    pre_start_path: str = os.getenv("PRE_START_PATH", "/app/prestart.py")
-) -> None:
+def set_app_module(logger: Logger = logging.getLogger()) -> str:
+    """Set the name of the Python module with the app instance to run."""
+    if Path("/app/main.py").is_file():
+        default_module_name = "main"
+    elif Path("/app/app/main.py").is_file():
+        default_module_name = "app.main"
+    else:
+        default_module_name = "base.main"
+    module_name = os.getenv("MODULE_NAME", default_module_name)
+    variable_name = os.getenv("VARIABLE_NAME", "app")
+    app_module = os.getenv("APP_MODULE", f"{module_name}:{variable_name}")
+    os.environ["APP_MODULE"] = app_module
+    logger.debug(f"[{Path(__file__).stem}] App module set to {app_module}.")
+    return app_module
+
+
+def run_pre_start_script(logger: Logger = logging.getLogger()) -> str:
     """Run a pre-start script at the provided path."""
     try:
-        print(f"Checking for pre-start script in {pre_start_path}.")
-        if Path(pre_start_path).is_file():
+        logger.debug(f"[{Path(__file__).stem}] Checking for pre-start script.")
+        pre_start_path_var = str(os.getenv("PRE_START_PATH", "/app/prestart.py"))
+        if Path(pre_start_path_var).is_file():
+            pre_start_path = pre_start_path_var
+        elif Path("/app/app/prestart.py").is_file():
+            pre_start_path = "/app/app/prestart.py"
+        if pre_start_path:
             process = "python" if Path(pre_start_path).suffix == ".py" else "sh"
-            print(f"Running pre-start script {process} {pre_start_path}.")
+            run_message = f"Running pre-start script with {process} {pre_start_path}."
+            logger.debug(f"[{Path(__file__).stem}] {run_message}")
             subprocess.run([process, pre_start_path])
+            message = f"Ran pre-start script with {process} {pre_start_path}."
         else:
-            print("No pre-start script found.")
+            message = "No pre-start script found."
+            raise FileNotFoundError(message)
     except Exception as e:
-        print(f"Error when running pre-start script: {e}")
+        message = f"Error from pre-start script: {e}"
+    logger.debug(f"[{Path(__file__).stem}] {message}")
+    return message
 
 
 def start_server(
     app_module: str = str(os.getenv("APP_MODULE", "base.main:app")),
     gunicorn_conf: Path = Path("/gunicorn_conf.py"),
+    logger: Logger = logging.getLogger(),
     with_reload: bool = bool(os.getenv("WITH_RELOAD", False)),
     worker_class: str = str(os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker")),
 ) -> None:
@@ -111,11 +124,10 @@ def start_server(
 
 
 if __name__ == "__main__":
-    app_module = set_app_module()
-    gunicorn_conf_path = set_conf_path("gunicorn")
+    logger = logging.getLogger()
     logging_conf_path = set_conf_path("logging")
-    configure_logging(logging_conf=logging_conf_path)
-    run_pre_start_script()
-    start_server(
-        app_module=app_module, gunicorn_conf=gunicorn_conf_path,
-    )
+    configure_logging(logger=logger, logging_conf=logging_conf_path)
+    gunicorn_conf_path = set_conf_path("gunicorn")
+    app_module = set_app_module(logger=logger)
+    run_pre_start_script(logger=logger)
+    start_server(app_module=app_module, gunicorn_conf=gunicorn_conf_path, logger=logger)