Add logging configuration for Gunicorn and Uvicorn

.vscode/launch.json

@@ -0,0 +1,23 @@
+{
+  "version": "0.2.0",
+  "configurations": [
+    {
+      "name": "Uvicorn",
+      "type": "python",
+      "request": "launch",
+      "stopOnEntry": false,
+      "pythonPath": "${command:python.interpreterPath}",
+      "module": "start",
+      "env": {
+        "APP_MODULE": "app.base.main:app",
+        "LOG_FORMAT": "uvicorn",
+        "LOG_LEVEL": "debug",
+        "LOGGING_CONF": "logging_conf.py",
+        "WITH_RELOAD": "true"
+      },
+      "console": "integratedTerminal",
+      "cwd": "${workspaceRoot}/inboard",
+      "justMyCode": true
+    }
+  ]
+}

Dockerfile

@@ -1,8 +1,9 @@
 FROM python:3.8 AS base
 LABEL maintainer="Brendon Smith"
-COPY poetry.lock pyproject.toml inboard /
-ENV APP_MODULE=base.main:app GUNICORN_CONF=/gunicorn_conf.py POETRY_VIRTUALENVS_CREATE=false PYTHONPATH=/app
+COPY poetry.lock pyproject.toml /
+ENV APP_MODULE=base.main:app POETRY_VIRTUALENVS_CREATE=false PYTHONPATH=/app
 RUN python -m pip install poetry && poetry install --no-dev --no-interaction --no-root -E fastapi
+COPY inboard/gunicorn_conf.py inboard/logging_conf.py inboard/start.py inboard/app /
 CMD python /start.py
 
 FROM base AS fastapi

README.md

@@ -1,4 +1,4 @@
-# inboard
+# :ship: inboard :whale:
 
 _Docker images to power your Python APIs and help you ship faster. With support for Uvicorn, Gunicorn, Starlette, and FastAPI._
 
