From 37466c71114c12876f635a5c704ac08669845346 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 16 Aug 2020 14:48:18 -0400 Subject: [PATCH 01/27] Add logging configuration modules https://docs.python.org/3/howto/logging.html https://docs.python.org/3/howto/logging-cookbook.html https://docs.python.org/3/library/logging.html https://docs.python.org/3/library/logging.config.html https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py - Log message format is based on gunicorn/glogging.py `CONFIG_DEFAULTS`, with the addition of the logger name. - Gunicorn propagates access logs by default. Uvicorn does not. - The new style Python dictionary configuration, as well as the YAML version, and the old-style .conf are included. --- inboard/logging_conf.conf | 54 +++++++++++++++++++++++++++++++++++++++ inboard/logging_conf.py | 35 +++++++++++++++++++++++++ inboard/logging_conf.yml | 32 +++++++++++++++++++++++ 3 files changed, 121 insertions(+) create mode 100644 inboard/logging_conf.conf create mode 100644 inboard/logging_conf.py create mode 100644 inboard/logging_conf.yml diff --git a/inboard/logging_conf.conf b/inboard/logging_conf.conf new file mode 100644 index 0000000..15735d8 --- /dev/null +++ b/inboard/logging_conf.conf @@ -0,0 +1,54 @@ +[formatters] +keys=inboard + +[formatter_inboard] +format=%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s +datefmt=[%Y-%m-%d %H:%M:%S %z] +class=logging.Formatter + +[handlers] +keys=inboard + +[handlers_inboard] +class=logging.StreamHandler +formatter=inboard +level=DEBUG +stream=ext://sys.stdout + +[loggers] +keys=root, fastapi, gunicorn, gunicorn.access, gunicorn.error, uvicorn, uvicorn.access, uvicorn.asgi, uvicorn.error + +[logger_root] +handlers=inboard + +[logger_fastapi] +propagate=1 + +[logger_gunicorn] +propagate=1 +qualname=gunicorn + +[logger_gunicorn.access] +propagate=1 +qualname=gunicorn.access + +[logger_gunicorn.error] +propagate=1 +qualname=gunicorn.error + +[logger_uvicorn] +level=INFO +propagate=1 +qualname=uvicorn + +[logger_uvicorn.access] +propagate=1 +qualname=uvicorn.access + +[logger_uvicorn.asgi] +propagate=1 +qualname=uvicorn.asgi + +[logger_uvicorn.error] +propagate=1 +qualname=uvicorn.error diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py new file mode 100644 index 0000000..4cb9be4 --- /dev/null +++ b/inboard/logging_conf.py @@ -0,0 +1,35 @@ +import os +from typing import Dict, Union + +LOG_LEVEL = str(os.getenv("LOG_LEVEL", "info")).upper() +PROPAGATE_ACCESS_LOGS = bool(os.getenv("PROPAGATE_ACCESS_LOGS", "true")) +LOGGING_CONFIG: Dict[str, Union[Dict, bool, int, str]] = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "inboard": { + "format": "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s", # noqa: E501 + "datefmt": "[%Y-%m-%d %H:%M:%S %z]", + "class": "logging.Formatter", + } + }, + "handlers": { + "inboard": { + "class": "logging.StreamHandler", + "formatter": "inboard", + "level": LOG_LEVEL, + "stream": "ext://sys.stdout", + } + }, + "root": {"handlers": ["inboard"], "level": LOG_LEVEL}, + "loggers": { + "fastapi": {"propagate": True}, + "gunicorn": {"propagate": True}, + "gunicorn.access": {"propagate": PROPAGATE_ACCESS_LOGS}, + "gunicorn.error": {"propagate": True}, + "uvicorn": {"propagate": True}, + "uvicorn.access": {"propagate": PROPAGATE_ACCESS_LOGS}, + "uvicorn.asgi": {"propagate": True}, + "uvicorn.error": {"propagate": True}, + }, +} diff --git a/inboard/logging_conf.yml b/inboard/logging_conf.yml new file mode 100644 index 0000000..624c548 --- /dev/null +++ b/inboard/logging_conf.yml @@ -0,0 +1,32 @@ +version: 1 +disable_existing_loggers: False +formatters: + inboard: + format: "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s" + datefmt: "[%Y-%m-%d %H:%M:%S %z]" + class: logging.Formatter +handlers: + inboard: + class: logging.StreamHandler + formatter: inboard + level: DEBUG + stream: ext://sys.stdout +root: + handlers: inboard +loggers: + fastapi: + propagate: true + gunicorn: + propagate: true + gunicorn.access: + propagate: true + gunicorn.error: + propagate: true + uvicorn: + propagate: true + uvicorn.access: + propagate: true + uvicorn.asgi: + propagate: true + uvicorn.error: + propagate: true From 524adbe23742889da1900d20f78b8ff7f8c02a8d Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 16 Aug 2020 14:43:50 -0400 Subject: [PATCH 02/27] Create README section for logging configuration - Move info on logging environment variables to separate logging section - Add links to logging info in Python docs --- README.md | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index f8ee2d7..86e4d0f 100644 --- a/README.md +++ b/README.md @@ -20,6 +20,7 @@ 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) @@ -271,6 +272,16 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" - [`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` - Custom: `KEEP_ALIVE="20"` +- `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 + ``` + +### Logging + - `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` - Custom (organized from greatest to least amount of logging): @@ -289,13 +300,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 From 1da6c660af58df872fe6fa122fef726fb85f083a Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 02:14:29 -0400 Subject: [PATCH 03/27] Add new logging configuration options to README --- README.md | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/README.md b/README.md index 86e4d0f..dec0c07 100644 --- a/README.md +++ b/README.md @@ -282,6 +282,13 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" ### Logging +- `LOGGING_CONF`: Path to a [Python logging configuration file](https://docs.python.org/3/library/logging.config.html). You may use either an old-style `.conf` or `.ini` file that will be passed to [`logging.config.fileConfig()`](https://docs.python.org/3/library/logging.config.html), or a new-style `.py`, `.yml`, or `.yaml` file containing a configuration dictionary object named `LOGGING_CONFIG` that will be passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html). Feel free to use the [`logging_conf.py`](./inboard/logging_conf.py) from this repo as a starting point for your own custom configuration. + - 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.conf"` - `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` - Custom (organized from greatest to least amount of logging): @@ -300,6 +307,9 @@ 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 +- `PROPAGATE_ACCESS_LOGS`: Gunicorn and Uvicorn have two primary log streams, `access` and `error`. The `error` logs are always propagated (output by the logger). The [Gunicorn logging config](https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py) and [Uvicorn logging config](https://github.com/encode/uvicorn/blob/master/uvicorn/config.py) both also propagate `access` logs by default, but some users may wish to disable `access` logs to reduce logging verbosity. This environment variable will set the behavior for both Gunicorn and Uvicorn. + - Default: `true` (access logs propagated by both Gunicorn and Uvicorn) + - Custom: `PROPAGATE_ACCESS_LOGS=false` 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. From 40f8a2bb724c6eff8f165318347d070e5dd2e97b Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 02:15:20 -0400 Subject: [PATCH 04/27] Add logging info to README description section --- README.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index dec0c07..fe30b8e 100644 --- a/README.md +++ b/README.md @@ -28,11 +28,12 @@ Brendon Smith ([br3ndonland](https://github.com/br3ndonland/)) ## 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)? From cd3fe7b1e81ad6c3f24f8bdba5cf93ed12696cb2 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 17:17:32 -0400 Subject: [PATCH 05/27] Improve logging config file format info in README --- README.md | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index fe30b8e..9711628 100644 --- a/README.md +++ b/README.md @@ -273,7 +273,7 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" - [`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` - Custom: `KEEP_ALIVE="20"` -- `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. +- `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 \ @@ -283,7 +283,12 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" ### Logging -- `LOGGING_CONF`: Path to a [Python logging configuration file](https://docs.python.org/3/library/logging.config.html). You may use either an old-style `.conf` or `.ini` file that will be passed to [`logging.config.fileConfig()`](https://docs.python.org/3/library/logging.config.html), or a new-style `.py`, `.yml`, or `.yaml` file containing a configuration dictionary object named `LOGGING_CONFIG` that will be passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html). Feel free to use the [`logging_conf.py`](./inboard/logging_conf.py) from this repo as a starting point for your own custom configuration. +- `LOGGING_CONF`: Path to a [Python logging configuration file](https://docs.python.org/3/library/logging.config.html). + - File format options: + - A new-style `.py` file containing a configuration dictionary object named `LOGGING_CONFIG` that will be passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html) (preferred) + - A new-style `.yml` or `.yaml` file that will be parsed by [PyYAML](https://pypi.org/project/PyYAML/) and then passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html) + - An old-style `.conf` or `.ini` file that will be passed to [`logging.config.fileConfig()`](https://docs.python.org/3/library/logging.config.html) + - Feel free to use the [`logging_conf.py`](./inboard/logging_conf.py) from this repo as a starting point for your own custom configuration. - Default: - `/app/logging_conf.py` if exists - Else `/app/app/logging_conf.py` if exists From 0e9a76609f356cda63ea1605a8c6e002e31e21b2 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 17:57:22 -0400 Subject: [PATCH 06/27] Add command for building Docker images to README --- README.md | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 9711628..ba73bd5 100644 --- a/README.md +++ b/README.md @@ -340,10 +340,12 @@ To build the Docker images for each stage: ```sh git clone git@github.com: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 From 1b2cc1c521bee801d5db4832a87d5508a469414a Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 19:41:25 -0400 Subject: [PATCH 07/27] Add separate COPY command for application files I am trying to have as few commands as possible, to reduce the number of Docker build layers, but adding another COPY command for the application files dramatically reduces build times. --- Dockerfile | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/Dockerfile b/Dockerfile index ff69c1d..280a538 100644 --- a/Dockerfile +++ b/Dockerfile @@ -1,8 +1,9 @@ FROM python:3.8 AS base LABEL maintainer="Brendon Smith" -COPY poetry.lock pyproject.toml inboard / +COPY poetry.lock pyproject.toml / ENV APP_MODULE=base.main:app GUNICORN_CONF=/gunicorn_conf.py POETRY_VIRTUALENVS_CREATE=false PYTHONPATH=/app RUN python -m pip install poetry && poetry install --no-dev --no-interaction --no-root -E fastapi +COPY inboard / CMD python /start.py FROM base AS fastapi From cd8de6bce6edbf6d4876431c2746b2f5b210a0c7 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 02:12:31 -0400 Subject: [PATCH 08/27] Install PyYAML to parse YAML configuration files https://pypi.org/project/PyYAML/ https://pyyaml.org/wiki/PyYAMLDocumentation --- poetry.lock | 4 ++-- pyproject.toml | 1 + 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/poetry.lock b/poetry.lock index 210b577..f2497c5 100644 --- a/poetry.lock +++ b/poetry.lock @@ -359,7 +359,7 @@ pytest = ">=2.7" dev = ["pre-commit", "tox", "pytest-asyncio"] [[package]] -category = "dev" +category = "main" description = "YAML parser and emitter for Python" name = "pyyaml" optional = false @@ -483,7 +483,7 @@ fastapi = ["fastapi"] starlette = ["starlette"] [metadata] -content-hash = "50c0a53686e43d3c8b0be6a478d8e55910fc7ef6d97fd5bdb38f6622fe974913" +content-hash = "42984799c7fb0e25b47eda4ee214c9032f38a8f3448b3ee86fbea098c21c1e25" lock-version = "1.0" python-versions = "^3.8" diff --git a/pyproject.toml b/pyproject.toml index 37de65a..86e1f35 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -13,6 +13,7 @@ readme = "README.md" [tool.poetry.dependencies] python = "^3.8" +pyyaml = "^5.3" gunicorn = "^20" uvicorn = "^0.11.8" fastapi = {version = "^0.60.1", optional = true} From cf8f71cc7e25a20e7f2054d529fb5fcea51f1aa5 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 16 Aug 2020 16:00:57 -0400 Subject: [PATCH 09/27] Set path to logging configuration module This commit will generalize the previous `set_gunicorn_conf()` function in start.py to also check the path to a logging configuration module. The function will now return a pathlib.Path() instance. --- inboard/start.py | 36 +++++++++++++++++++----------------- 1 file changed, 19 insertions(+), 17 deletions(-) diff --git a/inboard/start.py b/inboard/start.py index ec72100..6cfe938 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -2,7 +2,6 @@ import os import subprocess from pathlib import Path -from typing import Tuple import uvicorn # type: ignore @@ -21,18 +20,18 @@ def set_app_module() -> str: return app_module -def set_gunicorn_conf() -> Tuple[str, str]: - if Path("/app/gunicorn_conf.py").is_file(): - default_gunicorn_conf = "/app/gunicorn_conf.py" - elif Path("/app/app/gunicorn_conf.py").is_file(): - default_gunicorn_conf = "/app/app/gunicorn_conf.py" +def set_conf_path(module: str) -> Path: + conf_var = str(os.getenv(f"{module.upper()}_CONF")) + if Path(conf_var).is_file(): + conf_path = conf_var + elif Path(f"/app/{module}_conf.py").is_file(): + conf_path = f"/app/{module}_conf.py" + elif Path(f"/app/app/{module}_conf.py").is_file(): + conf_path = f"/app/app/{module}_conf.py" else: - default_gunicorn_conf = "/gunicorn_conf.py" - gunicorn_conf = os.getenv("GUNICORN_CONF", default_gunicorn_conf) - os.environ["GUNICORN_CONF"] = gunicorn_conf - worker_class = os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker") - os.environ["WORKER_CLASS"] = worker_class - return gunicorn_conf, worker_class + conf_path = f"/{module}_conf.py" + os.environ[f"{module.upper()}_CONF"] = conf_path + return Path(conf_path) def run_pre_start_script( @@ -52,7 +51,7 @@ def run_pre_start_script( def start_server( app_module: str = str(os.getenv("APP_MODULE", "base.main:app")), - gunicorn_conf: str = str(os.getenv("GUNICORN_CONF", "/gunicorn_conf.py")), + gunicorn_conf: Path = Path("/gunicorn_conf.py"), with_reload: bool = bool(os.getenv("WITH_RELOAD", False)), worker_class: str = str(os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker")), ) -> None: @@ -66,12 +65,15 @@ def start_server( ) else: subprocess.run( - ["gunicorn", "-k", worker_class, "-c", gunicorn_conf, app_module] + ["gunicorn", "-k", worker_class, "-c", gunicorn_conf.name, app_module] ) if __name__ == "__main__": - set_app_module() - set_gunicorn_conf() + app_module = set_app_module() + gunicorn_conf_path = set_conf_path("gunicorn") + logging_conf_path = set_conf_path("logging") run_pre_start_script() - start_server() + start_server( + app_module=app_module, gunicorn_conf=gunicorn_conf_path, + ) From e2fa04aa8f6ad32ffaf5e9aa8afd4fe8096bfc64 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 14:57:57 -0400 Subject: [PATCH 10/27] Add docstrings to functions in start.py --- inboard/start.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/inboard/start.py b/inboard/start.py index 6cfe938..8a27aea 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -7,6 +7,7 @@ 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(): @@ -21,6 +22,7 @@ def set_app_module() -> str: def set_conf_path(module: str) -> Path: + """Set the path to a configuration file.""" conf_var = str(os.getenv(f"{module.upper()}_CONF")) if Path(conf_var).is_file(): conf_path = conf_var @@ -37,6 +39,7 @@ def set_conf_path(module: str) -> Path: def run_pre_start_script( pre_start_path: str = os.getenv("PRE_START_PATH", "/app/prestart.py") ) -> None: + """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(): @@ -55,6 +58,7 @@ def start_server( with_reload: bool = bool(os.getenv("WITH_RELOAD", False)), worker_class: str = str(os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker")), ) -> None: + """Start the Uvicorn or Gunicorn server.""" if with_reload: uvicorn.run( app_module, From b05a498eb595aeb83a6145d77f7fe9eb0be48f9d Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 16:12:05 -0400 Subject: [PATCH 11/27] Add logging configuration function to start.py This commit will add start.py `configure_logging()`. The function accepts a `Path()` to a logging configuration file, which can be either .py, .yml, .yaml, .conf, or .ini. For .py files, the function will load the Python file as a module, load the `LOGGING_CONFIG` dictionary object, and pass it to `logging.config.dictConfig()`. YAML files are opened with a context manager. PyYAML parses the YAML, and then passes the parsed YAML dictionary to `logging.config.dictConfig()`. The old-style .conf, or .ini. files are loaded with `logging.config.fileConfig()`. The type: ignore mypy comment prevents the following error messages, related to `spec.loader.exec_module()`: - Item "_Loader" of "Optional[_Loader]" has no attribute "exec_module" [union-attr] mypy(error) - Item "None" of "Optional[_Loader]" has no attribute "exec_module" [union-attr] mypy(error) https://mypy.readthedocs.io/en/latest/error_code_list.html --- inboard/start.py | 38 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/inboard/start.py b/inboard/start.py index 8a27aea..2cdaf0d 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -1,9 +1,12 @@ #!/usr/bin/env python3 +import importlib.util +import logging.config import os import subprocess from pathlib import Path import uvicorn # type: ignore +import yaml def set_app_module() -> str: @@ -36,6 +39,40 @@ def set_conf_path(module: str) -> Path: return Path(conf_path) +def configure_logging(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": + spec = importlib.util.spec_from_file_location("confspec", logging_conf) + logging_conf_module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(logging_conf_module) # type: ignore + if getattr(logging_conf_module, "LOGGING_CONFIG"): + logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + else: + raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.") + if isinstance(logging_conf_dict, dict): + logging.config.dictConfig(logging_conf_dict) + message = f"Logging dict config loaded from {logging_conf}." + else: + raise TypeError("LOGGING_CONFIG is not a dictionary instance.") + elif logging_conf.suffix in [".yml", ".yaml"]: + with open(logging_conf, "r") as file: + logging_conf_file = file.read() + yaml_contents = yaml.load(logging_conf_file, Loader=yaml.SafeLoader) + logging.config.dictConfig(yaml_contents) + message = f"Logging dict config loaded from YAML in {logging_conf}." + elif logging_conf.suffix in [".conf", ".ini"]: + logging.config.fileConfig(logging_conf, disable_existing_loggers=False) + message = f"Logging file config loaded from {logging_conf}." + else: + 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) + return message + + def run_pre_start_script( pre_start_path: str = os.getenv("PRE_START_PATH", "/app/prestart.py") ) -> None: @@ -77,6 +114,7 @@ def start_server( app_module = set_app_module() gunicorn_conf_path = set_conf_path("gunicorn") 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, From e9b27ce50405e53c5f5a7982e85d107fe0cf22ac Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 16:55:55 -0400 Subject: [PATCH 12/27] Add logging to start.py br3ndonland/inboard@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. --- inboard/app/prestart.py | 6 +++- inboard/gunicorn_conf.py | 16 +++++---- inboard/start.py | 78 +++++++++++++++++++++++----------------- 3 files changed, 59 insertions(+), 41 deletions(-) diff --git a/inboard/app/prestart.py b/inboard/app/prestart.py index 78a3c81..fe3cd0a 100644 --- 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 index 992aecd..b555e05 100644 --- 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 index 2cdaf0d..5d3b333 100644 --- 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) From a294862d702d793ffbb22eb5b582e9a07c1cce06 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Mon, 17 Aug 2020 21:39:31 -0400 Subject: [PATCH 13/27] Return logging dictionary config after loading This commit will refactor start.py `configure_logging()` to return the dictionary config object, which can be potentially passed to Gunicorn. https://docs.gunicorn.org/en/latest/settings.html#logconfig-dict --- inboard/start.py | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/inboard/start.py b/inboard/start.py index 5d3b333..57a07b2 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -6,6 +6,7 @@ import subprocess from logging import Logger from pathlib import Path +from typing import Any, Dict, Union import uvicorn # type: ignore import yaml @@ -28,7 +29,7 @@ def set_conf_path(module: str) -> Path: def configure_logging( logger: Logger = logging.getLogger(), logging_conf: Path = Path("/logging_conf.py") -) -> str: +) -> Union[Dict[str, Any], Path, str]: """Configure Python logging based on a path to a logging configuration file.""" try: if logging_conf.suffix == ".py": @@ -42,22 +43,28 @@ def configure_logging( if isinstance(logging_conf_dict, dict): logging.config.dictConfig(logging_conf_dict) message = f"Logging dict config loaded from {logging_conf}." + logger.debug(f"[{Path(__file__).stem}] {message}") + return logging_conf_dict else: raise TypeError("LOGGING_CONFIG is not a dictionary instance.") elif logging_conf.suffix in [".yml", ".yaml"]: with open(logging_conf, "r") as file: logging_conf_file = file.read() - yaml_contents = yaml.load(logging_conf_file, Loader=yaml.SafeLoader) - logging.config.dictConfig(yaml_contents) + logging_conf_dict = yaml.load(logging_conf_file, Loader=yaml.SafeLoader) + logging.config.dictConfig(logging_conf_dict) message = f"Logging dict config loaded from YAML in {logging_conf}." + logger.debug(f"[{Path(__file__).stem}] {message}") + return logging_conf_dict elif logging_conf.suffix in [".conf", ".ini"]: logging.config.fileConfig(logging_conf, disable_existing_loggers=False) message = f"Logging file config loaded from {logging_conf}." + logger.debug(f"[{Path(__file__).stem}] {message}") + return logging_conf else: raise ImportError(f"Unable to configure logging with {logging_conf.name}.") except Exception as e: message = f"Error when configuring logging: {e}" - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(f"[{Path(__file__).stem}] {message}") return message @@ -104,7 +111,6 @@ def run_pre_start_script(logger: Logger = logging.getLogger()) -> str: 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: @@ -130,4 +136,4 @@ def start_server( 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) + start_server(app_module=app_module, gunicorn_conf=gunicorn_conf_path) From bf62cc8807d349d54756f351297c85f985306ef8 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Tue, 18 Aug 2020 00:33:36 -0400 Subject: [PATCH 14/27] Remove PROPAGATE_ACCESS_LOGS environment variable I'm getting inconsistent behavior from `PROPAGATE_ACCESS_LOGS=false`. I'm able to set the environment variable correctly, but the logging configuration always sets it to True for some reason. This commit will remove support for `PROPAGATE_ACCESS_LOGS` until I can figure this out. --- README.md | 3 --- inboard/logging_conf.py | 5 ++--- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index ba73bd5..c59abc8 100644 --- a/README.md +++ b/README.md @@ -313,9 +313,6 @@ 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 -- `PROPAGATE_ACCESS_LOGS`: Gunicorn and Uvicorn have two primary log streams, `access` and `error`. The `error` logs are always propagated (output by the logger). The [Gunicorn logging config](https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py) and [Uvicorn logging config](https://github.com/encode/uvicorn/blob/master/uvicorn/config.py) both also propagate `access` logs by default, but some users may wish to disable `access` logs to reduce logging verbosity. This environment variable will set the behavior for both Gunicorn and Uvicorn. - - Default: `true` (access logs propagated by both Gunicorn and Uvicorn) - - Custom: `PROPAGATE_ACCESS_LOGS=false` 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. diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index 4cb9be4..b4a3f1c 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -2,7 +2,6 @@ from typing import Dict, Union LOG_LEVEL = str(os.getenv("LOG_LEVEL", "info")).upper() -PROPAGATE_ACCESS_LOGS = bool(os.getenv("PROPAGATE_ACCESS_LOGS", "true")) LOGGING_CONFIG: Dict[str, Union[Dict, bool, int, str]] = { "version": 1, "disable_existing_loggers": False, @@ -25,10 +24,10 @@ "loggers": { "fastapi": {"propagate": True}, "gunicorn": {"propagate": True}, - "gunicorn.access": {"propagate": PROPAGATE_ACCESS_LOGS}, + "gunicorn.access": {"propagate": True}, "gunicorn.error": {"propagate": True}, "uvicorn": {"propagate": True}, - "uvicorn.access": {"propagate": PROPAGATE_ACCESS_LOGS}, + "uvicorn.access": {"propagate": True}, "uvicorn.asgi": {"propagate": True}, "uvicorn.error": {"propagate": True}, }, From 8c81ebac3802b5784e3dfb71e46b216f99035f9d Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Tue, 18 Aug 2020 00:57:16 -0400 Subject: [PATCH 15/27] Specify logging handlers for gunicorn.access As explained in the Python logging module docs: https://docs.python.org/3/library/logging.html > A common scenario is to attach handlers only to the root logger, and > to let propagation take care of the rest. This doesn't appear to be working for Gunicorn. I need to explicitly add a handler in order for the Uvicorn access logs to come through. Adding a handler to uvicorn.access doesn't seem to affect Gunicorn. --- inboard/logging_conf.conf | 7 ++----- inboard/logging_conf.py | 3 +-- inboard/logging_conf.yml | 3 +-- 3 files changed, 4 insertions(+), 9 deletions(-) diff --git a/inboard/logging_conf.conf b/inboard/logging_conf.conf index 15735d8..8472d3c 100644 --- a/inboard/logging_conf.conf +++ b/inboard/logging_conf.conf @@ -16,7 +16,7 @@ level=DEBUG stream=ext://sys.stdout [loggers] -keys=root, fastapi, gunicorn, gunicorn.access, gunicorn.error, uvicorn, uvicorn.access, uvicorn.asgi, uvicorn.error +keys=root, fastapi, gunicorn.access, gunicorn.error, uvicorn, uvicorn.access, uvicorn.asgi, uvicorn.error [logger_root] handlers=inboard @@ -24,11 +24,8 @@ handlers=inboard [logger_fastapi] propagate=1 -[logger_gunicorn] -propagate=1 -qualname=gunicorn - [logger_gunicorn.access] +handlers=inboard propagate=1 qualname=gunicorn.access diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index b4a3f1c..9a7493d 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -23,8 +23,7 @@ "root": {"handlers": ["inboard"], "level": LOG_LEVEL}, "loggers": { "fastapi": {"propagate": True}, - "gunicorn": {"propagate": True}, - "gunicorn.access": {"propagate": True}, + "gunicorn.access": {"handlers": ["inboard"], "propagate": True}, "gunicorn.error": {"propagate": True}, "uvicorn": {"propagate": True}, "uvicorn.access": {"propagate": True}, diff --git a/inboard/logging_conf.yml b/inboard/logging_conf.yml index 624c548..4f4b00c 100644 --- a/inboard/logging_conf.yml +++ b/inboard/logging_conf.yml @@ -16,10 +16,9 @@ root: loggers: fastapi: propagate: true - gunicorn: - propagate: true gunicorn.access: propagate: true + handlers: inboard gunicorn.error: propagate: true uvicorn: From 271a7b0b5028932b3b226dd55c91a87fe18c7890 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Tue, 18 Aug 2020 13:40:02 -0400 Subject: [PATCH 16/27] Add module name to log message formatter This removes the need to specify the module within each logging message. I was previously using `[{Path(__file__).stem}]` for this purpose. --- inboard/logging_conf.py | 2 +- inboard/start.py | 16 ++++++++-------- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index 9a7493d..650c2eb 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -7,7 +7,7 @@ "disable_existing_loggers": False, "formatters": { "inboard": { - "format": "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s", # noqa: E501 + "format": "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] [%(module)s] %(message)s", # noqa: E501 "datefmt": "[%Y-%m-%d %H:%M:%S %z]", "class": "logging.Formatter", } diff --git a/inboard/start.py b/inboard/start.py index 57a07b2..917e5fe 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -43,7 +43,7 @@ def configure_logging( if isinstance(logging_conf_dict, dict): logging.config.dictConfig(logging_conf_dict) message = f"Logging dict config loaded from {logging_conf}." - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(message) return logging_conf_dict else: raise TypeError("LOGGING_CONFIG is not a dictionary instance.") @@ -53,18 +53,18 @@ def configure_logging( logging_conf_dict = yaml.load(logging_conf_file, Loader=yaml.SafeLoader) logging.config.dictConfig(logging_conf_dict) message = f"Logging dict config loaded from YAML in {logging_conf}." - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(message) return logging_conf_dict elif logging_conf.suffix in [".conf", ".ini"]: logging.config.fileConfig(logging_conf, disable_existing_loggers=False) message = f"Logging file config loaded from {logging_conf}." - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(message) return logging_conf else: raise ImportError(f"Unable to configure logging with {logging_conf.name}.") except Exception as e: message = f"Error when configuring logging: {e}" - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(message) return message @@ -80,14 +80,14 @@ def set_app_module(logger: Logger = logging.getLogger()) -> str: 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}.") + logger.debug(f"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: - logger.debug(f"[{Path(__file__).stem}] Checking for pre-start script.") + logger.debug("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 @@ -96,7 +96,7 @@ def run_pre_start_script(logger: Logger = logging.getLogger()) -> str: if pre_start_path: process = "python" if Path(pre_start_path).suffix == ".py" else "sh" run_message = f"Running pre-start script with {process} {pre_start_path}." - logger.debug(f"[{Path(__file__).stem}] {run_message}") + logger.debug(run_message) subprocess.run([process, pre_start_path]) message = f"Ran pre-start script with {process} {pre_start_path}." else: @@ -104,7 +104,7 @@ def run_pre_start_script(logger: Logger = logging.getLogger()) -> str: raise FileNotFoundError(message) except Exception as e: message = f"Error from pre-start script: {e}" - logger.debug(f"[{Path(__file__).stem}] {message}") + logger.debug(message) return message From 1a9a8268811fd2acc5a926b473ba7d53e71f37c8 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Tue, 18 Aug 2020 13:44:57 -0400 Subject: [PATCH 17/27] Drop support for YAML and INI logging config files MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit I was previously supporting the old-format .conf/.ini files, and YAML files, in addition to the new-style Python dictionary configuration. Moving forward, I will only support Python dictionary configurations. Justification: - Dict configs are the newer, recommended format. - Dict configs provide additional features (see note from docs below) - Dict configs allow programmatic control of logging settings (see how log level is set in logging_conf.py for an example). - Gunicorn and Uvicorn both use dict configs in .py files. - Gunicorn accepts a dict config with the `logconfig_dict` option. - Reduces testing burden (I only have to write unit tests for .py files) - YAML is confusingly used for examples in the documentation, but isn't actually a recommended format. There's no built-in YAML data structure in Python, so the YAML must be parsed by PyYAML and converted into a dictionary, then passed to `logging.config.dictConfig()`. Why not just make it a dictionary in the first place? https://docs.python.org/3/library/logging.config.html: > The fileConfig() API is older than the dictConfig() API and does not > provide functionality to cover certain aspects of logging. For > example, you cannot configure Filter objects, which provide for > filtering of messages beyond simple integer levels, using fileConfig(). > If you need to have instances of Filter in your logging configuration, > you will need to use dictConfig(). Note that future enhancements to > configuration functionality will be added to dictConfig(), so it’s > worth considering transitioning to this newer API when it’s convenient > to do so. --- README.md | 9 ++----- inboard/logging_conf.conf | 51 --------------------------------------- inboard/logging_conf.yml | 31 ------------------------ inboard/start.py | 47 ++++++++++++------------------------ poetry.lock | 4 +-- pyproject.toml | 1 - 6 files changed, 20 insertions(+), 123 deletions(-) delete mode 100644 inboard/logging_conf.conf delete mode 100644 inboard/logging_conf.yml diff --git a/README.md b/README.md index c59abc8..2e5879e 100644 --- a/README.md +++ b/README.md @@ -283,18 +283,13 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" ### Logging -- `LOGGING_CONF`: Path to a [Python logging configuration file](https://docs.python.org/3/library/logging.config.html). - - File format options: - - A new-style `.py` file containing a configuration dictionary object named `LOGGING_CONFIG` that will be passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html) (preferred) - - A new-style `.yml` or `.yaml` file that will be parsed by [PyYAML](https://pypi.org/project/PyYAML/) and then passed to [`logging.config.dictConfig()`](https://docs.python.org/3/library/logging.config.html) - - An old-style `.conf` or `.ini` file that will be passed to [`logging.config.fileConfig()`](https://docs.python.org/3/library/logging.config.html) - - Feel free to use the [`logging_conf.py`](./inboard/logging_conf.py) from this repo as a starting point for your own custom configuration. +- `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.conf"` + - `LOGGING_CONF="/app/custom_logging.py"` - `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` - Custom (organized from greatest to least amount of logging): diff --git a/inboard/logging_conf.conf b/inboard/logging_conf.conf deleted file mode 100644 index 8472d3c..0000000 --- a/inboard/logging_conf.conf +++ /dev/null @@ -1,51 +0,0 @@ -[formatters] -keys=inboard - -[formatter_inboard] -format=%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s -datefmt=[%Y-%m-%d %H:%M:%S %z] -class=logging.Formatter - -[handlers] -keys=inboard - -[handlers_inboard] -class=logging.StreamHandler -formatter=inboard -level=DEBUG -stream=ext://sys.stdout - -[loggers] -keys=root, fastapi, gunicorn.access, gunicorn.error, uvicorn, uvicorn.access, uvicorn.asgi, uvicorn.error - -[logger_root] -handlers=inboard - -[logger_fastapi] -propagate=1 - -[logger_gunicorn.access] -handlers=inboard -propagate=1 -qualname=gunicorn.access - -[logger_gunicorn.error] -propagate=1 -qualname=gunicorn.error - -[logger_uvicorn] -level=INFO -propagate=1 -qualname=uvicorn - -[logger_uvicorn.access] -propagate=1 -qualname=uvicorn.access - -[logger_uvicorn.asgi] -propagate=1 -qualname=uvicorn.asgi - -[logger_uvicorn.error] -propagate=1 -qualname=uvicorn.error diff --git a/inboard/logging_conf.yml b/inboard/logging_conf.yml deleted file mode 100644 index 4f4b00c..0000000 --- a/inboard/logging_conf.yml +++ /dev/null @@ -1,31 +0,0 @@ -version: 1 -disable_existing_loggers: False -formatters: - inboard: - format: "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] %(message)s" - datefmt: "[%Y-%m-%d %H:%M:%S %z]" - class: logging.Formatter -handlers: - inboard: - class: logging.StreamHandler - formatter: inboard - level: DEBUG - stream: ext://sys.stdout -root: - handlers: inboard -loggers: - fastapi: - propagate: true - gunicorn.access: - propagate: true - handlers: inboard - gunicorn.error: - propagate: true - uvicorn: - propagate: true - uvicorn.access: - propagate: true - uvicorn.asgi: - propagate: true - uvicorn.error: - propagate: true diff --git a/inboard/start.py b/inboard/start.py index 917e5fe..9601ddb 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -9,7 +9,6 @@ from typing import Any, Dict, Union import uvicorn # type: ignore -import yaml def set_conf_path(module: str) -> Path: @@ -29,43 +28,29 @@ def set_conf_path(module: str) -> Path: def configure_logging( logger: Logger = logging.getLogger(), logging_conf: Path = Path("/logging_conf.py") -) -> Union[Dict[str, Any], Path, str]: +) -> Union[Dict[str, Any], str]: """Configure Python logging based on a path to a logging configuration file.""" try: - if logging_conf.suffix == ".py": - spec = importlib.util.spec_from_file_location("confspec", logging_conf) - logging_conf_module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(logging_conf_module) # type: ignore - if getattr(logging_conf_module, "LOGGING_CONFIG"): - logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") - else: - raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.") - if isinstance(logging_conf_dict, dict): - logging.config.dictConfig(logging_conf_dict) - message = f"Logging dict config loaded from {logging_conf}." - logger.debug(message) - return logging_conf_dict - else: - raise TypeError("LOGGING_CONFIG is not a dictionary instance.") - elif logging_conf.suffix in [".yml", ".yaml"]: - with open(logging_conf, "r") as file: - logging_conf_file = file.read() - logging_conf_dict = yaml.load(logging_conf_file, Loader=yaml.SafeLoader) - logging.config.dictConfig(logging_conf_dict) - message = f"Logging dict config loaded from YAML in {logging_conf}." - logger.debug(message) - return logging_conf_dict - elif logging_conf.suffix in [".conf", ".ini"]: - logging.config.fileConfig(logging_conf, disable_existing_loggers=False) - message = f"Logging file config loaded from {logging_conf}." + if logging_conf.suffix != ".py": + raise ImportError(f"{logging_conf.name} must have a .py extension.") + spec = importlib.util.spec_from_file_location("confspec", logging_conf) + logging_conf_module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(logging_conf_module) # type: ignore + if getattr(logging_conf_module, "LOGGING_CONFIG"): + logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + else: + raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.") + if isinstance(logging_conf_dict, dict): + logging.config.dictConfig(logging_conf_dict) + message = f"Logging dict config loaded from {logging_conf}." logger.debug(message) - return logging_conf + return logging_conf_dict else: - raise ImportError(f"Unable to configure logging with {logging_conf.name}.") + raise TypeError("LOGGING_CONFIG is not a dictionary instance.") except Exception as e: message = f"Error when configuring logging: {e}" logger.debug(message) - return message + return message def set_app_module(logger: Logger = logging.getLogger()) -> str: diff --git a/poetry.lock b/poetry.lock index f2497c5..210b577 100644 --- a/poetry.lock +++ b/poetry.lock @@ -359,7 +359,7 @@ pytest = ">=2.7" dev = ["pre-commit", "tox", "pytest-asyncio"] [[package]] -category = "main" +category = "dev" description = "YAML parser and emitter for Python" name = "pyyaml" optional = false @@ -483,7 +483,7 @@ fastapi = ["fastapi"] starlette = ["starlette"] [metadata] -content-hash = "42984799c7fb0e25b47eda4ee214c9032f38a8f3448b3ee86fbea098c21c1e25" +content-hash = "50c0a53686e43d3c8b0be6a478d8e55910fc7ef6d97fd5bdb38f6622fe974913" lock-version = "1.0" python-versions = "^3.8" diff --git a/pyproject.toml b/pyproject.toml index 86e1f35..37de65a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -13,7 +13,6 @@ readme = "README.md" [tool.poetry.dependencies] python = "^3.8" -pyyaml = "^5.3" gunicorn = "^20" uvicorn = "^0.11.8" fastapi = {version = "^0.60.1", optional = true} From 591458fe191ee688f4654f5052428ecb265f1a2e Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 15:10:11 -0400 Subject: [PATCH 18/27] Improve logging and return types in start.py start.py configure_logging - Simplify return statement: just return a dict start.py run_pre_start_script - If pre-start script is not found, log a message instead of raising an exception (pre-start script is optional) - Use `finally` to wrap return statement --- inboard/start.py | 50 +++++++++++++++++++++++++----------------------- 1 file changed, 26 insertions(+), 24 deletions(-) diff --git a/inboard/start.py b/inboard/start.py index 9601ddb..01f6ba6 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -6,7 +6,7 @@ import subprocess from logging import Logger from pathlib import Path -from typing import Any, Dict, Union +from typing import Any, Dict import uvicorn # type: ignore @@ -28,29 +28,30 @@ def set_conf_path(module: str) -> Path: def configure_logging( logger: Logger = logging.getLogger(), logging_conf: Path = Path("/logging_conf.py") -) -> Union[Dict[str, Any], str]: +) -> Dict[str, Any]: """Configure Python logging based on a path to a logging configuration file.""" try: - if logging_conf.suffix != ".py": - raise ImportError(f"{logging_conf.name} must have a .py extension.") - spec = importlib.util.spec_from_file_location("confspec", logging_conf) - logging_conf_module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(logging_conf_module) # type: ignore - if getattr(logging_conf_module, "LOGGING_CONFIG"): - logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + if isinstance(logging_conf, Path) and logging_conf.suffix == ".py": + spec = importlib.util.spec_from_file_location("confspec", logging_conf) + logging_conf_module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(logging_conf_module) # type: ignore + if getattr(logging_conf_module, "LOGGING_CONFIG"): + logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + else: + raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.") + if isinstance(logging_conf_dict, dict): + logging.config.dictConfig(logging_conf_dict) + message = f"Logging dict config loaded from {logging_conf}." + logger.debug(message) + return logging_conf_dict + else: + raise TypeError("LOGGING_CONFIG is not a dictionary instance.") else: - raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.") - if isinstance(logging_conf_dict, dict): - logging.config.dictConfig(logging_conf_dict) - message = f"Logging dict config loaded from {logging_conf}." - logger.debug(message) - return logging_conf_dict - else: - raise TypeError("LOGGING_CONFIG is not a dictionary instance.") + raise ImportError("Valid path to .py logging config file required.") except Exception as e: message = f"Error when configuring logging: {e}" logger.debug(message) - return message + raise def set_app_module(logger: Logger = logging.getLogger()) -> str: @@ -73,24 +74,25 @@ def run_pre_start_script(logger: Logger = logging.getLogger()) -> str: """Run a pre-start script at the provided path.""" try: logger.debug("Checking for pre-start script.") - pre_start_path_var = str(os.getenv("PRE_START_PATH", "/app/prestart.py")) + pre_start_path = None + pre_start_path_var = 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" + else: + message = "No pre-start script found." if pre_start_path: process = "python" if Path(pre_start_path).suffix == ".py" else "sh" run_message = f"Running pre-start script with {process} {pre_start_path}." logger.debug(run_message) subprocess.run([process, pre_start_path]) message = f"Ran pre-start script with {process} {pre_start_path}." - else: - message = "No pre-start script found." - raise FileNotFoundError(message) except Exception as e: message = f"Error from pre-start script: {e}" - logger.debug(message) - return message + finally: + logger.debug(message) + return message def start_server( From 6e66d98bf5eb8eb1c3991bb16951c5a08417a8f4 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 15:10:38 -0400 Subject: [PATCH 19/27] Configure Gunicorn logging programmatically Now that the logging dictConfig is being properly loaded, the dict needs to be sent to Gunicorn and used for its loggers. Gunicorn does not have an interface for running programmatically from within a Python module, like `uvicorn.run()`, so `subprocess.run()` is used. There isn't a clear way to pass a dictConfig to Gunicorn from the command line. As of Gunicorn version 20, Gunicorn accepts a command-line argument `--log-config-dict`, but it's unclear how to use this, and it will be removed, as explained in gunicorn issue 1909. One option is to import the dictConfig into gunicorn_conf.py: ```py from logging_conf import LOGGING_CONFIG logconfig_dict = LOGGING_CONFIG ``` This works if the logging_conf is static (like the logging_conf.py in this repo), but this repo gives developers the ability to supply a path to a custom logging configuration file, which is then loaded dynamically with start.py `configure_logging()`. To address these limitations, this commit will update gunicorn_conf.py to import `configure_logging()` from start.py, loading the dictConfig and passing it to Gunicorn with the `logconfig_dict` variable. --- inboard/gunicorn_conf.py | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py index b555e05..83ebf6d 100644 --- a/inboard/gunicorn_conf.py +++ b/inboard/gunicorn_conf.py @@ -3,6 +3,8 @@ 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") use_max_workers = None @@ -32,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 @@ -61,4 +70,4 @@ "accesslog": accesslog, } -print(f"[{Path(__file__).stem}] Gunicorn configuration:", json.dumps(log_data)) +print(f"[{Path(__file__).stem}] Additional configuration:", json.dumps(log_data)) From f6ca7da957e0abdb466365a8b0c598203b6fc478 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 20:51:43 -0400 Subject: [PATCH 20/27] Configure Uvicorn logging programmatically A dictionary can be passed to Uvicorn when running programmatically: ```py uvicorn.run(log_config=your_dict_config) ``` While useful, this capability is undocumented. --- inboard/start.py | 41 +++++++++++++++++++++++++++-------------- 1 file changed, 27 insertions(+), 14 deletions(-) diff --git a/inboard/start.py b/inboard/start.py index 01f6ba6..1945299 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -98,29 +98,42 @@ def run_pre_start_script(logger: Logger = logging.getLogger()) -> str: 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(), + logging_conf_dict: Dict[str, Any] = None, with_reload: bool = bool(os.getenv("WITH_RELOAD", False)), worker_class: str = str(os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker")), ) -> None: """Start the Uvicorn or Gunicorn server.""" - if with_reload: - uvicorn.run( - app_module, - host=os.getenv("HOST", "0.0.0.0"), - port=int(os.getenv("PORT", "80")), - log_level=os.getenv("LOG_LEVEL", "info"), - reload=True, - ) - else: - subprocess.run( - ["gunicorn", "-k", worker_class, "-c", gunicorn_conf.name, app_module] - ) + try: + if with_reload: + logger.debug("Running Uvicorn without Gunicorn and with reloading") + uvicorn.run( + app_module, + host=os.getenv("HOST", "0.0.0.0"), + port=int(os.getenv("PORT", "80")), + log_config=logging_conf_dict, + log_level=os.getenv("LOG_LEVEL", "info"), + reload=True, + ) + else: + logger.debug("Running Uvicorn with Gunicorn.") + subprocess.run( + ["gunicorn", "-k", worker_class, "-c", gunicorn_conf.name, app_module] + ) + except Exception as e: + logger.debug(f"Error when starting server with start script: {e}") if __name__ == "__main__": logger = logging.getLogger() logging_conf_path = set_conf_path("logging") - configure_logging(logger=logger, logging_conf=logging_conf_path) + logging_conf_dict = 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) + start_server( + app_module=app_module, + gunicorn_conf=gunicorn_conf_path, + logger=logger, + logging_conf_dict=logging_conf_dict, + ) From 27896dd80f4198e7eb92b58945051c06f03f292c Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 21:21:31 -0400 Subject: [PATCH 21/27] Add support for multiple log message formatters This commit will update the log message formatter in logging_conf.py to support multiple options: - `simple` (default): Simply the log level and message. - `verbose`: A custom format, with the first 80 characters containing metadata, and the remainder supplying the log message. - `gunicorn`: Gunicorn's default format. - `uvicorn`: Uvicorn's default format, with support for `LOG_COLORS`. --- README.md | 23 +++++++++++++++++++++++ inboard/logging_conf.py | 33 +++++++++++++++++++++++++-------- 2 files changed, 48 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 2e5879e..b1e3341 100644 --- a/README.md +++ b/README.md @@ -290,6 +290,29 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" - Else `/logging_conf.py` (the default file provided with the Docker image) - Custom: - `LOGGING_CONF="/app/custom_logging.py"` +- `LOG_COLORS` + - 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` + - 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` - Custom (organized from greatest to least amount of logging): diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index 650c2eb..1fc8534 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -1,29 +1,46 @@ import os +import sys from typing import Dict, Union +LOG_COLORS = bool(os.getenv("LOG_COLORS", sys.stdout.isatty())) +LOG_FORMAT = str(os.getenv("LOG_FORMAT", "simple")) LOG_LEVEL = str(os.getenv("LOG_LEVEL", "info")).upper() LOGGING_CONFIG: Dict[str, Union[Dict, bool, int, str]] = { "version": 1, "disable_existing_loggers": False, "formatters": { - "inboard": { - "format": "%(asctime)s [%(process)d] [%(name)s] [%(levelname)s] [%(module)s] %(message)s", # noqa: E501 - "datefmt": "[%Y-%m-%d %H:%M:%S %z]", + "simple": { "class": "logging.Formatter", - } + "format": "%(levelname)-10s %(message)s", + }, + "verbose": { + "class": "logging.Formatter", + "format": "%(asctime)-30s %(process)-10d %(name)-15s %(module)-15s %(levelname)-10s %(message)s", # noqa: E501 + "datefmt": "%Y-%m-%d %H:%M:%S %z", + }, + "gunicorn": { + "class": "logging.Formatter", + "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s", + "datefmt": "[%Y-%m-%d %H:%M:%S %z]", + }, + "uvicorn": { + "()": "uvicorn.logging.DefaultFormatter", + "format": "%(levelprefix)s %(message)s", + "use_colors": LOG_COLORS, + }, }, "handlers": { - "inboard": { + "default": { "class": "logging.StreamHandler", - "formatter": "inboard", + "formatter": LOG_FORMAT, "level": LOG_LEVEL, "stream": "ext://sys.stdout", } }, - "root": {"handlers": ["inboard"], "level": LOG_LEVEL}, + "root": {"handlers": ["default"], "level": LOG_LEVEL}, "loggers": { "fastapi": {"propagate": True}, - "gunicorn.access": {"handlers": ["inboard"], "propagate": True}, + "gunicorn.access": {"handlers": ["default"], "propagate": True}, "gunicorn.error": {"propagate": True}, "uvicorn": {"propagate": True}, "uvicorn.access": {"propagate": True}, From 197feda1e30f8936ab50e00ade57ea5d836ee984 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 12:33:10 -0400 Subject: [PATCH 22/27] Add Uvicorn VSCode debugger config https://code.visualstudio.com/docs/editor/debugging I also tried adding a Gunicorn debugger config, but it's difficult to keep track of the worker processes, and I was having some issues coordinating with `subprocess.run()`. --- .vscode/launch.json | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) create mode 100644 .vscode/launch.json diff --git a/.vscode/launch.json b/.vscode/launch.json new file mode 100644 index 0000000..931f9e3 --- /dev/null +++ b/.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 + } + ] +} From 60aa2caff10f5d44510bd946fcafab2db5fa7793 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 22:59:13 -0400 Subject: [PATCH 23/27] Proofread README - Correct `pip` command - Quote environment variable values to avoid confusion - Improve mounting of application files when running Docker with Uvicorn --- README.md | 90 +++++++++++++++++++++++++++++++++---------------------- 1 file changed, 54 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index b1e3341..f507f5d 100644 --- a/README.md +++ b/README.md @@ -122,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/ @@ -158,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. @@ -197,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 @@ -219,59 +221,63 @@ 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. @@ -285,24 +291,24 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" - `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) + - `"/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` +- `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` + - `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. + - `"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). + - `"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] @@ -314,13 +320,13 @@ ENV APP_MODULE="custom.module:api" WORKERS_PER_CORE="2" 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: @@ -368,11 +374,23 @@ docker build . --rm --target starlette -t localhost/br3ndonland/inboard/starlett ```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 From 57f777b615ae51ae3513dc4ee767a17c2d73f5f4 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 23:15:32 -0400 Subject: [PATCH 24/27] Improve selectivity of Docker COPY command Docker was previously copying the entire inboard directory, including inboard/`__init__.py`, to the root directory in the Docker image. This hasn't caused any issues so far, but could have unintended consequences if the `PYTHONPATH` were set to the root directory. This commit will avoid copying inboard/`__init__.py`. --- Dockerfile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Dockerfile b/Dockerfile index 280a538..4986873 100644 --- a/Dockerfile +++ b/Dockerfile @@ -3,7 +3,7 @@ LABEL maintainer="Brendon Smith" COPY poetry.lock pyproject.toml / ENV APP_MODULE=base.main:app GUNICORN_CONF=/gunicorn_conf.py POETRY_VIRTUALENVS_CREATE=false PYTHONPATH=/app RUN python -m pip install poetry && poetry install --no-dev --no-interaction --no-root -E fastapi -COPY inboard / +COPY inboard/gunicorn_conf.py inboard/logging_conf.py inboard/start.py inboard/app / CMD python /start.py FROM base AS fastapi From 00a3319725286e10ede23cf7fb48cbc2cfedde77 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 23:18:56 -0400 Subject: [PATCH 25/27] Restrict Gunicorn configuration output to debug There's a `print()` command in gunicorn_conf.py that prints the custom Gunicorn configuration not output by Gunicorn with `LOG_LEVEL="debug"`. This commit will only run the `print()` command if `LOG_LEVEL="debug"`. --- inboard/gunicorn_conf.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py index 83ebf6d..e295fc5 100644 --- a/inboard/gunicorn_conf.py +++ b/inboard/gunicorn_conf.py @@ -69,5 +69,5 @@ "errorlog": errorlog, "accesslog": accesslog, } - -print(f"[{Path(__file__).stem}] Additional configuration:", json.dumps(log_data)) +if loglevel == "debug": + print(f"[{Path(__file__).stem}] Custom configuration:", json.dumps(log_data)) From 83770eedd8a86f81d13fd67e322ca8bfee0f872d Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 23:47:44 -0400 Subject: [PATCH 26/27] Remove redundant Dockerfile environment variable GUNICORN_CONF is now being set by start.py. --- Dockerfile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Dockerfile b/Dockerfile index 4986873..6599a04 100644 --- a/Dockerfile +++ b/Dockerfile @@ -1,7 +1,7 @@ FROM python:3.8 AS base LABEL maintainer="Brendon Smith" COPY poetry.lock pyproject.toml / -ENV APP_MODULE=base.main:app GUNICORN_CONF=/gunicorn_conf.py POETRY_VIRTUALENVS_CREATE=false PYTHONPATH=/app +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 46e94075ee4c48db350de178a167a833cbc72e01 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Wed, 19 Aug 2020 23:59:43 -0400 Subject: [PATCH 27/27] :ship: Add emoji to README title :whale: :muscle: :nerd_face: :computer: --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index f507f5d..743b29d 100644 --- a/README.md +++ b/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._