Bug: Unable to log INFO or DEBUG level events

[ThinksFast]

Describe the bug Outside of a request handler, I'm unable to log debug or info level statements. Only warning and above will log.

To Reproduce Here is an MCVE:

import logging
import uvicorn

from starlite import Starlite, LoggingConfig, get

logging_config = LoggingConfig(
    loggers={
        "app": {
            "level": "DEBUG",
            "handlers": ["queue_listener"],
        }
    }
)

logger = logging.getLogger(__name__)

async def log_on_start_up():
    logger.debug("Logging debug")
    logger.info("Logging info")
    logger.warning("Logging warning")
    logger.exception("Logging exception")
    logger.error("Logging error")
    logger.critical("Logging critical")

@get("/")
async def home() -> dict[str, str]:
    """Handler function that returns a greeting dictionary."""

    return {"hello": "world"}

app = Starlite(
    route_handlers=[home],
    logging_config=logging_config,
    on_startup=[log_on_start_up],
    debug=True,
)

if __name__ == "__main__":
    uvicorn.run(app, host="127.0.0.1", port=8000)

On Starlite 1.43.0 in Python 3.11, the app logs the following on startup. Notice info and debug do not get logged.

(py311) starlite-mcve  $ uvicorn logmain:app --reload
INFO:     Will watch for changes in these directories: ['/Users/ThinksFast/Documents/starlite-mcve']
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [45930] using StatReload
INFO:     Started server process [45932]
INFO:     Waiting for application startup.
Logging warning
Logging exception
NoneType: None
Logging error
Logging critical
INFO:     Application startup complete.

I have another environment with Python 3.10 and Starlite 1.30 installed. The same code logs some additional lines from Uvicorn, and the log formatting is different, but the on_startup logging still doesn't print out the info or debug levels.

(py310) starlite-mcve  $ uvicorn logmain:app --reload
INFO:     Will watch for changes in these directories: ['/Users/ThinksFast/Documents/starlite-mcve']
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [45869] using StatReload
INFO:     Started server process [45871]
INFO:     Waiting for application startup.
INFO - 2022-12-01 23:18:59,903 - uvicorn.error - server - Started server process [45871]
INFO - 2022-12-01 23:18:59,903 - uvicorn.error - on - Waiting for application startup.
INFO - 2022-12-01 23:18:59,903 - logmain - logmain - Logging info
INFO:     Application startup complete.
WARNING - 2022-12-01 23:18:59,904 - logmain - logmain - Logging warning
ERROR - 2022-12-01 23:18:59,904 - logmain - logmain - Logging exception
NoneType: None
ERROR - 2022-12-01 23:18:59,904 - logmain - logmain - Logging error
CRITICAL - 2022-12-01 23:18:59,904 - logmain - logmain - Logging critical
INFO - 2022-12-01 23:18:59,904 - uvicorn.error - on - Application startup complete.

Additional context I have a production app which has logging in place for several on_startup functions. The logging in the functions has always worked for me, until recently. But I'm not sure what change I made that caused the logging to disappear.... was it a Starlite update, or some dependency, I'm not sure.

I did test logging in a request handler, and info-level logging works.. request.logger.info("Log me in a request") will get logged. Its only outside of request handlers that the logging seems to be ignored for info and debug levels.

[provinzkraut]

Okay, I can reproduce this. It's definitely unexpected behaviour.

[provinzkraut]

Turns out not to be a bug after all, I just can't read ;)

There are multiple things happening here:

