Add logging configuration for Gunicorn and Uvicorn #3
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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.
- Move info on logging environment variables to separate logging section - Add links to logging info in Python docs
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.
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.
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
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.
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
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.
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.
This removes the need to specify the module within each logging message.
I was previously using `[{Path(__file__).stem}]` for this purpose.
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.
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
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.
A dictionary can be passed to Uvicorn when running programmatically: ```py uvicorn.run(log_config=your_dict_config) ``` While useful, this capability is undocumented.
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`.
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()`.
- Correct `pip` command - Quote environment variable values to avoid confusion - Improve mounting of application files when running Docker with Uvicorn
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`.
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"`.
GUNICORN_CONF is now being set by start.py.
br3ndonland
added a commit
that referenced
this pull request
Sep 2, 2020
#3 The `start.configure_logging` method was previously configured to accept a file path to a Python logging configuration file. This works well for Docker, because the path is predictable inside the Docker image, but limits usefulness of logging_conf.py with `pip install inboard`. This commit will refactor `configure_logging` to accept a module path, in the style of `set_app_module`. References to `configure_logging`, pytest fixtures in conftest.py, and unit tests in test_start.py will be updated accordingly. The README will describe changes to `LOGGING_CONF`. This commit will also clarify some testing function argument names. - `start.set_conf_path`: `module` -> `module_stem` - `tmp_dir` -> `tmp_path` when the `tmp_path` fixture is used directly
br3ndonland
added a commit
that referenced
this pull request
Sep 7, 2020
#3 ff9155a Commit ff9155a refactored `start.configure_logging()` and the associated code to accept module paths instead of file paths. This commit will build on ff9155a to support both .py file and module paths for logging config files. In `start.configure_logging()`, a module spec is created, either from a file path or a module path, using methods from the importlib standard library module. If the spec is not successfully created, the importlib functions return `None`, and `start.configure_logging()` will raise an `ImportError`. The unit test suite will be expanded to accommodate this new feature, and the README will be updated with instructions. As another minor change, more specific Mypy ignore comments will be used (`# type: ignore` -> `# type: ignore[attr-defined]`).
br3ndonland
added a commit
that referenced
this pull request
Sep 7, 2020
br3ndonland
added a commit
that referenced
this pull request
Mar 6, 2021
#3 #4 https://docs.python.org/3/library/unittest.mock.html#where-to-patch - Mock the root logger object directly: The project previously had a `mock_logger` pytest fixture in conftest.py that instantiated a root logger with `logging.getLogger()`. The individual log level attributes were then patched with `mocker.patch.object(logger, "debug")`. This was problematic, because Mypy thought that the logger didn't have the attributes, requiring many `# type: ignore[attr-defined]` comments. Instead of `logging.getLogger()`, the root logger object itself will be directly patched whenever it is used for testing. - Remove `# type: ignore[attr-defined]` Mypy comments: now that the `mock_logger` is a proper `MockerFixture`, pytest and pytest-mock will create the necessary attributes automatically. - Improve exception handling when configuring logging: raise `ImportError` if module spec is not created - Simplify `dict` type annotations - Move error messages to error log level instead of debug: makes more sense for errors to be logged as errors - Add `e.__class__.__name__` to log messages when exceptions are raised: helps to have the exception class name - Correct `logging_conf_tmp_path_incorrect_extension` pytest fixture: should actually create a file
br3ndonland
added a commit
that referenced
this pull request
Mar 6, 2021
#3 #4 https://docs.python.org/3/library/unittest.mock.html#where-to-patch - Mock the root logger object directly: The project previously had a `mock_logger` pytest fixture in conftest.py that instantiated a root logger with `logging.getLogger()`. The individual log level attributes were then patched with `mocker.patch.object(logger, "debug")`. This was problematic, because Mypy thought that the logger didn't have the attributes, requiring many `# type: ignore[attr-defined]` comments. Instead of `logging.getLogger()`, the root logger object itself will be directly patched whenever it is used for testing. - Remove `# type: ignore[attr-defined]` Mypy comments: now that the `mock_logger` is a proper `MockerFixture`, pytest and pytest-mock will create the necessary attributes automatically. - Correct module spec syntax in `set_app_module()`: importlib needs the module path without the app instance name at the end. The way this function was written before, importlib was just returning `None`. inboard should be able to find the app module before continuing, or raise an `ImportError` exception if module spec is not created. - Move error messages to error log level instead of debug: makes more sense for errors to be logged as errors - Add `e.__class__.__name__` to log messages when exceptions are raised: helps to have the exception class name
br3ndonland
added a commit
that referenced
this pull request
Mar 6, 2021
#3 #4 https://docs.python.org/3/library/unittest.mock.html#where-to-patch - Mock the root logger object directly: The project previously had a `mock_logger` pytest fixture in conftest.py that instantiated a root logger with `logging.getLogger()`. The individual log level attributes were then patched with `mocker.patch.object(logger, "debug")`. This was problematic, because Mypy thought that the logger didn't have the attributes, requiring many `# type: ignore[attr-defined]` comments. Instead of `logging.getLogger()`, the root logger object itself will be directly patched whenever it is used for testing. - Remove `# type: ignore[attr-defined]` Mypy comments: now that the `mock_logger` is a proper `MockerFixture`, pytest and pytest-mock will create the necessary attributes automatically.
br3ndonland
added a commit
that referenced
this pull request
Mar 6, 2021
#3 #4 3b20619 https://docs.python.org/3/library/unittest.mock.html#where-to-patch - Mock the root logger object directly: The project previously had a `mock_logger` pytest fixture in conftest.py that instantiated a root logger with `logging.getLogger()`. The individual log level attributes were then patched with `mocker.patch.object(logger, "debug")`. This was problematic, because Mypy thought that the logger didn't have the attributes, requiring many `# type: ignore[attr-defined]` comments. Instead of `logging.getLogger()`, the root logger object itself will be directly patched whenever it is used for testing. - Remove `# type: ignore[attr-defined]` Mypy comments: now that the `mock_logger` is a proper `MockerFixture`, pytest and pytest-mock will create the necessary attributes automatically. - Simplify `dict` type annotations - Add `e.__class__.__name__` to log messages when exceptions are raised: helps to have the exception class name
br3ndonland
added a commit
that referenced
this pull request
Mar 6, 2021
#3 #4 https://docs.python.org/3/library/unittest.mock.html#where-to-patch The project previously had a `mock_logger` pytest fixture in conftest.py that instantiated a root logger with `logging.getLogger()`. Individual log levels were patched with `mocker.patch.object(logger, "debug")`. This was problematic, because Mypy thought that the logger didn't have the attributes, requiring many `# type: ignore[attr-defined]` comments. Instead of `logging.getLogger()`, the root logger object itself will be directly patched whenever it is used for testing. Now that the `mock_logger` is a proper `MockerFixture` within each test, pytest and pytest-mock will create the necessary attributes. This commit will remove the `# type: ignore[attr-defined]` Mypy comments :recycle: :fire: :art: .
br3ndonland
added a commit
that referenced
this pull request
Apr 4, 2021
#2 #3 ff9155a The core logic for running the Uvicorn and Gunicorn+Uvicorn servers is located in start.py. The `start.start_server()` method is what actually starts the servers. Uvicorn and Gunicorn are configured differently, so and the `start.start_server()` method ended up getting quite complex in order to handle these differences. This commit will refactor the configuration options passed to Gunicorn and Uvicorn into separate functions. The result is a start script with the same programming API and almost exactly the same line length, but improved readability and separation of concerns. - Refactor Gunicorn and Uvicorn options into separate functions, `start.set_gunicorn_options()` and `start.set_uvicorn_options()`. - Remove `start.set_conf_path()`: this function was written in a general way to find either Gunicorn or logging configuration files. Starting with ff9155a, it became used only for Gunicorn configuration files. Now that the configuration options for Gunicorn are in a separate function, the logic from `set_conf_path()` can be moved there. - Simplify logger type annotations: simply `import logging` and annotate functions with `logging.Logger` instead of having a separate import for `from logging import Logger`. - Reorganize test_start.py to more clearly reflect order of start.py
1 task
br3ndonland
added a commit
that referenced
this pull request
Apr 18, 2021
#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.
br3ndonland
added a commit
that referenced
this pull request
Apr 18, 2021
#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.
br3ndonland
added a commit
that referenced
this pull request
Apr 18, 2021
#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.
br3ndonland
added a commit
that referenced
this pull request
Apr 18, 2021
#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.
This was referenced Apr 18, 2021
br3ndonland
added a commit
that referenced
this pull request
May 16, 2021
#3 - Explain default logging behavior - State goal of simplifying Uvicorn+Gunicorn+Starlette/FastAPI logging - Justify why inboard only accepts dictionary configurations for logging
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Description
Logging is complicated in general, but logging a Uvicorn+Gunicorn+Starlette/FastAPI stack seems unnecessarily complicated, as demonstrated by the number of related issues and PRs below. Uvicorn and Gunicorn use different logging configurations, and it can be difficult to unify the log streams.
As one example, Gunicorn's API for loading logging configuration dictionaries has some problems. Gunicorn does not have an interface for running programmatically from within a Python module, like
uvicorn.run(), sosubprocess.run()can be used instead. There isn't a clear way to pass logging configuration dictionaries to Gunicorn from the command line. As of Gunicorn version 20, Gunicorn accepts a command-line argument--log-config-dict, but it doesn't work, and it looks like the maintainers plan to remove it.Uvicorn's API for loading logging configurations is also confusing:
093a1f7says, "--log-config <path>- Logging configuration file," but there's no information given on file format.--use-colors / --no-use-colorsis apparently ignored if--log-configis used, but there's also a note that developers can set theformatters.default.use_colorsandformatters.access.use_colorsto override the default behavior.LOGGING_CONFIGinconfig.py, but there's no information provided on how to supply a custom dictionary config..pyfiles.I eventually figured out that a dictionary can be passed to Uvicorn when running programmatically, such as
uvicorn.run(log_config=your_dict_config), although so far, this capability is only documented in the changelog for version 0.10.0.As another example, I was previously managing log streams in a Uvicorn+Gunicorn+FastAPI app with a strategy similar to this, which essentially propagated FastAPI and Uvicorn's logs to the
gunicorn.errorlog stream.Uvicorn's logging API is in flux, and as a result, I started having some issues with this strategy. Uvicorn 0.11.6 and encode/uvicorn#674 updated the logging configuration to avoid overriding the root logger, supposedly fixing encode/uvicorn#630. After upgrading to 0.11.6, duplicate log messages started appearing after starting the Uvicorn server (without Gunicorn). Confusingly, 0.11.6 was supposed to fix this issue, not create it.
Uvicorn 0.11.5 (all log messages are also colored by Uvicorn as expected):
Uvicorn 0.11.6 (log messages with the logger name are not colored):
Changes
This PR will add support for custom logging configurations. Uvicorn, Gunicorn, and FastAPI will be configured with the custom logging configuration. Log messages will have a predictable and customizable format.
For the future, I'm also considering Loguru, an alternative logging module with many improvements over the standard library
loggingmodule.Add logging configuration module (37466c7, 271a7b0): Log message formatting is based on
gunicorn/glogging.py CONFIG_DEFAULTS, with the addition of the logger name and Python module name.Set path to logging configuration module (cf8f71c): This commit will generalize the previous
set_gunicorn_conf()function instart.pyto also check the path to a logging configuration module.Add logging configuration function to
start.py(b05a498, e9b27ce, 1a9a826):start.py configure_logging()function accepts aPath()to a logging configuration file. The file should be a.pyfile containing aLOGGING_CONFIGdictionary object.importlib.util, load theLOGGING_CONFIGdictionary object from the module, and pass it tologging.config.dictConfig(). Gunicorn uses a similar strategy inbase.py class Application(BaseApplication).conf/.inifiles, and YAML files, but dropped this in 1a9a826. Justification:logging.configdocs:logging_conf.pyfor an example)..pyfiles.logconfig_dictoption..pyfiles)logging.config.dictConfig(). Why not just make it a dictionary in the first place?Configure Gunicorn logging programmatically (6e66d98):
gunicorn_conf.pywill importconfigure_logging()fromstart.py, loading the dictConfig and passing it to Gunicorn with thelogconfig_dictvariable.Configure Uvicorn logging programmatically (f6ca7da): A dictionary can be passed to Uvicorn when running programmatically, like
uvicorn.run(log_config=your_dict_config).Add support for multiple log message formatters (27896dd):
simple(default): Simply the log level and message.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, with support forLOG_COLORS. Note that, while Uvicorn does not allow both custom logging configuration and colors by default as explained above, the logging config in this repo does allow both to be used at the same time. I won't be supporting Uvicorn'saccessformatter, because it frequently throws errors related to ASGI scope:Related
benoitc/gunicorn#1087
benoitc/gunicorn#1572
benoitc/gunicorn#1602
benoitc/gunicorn#1775
benoitc/gunicorn#1880
benoitc/gunicorn#1909
encode/uvicorn#491
encode/uvicorn#511
encode/uvicorn#512
encode/uvicorn#515
encode/uvicorn#630
encode/uvicorn#662
encode/uvicorn#665
encode/uvicorn#674
encode/uvicorn#680
fastapi/fastapi#1508
tiangolo/uvicorn-gunicorn-fastapi-docker#19