From d28753bb350e27a259f8390fb40e73366610c0f0 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 14:18:36 -0400 Subject: [PATCH 01/12] Move Gunicorn conf tests to separate module br3ndonland/inboard#11 These tests weren't really testing the start script, so they shouldn't be in test_start.py. Moving the tests to test_gunicorn_conf.py also helps emulate the directory structure of the source code, so tests are more intuitively found. --- tests/test_gunicorn_conf.py | 85 +++++++++++++++++++++++++++++++++++++ tests/test_start.py | 84 +----------------------------------- 2 files changed, 86 insertions(+), 83 deletions(-) create mode 100644 tests/test_gunicorn_conf.py diff --git a/tests/test_gunicorn_conf.py b/tests/test_gunicorn_conf.py new file mode 100644 index 0000000..41a63a7 --- /dev/null +++ b/tests/test_gunicorn_conf.py @@ -0,0 +1,85 @@ +import multiprocessing +import os +from typing import Optional + +import pytest + +from inboard import gunicorn_conf + + +class TestCalculateWorkers: + """Test calculation of the number of Gunicorn worker processes. + --- + """ + + def test_gunicorn_conf_workers_default(self) -> None: + """Test default number of Gunicorn worker processes.""" + assert gunicorn_conf.workers >= 2 + assert gunicorn_conf.workers == multiprocessing.cpu_count() + + def test_gunicorn_conf_workers_custom_max( + self, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Test custom Gunicorn worker process calculation.""" + monkeypatch.setenv("MAX_WORKERS", "1") + monkeypatch.setenv("WEB_CONCURRENCY", "4") + monkeypatch.setenv("WORKERS_PER_CORE", "0.5") + assert os.getenv("MAX_WORKERS") == "1" + assert os.getenv("WEB_CONCURRENCY") == "4" + assert os.getenv("WORKERS_PER_CORE") == "0.5" + assert ( + gunicorn_conf.calculate_workers( + str(os.getenv("MAX_WORKERS")), + str(os.getenv("WEB_CONCURRENCY")), + str(os.getenv("WORKERS_PER_CORE")), + ) + == 1 + ) + + @pytest.mark.parametrize("number_of_workers", ["1", "2", "4"]) + def test_gunicorn_conf_workers_custom_concurrency( + self, monkeypatch: pytest.MonkeyPatch, number_of_workers: str + ) -> None: + """Test custom Gunicorn worker process calculation.""" + monkeypatch.setenv("WEB_CONCURRENCY", number_of_workers) + monkeypatch.setenv("WORKERS_PER_CORE", "0.5") + assert os.getenv("WEB_CONCURRENCY") == number_of_workers + assert os.getenv("WORKERS_PER_CORE") == "0.5" + assert ( + gunicorn_conf.calculate_workers( + None, + str(os.getenv("WEB_CONCURRENCY")), + str(os.getenv("WORKERS_PER_CORE")), + ) + == int(number_of_workers) + ) + + @pytest.mark.parametrize("concurrency", [None, "10"]) + def test_gunicorn_conf_workers_custom_cores( + self, monkeypatch: pytest.MonkeyPatch, concurrency: Optional[str] + ) -> None: + """Test custom Gunicorn worker process calculation. + - Assert that number of workers equals `WORKERS_PER_CORE`, and is at least 2. + - Assert that setting `WEB_CONCURRENCY` overrides `WORKERS_PER_CORE`. + """ + monkeypatch.setenv("WORKERS_PER_CORE", "0.5") + workers_per_core = os.getenv("WORKERS_PER_CORE") + assert workers_per_core == "0.5" + cores: int = multiprocessing.cpu_count() + assert gunicorn_conf.calculate_workers( + None, None, workers_per_core, cores=cores + ) == max(int(cores * float(workers_per_core)), 2) + assert ( + gunicorn_conf.calculate_workers(None, "10", workers_per_core, cores=cores) + == 10 + ) + monkeypatch.setenv("WEB_CONCURRENCY", concurrency) if concurrency else None + assert os.getenv("WEB_CONCURRENCY") == concurrency + assert ( + gunicorn_conf.calculate_workers( + None, concurrency, workers_per_core, cores=cores + ) + == 10 + if concurrency + else max(int(cores * float(workers_per_core)), 2) + ) diff --git a/tests/test_start.py b/tests/test_start.py index efc85ee..d2f1beb 100644 --- a/tests/test_start.py +++ b/tests/test_start.py @@ -1,92 +1,10 @@ -import multiprocessing import os from pathlib import Path -from typing import Optional import pytest from pytest_mock import MockerFixture -from inboard import gunicorn_conf, start - - -class TestConfigureGunicorn: - """Test Gunicorn configuration independently of Gunicorn server. - --- - """ - - def test_gunicorn_conf_workers_default(self) -> None: - """Test default number of Gunicorn worker processes.""" - assert gunicorn_conf.workers >= 2 - assert gunicorn_conf.workers == multiprocessing.cpu_count() - - def test_gunicorn_conf_workers_custom_max( - self, monkeypatch: pytest.MonkeyPatch - ) -> None: - """Test custom Gunicorn worker process calculation.""" - monkeypatch.setenv("MAX_WORKERS", "1") - monkeypatch.setenv("WEB_CONCURRENCY", "4") - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - assert os.getenv("MAX_WORKERS") == "1" - assert os.getenv("WEB_CONCURRENCY") == "4" - assert os.getenv("WORKERS_PER_CORE") == "0.5" - assert ( - gunicorn_conf.calculate_workers( - str(os.getenv("MAX_WORKERS")), - str(os.getenv("WEB_CONCURRENCY")), - str(os.getenv("WORKERS_PER_CORE")), - ) - == 1 - ) - - @pytest.mark.parametrize("number_of_workers", ["1", "2", "4"]) - def test_gunicorn_conf_workers_custom_concurrency( - self, monkeypatch: pytest.MonkeyPatch, number_of_workers: str - ) -> None: - """Test custom Gunicorn worker process calculation.""" - monkeypatch.setenv("WEB_CONCURRENCY", number_of_workers) - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - assert os.getenv("WEB_CONCURRENCY") == number_of_workers - assert os.getenv("WORKERS_PER_CORE") == "0.5" - assert ( - gunicorn_conf.calculate_workers( - None, - str(os.getenv("WEB_CONCURRENCY")), - str(os.getenv("WORKERS_PER_CORE")), - ) - == int(number_of_workers) - ) - - @pytest.mark.parametrize("concurrency", [None, "10"]) - def test_gunicorn_conf_workers_custom_cores( - self, monkeypatch: pytest.MonkeyPatch, concurrency: Optional[str] - ) -> None: - """Test custom Gunicorn worker process calculation. - - Assert that number of workers equals `WORKERS_PER_CORE`, and is at least 2. - - Assert that setting `WEB_CONCURRENCY` overrides `WORKERS_PER_CORE`. - """ - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - workers_per_core = os.getenv("WORKERS_PER_CORE") - assert workers_per_core == "0.5" - cores: int = multiprocessing.cpu_count() - assert gunicorn_conf.calculate_workers( - None, None, workers_per_core, cores=cores - ) == max(int(cores * float(workers_per_core)), 2) - assert ( - gunicorn_conf.calculate_workers(None, "10", workers_per_core, cores=cores) - == 10 - ) - monkeypatch.setenv("WEB_CONCURRENCY", concurrency) if concurrency else None - assert os.getenv("WEB_CONCURRENCY") == concurrency - assert ( - ( - gunicorn_conf.calculate_workers( - None, concurrency, workers_per_core, cores=cores - ) - == 10 - ) - if concurrency - else max(int(cores * float(workers_per_core)), 2) - ) +from inboard import start class TestConfigureLogging: From 315c1c1dbbf12d4acdbbebeef062582ad1b6c9fe Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 16:08:13 -0400 Subject: [PATCH 02/12] Refactor Gunicorn worker calculation and tests br3ndonland/inboard#11 br3ndonland/inboard@02b249e br3ndonland/inboard@fd60470 https://docs.python.org/3/reference/expressions.html#boolean-operations The `gunicorn_conf.calculate_workers()` method returns a desired number of Gunicorn workers, based on the arguments passed in. The arguments are read from environment variables. The calculation is deceptively complex, and a variety of edge cases emerged over time. Commit fd60470 fixed the web concurrency calculation, but not the max workers calculation. There should have been an `else use_max_workers if max_workers_str` condition. The tests were correspondingly complex and convoluted, testing various interrelated conditions, and becoming less and less readable. This commit will refactor the Gunicorn worker calculation and tests. The result is more readable (and correct) code. Refactor the `gunicorn_conf.calculate_workers()` method arguments: - Remove `_str` from function arguments: arguments are type-annotated, and it is redundant to add `_str` to arguments annotated as strings. - Rename the `web_concurrency_str` function argument to `total_workers`: the "web concurrency" name is a legacy Gunicorn environment variable, and doesn't really convey what the setting does. "Web concurrency" is a total number of workers, so just call it `total_workers`. - Make the `workers_per_core` argument a keyword argument (kwarg): the corresponding environment variable `WORKERS_PER_CORE` has a default, so set the same default on the kwarg. - Move the cpu cores calculation into the function body: not necessary to set a number of cores, so just use `multiprocessing.cpu_count()`. - Keep same order of arguments and argument type-annotations to avoid breaking existing functionality and to ensure backwards-compatibility. Refactor the `gunicorn_conf.calculate_workers()` method logic, by using `if` expressions to more clearly evaluate each condition, then returning the correct value by using `or` to evaluate Boolean conditions in order. Improve test parametrization to more thoroughly test use cases, and refactor tests so that each one tests an isolated use case: - Check defaults - Set maximum number of workers - Set total number of workers ("web concurrency") - Set desired number of workers per core - Set both maximum number of workers and total number of workers --- inboard/gunicorn_conf.py | 25 ++++----- tests/test_gunicorn_conf.py | 103 ++++++++++++------------------------ 2 files changed, 44 insertions(+), 84 deletions(-) diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py index 05f816e..1a02b00 100644 --- a/inboard/gunicorn_conf.py +++ b/inboard/gunicorn_conf.py @@ -6,24 +6,17 @@ def calculate_workers( - max_workers_str: Optional[str], - web_concurrency_str: Optional[str], - workers_per_core_str: str, - cores: int = multiprocessing.cpu_count(), + max_workers: Optional[str] = None, + total_workers: Optional[str] = None, + workers_per_core: str = "1", ) -> int: """Calculate the number of Gunicorn worker processes.""" - use_default_workers = max(int(float(workers_per_core_str) * cores), 2) - if max_workers_str and int(max_workers_str) > 0: - use_max_workers = int(max_workers_str) - if web_concurrency_str and int(web_concurrency_str) > 0: - use_web_concurrency = int(web_concurrency_str) - return ( - min(use_max_workers, use_web_concurrency) - if max_workers_str and web_concurrency_str - else use_web_concurrency - if web_concurrency_str - else use_default_workers - ) + cores = multiprocessing.cpu_count() + use_default = max(int(float(workers_per_core) * cores), 2) + use_max = m if max_workers and (m := int(max_workers)) > 0 else False + use_total = t if total_workers and (t := int(total_workers)) > 0 else False + use_least = min(use_max, use_total) if use_max and use_total else False + return use_least or use_max or use_total or use_default # Gunicorn setup diff --git a/tests/test_gunicorn_conf.py b/tests/test_gunicorn_conf.py index 41a63a7..94c2c12 100644 --- a/tests/test_gunicorn_conf.py +++ b/tests/test_gunicorn_conf.py @@ -1,5 +1,4 @@ import multiprocessing -import os from typing import Optional import pytest @@ -12,74 +11,42 @@ class TestCalculateWorkers: --- """ - def test_gunicorn_conf_workers_default(self) -> None: + def test_calculate_workers_default(self) -> None: """Test default number of Gunicorn worker processes.""" + cores = multiprocessing.cpu_count() assert gunicorn_conf.workers >= 2 - assert gunicorn_conf.workers == multiprocessing.cpu_count() - - def test_gunicorn_conf_workers_custom_max( - self, monkeypatch: pytest.MonkeyPatch - ) -> None: - """Test custom Gunicorn worker process calculation.""" - monkeypatch.setenv("MAX_WORKERS", "1") - monkeypatch.setenv("WEB_CONCURRENCY", "4") - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - assert os.getenv("MAX_WORKERS") == "1" - assert os.getenv("WEB_CONCURRENCY") == "4" - assert os.getenv("WORKERS_PER_CORE") == "0.5" - assert ( - gunicorn_conf.calculate_workers( - str(os.getenv("MAX_WORKERS")), - str(os.getenv("WEB_CONCURRENCY")), - str(os.getenv("WORKERS_PER_CORE")), - ) - == 1 - ) - - @pytest.mark.parametrize("number_of_workers", ["1", "2", "4"]) - def test_gunicorn_conf_workers_custom_concurrency( - self, monkeypatch: pytest.MonkeyPatch, number_of_workers: str - ) -> None: - """Test custom Gunicorn worker process calculation.""" - monkeypatch.setenv("WEB_CONCURRENCY", number_of_workers) - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - assert os.getenv("WEB_CONCURRENCY") == number_of_workers - assert os.getenv("WORKERS_PER_CORE") == "0.5" - assert ( - gunicorn_conf.calculate_workers( - None, - str(os.getenv("WEB_CONCURRENCY")), - str(os.getenv("WORKERS_PER_CORE")), - ) - == int(number_of_workers) - ) - - @pytest.mark.parametrize("concurrency", [None, "10"]) - def test_gunicorn_conf_workers_custom_cores( - self, monkeypatch: pytest.MonkeyPatch, concurrency: Optional[str] + assert gunicorn_conf.workers == max(cores, 2) + + @pytest.mark.parametrize("max_workers", (None, "1", "2", "5", "10")) + def test_calculate_workers_max(self, max_workers: Optional[str]) -> None: + """Test Gunicorn worker process calculation with custom maximum.""" + cores = multiprocessing.cpu_count() + result = gunicorn_conf.calculate_workers(max_workers, None) + assert result == int(max_workers) if max_workers else max(cores, 2) + + @pytest.mark.parametrize("total_workers", (None, "1", "2", "5", "10")) + def test_calculate_workers_total(self, total_workers: Optional[str]) -> None: + """Test Gunicorn worker process calculation with custom total.""" + cores = multiprocessing.cpu_count() + result = gunicorn_conf.calculate_workers(None, total_workers) + assert result == int(total_workers) if total_workers else max(cores, 2) + + @pytest.mark.parametrize("workers_per_core", ("0.5", "1.5", "10")) + def test_calculate_workers_per_core(self, workers_per_core: str) -> None: + """Test Gunicorn worker process calculation with custom workers per core. + Worker number should be the greater of 2 or the workers per core setting. + """ + cores = multiprocessing.cpu_count() + result = gunicorn_conf.calculate_workers(workers_per_core=workers_per_core) + assert result == max(int(float(workers_per_core) * cores), 2) + + @pytest.mark.parametrize("max_workers", ("1", "2", "5", "10")) + @pytest.mark.parametrize("total_workers", ("1", "2", "5", "10")) + def test_calculate_workers_both_max_and_total( + self, max_workers: str, total_workers: str ) -> None: - """Test custom Gunicorn worker process calculation. - - Assert that number of workers equals `WORKERS_PER_CORE`, and is at least 2. - - Assert that setting `WEB_CONCURRENCY` overrides `WORKERS_PER_CORE`. + """Test Gunicorn worker process calculation if max workers and total workers + (web concurrency) are both set. Worker number should be the lesser of the two. """ - monkeypatch.setenv("WORKERS_PER_CORE", "0.5") - workers_per_core = os.getenv("WORKERS_PER_CORE") - assert workers_per_core == "0.5" - cores: int = multiprocessing.cpu_count() - assert gunicorn_conf.calculate_workers( - None, None, workers_per_core, cores=cores - ) == max(int(cores * float(workers_per_core)), 2) - assert ( - gunicorn_conf.calculate_workers(None, "10", workers_per_core, cores=cores) - == 10 - ) - monkeypatch.setenv("WEB_CONCURRENCY", concurrency) if concurrency else None - assert os.getenv("WEB_CONCURRENCY") == concurrency - assert ( - gunicorn_conf.calculate_workers( - None, concurrency, workers_per_core, cores=cores - ) - == 10 - if concurrency - else max(int(cores * float(workers_per_core)), 2) - ) + result = gunicorn_conf.calculate_workers(max_workers, total_workers) + assert result == min(int(max_workers), int(total_workers)) From aaef2f0804615b8adbf0a1136e48b10d97f4b766 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 16:12:09 -0400 Subject: [PATCH 03/12] Organize Gunicorn settings br3ndonland/inboard@4914a4b - Remove unnecessary setup section: just read environment variables when instantiating the settings objects that are directly read by Gunicorn. The same result is obtained with half the lines of code (29 -> 14). - Sort settings alphabetically --- inboard/gunicorn_conf.py | 41 +++++++++++++--------------------------- 1 file changed, 13 insertions(+), 28 deletions(-) diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py index 1a02b00..684711e 100644 --- a/inboard/gunicorn_conf.py +++ b/inboard/gunicorn_conf.py @@ -19,33 +19,18 @@ def calculate_workers( return use_least or use_max or use_total or use_default -# Gunicorn setup -max_workers_str = os.getenv("MAX_WORKERS") -web_concurrency_str = os.getenv("WEB_CONCURRENCY") -workers_per_core_str = os.getenv("WORKERS_PER_CORE", "1") -workers = calculate_workers(max_workers_str, web_concurrency_str, workers_per_core_str) +# Gunicorn settings +bind = os.getenv("BIND") or f'{os.getenv("HOST", "0.0.0.0")}:{os.getenv("PORT", "80")}' +accesslog = os.getenv("ACCESS_LOG", "-") +errorlog = os.getenv("ERROR_LOG", "-") +graceful_timeout = int(os.getenv("GRACEFUL_TIMEOUT", "120")) +keepalive = int(os.getenv("KEEP_ALIVE", "5")) +logconfig_dict = configure_logging() +loglevel = os.getenv("LOG_LEVEL", "info") +timeout = int(os.getenv("TIMEOUT", "120")) worker_tmp_dir = "/dev/shm" -host = os.getenv("HOST", "0.0.0.0") -port = os.getenv("PORT", "80") -bind_env = os.getenv("BIND") -use_bind = bind_env or f"{host}:{port}" -use_loglevel = os.getenv("LOG_LEVEL", "info") -accesslog_var = os.getenv("ACCESS_LOG", "-") -use_accesslog = accesslog_var or None -errorlog_var = os.getenv("ERROR_LOG", "-") -use_errorlog = errorlog_var or None -graceful_timeout_str = os.getenv("GRACEFUL_TIMEOUT", "120") -timeout_str = os.getenv("TIMEOUT", "120") -keepalive_str = os.getenv("KEEP_ALIVE", "5") - -# Gunicorn config variables -logconfig_dict = configure_logging( - logging_conf=os.getenv("LOGGING_CONF", "inboard.logging_conf") +workers = calculate_workers( + os.getenv("MAX_WORKERS"), + os.getenv("WEB_CONCURRENCY"), + workers_per_core=os.getenv("WORKERS_PER_CORE", "1"), ) -loglevel = use_loglevel -bind = use_bind -errorlog = use_errorlog -accesslog = use_accesslog -graceful_timeout = int(graceful_timeout_str) -timeout = int(timeout_str) -keepalive = int(keepalive_str) From 324f88f571eac7dc979e17232b1ef0b49f53822a Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 16:49:03 -0400 Subject: [PATCH 04/12] Test Gunicorn settings br3ndonland/inboard#11 https://docs.gunicorn.org/en/latest/settings.html#print-config https://docs.pytest.org/en/latest/how-to/capture-stdout-stderr.html The Gunicorn configuration file was technically covered by unit tests, but the individual settings were not tested. This commit will add tests of the Gunicorn settings. The tests use Gunicorn's `--print-config` option to load and output the configuration. The pytest fixture `capfd` is used to read the Gunicorn output. --- tests/test_gunicorn_conf.py | 80 +++++++++++++++++++++++++++++++++++++ 1 file changed, 80 insertions(+) diff --git a/tests/test_gunicorn_conf.py b/tests/test_gunicorn_conf.py index 94c2c12..b2d24df 100644 --- a/tests/test_gunicorn_conf.py +++ b/tests/test_gunicorn_conf.py @@ -1,4 +1,6 @@ import multiprocessing +import subprocess +from pathlib import Path from typing import Optional import pytest @@ -50,3 +52,81 @@ def test_calculate_workers_both_max_and_total( """ result = gunicorn_conf.calculate_workers(max_workers, total_workers) assert result == min(int(max_workers), int(total_workers)) + + +class TestGunicornSettings: + """Test Gunicorn configuration setup and settings. + --- + """ + + @pytest.mark.parametrize("module", ("base", "fastapi", "starlette")) + @pytest.mark.timeout(2) + def test_gunicorn_config(self, capfd: pytest.CaptureFixture, module: str) -> None: + """Load Gunicorn configuration file and verify output.""" + app_module = f"inboard.app.main_{module}:app" + gunicorn_conf_path = gunicorn_conf.__file__ + gunicorn_options = [ + "gunicorn", + "--print-config", + "-c", + gunicorn_conf_path, + "-k", + "uvicorn.workers.UvicornWorker", + app_module, + ] + subprocess.run(gunicorn_options) + captured = capfd.readouterr() + captured_and_cleaned = captured.out.replace(" ", "").splitlines() + assert app_module in captured.out + assert gunicorn_conf_path in captured.out + assert "INFO" in captured.out + assert "uvicorn.logging.DefaultFormatter" in captured.out + assert "graceful_timeout=120" in captured_and_cleaned + assert "keepalive=5" in captured_and_cleaned + assert "loglevel=info" in captured_and_cleaned + assert "timeout=120" in captured_and_cleaned + assert f"workers={max(multiprocessing.cpu_count(), 2)}" in captured_and_cleaned + + @pytest.mark.parametrize("module", ("base", "fastapi", "starlette")) + @pytest.mark.timeout(2) + def test_gunicorn_config_with_custom_options( + self, + capfd: pytest.CaptureFixture, + gunicorn_conf_tmp_file_path: Path, + logging_conf_tmp_file_path: Path, + monkeypatch: pytest.MonkeyPatch, + module: str, + ) -> None: + """Customize options, load Gunicorn configuration file and verify output.""" + app_module = f"inboard.app.main_{module}:app" + gunicorn_conf_path = str(gunicorn_conf_tmp_file_path) + logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py" + monkeypatch.setenv("GRACEFUL_TIMEOUT", "240") + monkeypatch.setenv("KEEP_ALIVE", "10") + monkeypatch.setenv("LOG_FORMAT", "verbose") + monkeypatch.setenv("LOG_LEVEL", "debug") + monkeypatch.setenv("LOGGING_CONF", logging_conf_file) + monkeypatch.setenv("MAX_WORKERS", "10") + monkeypatch.setenv("TIMEOUT", "240") + monkeypatch.setenv("WEB_CONCURRENCY", "15") + gunicorn_options = [ + "gunicorn", + "--print-config", + "-c", + gunicorn_conf_path, + "-k", + "uvicorn.workers.UvicornWorker", + app_module, + ] + subprocess.run(gunicorn_options) + captured = capfd.readouterr() + captured_and_cleaned = captured.out.replace(" ", "").splitlines() + assert app_module in captured.out + assert gunicorn_conf_path in captured.out + assert "DEBUG" in captured.out + assert "uvicorn.logging.DefaultFormatter" in captured.out + assert "graceful_timeout=240" in captured_and_cleaned + assert "keepalive=10" in captured_and_cleaned + assert "loglevel=debug" in captured_and_cleaned + assert "timeout=240" in captured_and_cleaned + assert "workers=10" in captured_and_cleaned From 1b739ed625dacc932ee5255320cb57157ac68971 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 17:14:15 -0400 Subject: [PATCH 05/12] Use similar syntax to set up Gunicorn and Uvicorn br3ndonland/inboard#30 This commit will add some minor improvements to the refactor of the Gunicorn and Uvicorn setup in start.py (added in #30). - Pass `app_module` into `start.set_gunicorn_options()`, rather than appending later when running the server - Read environment variables earlier in `start.set_uvicorn_options()` to provide consistent syntax when returning the dictionary at the end: this strategy seems opposed to the one taken in `gunicorn_conf.py` (read environment variables when they are used, rather than before), but the end result is similar (consistent syntax in the settings). --- inboard/start.py | 28 +++++++++++++++------------- tests/test_start.py | 14 +++++++++++--- 2 files changed, 26 insertions(+), 16 deletions(-) diff --git a/inboard/start.py b/inboard/start.py index fd6b67e..93dee2f 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -68,34 +68,37 @@ def set_app_module(logger: logging.Logger = logging.getLogger()) -> str: raise -def set_gunicorn_options() -> list: +def set_gunicorn_options(app_module: str) -> list: """Set options for running the Gunicorn server.""" gunicorn_conf_path = os.getenv("GUNICORN_CONF", "/app/inboard/gunicorn_conf.py") worker_class = os.getenv("WORKER_CLASS", "uvicorn.workers.UvicornWorker") if not Path(gunicorn_conf_path).is_file(): raise FileNotFoundError(f"Unable to find {gunicorn_conf_path}") - return ["gunicorn", "-k", worker_class, "-c", gunicorn_conf_path] + return ["gunicorn", "-k", worker_class, "-c", gunicorn_conf_path, app_module] def set_uvicorn_options(log_config: Optional[dict] = None) -> dict: """Set options for running the Uvicorn server.""" - with_reload = ( - True - if (value := os.getenv("WITH_RELOAD")) and value.lower() == "true" - else False - ) + host = os.getenv("HOST", "0.0.0.0") + port = int(os.getenv("PORT", "80")) + log_level = os.getenv("LOG_LEVEL", "info") reload_dirs = ( [d.lstrip() for d in str(os.getenv("RELOAD_DIRS")).split(sep=",")] if os.getenv("RELOAD_DIRS") else None ) + use_reload = ( + True + if (value := os.getenv("WITH_RELOAD")) and value.lower() == "true" + else False + ) return dict( - host=os.getenv("HOST", "0.0.0.0"), - port=int(os.getenv("PORT", "80")), + host=host, + port=port, log_config=log_config, - log_level=os.getenv("LOG_LEVEL", "info"), - reload=with_reload, + log_level=log_level, reload_dirs=reload_dirs, + reload=use_reload, ) @@ -109,8 +112,7 @@ def start_server( try: if process_manager == "gunicorn": logger.debug("Running Uvicorn with Gunicorn.") - gunicorn_options: list = set_gunicorn_options() - gunicorn_options.append(app_module) + gunicorn_options: list = set_gunicorn_options(app_module) subprocess.run(gunicorn_options) elif process_manager == "uvicorn": logger.debug("Running Uvicorn without Gunicorn.") diff --git a/tests/test_start.py b/tests/test_start.py index d2f1beb..39db313 100644 --- a/tests/test_start.py +++ b/tests/test_start.py @@ -256,8 +256,11 @@ def test_set_gunicorn_options_default( self, gunicorn_conf_path: Path, monkeypatch: pytest.MonkeyPatch ) -> None: """Test default Gunicorn server options.""" + app_module = "inboard.app.main_fastapi:app" + monkeypatch.setenv("APP_MODULE", app_module) monkeypatch.setenv("GUNICORN_CONF", str(gunicorn_conf_path)) - result = start.set_gunicorn_options() + result = start.set_gunicorn_options(app_module) + assert os.getenv("APP_MODULE") == app_module assert os.getenv("GUNICORN_CONF") == str(gunicorn_conf_path) assert "/gunicorn_conf.py" in str(gunicorn_conf_path) assert "logging" not in str(gunicorn_conf_path) @@ -268,6 +271,7 @@ def test_set_gunicorn_options_default( "uvicorn.workers.UvicornWorker", "-c", str(gunicorn_conf_path), + app_module, ] def test_set_gunicorn_options_custom( @@ -277,8 +281,11 @@ def test_set_gunicorn_options_custom( tmp_path: Path, ) -> None: """Test custom Gunicorn server options with temporary configuration file.""" + app_module = "inboard.app.main_starlette:app" + monkeypatch.setenv("APP_MODULE", app_module) monkeypatch.setenv("GUNICORN_CONF", str(gunicorn_conf_tmp_file_path)) - result = start.set_gunicorn_options() + result = start.set_gunicorn_options(app_module) + assert os.getenv("APP_MODULE") == app_module assert os.getenv("GUNICORN_CONF") == str(gunicorn_conf_tmp_file_path) assert "/gunicorn_conf.py" in str(gunicorn_conf_tmp_file_path) assert "logging" not in str(gunicorn_conf_tmp_file_path) @@ -289,13 +296,14 @@ def test_set_gunicorn_options_custom( "uvicorn.workers.UvicornWorker", "-c", str(gunicorn_conf_tmp_file_path), + app_module, ] def test_set_incorrect_conf_path(self, monkeypatch: pytest.MonkeyPatch) -> None: """Set path to non-existent file and raise an error.""" monkeypatch.setenv("GUNICORN_CONF", "/no/file/here") with pytest.raises(FileNotFoundError): - start.set_gunicorn_options() + start.set_gunicorn_options("inboard.app.main_fastapi:app") class TestSetUvicornOptions: From 8cd8db2bb65b3580a98da140b4a60440c05821e8 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 21:17:40 -0400 Subject: [PATCH 06/12] Consolidate logging configuration method and tests br3ndonland/inboard#3 The `configure_logging()` method was previously located in `start.py`, but the logging configuration dictionary was in `logging_conf.py`. This organization was not ideal for readability and separation of concerns. It also created logistical complications, such as requiring the Gunicorn configuration file `gunicorn_conf.py` to import from start.py, so that it could configure logging for Gunicorn. The `start.py` script should be self-contained, and should import other modules and objects from the package, not the other way around. This commit will move `configure_logging()` to `logging_conf.py`, and move the tests to a corresponding module, `test_logging_conf.py`. This matches up nicely with the latest updates to the `gunicorn_conf.py`, by having a setup method at the top of the module, and the settings below. --- inboard/gunicorn_conf.py | 2 +- inboard/logging_conf.py | 34 +++++++++ inboard/start.py | 30 +------- tests/test_logging_conf.py | 148 +++++++++++++++++++++++++++++++++++++ tests/test_start.py | 135 --------------------------------- 5 files changed, 184 insertions(+), 165 deletions(-) create mode 100644 tests/test_logging_conf.py diff --git a/inboard/gunicorn_conf.py b/inboard/gunicorn_conf.py index 684711e..a4936f9 100644 --- a/inboard/gunicorn_conf.py +++ b/inboard/gunicorn_conf.py @@ -2,7 +2,7 @@ import os from typing import Optional -from inboard.start import configure_logging +from inboard.logging_conf import configure_logging def calculate_workers( diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index a82fc22..f5233c7 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -1,5 +1,39 @@ +import importlib.util +import logging +import logging.config import os import sys +from pathlib import Path + + +def configure_logging( + logger: logging.Logger = logging.getLogger(), + logging_conf: str = os.getenv("LOGGING_CONF", "inboard.logging_conf"), +) -> dict: + """Configure Python logging based on a path to a logging module or file.""" + try: + logging_conf_path = Path(logging_conf) + spec = ( + importlib.util.spec_from_file_location("confspec", logging_conf_path) + if logging_conf_path.is_file() and logging_conf_path.suffix == ".py" + else importlib.util.find_spec(logging_conf) + ) + if not spec: + raise ImportError(f"Unable to import {logging_conf}") + logging_conf_module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(logging_conf_module) # type: ignore[union-attr] + if not hasattr(logging_conf_module, "LOGGING_CONFIG"): + raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}") + logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + if not isinstance(logging_conf_dict, dict): + raise TypeError("LOGGING_CONFIG is not a dictionary instance") + logging.config.dictConfig(logging_conf_dict) + logger.debug(f"Logging dict config loaded from {logging_conf_path}.") + return logging_conf_dict + except Exception as e: + logger.error(f"Error when setting logging module: {e.__class__.__name__} {e}.") + raise + LOG_COLORS = ( True diff --git a/inboard/start.py b/inboard/start.py index 93dee2f..e355d42 100644 --- a/inboard/start.py +++ b/inboard/start.py @@ -1,7 +1,6 @@ #!/usr/bin/env python3 import importlib.util import logging -import logging.config import os import subprocess from pathlib import Path @@ -9,34 +8,7 @@ import uvicorn # type: ignore - -def configure_logging( - logger: logging.Logger = logging.getLogger(), - logging_conf: str = os.getenv("LOGGING_CONF", "inboard.logging_conf"), -) -> dict: - """Configure Python logging based on a path to a logging module or file.""" - try: - logging_conf_path = Path(logging_conf) - spec = ( - importlib.util.spec_from_file_location("confspec", logging_conf_path) - if logging_conf_path.is_file() and logging_conf_path.suffix == ".py" - else importlib.util.find_spec(logging_conf) - ) - if not spec: - raise ImportError(f"Unable to import {logging_conf}") - logging_conf_module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(logging_conf_module) # type: ignore[union-attr] - if not hasattr(logging_conf_module, "LOGGING_CONFIG"): - raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}") - logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") - if not isinstance(logging_conf_dict, dict): - raise TypeError("LOGGING_CONFIG is not a dictionary instance") - logging.config.dictConfig(logging_conf_dict) - logger.debug(f"Logging dict config loaded from {logging_conf_path}.") - return logging_conf_dict - except Exception as e: - logger.error(f"Error when setting logging module: {e.__class__.__name__} {e}.") - raise +from inboard.logging_conf import configure_logging def run_pre_start_script(logger: logging.Logger = logging.getLogger()) -> str: diff --git a/tests/test_logging_conf.py b/tests/test_logging_conf.py new file mode 100644 index 0000000..6ca4158 --- /dev/null +++ b/tests/test_logging_conf.py @@ -0,0 +1,148 @@ +import os +from pathlib import Path + +import pytest +from pytest_mock import MockerFixture + +from inboard import logging_conf + + +class TestConfigureLogging: + """Test logging configuration method. + --- + """ + + def test_configure_logging_file( + self, logging_conf_file_path: Path, mocker: MockerFixture + ) -> None: + """Test logging configuration with correct logging config file path.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logging_conf.configure_logging( + logger=mock_logger, logging_conf=str(logging_conf_file_path) + ) + mock_logger.debug.assert_called_once_with( + f"Logging dict config loaded from {logging_conf_file_path}." + ) + + def test_configure_logging_module( + self, logging_conf_module_path: str, mocker: MockerFixture + ) -> None: + """Test logging configuration with correct logging config module path.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logging_conf.configure_logging( + logger=mock_logger, logging_conf=logging_conf_module_path + ) + mock_logger.debug.assert_called_once_with( + f"Logging dict config loaded from {logging_conf_module_path}." + ) + + def test_configure_logging_module_incorrect(self, mocker: MockerFixture) -> None: + """Test logging configuration with incorrect logging config module path.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + mock_logger_error_msg = "Error when setting logging module" + with pytest.raises(ModuleNotFoundError): + logging_conf.configure_logging( + logger=mock_logger, logging_conf="no.module.here" + ) + assert mock_logger_error_msg in mock_logger.error.call_args.args[0] + assert "ModuleNotFoundError" in mock_logger.error.call_args.args[0] + + def test_configure_logging_tmp_file( + self, logging_conf_tmp_file_path: Path, mocker: MockerFixture + ) -> None: + """Test logging configuration with temporary logging config file path.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py" + logging_conf.configure_logging( + logger=mock_logger, logging_conf=logging_conf_file + ) + mock_logger.debug.assert_called_once_with( + f"Logging dict config loaded from {logging_conf_file}." + ) + + def test_configure_logging_tmp_file_incorrect_extension( + self, + logging_conf_tmp_path_incorrect_extension: Path, + mocker: MockerFixture, + ) -> None: + """Test logging configuration with incorrect temporary file type.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + incorrect_logging_conf = logging_conf_tmp_path_incorrect_extension.joinpath( + "tmp_logging_conf" + ) + logger_error_msg = "Error when setting logging module" + import_error_msg = f"Unable to import {incorrect_logging_conf}" + with pytest.raises(ImportError) as e: + logging_conf.configure_logging( + logger=mock_logger, + logging_conf=str(incorrect_logging_conf), + ) + assert str(e.value) in import_error_msg + mock_logger.error.assert_called_once_with( + f"{logger_error_msg}: ImportError {import_error_msg}." + ) + with open(incorrect_logging_conf, "r") as f: + contents = f.read() + assert "This file doesn't have the correct extension" in contents + + def test_configure_logging_tmp_module( + self, + logging_conf_tmp_file_path: Path, + mocker: MockerFixture, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + """Test logging configuration with temporary logging config path.""" + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + monkeypatch.syspath_prepend(logging_conf_tmp_file_path) + monkeypatch.setenv("LOGGING_CONF", "tmp_log") + assert os.getenv("LOGGING_CONF") == "tmp_log" + logging_conf.configure_logging(logger=mock_logger, logging_conf="tmp_log") + mock_logger.debug.assert_called_once_with( + "Logging dict config loaded from tmp_log." + ) + + def test_configure_logging_tmp_module_incorrect_type( + self, + logging_conf_tmp_path_incorrect_type: Path, + mocker: MockerFixture, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + """Test logging configuration with temporary logging config path. + - Correct module name + - `LOGGING_CONFIG` object with incorrect type + """ + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + monkeypatch.syspath_prepend(logging_conf_tmp_path_incorrect_type) + monkeypatch.setenv("LOGGING_CONF", "incorrect_type") + logger_error_msg = "Error when setting logging module" + type_error_msg = "LOGGING_CONFIG is not a dictionary instance" + assert os.getenv("LOGGING_CONF") == "incorrect_type" + with pytest.raises(TypeError): + logging_conf.configure_logging( + logger=mock_logger, logging_conf="incorrect_type" + ) + mock_logger.error.assert_called_once_with( + f"{logger_error_msg}: TypeError {type_error_msg}." + ) + + def test_configure_logging_tmp_module_no_dict( + self, + logging_conf_tmp_path_no_dict: Path, + mocker: MockerFixture, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + """Test logging configuration with temporary logging config path. + - Correct module name + - No `LOGGING_CONFIG` object + """ + mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + monkeypatch.syspath_prepend(logging_conf_tmp_path_no_dict) + monkeypatch.setenv("LOGGING_CONF", "no_dict") + logger_error_msg = "Error when setting logging module" + attribute_error_msg = "No LOGGING_CONFIG in no_dict" + assert os.getenv("LOGGING_CONF") == "no_dict" + with pytest.raises(AttributeError): + logging_conf.configure_logging(logger=mock_logger, logging_conf="no_dict") + mock_logger.error.assert_called_once_with( + f"{logger_error_msg}: AttributeError {attribute_error_msg}." + ) diff --git a/tests/test_start.py b/tests/test_start.py index 39db313..cb5bc41 100644 --- a/tests/test_start.py +++ b/tests/test_start.py @@ -7,141 +7,6 @@ from inboard import start -class TestConfigureLogging: - """Test logging configuration methods. - --- - """ - - def test_configure_logging_file( - self, logging_conf_file_path: Path, mocker: MockerFixture - ) -> None: - """Test `start.configure_logging` with correct logging config file path.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - start.configure_logging( - logger=mock_logger, logging_conf=str(logging_conf_file_path) - ) - mock_logger.debug.assert_called_once_with( - f"Logging dict config loaded from {logging_conf_file_path}." - ) - - def test_configure_logging_module( - self, logging_conf_module_path: str, mocker: MockerFixture - ) -> None: - """Test `start.configure_logging` with correct logging config module path.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - start.configure_logging( - logger=mock_logger, logging_conf=logging_conf_module_path - ) - mock_logger.debug.assert_called_once_with( - f"Logging dict config loaded from {logging_conf_module_path}." - ) - - def test_configure_logging_module_incorrect(self, mocker: MockerFixture) -> None: - """Test `start.configure_logging` with incorrect logging config module path.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - mock_logger_error_msg = "Error when setting logging module" - with pytest.raises(ModuleNotFoundError): - start.configure_logging(logger=mock_logger, logging_conf="no.module.here") - assert mock_logger_error_msg in mock_logger.error.call_args.args[0] - assert "ModuleNotFoundError" in mock_logger.error.call_args.args[0] - - def test_configure_logging_tmp_file( - self, logging_conf_tmp_file_path: Path, mocker: MockerFixture - ) -> None: - """Test `start.configure_logging` with temporary logging config file path.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py" - start.configure_logging(logger=mock_logger, logging_conf=logging_conf_file) - mock_logger.debug.assert_called_once_with( - f"Logging dict config loaded from {logging_conf_file}." - ) - - def test_configure_logging_tmp_file_incorrect_extension( - self, - logging_conf_tmp_path_incorrect_extension: Path, - mocker: MockerFixture, - ) -> None: - """Test `start.configure_logging` with incorrect temporary file type.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - incorrect_logging_conf = logging_conf_tmp_path_incorrect_extension.joinpath( - "tmp_logging_conf" - ) - logger_error_msg = "Error when setting logging module" - import_error_msg = f"Unable to import {incorrect_logging_conf}" - with pytest.raises(ImportError) as e: - start.configure_logging( - logger=mock_logger, - logging_conf=str(incorrect_logging_conf), - ) - assert str(e.value) in import_error_msg - mock_logger.error.assert_called_once_with( - f"{logger_error_msg}: ImportError {import_error_msg}." - ) - with open(incorrect_logging_conf, "r") as f: - contents = f.read() - assert "This file doesn't have the correct extension" in contents - - def test_configure_logging_tmp_module( - self, - logging_conf_tmp_file_path: Path, - mocker: MockerFixture, - monkeypatch: pytest.MonkeyPatch, - ) -> None: - """Test `start.configure_logging` with temporary logging config path.""" - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - monkeypatch.syspath_prepend(logging_conf_tmp_file_path) - monkeypatch.setenv("LOGGING_CONF", "tmp_log") - assert os.getenv("LOGGING_CONF") == "tmp_log" - start.configure_logging(logger=mock_logger, logging_conf="tmp_log") - mock_logger.debug.assert_called_once_with( - "Logging dict config loaded from tmp_log." - ) - - def test_configure_logging_tmp_module_incorrect_type( - self, - logging_conf_tmp_path_incorrect_type: Path, - mocker: MockerFixture, - monkeypatch: pytest.MonkeyPatch, - ) -> None: - """Test `start.configure_logging` with temporary logging config path. - - Correct module name - - `LOGGING_CONFIG` object with incorrect type - """ - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - monkeypatch.syspath_prepend(logging_conf_tmp_path_incorrect_type) - monkeypatch.setenv("LOGGING_CONF", "incorrect_type") - logger_error_msg = "Error when setting logging module" - type_error_msg = "LOGGING_CONFIG is not a dictionary instance" - assert os.getenv("LOGGING_CONF") == "incorrect_type" - with pytest.raises(TypeError): - start.configure_logging(logger=mock_logger, logging_conf="incorrect_type") - mock_logger.error.assert_called_once_with( - f"{logger_error_msg}: TypeError {type_error_msg}." - ) - - def test_configure_logging_tmp_module_no_dict( - self, - logging_conf_tmp_path_no_dict: Path, - mocker: MockerFixture, - monkeypatch: pytest.MonkeyPatch, - ) -> None: - """Test `start.configure_logging` with temporary logging config path. - - Correct module name - - No `LOGGING_CONFIG` object - """ - mock_logger = mocker.patch.object(start.logging, "root", autospec=True) - monkeypatch.syspath_prepend(logging_conf_tmp_path_no_dict) - monkeypatch.setenv("LOGGING_CONF", "no_dict") - logger_error_msg = "Error when setting logging module" - attribute_error_msg = "No LOGGING_CONFIG in no_dict" - assert os.getenv("LOGGING_CONF") == "no_dict" - with pytest.raises(AttributeError): - start.configure_logging(logger=mock_logger, logging_conf="no_dict") - mock_logger.error.assert_called_once_with( - f"{logger_error_msg}: AttributeError {attribute_error_msg}." - ) - - class TestRunPreStartScript: """Run pre-start scripts using the method in `start.py`. --- From 0ba94fc07cd0f07952ca2807fb35d200b90992da Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sat, 17 Apr 2021 23:33:31 -0400 Subject: [PATCH 07/12] Correct attribute error on module spec loader The loader attribute on a module spec is technically optional, so mypy raises a `[union-attr]` error: Item "_Loader" of "Optional[_Loader]" has no attribute "exec_module" To avoid referencing the potentially undefined `_Loader.exec_module` attribute, this commit will update the syntax to get the attribute with `getattr(spec.loader, "exec_module")` prior to running `exec_module()`. An `AttributeError` will be raised if the attribute does not exist. --- inboard/logging_conf.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index f5233c7..a0732bb 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -21,7 +21,8 @@ def configure_logging( if not spec: raise ImportError(f"Unable to import {logging_conf}") logging_conf_module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(logging_conf_module) # type: ignore[union-attr] + exec_module = getattr(spec.loader, "exec_module") + exec_module(logging_conf_module) if not hasattr(logging_conf_module, "LOGGING_CONFIG"): raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}") logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") From 373c98d818d5dfeb6e5d5713f420f414e40834dc Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 18 Apr 2021 00:30:56 -0400 Subject: [PATCH 08/12] Split up logging configuration method br3ndonland/inboard#3 The `configure_logging()` method did multiple things: find and import a logging configuration module, load the logging configuration dictionary, and apply the dictionary configuration to the Python logger. This commit will refactor `configure_logging()` into two methods. 1. `find_and_load_logging_conf()` will return a dictionary configuration 2. `configure_logging()` will apply the dictionary configuration The return value of `configure_logging()` will remain the same, so there will not be any changes to the programming API. Also, now that the `configure_logging()` method is in the same module as the logging configuration dictionary, that dictionary will be used by default, instead of finding the module separately. --- inboard/logging_conf.py | 48 +++++++++++++++++++++++++---------------- 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/inboard/logging_conf.py b/inboard/logging_conf.py index a0732bb..b2ff4b9 100644 --- a/inboard/logging_conf.py +++ b/inboard/logging_conf.py @@ -4,30 +4,42 @@ import os import sys from pathlib import Path +from typing import Optional + + +def find_and_load_logging_conf(logging_conf: str) -> dict: + """Find and load a logging configuration module or file.""" + logging_conf_path = Path(logging_conf) + spec = ( + importlib.util.spec_from_file_location("confspec", logging_conf_path) + if logging_conf_path.is_file() and logging_conf_path.suffix == ".py" + else importlib.util.find_spec(logging_conf) + ) + if not spec: + raise ImportError(f"Unable to import {logging_conf_path}") + logging_conf_module = importlib.util.module_from_spec(spec) + exec_module = getattr(spec.loader, "exec_module") + exec_module(logging_conf_module) + if not hasattr(logging_conf_module, "LOGGING_CONFIG"): + raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}") + logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") + if not isinstance(logging_conf_dict, dict): + raise TypeError("LOGGING_CONFIG is not a dictionary instance") + return logging_conf_dict def configure_logging( logger: logging.Logger = logging.getLogger(), - logging_conf: str = os.getenv("LOGGING_CONF", "inboard.logging_conf"), + logging_conf: Optional[str] = os.getenv("LOGGING_CONF"), ) -> dict: - """Configure Python logging based on a path to a logging module or file.""" + """Configure Python logging given the name of a logging module or file.""" try: - logging_conf_path = Path(logging_conf) - spec = ( - importlib.util.spec_from_file_location("confspec", logging_conf_path) - if logging_conf_path.is_file() and logging_conf_path.suffix == ".py" - else importlib.util.find_spec(logging_conf) - ) - if not spec: - raise ImportError(f"Unable to import {logging_conf}") - logging_conf_module = importlib.util.module_from_spec(spec) - exec_module = getattr(spec.loader, "exec_module") - exec_module(logging_conf_module) - if not hasattr(logging_conf_module, "LOGGING_CONFIG"): - raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}") - logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG") - if not isinstance(logging_conf_dict, dict): - raise TypeError("LOGGING_CONFIG is not a dictionary instance") + if not logging_conf: + logging_conf_path = __name__ + logging_conf_dict = LOGGING_CONFIG + else: + logging_conf_path = logging_conf + logging_conf_dict = find_and_load_logging_conf(logging_conf_path) logging.config.dictConfig(logging_conf_dict) logger.debug(f"Logging dict config loaded from {logging_conf_path}.") return logging_conf_dict From 9a61fc28dc8f830156d8a5b12701907c46c84e69 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 18 Apr 2021 00:58:44 -0400 Subject: [PATCH 09/12] Remove prefix from mocker objects in logger tests Mocker objects are sometimes prefixed with `mock_` to indicate that they are separate objects. This is largely unnecessary, so it will be removed from the tests of the logging configuration. --- tests/test_logging_conf.py | 60 +++++++++++++++++--------------------- 1 file changed, 26 insertions(+), 34 deletions(-) diff --git a/tests/test_logging_conf.py b/tests/test_logging_conf.py index 6ca4158..773e967 100644 --- a/tests/test_logging_conf.py +++ b/tests/test_logging_conf.py @@ -16,11 +16,11 @@ def test_configure_logging_file( self, logging_conf_file_path: Path, mocker: MockerFixture ) -> None: """Test logging configuration with correct logging config file path.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) logging_conf.configure_logging( - logger=mock_logger, logging_conf=str(logging_conf_file_path) + logger=logger, logging_conf=str(logging_conf_file_path) ) - mock_logger.debug.assert_called_once_with( + logger.debug.assert_called_once_with( f"Logging dict config loaded from {logging_conf_file_path}." ) @@ -28,35 +28,31 @@ def test_configure_logging_module( self, logging_conf_module_path: str, mocker: MockerFixture ) -> None: """Test logging configuration with correct logging config module path.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) logging_conf.configure_logging( - logger=mock_logger, logging_conf=logging_conf_module_path + logger=logger, logging_conf=logging_conf_module_path ) - mock_logger.debug.assert_called_once_with( + logger.debug.assert_called_once_with( f"Logging dict config loaded from {logging_conf_module_path}." ) def test_configure_logging_module_incorrect(self, mocker: MockerFixture) -> None: """Test logging configuration with incorrect logging config module path.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) - mock_logger_error_msg = "Error when setting logging module" + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger_error_msg = "Error when setting logging module" with pytest.raises(ModuleNotFoundError): - logging_conf.configure_logging( - logger=mock_logger, logging_conf="no.module.here" - ) - assert mock_logger_error_msg in mock_logger.error.call_args.args[0] - assert "ModuleNotFoundError" in mock_logger.error.call_args.args[0] + logging_conf.configure_logging(logger=logger, logging_conf="no.module.here") + assert logger_error_msg in logger.error.call_args.args[0] + assert "ModuleNotFoundError" in logger.error.call_args.args[0] def test_configure_logging_tmp_file( self, logging_conf_tmp_file_path: Path, mocker: MockerFixture ) -> None: """Test logging configuration with temporary logging config file path.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py" - logging_conf.configure_logging( - logger=mock_logger, logging_conf=logging_conf_file - ) - mock_logger.debug.assert_called_once_with( + logging_conf.configure_logging(logger=logger, logging_conf=logging_conf_file) + logger.debug.assert_called_once_with( f"Logging dict config loaded from {logging_conf_file}." ) @@ -66,7 +62,7 @@ def test_configure_logging_tmp_file_incorrect_extension( mocker: MockerFixture, ) -> None: """Test logging configuration with incorrect temporary file type.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) incorrect_logging_conf = logging_conf_tmp_path_incorrect_extension.joinpath( "tmp_logging_conf" ) @@ -74,11 +70,11 @@ def test_configure_logging_tmp_file_incorrect_extension( import_error_msg = f"Unable to import {incorrect_logging_conf}" with pytest.raises(ImportError) as e: logging_conf.configure_logging( - logger=mock_logger, + logger=logger, logging_conf=str(incorrect_logging_conf), ) assert str(e.value) in import_error_msg - mock_logger.error.assert_called_once_with( + logger.error.assert_called_once_with( f"{logger_error_msg}: ImportError {import_error_msg}." ) with open(incorrect_logging_conf, "r") as f: @@ -92,14 +88,12 @@ def test_configure_logging_tmp_module( monkeypatch: pytest.MonkeyPatch, ) -> None: """Test logging configuration with temporary logging config path.""" - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) monkeypatch.syspath_prepend(logging_conf_tmp_file_path) monkeypatch.setenv("LOGGING_CONF", "tmp_log") assert os.getenv("LOGGING_CONF") == "tmp_log" - logging_conf.configure_logging(logger=mock_logger, logging_conf="tmp_log") - mock_logger.debug.assert_called_once_with( - "Logging dict config loaded from tmp_log." - ) + logging_conf.configure_logging(logger=logger, logging_conf="tmp_log") + logger.debug.assert_called_once_with("Logging dict config loaded from tmp_log.") def test_configure_logging_tmp_module_incorrect_type( self, @@ -111,17 +105,15 @@ def test_configure_logging_tmp_module_incorrect_type( - Correct module name - `LOGGING_CONFIG` object with incorrect type """ - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) monkeypatch.syspath_prepend(logging_conf_tmp_path_incorrect_type) monkeypatch.setenv("LOGGING_CONF", "incorrect_type") logger_error_msg = "Error when setting logging module" type_error_msg = "LOGGING_CONFIG is not a dictionary instance" assert os.getenv("LOGGING_CONF") == "incorrect_type" with pytest.raises(TypeError): - logging_conf.configure_logging( - logger=mock_logger, logging_conf="incorrect_type" - ) - mock_logger.error.assert_called_once_with( + logging_conf.configure_logging(logger=logger, logging_conf="incorrect_type") + logger.error.assert_called_once_with( f"{logger_error_msg}: TypeError {type_error_msg}." ) @@ -135,14 +127,14 @@ def test_configure_logging_tmp_module_no_dict( - Correct module name - No `LOGGING_CONFIG` object """ - mock_logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) + logger = mocker.patch.object(logging_conf.logging, "root", autospec=True) monkeypatch.syspath_prepend(logging_conf_tmp_path_no_dict) monkeypatch.setenv("LOGGING_CONF", "no_dict") logger_error_msg = "Error when setting logging module" attribute_error_msg = "No LOGGING_CONFIG in no_dict" assert os.getenv("LOGGING_CONF") == "no_dict" with pytest.raises(AttributeError): - logging_conf.configure_logging(logger=mock_logger, logging_conf="no_dict") - mock_logger.error.assert_called_once_with( + logging_conf.configure_logging(logger=logger, logging_conf="no_dict") + logger.error.assert_called_once_with( f"{logger_error_msg}: AttributeError {attribute_error_msg}." ) From 273f795471e6468954abf4c2d13e880c517bba63 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 18 Apr 2021 06:09:09 -0400 Subject: [PATCH 10/12] Test logger output after configuring logging br3ndonland/inboard#3 https://docs.pytest.org/en/latest/how-to/capture-stdout-stderr.html https://docs.pytest.org/en/latest/how-to/logging.html In addition to testing the methods that load the logging configuration, it can also be useful to test that logger messages have the expected format. This commit will add tests that output logger messages in various formats and assert that each output matches the expected format. As in the tests of the Gunicorn server output, these tests will use the pytest `capfd` fixture. It is also possible to use the `caplog` fixture, but I have not had as much success with it. --- tests/test_logging_conf.py | 39 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/tests/test_logging_conf.py b/tests/test_logging_conf.py index 773e967..de3dfb4 100644 --- a/tests/test_logging_conf.py +++ b/tests/test_logging_conf.py @@ -138,3 +138,42 @@ def test_configure_logging_tmp_module_no_dict( logger.error.assert_called_once_with( f"{logger_error_msg}: AttributeError {attribute_error_msg}." ) + + +class TestLoggingOutput: + """Test logger output after configuring logging. + --- + """ + + def test_logging_output_default(self, capfd: pytest.CaptureFixture) -> None: + """Test logger output with default format.""" + logger = logging_conf.logging.getLogger() + logging_conf.configure_logging() + logger.info("Hello, World!") + captured = capfd.readouterr() + assert "INFO" in captured.out + assert "Hello, World!" in captured.out + + @pytest.mark.parametrize( + "log_format,log_level_output", (("gunicorn", "[DEBUG]"), ("verbose", "DEBUG")) + ) + def test_logging_output_custom_format( + self, + capfd: pytest.CaptureFixture, + log_format: str, + log_level_output: str, + logging_conf_tmp_file_path: Path, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + """Test logger output with custom format.""" + logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py" + monkeypatch.setenv("LOG_FORMAT", "gunicorn") + monkeypatch.setenv("LOG_LEVEL", "debug") + logger = logging_conf.logging.getLogger() + logging_conf.configure_logging(logging_conf=logging_conf_file) + logger.debug("Hello, Customized World!") + captured = capfd.readouterr() + assert log_format not in captured.out + assert log_level_output in captured.out + assert f"Logging dict config loaded from {logging_conf_file}." in captured.out + assert "Hello, Customized World!" in captured.out From aa243dd48e5e1c229a1d2357115e8ba99ac83481 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 18 Apr 2021 06:18:45 -0400 Subject: [PATCH 11/12] Update links to pytest docs https://docs.pytest.org/en/latest/contents.html Love the new docs! :tada: --- README.md | 17 +++++++++-------- tests/app/test_main.py | 2 +- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/README.md b/README.md index c507b97..25c4579 100644 --- a/README.md +++ b/README.md @@ -452,17 +452,18 @@ See _[CONTRIBUTING.md](./.github/CONTRIBUTING.md)_ for general information on ho ### Testing with pytest - Tests are in the _tests/_ directory. -- Run tests by [invoking `pytest` from the command-line](https://docs.pytest.org/en/stable/usage.html) within the Poetry environment in the root directory of the repo. +- Run tests by [invoking `pytest` from the command-line](https://docs.pytest.org/en/latest/how-to/usage.html) within the Poetry environment in the root directory of the repo. - [pytest](https://docs.pytest.org/en/latest/) features used include: - - [fixtures](https://docs.pytest.org/en/latest/fixture.html) - - [monkeypatch](https://docs.pytest.org/en/latest/monkeypatch.html) - - [parametrize](https://docs.pytest.org/en/latest/parametrize.html) - - [`tmp_path`](https://docs.pytest.org/en/latest/tmpdir.html) -- [pytest plugins](https://docs.pytest.org/en/stable/plugins.html) include: + - [capturing `stdout` with `capfd`](https://docs.pytest.org/en/latest/how-to/capture-stdout-stderr.html) + - [fixtures](https://docs.pytest.org/en/latest/how-to/fixtures.html) + - [monkeypatch](https://docs.pytest.org/en/latest/how-to/monkeypatch.html) + - [parametrize](https://docs.pytest.org/en/latest/how-to/parametrize.html) + - [temporary directories and files (`tmp_path` and `tmp_dir`)](https://docs.pytest.org/en/latest/how-to/tmpdir.html) +- [pytest plugins](https://docs.pytest.org/en/latest/how-to/plugins.html) include: - [pytest-cov](https://github.com/pytest-dev/pytest-cov) - [pytest-mock](https://github.com/pytest-dev/pytest-mock) -- [pytest configuration](https://docs.pytest.org/en/stable/customize.html) is in _[pyproject.toml](https://github.com/br3ndonland/inboard/blob/develop/pyproject.toml)_. -- [FastAPI testing](https://fastapi.tiangolo.com/tutorial/testing/) and [Starlette testing](https://www.starlette.io/testclient/) rely on the [Starlette `TestClient`](https://www.starlette.io/testclient/), which uses [Requests](https://requests.readthedocs.io/en/master/) under the hood. +- [pytest configuration](https://docs.pytest.org/en/latest/reference/customize.html) is in _[pyproject.toml](https://github.com/br3ndonland/inboard/blob/develop/pyproject.toml)_. +- [FastAPI testing](https://fastapi.tiangolo.com/tutorial/testing/) and [Starlette testing](https://www.starlette.io/testclient/) rely on the [Starlette `TestClient`](https://www.starlette.io/testclient/). - Test coverage results are reported when invoking `pytest` from the command-line. To see interactive HTML coverage reports, invoke pytest with `pytest --cov-report=html`. - Test coverage reports are generated within GitHub Actions workflows by [pytest-cov](https://github.com/pytest-dev/pytest-cov) with [coverage.py](https://github.com/nedbat/coveragepy), and uploaded to [Codecov](https://docs.codecov.io/docs) using [codecov/codecov-action](https://github.com/marketplace/actions/codecov). Codecov is then integrated into pull requests with the [Codecov GitHub app](https://github.com/marketplace/codecov). diff --git a/tests/app/test_main.py b/tests/app/test_main.py index 2f10aa6..cdbb5b9 100644 --- a/tests/app/test_main.py +++ b/tests/app/test_main.py @@ -110,7 +110,7 @@ class TestEndpoints: --- See the [FastAPI testing docs](https://fastapi.tiangolo.com/tutorial/testing/), [Starlette TestClient docs](https://www.starlette.io/testclient/), and the - [pytest docs on parametrize](https://docs.pytest.org/en/latest/parametrize.html). + [pytest docs](https://docs.pytest.org/en/latest/how-to/parametrize.html). """ def test_get_asgi_uvicorn( From 40baca423d1969a20698308b670ab9d89fedee71 Mon Sep 17 00:00:00 2001 From: Brendon Smith Date: Sun, 18 Apr 2021 06:50:59 -0400 Subject: [PATCH 12/12] Clarify Gunicorn variable descriptions in README - `MAX_WORKERS` - `WEB_CONCURRENCY` - `WORKERS_PER_CORE` --- README.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 25c4579..0707bdd 100644 --- a/README.md +++ b/README.md @@ -260,10 +260,10 @@ ENV APP_MODULE="package.custom.module:api" WORKERS_PER_CORE="2" - Custom: - `GUNICORN_CONF="/app/package/custom_gunicorn_conf.py"` - [Gunicorn worker processes](https://docs.gunicorn.org/en/latest/settings.html#worker-processes): The number of Gunicorn worker processes to run is determined based on the `MAX_WORKERS`, `WEB_CONCURRENCY`, and `WORKERS_PER_CORE` environment variables, with a default of 1 worker per CPU core and a default minimum of 2. This is the "performance auto-tuning" feature described in [tiangolo/uvicorn-gunicorn-docker](https://github.com/tiangolo/uvicorn-gunicorn-docker). - - `MAX_WORKERS`: Maximum number of workers to use, independent of number of CPU cores. + - `MAX_WORKERS`: Maximum number of workers, independent of number of CPU cores. - Default: not set (unlimited) - Custom: `MAX_WORKERS="24"` - - `WEB_CONCURRENCY`: Set number of workers independently of number of CPU cores. + - `WEB_CONCURRENCY`: Total number of workers, independent of number of CPU cores. - Default: not set - Custom: `WEB_CONCURRENCY="4"` - `WORKERS_PER_CORE`: Number of Gunicorn workers per CPU core. Overridden if `WEB_CONCURRENCY` is set. @@ -272,7 +272,7 @@ ENV APP_MODULE="package.custom.module:api" WORKERS_PER_CORE="2" - `WORKERS_PER_CORE="2"`: Run 2 worker processes per core (8 worker processes on a server with 4 cores). - `WORKERS_PER_CORE="0.5"` (floating point values permitted): Run 1 worker process for every 2 cores (2 worker processes on a server with 4 cores). - Notes: - - The default number of workers is the number of CPU cores multiplied by the environment variable `WORKERS_PER_CORE="1"`. On a machine with only 1 CPU core, the default minimum number of workers is 2 to avoid poor performance and blocking, as explained in the release notes for [tiangolo/uvicorn-gunicorn-docker 0.3.0](https://github.com/tiangolo/uvicorn-gunicorn-docker/releases/tag/0.3.0). + - The default number of workers is the number of CPU cores multiplied by the value of the environment variable `WORKERS_PER_CORE` (which defaults to 1). On a machine with only 1 CPU core, the default minimum number of workers is 2 to avoid poor performance and blocking, as explained in the release notes for [tiangolo/uvicorn-gunicorn-docker 0.3.0](https://github.com/tiangolo/uvicorn-gunicorn-docker/releases/tag/0.3.0). - If both `MAX_WORKERS` and `WEB_CONCURRENCY` are set, the least of the two will be used as the total number of workers. - If either `MAX_WORKERS` or `WEB_CONCURRENCY` are set to 1, the total number of workers will be 1, overriding the default minimum of 2. - `PROCESS_MANAGER`: Manager for Uvicorn worker processes. As described in the [Uvicorn docs](https://www.uvicorn.org), "Uvicorn includes a Gunicorn worker class allowing you to run ASGI applications, with all of Uvicorn's performance benefits, while also giving you Gunicorn's fully-featured process management."