1. You configure a logger called app
2. You are retrieving a logger called "__main__" (__name__ will be set to "__main__" if you run a python module directly like this, that's why the __name__ == "__main__" thing works)
3. The NoneType: None is caused because you are using logger.exception outside of an exception handler. See the docs on logger.exception

It works with request.logger because that is accessing the "starlite" logger.

I think our documentation is a bit misleading here if you're unfamiliar with Python logging (or in general)

[ThinksFast]

Thanks for the feedback! I have been running the program by calling this from terminal: uvicorn main:app. Which would have set name == "main". So that makes sense it's not calling the correct logger. Although this previously was working for me, I haven't changed my logging config, and the on_startup functions in my production app would log INFO statements just fine.

But I'm not sure why Starlite 1.30 would log the extra lines from Uvicorn, if I'm running the program the same way. uvicorn main:app

And if I set logger = logging.getLogger("app"), it still doesn't log INFO or DEBUG statements.

[provinzkraut]

But I'm not sure why Starlite 1.30 would log the extra lines from Uvicorn, if I'm running the program the same way. uvicorn main:app

Starlite isn't. Uvicorn is. You're configuring neither Starlite's not Uvicorn's logger here. You are configuring an independent logger called "app"

And if I set logger = logging.getLogger("app"), it still doesn't log INFO or DEBUG statements.

You need to put the getLogger inside log_on_start_up. If you're getting it before that, it's not configured yet.

[ThinksFast]

I just tried modifying the on_startup function to include getLogger, and it still doesn't log INFO or DEBUG.

This function:

async def log_on_start_up():
    logger = logging.getLogger("app")

    logger.debug("Logging debug")
    logger.info("Logging info")
    logger.warning("Logging warning")
    logger.exception("Logging exception")
    logger.error("Logging error")
    logger.critical("Logging critical")

Generates these logs on startup:

INFO:     Started server process [52312]
INFO:     Waiting for application startup.
Logging warning
Logging exception
NoneType: None
Logging error
Logging critical
INFO:     Application startup complete.

And if I add a formatter to the logger, I still get the same logs on startup... i.e. they're not formatted. So does this mean the logger is not configured when the on_startup functions run?

Here's a complete example:

import logging
import uvicorn

from starlite import Starlite, LoggingConfig, get, Request, State, Template, Controller

logging_config = LoggingConfig(
    loggers={
        "app": {
            "level": "DEBUG",
            "handlers": ["queue_listener"],
        }
    },
    formatters={
        "standard": {
            "format": "%(asctime)s loglevel=%(levelname)-6s logger=%(name)s %(funcName)s() L%(lineno)-4d %(message)s"
        }
    },
)

logger = logging.getLogger("app")

async def log_on_start_up():
    logger = logging.getLogger("app")

    logger.debug("Logging debug")
    logger.info("Logging info")
    logger.warning("Logging warning")
    logger.exception("Logging exception")
    logger.error("Logging error")
    logger.critical("Logging critical")

class FrontEnd(Controller):
    @get("/")
    async def serveHomepage(self, request: Request, state: State) -> Template:
        request.logger.info("Serving Homepage")
        return Template(
            name="homepage.html.j2",
            context={"request": request},
        )

app = Starlite(
    route_handlers=[FrontEnd],
    logging_config=logging_config,
    on_startup=[log_on_start_up],
    debug=True,
)

if __name__ == "__main__":
    uvicorn.run(app, host="127.0.0.1", port=8000)

[provinzkraut]

import logging
import uvicorn

from starlite import Starlite, LoggingConfig, get

logging_config = LoggingConfig(
    loggers={
        "app": {
            "level": "DEBUG",
            "handlers": ["queue_listener"],
        }
    }
)

async def log_on_start_up():
    logger = logging.getLogger("app")

    logger.debug("Logging debug")
    logger.info("Logging info")
    logger.warning("Logging warning")
    logger.error("Logging error")
    logger.critical("Logging critical")

@get("/")
async def home() -> dict[str, str]:
    """Handler function that returns a greeting dictionary."""

    return {"hello": "world"}

app = Starlite(
    route_handlers=[home],
    logging_config=logging_config,
    on_startup=[log_on_start_up],
    debug=True,
)

if __name__ == "__main__":
    uvicorn.run(app, host="127.0.0.1", port=8000)

This works for me.

[ThinksFast]

Doesn't for me. I get this logged on startup with the code you provided. Running Python 3.11, Starlite 1.43.0.

$ uvicorn main:app --reload
INFO:     Will watch for changes in these directories: ['/Users/ThinksFast/Documents/GitHub/starlite-mcve']
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [52606] using StatReload
INFO:     Started server process [52608]
INFO:     Waiting for application startup.
Logging warning
Logging error
Logging critical
INFO:     Application startup complete.

[provinzkraut]

This is very odd. Can you reproduce it in a new venv? Also, can you post the results of pip freeze?

[ThinksFast]

Strange. It does log correctly in a new environment. But it's also double-logging:

INFO:     Started server process [53798]
INFO:     Waiting for application startup.
DEBUG - 2022-12-02 18:38:46,782 - app - logmain - Logging debug
DEBUG - 2022-12-02 18:38:46,782 - app - logmain - Logging debug
INFO - 2022-12-02 18:38:50,071 - app - logmain - Logging info
INFO - 2022-12-02 18:38:50,071 - app - logmain - Logging info
WARNING - 2022-12-02 18:38:53,179 - app - logmain - Logging warning
WARNING - 2022-12-02 18:38:53,179 - app - logmain - Logging warning
ERROR - 2022-12-02 18:38:54,307 - app - logmain - Logging error
ERROR - 2022-12-02 18:38:54,307 - app - logmain - Logging error
CRITICAL - 2022-12-02 18:38:55,513 - app - logmain - Logging critical
CRITICAL - 2022-12-02 18:38:55,513 - app - logmain - Logging critical
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

Here's the pip freeze from my original environment:

$ pip freeze

aiolimiter==1.0.0 anyio==3.6.2 appnope @ file:///home/conda/feedstock_root/build_artifacts/appnope_1649077682618/work APScheduler==3.9.1 argon2-cffi @ file:///home/conda/feedstock_root/build_artifacts/argon2-cffi_1640817743617/work argon2-cffi-bindings @ file:///Users/runner/miniforge3/conda-bld/argon2-cffi-bindings_1666850851456/work asttokens @ file:///home/conda/feedstock_root/build_artifacts/asttokens_1667325728359/work async-timeout==4.0.2 asyncpg==0.26.0 attrs @ file:///home/conda/feedstock_root/build_artifacts/attrs_1659291887007/work backcall @ file:///home/conda/feedstock_root/build_artifacts/backcall_1592338393461/work backports.functools-lru-cache @ file:///home/conda/feedstock_root/build_artifacts/backports.functools_lru_cache_1618230623929/work beautifulsoup4 @ file:///home/conda/feedstock_root/build_artifacts/beautifulsoup4_1649463573192/work black==22.10.0 bleach @ file:///home/conda/feedstock_root/build_artifacts/bleach_1656355450470/work Brotli==1.0.9 certifi==2022.9.24 cffi==1.15.1 charset-normalizer==2.1.1 click==8.1.3 cryptography==38.0.4 debugpy @ file:///Users/runner/miniforge3/conda-bld/debugpy_1666826584371/work decorator @ file:///home/conda/feedstock_root/build_artifacts/decorator_1641555617451/work defusedxml @ file:///home/conda/feedstock_root/build_artifacts/defusedxml_1615232257335/work dnspython==2.2.1 ecdsa==0.18.0 email-validator==1.3.0 entrypoints @ file:///home/conda/feedstock_root/build_artifacts/entrypoints_1643888246732/work executing @ file:///home/conda/feedstock_root/build_artifacts/executing_1667317341051/work Faker==15.3.3 fastjsonschema @ file:///home/conda/feedstock_root/build_artifacts/python-fastjsonschema_1663619548554/work/dist flake8==5.0.4 flit_core @ file:///home/conda/feedstock_root/build_artifacts/flit-core_1667734568827/work/source/flit_core greenlet==1.1.3.post0 h11==0.14.0 hiredis==2.0.0 httpcore==0.16.2 httpx==0.23.1 idna==3.4 importlib-metadata @ file:///home/conda/feedstock_root/build_artifacts/importlib-metadata_1666781969417/work importlib-resources @ file:///home/conda/feedstock_root/build_artifacts/importlib_resources_1665204935269/work ipykernel @ file:///Users/runner/miniforge3/conda-bld/ipykernel_1668027175059/work ipython @ file:///Users/runner/miniforge3/conda-bld/ipython_1667140746261/work ipython-genutils==0.2.0 jedi @ file:///home/conda/feedstock_root/build_artifacts/jedi_1659959867326/work Jinja2==3.1.2 jsonparse==0.11.3 jsonschema @ file:///home/conda/feedstock_root/build_artifacts/jsonschema-meta_1667361745641/work jupyter-server @ file:///home/conda/feedstock_root/build_artifacts/jupyter_server_1668451283216/work jupyter_client @ file:///home/conda/feedstock_root/build_artifacts/jupyter_client_1668112089550/work jupyter_core @ file:///Users/runner/miniforge3/conda-bld/jupyter_core_1668031074395/work jupyterlab-pygments @ file:///home/conda/feedstock_root/build_artifacts/jupyterlab_pygments_1649936611996/work MarkupSafe==2.1.1 matplotlib-inline @ file:///home/conda/feedstock_root/build_artifacts/matplotlib-inline_1660814786464/work mccabe==0.7.0 mistune @ file:///home/conda/feedstock_root/build_artifacts/mistune_1657892024508/work multidict==6.0.2 mypy-extensions==0.4.3 nbclassic @ file:///home/conda/feedstock_root/build_artifacts/nbclassic_1667492839781/work nbclient @ file:///home/conda/feedstock_root/build_artifacts/nbclient_1665125402713/work nbconvert @ file:///home/conda/feedstock_root/build_artifacts/nbconvert-meta_1668442474361/work nbformat @ file:///home/conda/feedstock_root/build_artifacts/nbformat_1665426034066/work nest-asyncio @ file:///home/conda/feedstock_root/build_artifacts/nest-asyncio_1664684991461/work notebook @ file:///home/conda/feedstock_root/build_artifacts/notebook_1667565639349/work notebook_shim @ file:///home/conda/feedstock_root/build_artifacts/notebook-shim_1667478401171/work numpy @ file:///Users/runner/miniforge3/conda-bld/numpy_1666788427212/work oauthlib==3.2.2 orjson==3.8.2 packaging==21.3 pandas==1.5.1 pandocfilters @ file:///home/conda/feedstock_root/build_artifacts/pandocfilters_1631603243851/work parso @ file:///home/conda/feedstock_root/build_artifacts/parso_1638334955874/work pathspec==0.10.2 pendulum==2.1.2 pexpect @ file:///home/conda/feedstock_root/build_artifacts/pexpect_1667297516076/work pickleshare @ file:///home/conda/feedstock_root/build_artifacts/pickleshare_1602536217715/work picologging==0.9.1 pkgutil_resolve_name @ file:///home/conda/feedstock_root/build_artifacts/pkgutil-resolve-name_1633981968097/work platformdirs==2.5.2 prometheus-client @ file:///home/conda/feedstock_root/build_artifacts/prometheus_client_1665692535292/work prompt-toolkit @ file:///home/conda/feedstock_root/build_artifacts/prompt-toolkit_1667565496306/work psutil @ file:///Users/runner/miniforge3/conda-bld/psutil_1667885986115/work psycopg==3.1.4 psycopg-c @ file:///Users/runner/miniforge3/conda-bld/psycopg-split_1666775433924/work/psycopg-c psycopg2==2.9.5 ptyprocess @ file:///home/conda/feedstock_root/build_artifacts/ptyprocess_1609419310487/work/dist/ptyprocess-0.7.0-py2.py3-none-any.whl pure-eval @ file:///home/conda/feedstock_root/build_artifacts/pure_eval_1642875951954/work pyasn1==0.4.8 pycodestyle==2.9.1 pycparser==2.21 pydantic==1.10.2 pydantic-factories==1.16.0 pydantic-openapi-schema==1.3.0 pyflakes==2.5.0 Pygments @ file:///home/conda/feedstock_root/build_artifacts/pygments_1660666458521/work pyparsing==3.0.9 pyrsistent @ file:///Users/runner/miniforge3/conda-bld/pyrsistent_1667498922756/work python-dateutil==2.8.2 python-dotenv==0.21.0 python-jose==3.3.0 pytz==2022.6 pytz-deprecation-shim==0.1.0.post0 pytzdata==2020.1 PyYAML==6.0 pyzmq @ file:///Users/runner/miniforge3/conda-bld/pyzmq_1666828600745/work redis==4.3.5 requests==2.28.1 requests-oauthlib==1.3.1 rfc3986==1.5.0 rsa==4.9 Send2Trash @ file:///home/conda/feedstock_root/build_artifacts/send2trash_1628511208346/work six==1.16.0 sniffio==1.3.0 soupsieve @ file:///home/conda/feedstock_root/build_artifacts/soupsieve_1658207591808/work SQLAlchemy==2.0.0b3 stack-data @ file:///home/conda/feedstock_root/build_artifacts/stack_data_1668260892666/work starlite==1.43.0 starlite-multipart==1.2.0 structlog==22.3.0 terminado @ file:///Users/runner/miniforge3/conda-bld/terminado_1666707848606/work tinycss2 @ file:///home/conda/feedstock_root/build_artifacts/tinycss2_1666100256010/work tornado @ file:///Users/runner/miniforge3/conda-bld/tornado_1666788726107/work traitlets @ file:///home/conda/feedstock_root/build_artifacts/traitlets_1666115969632/work tweepy==4.12.1 typing_extensions==4.4.0 tzdata==2022.6 tzlocal==4.2 urllib3==1.26.13 uvicorn==0.19.0 wcwidth @ file:///home/conda/feedstock_root/build_artifacts/wcwidth_1600965781394/work webencodings==0.5.1 websocket-client @ file:///home/conda/feedstock_root/build_artifacts/websocket-client_1667568040382/work zipp @ file:///home/conda/feedstock_root/build_artifacts/zipp_1666647772197/work

[provinzkraut]

The duplicate entries are expected and are caused by propagation. You can check this by adding "propagate": False to your config.

[provinzkraut]

@ThinksFast Can this be closed?

[ThinksFast]

Sorry, I've been traveling and haven't had a chance to work on this. But I just tried implementing propagate=False in the minimal example and it still logs twice. Not sure why, but I'll dig into the logging docs and play with this some more.

I'm also not able to get the production app correctly logging on my local, even when I recreate a new environment from scratch.

I should be able to spend some time on this in the next two days, I'll report back soon!

[Goldziher]

ping @ThinksFast - this will be closed tomorrow. please check.

[ThinksFast]

Ok, life has been a bit busy this week. I’ll close the ticket for now and reopen it if I can’t resolve it on my own.

[ThinksFast]

Minor update: I switched to picologging and now all my log statements are logged. The only code I changed was the import statement:

From: import logging To: import picologging as logging

And now in my production app, this code logs correctly... 🤷‍♂️

logger = logging.getLogger("app")
logger.info("Logging info level")