Bug: litestar run --debug does not propagate to loggers correctly

[JacobCoffee]

Description

The error issue from #1672 was resolved in #1742; however, the log levels should properly be set when --debug is set with the CLI.

URL to code causing the issue

• litestar/litestar/app.py

  Line 394 in d94717e

  self.debug = config.debug

• litestar/litestar/app.py

  Line 449 in d94717e

  @debug.setter

• ?

MCVE

# mcve.py
from litestar import Litestar, get, Request
from litestar.logging import StructLoggingConfig


@get("/")
def hello_world(request: Request) -> dict[str, str]:
    """Keeping the tradition alive with hello world."""
    request.logger.info("info inside a request")
    request.logger.debug("debug inside a request")
    return {"hello": "world"}

app = Litestar(
    route_handlers=[hello_world],
    logging_config=StructLoggingConfig(),
)

Steps to reproduce

1. Create MCVE file, e.g. mcve.py
2. Run the file `litestar run --debug --app "mcve.py"`
3. Browse to `http://localhost:8000`
4. Observe that `request.logger.debug("debug inside a request")` is within the expected log filter level but is not logged.

Screenshots

No response

Logs

No response

Litestar Version

2.0a7

Platform

• Linux
• Mac
• Windows
• Other (Please specify in the description above)

[JacobCoffee]

In testing

litestar/litestar/app.py

Lines 449 to 455 in d94717e

	@debug.setter
	def debug(self, value: bool) -> None:
	if self.logger:
	self.logger.setLevel(logging.DEBUG if value else logging.INFO)
	if isinstance(self.logging_config, LoggingConfig):
	self.logging_config.loggers["litestar"]["level"] = "DEBUG" if value else "INFO"
	self._debug = value

@debug.setter
    def debug(self, value: bool) -> None:
        import logging
        print("Inside the debug setter")
        if self.logger:
            print("Inside the debug setter and logger is not None")
            self.logger.setLevel(logging.DEBUG if value else logging.INFO)
        if isinstance(self.logging_config, LoggingConfig):
            print("Inside the debug setter and logging_config is not None")
            # Here, we print out the root logger's level before trying to set it
            print(f"Root logger level before setting: {logging.getLogger().level}")
            logging.getLogger().setLevel(logging.DEBUG if value else logging.INFO)
            print(f"Root logger level after setting: {logging.getLogger().level}")
        self._debug = value
        print("Outside the debug setter")
        print(f"Root logger level at end of setter: {logging.getLogger().level}")
        print(self._debug)

mcve.py, testing with and without logging.getLogger, with and without StructLoggingCOnfig, etc.

from litestar import Litestar, get, Request
from litestar.logging import StructLoggingConfig

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

@get("/")
def hello_world(request: Request) -> dict[str, str]:
    """Keeping the tradition alive with hello world."""
    print("inside hello world")

    if request.logger is not None:
        print(
            f"Logger name: {request.logger.name}, Parent logger name: {request.logger.parent.name if request.logger.parent else 'None'}")
    else:
        print("request.logger is None")
    handler_levels = [handler.level for handler in request.logger.handlers]
    print(f"Logger level: {request.logger.level}, Handler levels: {handler_levels}")

    logger.debug("debug inside a request")
    logger.info("info inside a request")

    request.logger.info("info inside a request")
    request.logger.debug("debug inside a request")

    print("outside hello world")

    return {"hello": "world"}

app = Litestar(
    route_handlers=[hello_world],
    # logging_config=StructLoggingConfig(),
)

➜ litestar run --debug 

  @get("/")
Inside the debug setter
Inside the debug setter and logging_config is not None
Root logger level before setting: 30
Root logger level after setting: 10
Outside the debug setter
Root logger level at end of setter: 10
True

Using Litestar app from app:app
Starting server process 

INFO:     Started server process [1157565]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:36263 (Press CTRL+C to quit)

