litestar: Bug: Unable to log INFO or DEBUG level events

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.

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 15 (15 by maintainers)

Most upvoted comments

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.