Middleware Runs Twice if Route Not Found + Middleware Exception

Question

Middleware Runs Twice if Route Not Found + Middleware Exception

imnotjames opened this issue 8 months ago · 8 comments

imnotjames commented 8 months ago

Is there an existing issue for this?

I have searched the existing issues

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

Answer 1 · 2024-06-02T18:41:00.000Z

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

Answer 2 · 2024-06-02T18:42:27.000Z

Possible related to #2600

Answer 3 · 2024-06-02T20:20:58.000Z

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

Answer 4 · 2024-06-03T04:50:44.000Z

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

Answer 5 · 2024-06-23T11:31:12.000Z

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]>

Answer 6 · 2024-06-23T12:42:40.000Z

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

Answer 7 · 2024-06-23T17:09:09.000Z

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.

Answer 8 · 2024-06-30T14:48:33.000Z

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