@@ -20,18 +20,20 @@ Brendon Smith ([br3ndonland](https://github.com/br3ndonland/))
 - [Configuration](#configuration)
   - [General](#general)
   - [Gunicorn and Uvicorn](#gunicorn-and-uvicorn)
+  - [Logging](#logging)
 - [Development](#development)
   - [Code style](#code-style)
   - [Building development images](#building-development-images)
   - [Running development containers](#running-development-containers)
 
 ## Description
 
-This is a refactor of [tiangolo/uvicorn-gunicorn-docker](https://github.com/tiangolo/uvicorn-gunicorn-docker) with the following advantages:
+This repo is inspired by [tiangolo/uvicorn-gunicorn-docker](https://github.com/tiangolo/uvicorn-gunicorn-docker), with the following advantages:
 
-- **One repo**. The tiangolo/uvicorn-gunicorn images are in at least three separate repos ([tiangolo/uvicorn-gunicorn-docker](https://github.com/tiangolo/uvicorn-gunicorn-docker), [tiangolo/uvicorn-gunicorn-fastapi-docker](https://github.com/tiangolo/uvicorn-gunicorn-fastapi-docker), and [tiangolo/uvicorn-gunicorn-starlette-docker](https://github.com/tiangolo/uvicorn-gunicorn-starlette-docker)), with large amounts of code duplication, making maintenance difficult for an already-busy maintainer. This repo combines three into one.
+- **One repo**. The tiangolo/uvicorn-gunicorn images are in at least three separate repos ([tiangolo/uvicorn-gunicorn-docker](https://github.com/tiangolo/uvicorn-gunicorn-docker), [tiangolo/uvicorn-gunicorn-fastapi-docker](https://github.com/tiangolo/uvicorn-gunicorn-fastapi-docker), and [tiangolo/uvicorn-gunicorn-starlette-docker](https://github.com/tiangolo/uvicorn-gunicorn-starlette-docker)), with large amounts of code duplication, making maintenance difficult for an [already-busy maintainer](https://github.com/encode/uvicorn/pull/705#issuecomment-660042305). This repo combines three into one.
 - **One _Dockerfile_.** This repo leverages [multi-stage builds](https://docs.docker.com/develop/develop-images/multistage-build/) to produce multiple Docker images from one _Dockerfile_.
 - **One Python requirements file.** This repo uses [Poetry](https://github.com/python-poetry/poetry) with Poetry Extras for dependency management with a single _pyproject.toml_.
+- **One logging configuration.** Logging a Uvicorn+Gunicorn+Starlette/FastAPI stack is unnecessarily complicated. Uvicorn and Gunicorn use different logging configurations, and it can be difficult to unify the log streams. In this repo, Uvicorn, Gunicorn, and FastAPI log streams are propagated to the root logger, and handled by the custom root logging config. Developers can also supply their own custom logging configurations.
 - **One programming language.** Pure Python with no shell scripts.
 - **One platform.** You're already on GitHub. Why not [pull Docker images from GitHub Packages](https://docs.github.com/en/packages/using-github-packages-with-your-projects-ecosystem/configuring-docker-for-use-with-github-packages)?
 
@@ -120,7 +122,7 @@ FROM docker.pkg.github.com/br3ndonland/inboard/fastapi
 
 # Install Python requirements
 COPY requirements.txt /
-RUN pip install -r requirements.txt
+RUN python -m pip install -r requirements.txt
 
 # Install Python app
 COPY package /app/
@@ -156,6 +158,8 @@ docker run -d -p 80:80 -e "LOG_LEVEL=debug" -e "WITH_RELOAD=true" -v $(pwd)/pack
   - `APP_MODULE`
   - `HOST`
   - `PORT`
+  - `LOG_COLORS`
+  - `LOG_FORMAT`
   - `LOG_LEVEL`
 - `-v $(pwd)/package:/app`: the specified directory (`/path/to/repo/package` in this example) will be [mounted as a volume](https://docs.docker.com/engine/reference/run/#volume-shared-filesystems) inside of the container at `/app`. When files in the working directory change, Docker and Uvicorn will sync the files to the running Docker container.
 - The final argument is the Docker image name (`imagename` in this example). Replace with your image name.
@@ -195,14 +199,14 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2"
 
 ### General
 
-- `MODULE_NAME`: Python module (file) with app instance.
+- `MODULE_NAME`: Python module (file) with app instance. Note that the base image sets the environment variable `PYTHONPATH=/app`, so the module name will be relative to `/app` unless you supply a custom `PYTHONPATH`.
   - Default:
-    - `main` if there's a file `/app/main.py`
-    - Else `app.main` if there's a file `/app/app/main.py`
+    - `"main"` if there's a file `/app/main.py`
+    - Else `"app.main"` if there's a file `/app/app/main.py`
   - Custom: For a module at `/app/custom/module.py`, `MODULE_NAME="custom.module"`
 - `VARIABLE_NAME`: Variable (object) inside of the Python module that contains the ASGI application instance.
 
-  - Default: `app`
+  - Default: `"app"`
   - Custom: For an application instance named `api`, `VARIABLE_NAME="api"`
 
     ```py
@@ -217,68 +221,112 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2"
 
 - `APP_MODULE`: Combination of `MODULE_NAME` and `VARIABLE_NAME` pointing to the app instance.
   - Default:
-    - `MODULE_NAME:VARIABLE_NAME` (`main:app` or `app.main:app`)
+    - `MODULE_NAME:VARIABLE_NAME` (`"main:app"` or `"app.main:app"`)
   - Custom: For a module at `/app/custom/module.py` and variable `api`, `APP_MODULE="custom.module:api"`
 - `PRE_START_PATH`: Path to a pre-start script. Add a file `prestart.py` or `prestart.sh` to the application directory, and copy the directory into the Docker image as described (for a project with the Python application in `repo/package`, `COPY package /app/`). The container will automatically detect and run the prestart script before starting the web server.
 
-  - Default: `/app/prestart.py`
+  - Default: `"/app/prestart.py"`
   - Custom: `PRE_START_PATH="/custom/script.sh"`
 
+- [`PYTHONPATH`](https://docs.python.org/3/using/cmdline.html#envvar-PYTHONPATH): Python's search path for module files.
+  - Default: `PYTHONPATH="/app"`
+  - Custom: `PYTHONPATH="/app/custom"`
+
 ### Gunicorn and Uvicorn
 
 - `GUNICORN_CONF`: Path to a [Gunicorn configuration file](https://docs.gunicorn.org/en/latest/settings.html#config-file).
   - Default:
-    - `/app/gunicorn_conf.py` if exists
-    - Else `/app/app/gunicorn_conf.py` if exists
-    - Else `/gunicorn_conf.py` (the default file provided with the Docker image)
+    - `"/app/gunicorn_conf.py"` if exists
+    - Else `"/app/app/gunicorn_conf.py"` if exists
+    - Else `"/gunicorn_conf.py"` (the default file provided with the Docker image)
   - Custom:
     - `GUNICORN_CONF="/app/custom_gunicorn_conf.py"`
     - Feel free to use the [`gunicorn_conf.py`](./inboard/gunicorn_conf.py) from this repo as a starting point for your own custom configuration.
 - `HOST`: Host IP address (inside of the container) where Gunicorn will listen for requests.
-  - Default: `0.0.0.0`
+  - Default: `"0.0.0.0"`
   - Custom: _TODO_
 - `PORT`: Port the container should listen on.
-  - Default: `80`
+  - Default: `"80"`
   - Custom: `PORT="8080"`
 - [`BIND`](https://docs.gunicorn.org/en/latest/settings.html#server-socket): The actual host and port passed to Gunicorn.
-  - Default: `HOST:PORT` (`0.0.0.0:80`)
+  - Default: `HOST:PORT` (`"0.0.0.0:80"`)
   - Custom: `BIND="0.0.0.0:8080"`
 - [`WORKER_CLASS`](https://docs.gunicorn.org/en/latest/settings.html#worker-processes): The class to be used by Gunicorn for the workers.
   - Default: `uvicorn.workers.UvicornWorker`
   - Custom: For the alternate Uvicorn worker, `WORKER_CLASS="uvicorn.workers.UvicornH11Worker"`
 - [`WORKERS_PER_CORE`](https://docs.gunicorn.org/en/latest/settings.html#worker-processes): Number of Gunicorn workers per CPU core.
-  - Default: `1`
+  - Default: `"1"`
   - Custom: `WORKERS_PER_CORE="2"`
   - Notes:
     - This image will check how many CPU cores are available in the current server running your container. It will set the number of workers to the number of CPU cores multiplied by this value.
     - On a server with 2 CPU cores, `WORKERS_PER_CORE="3"` will run 6 worker processes.
     - Floating point values are permitted. If you have a powerful server (let's say, with 8 CPU cores) running several applications, including an ASGI application that won't need high performance, but you don't want to waste server resources, you could set the environment variable to `WORKERS_PER_CORE="0.5"`. A server with 8 CPU cores would start only 4 worker processes.
-    - By default, if `WORKERS_PER_CORE` is `1` and the server has only 1 CPU core, 2 workers will be started instead of 1, to avoid poor performance and blocking applications. This behavior can be overridden using `WEB_CONCURRENCY`.
+    - By default, if `WORKERS_PER_CORE="1"` and the server has only 1 CPU core, 2 workers will be started instead of 1, to avoid poor performance and blocking applications. This behavior can be overridden using `WEB_CONCURRENCY`.
 - `MAX_WORKERS`: Maximum number of workers to use, independent of number of CPU cores.
   - Default: unlimited (not set)
   - Custom: `MAX_WORKERS="24"`
 - [`WEB_CONCURRENCY`](https://docs.gunicorn.org/en/latest/settings.html#worker-processes): Set number of workers independently of number of CPU cores.
   - Default:
     - Number of CPU cores multiplied by the environment variable `WORKERS_PER_CORE`.
-    - In a server with 2 cores and default `WORKERS_PER_CORE="1"`, default `2`.
+    - In a server with 2 cores and default `WORKERS_PER_CORE="1"`, default `"2"`.
   - Custom: To have 4 workers, `WEB_CONCURRENCY="4"`
 - [`TIMEOUT`](https://docs.gunicorn.org/en/stable/settings.html#timeout): Workers silent for more than this many seconds are killed and restarted.
-  - Default: `120`
+  - Default: `"120"`
   - Custom: `TIMEOUT="20"`
 - [`GRACEFUL_TIMEOUT`](https://docs.gunicorn.org/en/stable/settings.html#graceful-timeout): Number of seconds to allow workers finish serving requests before restart.
-  - Default:`120`
+  - Default: `"120"`
   - Custom: `GRACEFUL_TIMEOUT="20"`
 - [`KEEP_ALIVE`](https://docs.gunicorn.org/en/stable/settings.html#keepalive): Number of seconds to wait for requests on a Keep-Alive connection.
-  - Default: `2`
+  - Default: `"2"`
   - Custom: `KEEP_ALIVE="20"`
+- `GUNICORN_CMD_ARGS`: Additional [command-line arguments for Gunicorn](https://docs.gunicorn.org/en/stable/settings.html). Gunicorn looks for the `GUNICORN_CMD_ARGS` environment variable automatically, and gives these settings precedence over other environment variables and Gunicorn config files.
+  - Custom: To use a custom TLS certificate, copy or mount the certificate and private key into the Docker image, and set [`--keyfile` and `--certfile`](http://docs.gunicorn.org/en/latest/settings.html#ssl) to the location of the files.
+    ```sh
+    docker run -d -p 443:443 \
+      -e GUNICORN_CMD_ARGS="--keyfile=/secrets/key.pem --certfile=/secrets/cert.pem" \
+      -e PORT=443 myimage
+    ```
+
+### Logging
+
+- `LOGGING_CONF`: Path to a [Python logging configuration file](https://docs.python.org/3/library/logging.config.html). The configuration must be a new-style `.py` file, containing a configuration dictionary object named `LOGGING_CONFIG`. The `LOGGING_CONFIG` dictionary will be passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html)
+  - Default:
+    - `"/app/logging_conf.py"` if exists
+    - Else `"/app/app/logging_conf.py"` if exists
+    - Else `"/logging_conf.py"` (the default file provided with the Docker image)
+  - Custom:
+    - `LOGGING_CONF="/app/custom_logging.py"`
+- `LOG_COLORS`: Whether or not to color log messages. Currently only supported for `LOG_FORMAT="uvicorn"`.
+  - Default:
+    - Auto-detected based on [`sys.stdout.isatty()`](https://docs.python.org/3/library/sys.html#sys.stdout).
+  - Custom:
+    - `LOG_COLORS="true"`
+    - `LOG_COLORS="false"`
+- `LOG_FORMAT`: [Python logging format](https://docs.python.org/3/library/logging.html#formatter-objects).
+  - Default:
+    - `"simple"`: Simply the log level and message.
+  - Custom:
+    - `"verbose"`: The most informative format, with the first 80 characters providing metadata, and the remainder supplying the log message.
+    - `"gunicorn"`: Gunicorn's default format.
+    - `"uvicorn"`: Uvicorn's default format, similar to `simple`, with support for `LOG_COLORS`. Note that Uvicorn's `access` formatter is not supported here, because it frequently throws errors related to [ASGI scope](https://asgi.readthedocs.io/en/latest/specs/lifespan.html).
+  ```sh
+  # simple
+  INFO       Started server process [19012]
+  # verbose
+  2020-08-19 20:50:05 -0400      19012      uvicorn.error   main            INFO       Started server process [19012]
+  # gunicorn
+  [2020-08-19 21:07:31 -0400] [19012] [INFO] Started server process [19012]
+  # uvicorn (can also be colored)
+  INFO:     Started server process [19012]
+  ```
 - `LOG_LEVEL`: Log level for [Gunicorn](https://docs.gunicorn.org/en/latest/settings.html#logging) or [Uvicorn](https://www.uvicorn.org/settings/#logging).
-  - Default: `info`
+  - Default: `"info"`
   - Custom (organized from greatest to least amount of logging):
-    - `debug`
-    - `info`
-    - `warning`
-    - `error`
-    - `critical`
+    - `LOG_LEVEL="debug"`
+    - `LOG_LEVEL="info"`
+    - `LOG_LEVEL="warning"`
+    - `LOG_LEVEL="error"`
+    - `LOG_LEVEL="critical"`
 - `ACCESS_LOG`: Access log file to which to write.
   - Default: `"-"` (`stdout`, print in Docker logs)
   - Custom:
@@ -289,13 +337,8 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2"
   - Custom:
     - `ERROR_LOG="./path/to/errorlogfile.txt"`
     - `ERROR_LOG=` (set to an empty value) to disable
-- `GUNICORN_CMD_ARGS`: Additional [command-line arguments for Gunicorn](https://docs.gunicorn.org/en/stable/settings.html). These settings will have precedence over the other environment variables and any Gunicorn config file.
-  - Custom: To use a custom TLS certificate, copy or mount the certificate and private key into the Docker image, and set [`--keyfile` and `--certfile`](http://docs.gunicorn.org/en/latest/settings.html#ssl) to the location of the files.
-    ```sh
-    docker run -d -p 443:443 \
-      -e GUNICORN_CMD_ARGS="--keyfile=/secrets/key.pem --certfile=/secrets/cert.pem" \
-      -e PORT=443 myimage
-    ```
+
+For more information on Python logging configuration, see the [Python `logging` how-to](https://docs.python.org/3/howto/logging.html), [Python `logging` cookbook](https://docs.python.org/3/howto/logging-cookbook.html), [Python `logging` module docs](https://docs.python.org/3/library/logging.html), and [Python `logging.config` module docs](https://docs.python.org/3/library/logging.config.html). Also consider [Loguru](https://loguru.readthedocs.io/en/stable/index.html), an alternative logging module with many improvements over the standard library `logging` module.
 
 ## Development
 
@@ -318,22 +361,36 @@ To build the Docker images for each stage:
 
 ```sh
 git clone [email protected]:br3ndonland/inboard.git
+
 cd inboard
-docker build . --target base -t localhost/br3ndonland/inboard/base:latest
-docker build . --target fastapi -t localhost/br3ndonland/inboard/fastapi:latest
-docker build . --target starlette -t localhost/br3ndonland/inboard/starlette:latest
+
+docker build . --rm --target base -t localhost/br3ndonland/inboard/base:latest && \
+docker build . --rm --target fastapi -t localhost/br3ndonland/inboard/fastapi:latest && \
+docker build . --rm --target starlette -t localhost/br3ndonland/inboard/starlette:latest
 ```
 
 ### Running development containers
 
 ```sh
 # Uvicorn with reloading
 cd inboard
+
 docker run -d -p 80:80 -e "LOG_LEVEL=debug" -e "WITH_RELOAD=true" \
+  -v $(pwd)/inboard/gunicorn_conf.py:/gunicorn_conf.py \
+  -v $(pwd)/inboard/logging_conf.py:/logging_conf.py \
+  -v $(pwd)/inboard/start.py:/start.py \
   -v $(pwd)/inboard/app:/app localhost/br3ndonland/inboard/base
+
 docker run -d -p 80:80 -e "LOG_LEVEL=debug" -e "WITH_RELOAD=true" \
+  -v $(pwd)/inboard/gunicorn_conf.py:/gunicorn_conf.py \
+  -v $(pwd)/inboard/logging_conf.py:/logging_conf.py \
+  -v $(pwd)/inboard/start.py:/start.py \
   -v $(pwd)/inboard/app:/app localhost/br3ndonland/inboard/fastapi
+
 docker run -d -p 80:80 -e "LOG_LEVEL=debug" -e "WITH_RELOAD=true" \
+  -v $(pwd)/inboard/gunicorn_conf.py:/gunicorn_conf.py \
+  -v $(pwd)/inboard/logging_conf.py:/logging_conf.py \
+  -v $(pwd)/inboard/start.py:/start.py \
   -v $(pwd)/inboard/app:/app localhost/br3ndonland/inboard/starlette
 
 # Gunicorn and Uvicorn

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.",
+)

inboard/gunicorn_conf.py

@@ -1,6 +1,9 @@
 import json
 import multiprocessing
 import os
+from pathlib import Path
+
+from start import configure_logging  # type: ignore
 
 workers_per_core_str = os.getenv("WORKERS_PER_CORE", "1")
 max_workers_str = os.getenv("MAX_WORKERS")
@@ -31,8 +34,15 @@
 graceful_timeout_str = os.getenv("GRACEFUL_TIMEOUT", "120")
 timeout_str = os.getenv("TIMEOUT", "120")
 keepalive_str = os.getenv("KEEP_ALIVE", "5")
+try:
+    logging_conf_dict = configure_logging(
+        logging_conf=Path(os.getenv("LOGGING_CONF", "/logging_conf.py"))
+    )
+except Exception:
+    logging_conf_dict = None
 
 # Gunicorn config variables
+logconfig_dict = logging_conf_dict
 loglevel = use_loglevel
 workers = web_concurrency
 bind = use_bind
@@ -43,8 +53,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 +68,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))
+if loglevel == "debug":
+    print(f"[{Path(__file__).stem}] Custom configuration:", json.dumps(log_data))