search

sanic-org / sanic

Accelerate your web app development | Build fast. Run fast.
https://sanic.dev
MIT License
18.02k stars 1.55k forks source link

Middleware Runs Twice if Route Not Found + Middleware Exception #2950

Closed imnotjames closed 3 months ago

imnotjames commented 3 months ago

Is there an existing issue for this?

Describe the bug

Middleware will be run twice if the router raises an exception and then the middleware raises an Exception.

Output:

[2024-06-02 14:29:48 -0400] [304967] [INFO] Starting worker [304967]
Middleware 1 ran
Middleware 2 ran
Middleware 1 ran
Middleware 2 ran
[2024-06-02 14:29:54 -0400] [304967] [ERROR] Exception occurred while handling uri: 'http://localhost:8000/not-found'
Traceback (most recent call last):
  File "handle_request", line 39, in handle_request
    Iterable,

  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/router.py", line 75, in get
    return self._get(path, method, host)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/router.py", line 40, in _get
    raise NotFound(f"Requested URL {e.path} not found") from None
sanic.exceptions.NotFound: Requested URL /foo not found

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/http/http1.py", line 119, in http1
    await self.protocol.request_handler(self.request)
  File "handle_request", line 159, in handle_request
    use for the application. Defaults to `Request`.
  File "handle_exception", line 73, in handle_exception
    from sanic.http import Stage
                       ^^^^^^^^^^
  File "_run_request_middleware", line 17, in _run_request_middleware
    from asyncio.futures import Future
                       ^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/middleware.py", line 45, in __call__
    return self.func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/Projects/vidrovr/vrlib/example.py", line 14, in my_middleware2
    raise SanicException()
