Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
1 task done
imnotjames opened this issue Jun 2, 2024 · 7 comments · May be fixed by #2971
Open
1 task done

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

imnotjames opened this issue Jun 2, 2024 · 7 comments · May be fixed by #2971
Labels

Comments

@imnotjames
Copy link

imnotjames commented Jun 2, 2024

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

@imnotjames imnotjames added the bug label Jun 2, 2024
@imnotjames
Copy link
Author

imnotjames commented Jun 2, 2024

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
Copy link
Author

Possible related to #2600

@imnotjames
Copy link
Author

imnotjames commented Jun 2, 2024

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
Copy link
Author

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

@ahopkins
Copy link
Member

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
Copy link
Author

imnotjames commented Jun 23, 2024

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
Copy link
Member

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.

@ahopkins ahopkins linked a pull request Jun 25, 2024 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants