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