Exception in ASGI application

[dineshbvadhia]

At this stage this looks like a starlette problem (or Windows 11) but maybe you have come across it. I ran the https://github.com/NRWLDev/fastapi-problem/blob/main/examples/custom.py and the examples work except the unexpected error. On the browser http://localhost:8000/unexpected-error returns correctly but at the server the error is an Exception in ASGI application with a long traceback. Any thoughts?

INFO:     Application startup complete.

INFO:     127.0.0.1:64197 - "GET /validation-error HTTP/1.1" 422 Unprocessable Entity
INFO:     127.0.0.1:64198 - "GET /not-allowed HTTP/1.1" 405 Method Not Allowed
INFO:     127.0.0.1:64224 - "GET /not-found HTTP/1.1" 404 Not Found

INFO:     127.0.0.1:64225 - "GET /unexpected-error HTTP/1.1" 500 Internal Server Error
ERROR:    Exception in ASGI application

Traceback (most recent call last):
  File "...uvicorn\protocols\http\httptools_impl.py", line 399, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "...uvicorn\middleware\proxy_headers.py", line 70, in __call__
    return await self.app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "...fastapi\applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "...starlette\applications.py", line 123, in __call__
    await self.middleware_stack(scope, receive, send)
  File "...starlette\middleware\errors.py", line 186, in __call__
    raise exc
  File "...starlette\middleware\errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "...starlette\middleware\exceptions.py", line 65, in __call__
    await wrap_app_handling_exceptions(self.app, conn)(scope, receive, send)
  File "...starlette\_exception_handler.py", line 64, in wrapped_app
    raise exc
  File "...starlette\_exception_handler.py", line 53, in wrapped_app
    await app(scope, receive, sender)
  File "...starlette\routing.py", line 756, in __call__
    await self.middleware_stack(scope, receive, send)
  File "...starlette\routing.py", line 776, in app
    await route.handle(scope, receive, send)
  File "...starlette\routing.py", line 297, in handle
    await self.app(scope, receive, send)
  File "...starlette\routing.py", line 77, in app
    await wrap_app_handling_exceptions(app, request)(scope, receive, send)
  File "...starlette\_exception_handler.py", line 64, in wrapped_app
    raise exc
  File "...starlette\_exception_handler.py", line 53, in wrapped_app
    await app(scope, receive, sender)
  File "...starlette\routing.py", line 72, in app
    response = await func(request)
               ^^^^^^^^^^^^^^^^^^^
  File "...fastapi\routing.py", line 278, in app
    raw_response = await run_endpoint_function(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "...fastapi\routing.py", line 191, in run_endpoint_function
    return await dependant.call(**values)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "...custom.py", line 66, in unexpected_error
    return {"value": 1 / 0}
                     ~~^~~
ZeroDivisionError: division by zero

[EdgyEdgemond]

That is just the uvicorn.error logger catching it. This is a logging configuration/preference issue, you can disable uvicorn.error in logging config, I personally disable that one, and enable uvicorn.access.

for example:

import logging.config

logging.config.dictConfig(
        {
            "version": 1,
            "disable_existing_loggers": True,
            "formatters": {
                "default": {
                    "format": "[%(asctime)s][%(name)s:%(lineno)d][%(levelname)s]: %(message)s",
                    "datefmt": "%Y-%m-%d %H:%M:%S",
                },
            },
            "handlers": {
                "default": {
                    "class": "logging.StreamHandler",
                    "level": "info",
                    "formatter": "default",
                },
            },
            "loggers": {
                "my_project": {
                    "handlers": ["default"],
                    "level": "info",
                    "propagate": False,
                },
                "uvicorn.access": {
                    "handlers": ["default"],
                    "level": "info",
                    "propagate": False,
                },
            },
        }
)

[dineshbvadhia]

Testing with above raises a ValueError: Unable to configure handler 'default' ?

[EdgyEdgemond]

Odd, Ill give it a try with the examples tomorrow. That is config that I actively use so should work.

[EdgyEdgemond]

Maybe try with level "INFO" instead of "info". I did replace dynamic levels with lowercase strings assuming it would be equivalent.

[dineshbvadhia]

It works with "INFO". The terminal output for http://localhost:8000/unexpected-error is:

[2024-06-12 09:52:20][uvicorn.access:466][INFO]: 127.0.0.1:50981 - "GET /unexpected-error HTTP/1.1" 500
[2024-06-12 09:52:21][uvicorn.access:466][INFO]: 127.0.0.1:50982 - "GET /favicon.ico HTTP/1.1" 404

Not sure where the favicon.ico came from but output is in the right direction. Thanks :)

[EdgyEdgemond]

Have updated the examples to suppress uvicorn.error by default, to keep them clean.

Are you using a browser to access it or using a cli tool?

[EdgyEdgemond]

If you are using a browser, the favicon request makes sense, browsers just try to grab that by default.

[dineshbvadhia]

Using the instructions in the custom.py example ie

Run this example:
$ fastapi dev examples/custom.py

To see a custom unhandled server error response.
$ curl http://localhost:8000/unexpected-error