Starlette: Logging in code disables Starlette logging when called programatically

[berislavlopac]

So, here's the simplest code, using the quickstart example from Starlette's documentation, in a file test.py:

from starlette.applications import Starlette
from starlette.responses import JSONResponse
import uvicorn
import logging

app = Starlette()


@app.route('/')
async def homepage(request):
    return JSONResponse({'hello': 'world'})


if __name__ == '__main__':
    logging.info('Starting server')
    uvicorn.run(app, host='0.0.0.0', port=8000, log_level='debug')

If we run this directly, with python -m test, there is no logging out put in the console. If we either disable the penultimate line (logging.info(...), or if we run it externally (uvicorn test:app), we get the regular logging output:

$ uvicorn test:app
INFO: Started server process [18682]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

So, in the case of running uvicorn programatically and logging stuff in our code, the logging fails to appear. The log_level argument has no effect either way.

[tomchristie]

Oh my, Python logging is inscrutable.
This is uvicorn rather than Starlette. It looks like we probably need to make sure that we call setLevel on the logger instance, here

eg...

def get_logger(log_level):
    log_level = LOG_LEVELS[log_level]
    logging.basicConfig(format="%(levelname)s: %(message)s", level=log_level)
    logger = logging.getLogger("uvicorn")
    logger.setLevel(log_level)
    return logger

But this breaks some of our tests that rely on the logging behavior (I can't see why)

Anyway, any contributor insight into this much appreciated.

[alexbotello]

@tomchristie it seems the issue is with the caplog.set_level. I was able to get the tests working by passing the name of our logger, "uvicorn" to the function.

So uvicorn/tests/middleware/test_message_logger.py lines 16, 37, 55 should be:

caplog.set_level(logging.DEBUG, logger="uvicorn")

[supriyo-biswas]

This issue also seems to disable asyncio's logging.

[alexbotello]

Just a note here, if you wish to log code outside the uvicorn event loop you'll have to set a logger at your application level.

For example:

import logging
import uvicorn
from starlette.applications import Starlette
from starlette.responses import PlainTextResponse

logger = logging.getLogger()
logger.setLevel(logging.INFO)

app = Starlette()

@app.route("/")
async def homepage(request):
    return PlainTextResponse("Hello, World!", status_code=200)

if __name__ == "__main__":
    logging.info("Starting Starlette server!")
    uvicorn.run(app, host="0.0.0.0", port=8000)

Will output this to your console:

$ python app.py
INFO:root:Starting Starlette server!
INFO:uvicorn:Started server process [29447]
INFO:uvicorn:Waiting for application startup.
INFO:uvicorn:Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)

This code will work with the current version of uvicorn, uvicorn==0.3.16. @tomchristie's fix above just ensures that uvicorn's logging will not be disabled in a case like @berislavlopac's original example.

[tomchristie]

Resolved with uvicorn 0.3.17