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

[petermorrow]

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.



md5-cd4f6a50ee30a58047f2b4730d7940c2



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



md5-252baa411a63ff5d6de963aa02505c11



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



md5-0a1798c50c3f76c82bbf46d3198a611e



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 [e-mail] 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
https://github.com/encode/uvicorn/issues/511?email_source=notifications&email_token=AAINSPVJR367JCAE36ZBI73QXAG2RA5CNFSM4JVOGZG2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4H6DUJJA,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAINSPUGCSVEHMK5ODM4Y3DQXAG2RANCNFSM4JVOGZGQ
.

[petermorrow]

@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 [e-mail]
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
https://github.com/encode/uvicorn/issues/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

[petermorrow]

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.

[petermorrow]

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 [e-mail] 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
https://github.com/encode/uvicorn/issues/511?email_source=notifications&email_token=AAINSPT2JAY6B6JEUGNE57LQXZZ6BA5CNFSM4JVOGZG2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEGJ365I#issuecomment-563330933,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAINSPWAQZHESHRLND4PVJDQXZZ6BANCNFSM4JVOGZGQ
.

[petermorrow]

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, 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

[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!