uvicorn: [BUG] Using --log-config disables uvicorn loggers

Summary

Uvicorn logs are disabled when starting a uvicorn server process with a custom --log-config file.

Steps to Reproduce

logging_config.ini

[loggers]
keys=root

[handlers]
keys=h

[formatters]
keys=f

[logger_root]
level=INFO
handlers=h

[handler_h]
class=StreamHandler
level=INFO
formatter=f
args=(sys.stderr,)

[formatter_f]
format=%(asctime)s %(name)s %(levelname)-4s %(message)s

scratch_fastapi.py

import logging
from fastapi import FastAPI

logger = logging.getLogger(__name__)
app = FastAPI()

@app.on_event("startup")
async def startup():
    logger.warning('Raising an exception on startup')
    raise Exception("Nope!")

Run without `--log-config`

uvicorn scratch_fastapi:app

INFO:     Started server process [7448]
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Waiting for application startup.
WARNING:  Raising an exception on startup
ERROR:    Traceback (most recent call last):
  File "/Users/peter/.virtualenvs/JR/lib/python3.7/site-packages/starlette/routing.py", line 473, in __call__
    await self.startup()
  File "/Users/peter/.virtualenvs/JR/lib/python3.7/site-packages/starlette/routing.py", line 457, in startup
    await handler()
  File "./scratch_fastapi.py", line 10, in startup
    raise Exception("Nope!")
Exception: Nope!

ERROR:    Application startup failed. Exiting.

Run with `--log-config`

uvicorn scratch_fastapi:app --log-config=logging_config.ini

2019-12-04 11:56:43,681 scratch_fastapi WARNING Raising an exception on startup

Notice that all the logs from uvicorn are gone.

Expected Behavior

The existing uvicorn logger is not disabled.

System Information

OS: MacOS Mojave Python: 3.7.5 Uvicorn version: uvicorn==0.10.8

Pip freeze output for full dependencies list:

Click==7.0
dnspython==1.16.0
email-validator==1.0.5
fastapi==0.44.0
h11==0.8.1
httptools==0.0.13
idna==2.8
pydantic==1.2
starlette==0.12.9
uvicorn==0.10.8
uvloop==0.14.0
websockets==8.1

Fix

I have a simple fix here that I’ll follow up with a PR for.

About this issue

Original URL
State: closed
Created 5 years ago
Comments: 15 (11 by maintainers)

Commits related to this issue

Allow .json or .yaml --log-config files (#665) * Allow .json or .yaml --log-config files This adds support for `.json` and `.yaml` config files when running `uvicorn` from the CLI. This allows cl... — committed to encode/uvicorn by jcwilson 4 years ago

Most upvoted comments

This doesn’t appear resolved as the PR that fixed this, https://github.com/encode/uvicorn/pull/626, was reverted the day after in https://github.com/encode/uvicorn/pull/650.

Would a PR be accepted in uvicorn/config.py for this change?

-                logging.config.fileConfig(self.log_config)
+                logging.config.fileConfig(self.log_config, disable_existing_loggers=False)

This is what the PR that closed the issue was originally doing: https://github.com/encode/uvicorn/pull/626/files#diff-2018370b7a33e4ad7ee7df28b8248459L235

derekbekoe on Jul 9, 2020

@euri10 I’m not sure if you mean that getting the logger at the function level (or outside the module level) would resolve the issue, but when you do the issue persists.

Also consider this example:

import logging
from fastapi import FastAPI

app = FastAPI()

@app.on_event("startup")
async def startup():
    logger = logging.getLogger(__name__)
    logger.info("Everything is going well")
    raise Exception("Nope!")

This simply exits with no logs from uvicorn reporting the exception. I would imagine that regardless of whether a user is getting their loggers at the module level or not this would be difficult to debug in production where a --log-config is set via their CI/CD. I can’t imagine a use case where someone would expect to disable uvicorn’s logs with the --log-config option, but maybe that’s the typical use case. With that being said, maybe there could be another --log-disable-existing-false option or something.

My company’s use case here is to customize uvicorn’s log formatter to include the timestamp in the log message, which we expected to be able to accomplish with the --log-config option but maybe there’s a better way. Happy to try an alternative method.

petermorrowdev on Dec 4, 2019

@petermorrow It’s not at all clear to me that disable_existing_loggers=False is the behavior that we’d typically want here.

It’d potentially be better for us to provide an example in the docs of a log file configuration that matches our existing defaults. That way users can either add or remove bits from the logging configuration.

tomchristie on Dec 9, 2019