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

[petermorrowdev]

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.

[euri10]

I'd be tempted to say it's expected, not sure if this is the right fix or if your expected default behavior is correct, but I guess everyone may have a different view on this. To add some context to the above, what do you think of the section ( Do not get logger at the module level unless disable_existing_loggers is False) in this good old post I'm still referring to from time to time when I'm confused 😕 The post: https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in-python/ Le mer. 4 déc. 2019 à 9:25 PM, Peter Morrow <[email protected]> a écrit :

…

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 *fastapi_example.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. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#511?email_source=notifications&email_token=AAINSPVJR367JCAE36ZBI73QXAG2RA5CNFSM4JVOGZG2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4H6DUJJA>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAINSPUGCSVEHMK5ODM4Y3DQXAG2RANCNFSM4JVOGZGQ> .

[petermorrowdev]

@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.

[euri10]

ok my bad, I didn't know that the fileConfig method was defaulting to True, I'm always using a dict thus using dictConfig method. I'm loading from a yaml file and it has the `disable_existing_loggers=False` so it's the same as what your fix provides, I find yaml way more readable and didn't know you can't put the same disable_existing_loggers in the ini config, which sucks So I clearly misinterpreted your case, sorry/

…

On Wed, Dec 4, 2019 at 10:12 PM Peter Morrow ***@***.***> wrote: @euri10 <https://github.com/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__) 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. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#511?email_source=notifications&email_token=AAINSPV2OSCKY6WYJPTPUN3QXAMMHA5CNFSM4JVOGZG2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEF6QFIA#issuecomment-561840800>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAINSPWDGN6TQPCFZHJYXNDQXAMMHANCNFSM4JVOGZGQ> .

-- benoit barthelet http://pgp.mit.edu/pks/lookup?op=get&search=0xF150E01A72F6D2EE

[petermorrowdev]

No problem @euri10! I understand how you could misinterpret it.

How can we get this simple fix merged?

[tomchristie]

@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.

[petermorrowdev]

Thanks for the reply @tomchristie. I'm a big fan and user of your work (especially DRF)!

How would you write that logging_config.ini file to match uvicorn's existing defaults?

I'm struggling to figure out how to translate the dictConfig at uvicorn.config.LOGGING_CONFIG to the .ini format for fileConfig.

[euri10]

I may be wrong but I think this is not possible to replicate the current LOGGING_CONFIG with an ini file with the current state of uvicorn as the disable_existing_loggers=False you can pass in a dict is part of the fileConfig method for an ini file. So imho your fix is the right way to handle this or by design uvicorn --log-config=logging.ini will have disable_existing_loggers=True all the time Le lun. 9 déc. 2019 à 5:54 PM, Peter Morrow <[email protected]> a écrit :

…

Thanks for the reply @tomchristie <https://github.com/tomchristie>. I'm a big fan and user of your work (especially DRF)! How would you write that logging_config.ini file to match uvicorn's existing defaults? I'm struggling to figure out how to translate the dictConfig at uvicorn.config.LOGGING_CONFIG to the .ini format for fileConfig. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#511?email_source=notifications&email_token=AAINSPT2JAY6B6JEUGNE57LQXZZ6BA5CNFSM4JVOGZG2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEGJ365I#issuecomment-563330933>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAINSPWAQZHESHRLND4PVJDQXZZ6BANCNFSM4JVOGZGQ> .

[petermorrowdev]

I agree with @euri10. I do not think that it's currently possible to replicate the default LOGGING_CONFIG using --log-config.

What do you think @tomchristie?

[tomchristie]

@petermorrow I don't know - it'd be super helpful if someone could produce an example that's close, and show clearly which bit we'd be missing support for?

[tlc]

So --log-config is currently unusable? Nobody wants to disable the uvicorn loggers and there's no (known) way to make a logger.ini that doesn't disable them?

I would ask why there are any previous loggers to disable? --log-config should be setting the log config.

So what are people using? Are you using fileConfig or dictConfig in your app code?

[euri10]

fixed by #626

[derekbekoe]

This doesn't appear resolved as the PR that fixed this, #626, was reverted the day after in #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

[1oglop1]

@euri10 can you reopen this please?

[euri10]

and thanks all for your patience

[1oglop1]

That was quick!
Sorry I wasn't aware of #512, just hit this issue and though it may be helpful reminding to reopen :)
Thank you!