sanic.exceptions.SanicException: Internal Server Error

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/http/http1.py", line 426, in error_response
    await app.handle_exception(
  File "handle_exception", line 73, in handle_exception
    from sanic.http import Stage
                       ^^^^^^^^^^
  File "_run_request_middleware", line 17, in _run_request_middleware
    from asyncio.futures import Future
                       ^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/middleware.py", line 45, in __call__
    return self.func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/Projects/vidrovr/vrlib/example.py", line 14, in my_middleware2
    raise SanicException()
sanic.exceptions.SanicException: Internal Server Error

Code snippet

from sanic import Sanic
from sanic.exceptions import SanicException
from sanic.response import html

app = Sanic(__name__)

@app.middleware("request")
def my_middleware1(request):
    print("Middleware 1 ran", flush=True)

@app.middleware("request")
def my_middleware2(request):
    print("Middleware 2 ran", flush=True)
    raise SanicException()

@app.get("/")
def index(request):
    return html("<p>hello world</p>")

if __name__ == "__main__":
    app.run(debug=True, auto_reload=False, access_log=False)
$ curl localhost:8000/not-found

or

$ curl -X POST localhost:8000

Expected Behavior

Request Middleware only runs once

How do you run Sanic?

Sanic CLI

Operating System

Linux

Sanic Version

23.12.1

Additional context

No response

imnotjames commented 3 months ago

This seems to be where the router raises an exception and then run_middleware is set to True at

https://github.com/sanic-org/sanic/blob/main/sanic/app.py#L1434-L1438

Then the middleware runs in the exception handler, it raises and that bubbles up to..

https://github.com/sanic-org/sanic/blob/main/sanic/http/http1.py#L149

which then calls the error response code which runs middleware if stage is HANDLER or REQUEST (which it is) and exception is not of type ServiceUnavailable or RequestCancelled

imnotjames commented 3 months ago

Possible related to https://github.com/sanic-org/sanic/issues/2600

imnotjames commented 3 months ago

Note that I was able to work around this by preventing all middleware from raising via..

def register_middleware(app, middleware, *args, **kwargs):
    async def wrapper(request, *mw_args, **mw_kwargs):
        try:
            return await middleware(request, *mw_args, **mw_kwargs)
        except Exception as e:
            response = app.error_handler.response(request, e)
            if iscoroutine(response):
                return await response
            return response

    app.register_middleware(wrapper, *args, **kwargs)

But that feels more like a hack than a solution

imnotjames commented 3 months ago

Maybe the code for running middleware should be similar to https://github.com/sanic-org/sanic/blob/main/sanic/app.py#L1223

ahopkins commented 3 months ago

I am not experiencing this:

>>> client.get("")
Middleware 1 ran
Middleware 2 ran
[2024-06-23 14:30:34 +0300] [1341151] [DEBUG] The client accepts */*, using 'html' from test.index
[2024-06-23 14:30:34 +0300] - (sanic.access)[INFO][127.0.0.1:54718]: GET http://127.0.0.1:9999/  500 16023
<Response [500 Internal Server Error]>
imnotjames commented 3 months ago

I am not experiencing this:

>>> client.get("")
Middleware 1 ran
Middleware 2 ran
[2024-06-23 14:30:34 +0300] [1341151] [DEBUG] The client accepts */*, using 'html' from test.index
[2024-06-23 14:30:34 +0300] - (sanic.access)[INFO][127.0.0.1:54718]: GET http://127.0.0.1:9999/  500 16023
<Response [500 Internal Server Error]>

How are you constructing client? I'm not super familiar with the sanic testing client but that kind of looks like you're doing a get against / with that which is a found route.

This only seems to exhibit when a route is not found.

Using the test client I seem to be able to exhibit the issue with:

from sanic import Sanic
from sanic.exceptions import SanicException
from sanic.response import html

app = Sanic(__name__)

@app.middleware("request")
def my_middleware1(request):
    print("Middleware 1 ran", flush=True)

@app.middleware("request")
def my_middleware2(request):
    print("Middleware 2 ran", flush=True)
    raise SanicException()

@app.get("/")
def index(request):
    return html("<p>hello world</p>")

if __name__ == "__main__":
    app.test_client.get("not-found")
$ python test.py

[2024-06-23 09:05:49 -0400] [45485] [INFO] 
  ┌──────────────────────────────────────────────────────────────────────────────────────────────────────┐
  │                                            Sanic v23.12.1                                            │
  │                                 Goin' Fast @ http://127.0.0.1:58325                                  │
  ├───────────────────────┬──────────────────────────────────────────────────────────────────────────────┤
  │                       │      app: __main__                                                           │
  │     ▄███ █████ ██     │     mode: production, single worker                                          │
  │    ██                 │   server: sanic, HTTP/1.1                                                    │
  │     ▀███████ ███▄     │   python: 3.11.9                                                             │
  │                 ██    │ platform: Linux-6.9.5-arch1-1-x86_64-with-glibc2.39                          │
  │    ████ ████████▀     │ packages: sanic-routing==23.12.0, sanic-testing==23.12.0, sanic-ext==23.12.0 │
  │                       │                                                                              │
  │ Build Fast. Run Fast. │                                                                              │
  └───────────────────────┴──────────────────────────────────────────────────────────────────────────────┘

[2024-06-23 09:05:49 -0400] [45485] [WARNING] Sanic is running in PRODUCTION mode. Consider using '--debug' or '--dev' while actively developing your application.

[2024-06-23 09:05:49 -0400] [45485] [INFO] Sanic Extensions:
[2024-06-23 09:05:49 -0400] [45485] [INFO]   > injection [0 dependencies; 0 constants]
[2024-06-23 09:05:49 -0400] [45485] [INFO]   > openapi [http://127.0.0.1:58325/docs]
[2024-06-23 09:05:49 -0400] [45485] [INFO]   > http 
[2024-06-23 09:05:49 -0400] [45485] [INFO]   > templating [jinja2==3.1.4]
[2024-06-23 09:05:49 -0400] [45485] [INFO] http://127.0.0.1:58325/not-found
Middleware 1 ran
Middleware 2 ran
Middleware 1 ran
Middleware 2 ran
[2024-06-23 09:05:49 -0400] [45485] [ERROR] Exception occurred while handling uri: 'http://127.0.0.1:58325/not-found'
Traceback (most recent call last):
  File "handle_request", line 39, in handle_request
    Iterable,

  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/router.py", line 75, in get
    return self._get(path, method, host)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/router.py", line 40, in _get
    raise NotFound(f"Requested URL {e.path} not found") from None
sanic.exceptions.NotFound: Requested URL /not-found not found

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/http/http1.py", line 119, in http1
    await self.protocol.request_handler(self.request)
  File "handle_request", line 158, in handle_request
    request_class (Optional[Type[Request]]): The request class to
  File "handle_exception", line 73, in handle_exception
    from sanic.http import Stage
                       ^^^^^^^^^^
  File "_run_request_middleware", line 17, in _run_request_middleware
    from asyncio.futures import Future
                       ^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/middleware.py", line 45, in __call__
    return self.func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/Projects/vidrovr/vrlib/test.py", line 14, in my_middleware2
    raise SanicException()
sanic.exceptions.SanicException: Internal Server Error

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/http/http1.py", line 423, in error_response
    await app.handle_exception(
  File "handle_exception", line 73, in handle_exception
    from sanic.http import Stage
                       ^^^^^^^^^^
  File "_run_request_middleware", line 17, in _run_request_middleware
    from asyncio.futures import Future
                       ^^^^^^^^^^^^^^^^
  File "/home/james/.local/share/pyenv/versions/3.11.9/envs/.venv/lib/python3.11/site-packages/sanic/middleware.py", line 45, in __call__
    return self.func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/james/Projects/vidrovr/vrlib/test.py", line 14, in my_middleware2
    raise SanicException()
sanic.exceptions.SanicException: Internal Server Error
[2024-06-23 09:05:49 -0400] [45485] [INFO] Starting worker [45485]
[2024-06-23 09:05:49 -0400] [45485] [INFO] Stopping worker [45485]
[2024-06-23 09:05:49 -0400] [45485] [INFO] Worker complete [45485]
[2024-06-23 09:05:49 -0400] [45485] [INFO] Server Stopped
ahopkins commented 3 months ago

It was with the REPL client.

looks like you're doing a get against / with that which is a found route.

Missed the part you were on a NotFound. Will look at this again before release.

imnotjames commented 3 months ago

Thanks! I applied that PRs patch locally and it seems to correct the issue here. :)