inside hello world
Logger name: root, Parent logger name: None
Logger level: 20, Handler levels: [10]
outside hello world

INFO:     127.0.0.1:42922 - "GET / HTTP/1.1" 200 OK
INFO - 2023-06-10 11:24:32,-1507875053 - root - http - info inside a request

It seems like once set, something reverts the logging level back to 20

[JacobCoffee]

@get("/")
def hello_world(request: Request) -> dict[str, str]:
    """Keeping the tradition alive with hello world."""
    print(f"Root logger level at start of request: {logging.getLogger().level}")
    print("inside hello world")

    if request.logger is not None:
        print(
            f"Logger name: {request.logger.name}, Parent logger name: {request.logger.parent.name if request.logger.parent else 'None'}")
    else:
        print("request.logger is None")
    handler_levels = [handler.level for handler in request.logger.handlers]
    print(f"Logger level: {request.logger.level}, Handler levels: {handler_levels}")

    logger.debug("debug inside a request")
    logger.info("info inside a request")

    request.logger.info("info inside a request")
    request.logger.debug("debug inside a request")

    print("outside hello world")

    return {"hello": "world"}

app = Litestar(
    route_handlers=[hello_world],
    # logging_config=StructLoggingConfig(),
)


Root logger level at start of request: 10
inside hello world
Logger name: root, Parent logger name: None
Logger level: 20, Handler levels: [10]
outside hello world
INFO - 2023-06-10 11:26:24,-1507762523 - root - http - info inside a request

Different Loggers:

@get("/")
def hello_world(request: Request) -> dict[str, str]:
    """Keeping the tradition alive with hello world."""
    root_logger_id = id(logging.getLogger())
    request_logger_id = id(request.logger)
    print(f"Root logger ID: {root_logger_id}, request logger ID: {request_logger_id}")

Root logger ID: 139982122524304, request logger ID: 139982057730832
Root logger level at start of request: 10
inside hello world
Logger name: root, Parent logger name: None
Logger level: 20, Handler levels: [10]
outside hello world

[cofin]

@JacobCoffee is this still an issue?

[JacobCoffee]

Yes

[JacobCoffee]

The original issue was fixed but the expected behavior of this I haven't been able to solve

[Mattwmaster58]

Would this be the issue that would be causing my app to send 500s opaquely? On version 2.0.0, I can repro the following issue:

@get("/")
async def perch() -> str:
    return "helo"
    
app = Litestar(
    route_handlers=[perch],
    compression_config=CompressionConfig(backend="brotli")
)

Ensure --debug is used to start the app.py, ensure that brotli is NOT installed, and you will see opaque 500s in the console because brotli is not installed. Setting debug in the Litestar obj does work, though

[JacobCoffee]

Yes I believe so, could you try the resolution from https://github.com/litestar-org/litestar/pull/2014/files#diff-110e498a2e71333ae98121de712e741ce2410c899c7929ac88be1a12f3978c59?

[Mattwmaster58]

I manually patched from site packages (hope that's a valid way, I verified this was the code that was running with a print statements) - no dice. My issue still persists, I see │ Debug mode │ Enabled │, but getting opaque 500s. I applied the whole patch, not just the file diff linked.

[provinzkraut]

I don't think this is the same issue, but would have to investigate.

@Mattwmaster58 Could you open a separate issue with an MCVE for your case?

[Mattwmaster58]

Absolutely

…

On Thu, Aug 10, 2023, 12:33 PM Janek Nouvertné ***@***.***> wrote: I don't think this is the same issue, but would have to investigate. @Mattwmaster58 <https://github.com/Mattwmaster58> Could you open a separate issue with an MCVE for your case? — Reply to this email directly, view it on GitHub <#1804 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AGI56LIWWEBQ3BWTIGFEELDXUUEOBANCNFSM6AAAAAAZA5CXGU> . You are receiving this because you were mentioned.Message ID: ***@***.***>