(958) Add exception logging in debug mode

[JacobCoffee]

Re: Issue #958

PR Checklist

• Have you followed the guidelines in CONTRIBUTING.md?
• Have you got 100% test coverage on new code?
• Have you updated the prose documentation?
• Have you updated the reference documentation?

[Goldziher]

so, wassup here? Why does this take so long?

[JacobCoffee]

not 100% sure on the testing here, can someone verify it is checking correctly?

[provinzkraut]

@JacobCoffee What's the status of this?

[provinzkraut]

The remaining problem here is that app.logger.debug is called (which is correct), but the starlite logger is at the INFO level. I propose the following changes to the default logging configuration when debug=True is passed to Starlite:

1. If no logger is configured and logging_config is not explicitly set to None, configure a logger
2. Set the starlite logger to DEBUG

[JacobCoffee]

I am working on a fix for the pytest issue via this
pytest-dev/pytest#3697 (comment)

[peterschutt]

@JacobCoffee have you seen this fixture in the logging middleware tests?

https://github.com/starlite-api/starlite/blob/901596e566cd1b0ab902e67867300b7d8cf4e348/tests/middleware/test_logging_middleware.py#L29-L38

I'd say that's there to solve the same problem that you are hitting here, although there might be other reasons for it also. However, if you are looking for a low friction way to get this through, then you could move that fixture out of tests/middleware/test_logging_middleware.py and move it into tests/middleware/conftest.py, change the log level that is set in the fixture to debug, and set the logger returned from that callable on to your application logger for the test.

I've done this and have tested that the full suite passes, so I'll PR it into your fork and you can take a look.

If you do still want to go the route of implementing that capturing context manager pattern from the linked issue, you should perhaps look at whether we can apply that to the logging middleware tests where the current fixture-based workaround is being applied as well.

[provinzkraut]

@peterschutt

I've done this and have tested that the full suite passes

This fixture was my first attempt as well, but it didn't seem to work as intended.

@pytest.fixture
def get_logger():
    return LoggingConfig(
        handlers=default_handlers,
        loggers={
            "starlite": {"level": "DEBUG", "handlers": ["queue_listener"], "propagate": True},
        },
    ).configure()


@pytest.mark.parametrize(
    "debug,logging_config",
    [
        (True, LoggingConfig()),
        (False, LoggingConfig()),
        (False, None),
    ],
)
def test_exception_handler_middleware_debug_logging(
    get_logger, caplog: "LogCaptureFixture", debug: bool, logging_config: Optional[LoggingConfig]
) -> None:
    @get("/test")
    def handler() -> None:
        raise ValueError("Test debug exception")

    app = Starlite([handler], logging_config=logging_config, debug=debug)
    app.get_logger = get_logger

    with TestClient(app=app) as client, caplog.at_level("DEBUG"):

        response = client.get("/test")
        assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR
        assert "Test debug exception" in response.text

        if debug and logging_config:
            assert len(caplog.records) == 1
            # other assertions for the content of this record here
        else:
            assert not caplog.records

Still fails for me. How did you get it working?

Anyway, I tested the workaround @JacobCoffee linked, and it seems to me that it's a more stable solution. I think it's worth generally adopting that for our tests. Wdyt?

[peterschutt]

I hit that too, but the code accesses app.logger, it doesn't call app.get_logger(). So, instead of app.get_logger = ... I used app.logger = get_logger("starlite").

[peterschutt]

I think it's worth generally adopting that for our tests. Wdyt?

I agree, but whether that is something that @JacobCoffee wants to do as part of this task, or we split it out to another issue, I'm not fussed.

[Goldziher]

Suggested change

	if self.debug and (logger := starlite_app.logger):
	if self.debug and (logger := starlite_app.get_logge()):

no?

[JacobCoffee]

Perhaps, but it broke my test 🙃 looking into why tonight hopefully

[provinzkraut]

Maybe because the function isn’t called get_logge but get_logger? 😉

[JacobCoffee]

i fixed that as soon as i committed the suggestion and realized 😛
commit dffccbf

[peterschutt]

If this change breaks the test, it most likely is because we are patching app.logger with response of calling the get_logger fixture in the test, whereas for this to work, we'd have to patch the app.get_logger attribute with the get_logger fixture itself.

In the starlite constructor, we both assign the get_logger callable and a logger instance to the application instance:

        if self.logging_config:
            self.get_logger = self.logging_config.configure()
            self.logger = self.get_logger("starlite")

...and it wasn't obvious to me which one we should be using in this case either.

[Goldziher]

@all-contributors add @JacobCoffee code

[allcontributors]

@Goldziher

@JacobCoffee already contributed before to code

[provinzkraut]

@Goldziher Why was this merged? Tests are not passing.