Logging config not applied for uvicorn in gunicorn

[bodograumann]

We are running a fastapi service based on inboard/fastapi.
To customize the logging we have defined a custom LOGGING_CONF and LOG_FORMAT.
This is usually correctly applied. It works for guincorn, fastapi and our own code.

However when an unhandled exceptions is raised in the service, it is propagated to uvicorn here: https://github.com/Kludex/uvicorn/blob/main/uvicorn/protocols/http/h11_impl.py#L408
and there it is not logged in the desired format.

Reading https://github.com/br3ndonland/inboard/blob/1b6ea662167e01e09363e035187db105f1c0f278/inboard/gunicorn_workers.py, I guess the idea is that uvicorn uses the gunicorn log handler and it has the correct formatter configured, but somehow that doesn't happen.

[br3ndonland]

Thanks for reporting. I'm happy to help with this.

The inboard default logging config propagates all the relevant log streams from FastAPI, Gunicorn, and Uvicorn to the root logger, formats all the log messages in the same way, and outputs all messages to stdout. This was an intentional design decision that helped keep things simple and work around the differences between Uvicorn and Gunicorn (Kludex/uvicorn#527, Kludex/uvicorn#947 (comment)).

In your case, if you are supplying your own logging config, the behavior may be different.

The logger that Uvicorn is using in h11_impl.py looks to be uvicorn.error as seen here and here. So I would suggest double checking that you're propagating and handling uvicorn.error correctly. You can see the logger propagation in the default config here:

inboard/inboard/logging_conf.py

Lines 166 to 174 in a0106c5

	"loggers": {
	"fastapi": {"propagate": True},
	"gunicorn.access": {"handlers": ["default"], "propagate": True},
	"gunicorn.error": {"propagate": True},
	"uvicorn": {"propagate": True},
	"uvicorn.access": {"propagate": True},
	"uvicorn.asgi": {"propagate": True},
	"uvicorn.error": {"propagate": True},
	},

If you're supplying LOG_FORMAT, you'll also want to double check that the value maps to one of the formatters in your logging config. For example, inboard's default simple formatter maps to the formatter here:

inboard/inboard/logging_conf.py

Lines 132 to 136 in a0106c5

	"formatters": {
	"simple": {
	"class": "logging.Formatter",
	"format": "%(levelname)-10s %(message)s",
	},

If you're still having trouble, feel free to share your logging config here and I can take a closer look.

[bodograumann]

Thank your for the help.

We are importing LOGGING_CONFIG from inboard and mainly adding new formatters.
So the behaviour should not be that different.

Could you explain, why the uvicorn logger is set to not propagate to the root logger?
Maybe the way the logger is currently set for uvicorn should also use the formatters from the gunicorn base worker class?

[br3ndonland]

Could you explain, why the uvicorn logger is set to not propagate to the root logger?

The Uvicorn worker class disables propagation because it results in duplicate logs if enabled (Kludex/uvicorn#614, Kludex/uvicorn#623). This is why the Python logging docs say "it may emit the same record multiple times."

The logging configuration for Gunicorn overall is handled here:

inboard/inboard/gunicorn_conf.py

Line 30 in a0106c5

logconfig_dict = configure_logging()

Maybe the way the logger is currently set for uvicorn should also use the formatters from the gunicorn base worker class?

Gunicorn does not expose a logging.Formatter class, so a custom logging.Formatter class would have to be implemented. The custom class would have to wrap some of Gunicorn's logging methods. This is not straightforward (benoitc/gunicorn#1572, benoitc/gunicorn#2329).

[bodograumann]

The Uvicorn worker class disables propagation because it results in duplicate logs if enabled (Kludex/uvicorn#614, Kludex/uvicorn#623). This is why the Python logging docs say "it may emit the same record multiple times."

Interesting. The issue you mention is in the context where uvicorn wants to take lead on the logging.
In inboard however, the idea is that all streams are propagated to the root logger.
Couldn't we just unset all handlers from the uvicorn logger instead and keep propagation active?