search

topsport-com-au / starlite-saqlalchemy

Starlite API boilerplate abstraction and utilities.
https://topsport-com-au.github.io/starlite-saqlalchemy/
MIT License
31 stars 8 forks source link

bug(logging): pydantic validation error in handler causes error from `rich` formatting #255

Open peterschutt opened 1 year ago

peterschutt commented 1 year ago

A pydantic validation error raised in a handler causes an error in rich logging output. If the error raised in the handler isn't a pydantic validation error (e.g., RuntimeError, ValueError, etc) then it doesn't seem to be an issue. If rich isn't installed, there isn't an issue either.

To reproduce, install starlite-saqlalchemy and rich and create .env and main.py as per below:

ENVIRONMENT=local
CHECK_DB_READY=false
CHECK_REDIS_READY=false
SERVER_APP_LOC=main:app
SERVER_APP_LOC_IS_FACTORY=false
# main.py
from pydantic import BaseModel

from starlite import Starlite, get
from starlite_saqlalchemy import ConfigureApp, PluginConfig, scripts

class Model(BaseModel):
    a: float

@get("/test")
async def test() -> Model:
    return Model(a="string")

app = Starlite(route_handlers=[test], on_app_init=[ConfigureApp(PluginConfig(do_worker=False))])

if __name__ == "__main__":
    scripts.run_app()

The repro explicitly causes a pydantic validation error in the handler which causes:

--- Logging error ---
Traceback (most recent call last):
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 47, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/routes/http.py", line 79, in handle
    response = await self._get_response_for_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/routes/http.py", line 131, in _get_response_for_request
    response = await self._call_handler_function(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/routes/http.py", line 160, in _call_handler_function
    response_data, cleanup_group = await self._get_response_data(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/routes/http.py", line 218, in _get_response_data
    data = await route_handler.fn.value(**parsed_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/main.py", line 13, in test
    return Model(a="string")
           ^^^^^^^^^^^^^^^^^
  File "pydantic/main.py", line 342, in pydantic.main.BaseModel.__init__
pydantic.error_wrappers.ValidationError: 1 validation error for Model
a
  value is not a valid float (type=type_error.float)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 47, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite_saqlalchemy/log/controller.py", line 75, in middleware
    await app(scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/base.py", line 137, in wrapped_call
    await original__call__(self, scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/compression.py", line 138, in __call__
    await self.app(
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 58, in __call__
    await response(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite_saqlalchemy/log/controller.py", line 151, in __call__
    await LOGGER.aerror("Error in logging before-send handler!", exc_info=exc)
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/_log_levels.py", line 168, in <lambda>
    lambda: ctx.run(
            ^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/_log_levels.py", line 169, in <lambda>
    lambda: self._proxy_to_logger(name, event, **kw)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/_base.py", line 205, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/_base.py", line 162, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/dev.py", line 424, in __call__
    self._exception_formatter(sio, exc_info)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/dev.py", line 187, in rich_traceback
    Traceback.from_exception(*exc_info, show_locals=True)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/traceback.py", line 335, in from_exception
    rich_traceback = cls.extract(
                     ^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/traceback.py", line 405, in extract
    exc_type=safe_str(exc_type.__name__),
                      ^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute '__name__'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 47, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/asgi/asgi_router.py", line 80, in __call__
    await asgi_app(scope, receive, send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 58, in __call__
    await response(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/response/base.py", line 381, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/response/base.py", line 352, in start_response
    await send(event)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/app.py", line 700, in wrapped_send
    await send(message)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 501, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 407, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/app.py", line 422, in __call__
    await self.asgi_handler(scope, receive, self._wrap_send(send=send, scope=scope))  # type: ignore[arg-type]
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/middleware/exceptions/middleware.py", line 58, in __call__
    await response(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/response/base.py", line 381, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/response/base.py", line 352, in start_response
    await send(event)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/starlite/app.py", line 700, in wrapped_send
    await send(message)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 501, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/syntax.py", line 497, in tokens_to_spans
    _token_type, token = next(tokens)
                         ^^^^^^^^^^^^
StopIteration

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/logging/handlers.py", line 1498, in emit
    self.enqueue(self.prepare(record))
                 ^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/logging/handlers.py", line 1480, in prepare
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/logging/__init__.py", line 953, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/stdlib.py", line 963, in format
    ed = p(logger, meth_name, ed)
         ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/dev.py", line 424, in __call__
    self._exception_formatter(sio, exc_info)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/structlog/dev.py", line 186, in rich_traceback
    Console(file=sio, color_system="truecolor").print(
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1694, in print
    extend(render(renderable, render_options))
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1330, in render
    yield from self.render(render_output, _options)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1326, in render
    for render_output in iter_render:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/constrain.py", line 29, in __rich_console__
    yield from console.render(self.renderable, child_options)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1326, in render
    for render_output in iter_render:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/panel.py", line 220, in __rich_console__
    lines = console.render_lines(renderable, child_options, style=style)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1366, in render_lines
    lines = list(
            ^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/segment.py", line 292, in split_and_crop_lines
    for segment in segments:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1326, in render
    for render_output in iter_render:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/padding.py", line 97, in __rich_console__
    lines = console.render_lines(
            ^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1366, in render_lines
    lines = list(
            ^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/segment.py", line 292, in split_and_crop_lines
    for segment in segments:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1330, in render
    yield from self.render(render_output, _options)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/console.py", line 1326, in render
    for render_output in iter_render:
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/syntax.py", line 609, in __rich_console__
    segments = Segments(self._get_syntax(console, options))
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/segment.py", line 668, in __init__
    self.segments = list(segments)
                    ^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/syntax.py", line 637, in _get_syntax
    text = self.highlight(processed_code, self.line_range)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/syntax.py", line 509, in highlight
    text.append_tokens(tokens_to_spans())
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/rich/text.py", line 995, in append_tokens
    for content, style in tokens:
RuntimeError: generator raised StopIteration
Call stack:
  File "<string>", line 1, in <module>
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/multiprocessing/spawn.py", line 120, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/multiprocessing/spawn.py", line 133, in _main
    return self._bootstrap(parent_sentinel)
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/_subprocess.py", line 76, in subprocess_started
    target(sockets=sockets)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/server.py", line 60, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
  File "/home/peter/.pyenv/versions/3.11.1/lib/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "/home/peter/PycharmProjects/rich-error-repro/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 412, in run_asgi
    self.logger.error(msg, exc_info=exc)
Message: 'Exception in ASGI application\n'
Arguments: ()
geofft commented 1 year ago

I think this is the same as Textualize/rich#2800. rich==13.0.1 seems okay; rich==13.1.0 is not.