Sanic 22.9.1 entered into the request middlewire twice when response timeout

[floydljy]

Is there an existing issue for this?

• [X] I have searched the existing issues

Describe the bug

I'm trying to do perforamance test for our apps about new Sanic version v22.9.1 (old version is 22.6.0) During performance testing ,my handler code is slow as expected, and my response time for sanic is 60 seconds

Normally, it will return a "response timeout error" to the client, and we test the 22.6.0, and everything works as designe. But after upgrade to 22.9.1(The only change for the code), we see a new err which should be the failure inside one of our blueprint request middlewire. Normally the code will only run once. but in the new version, we see the function was called twice, and the interval between the two calls is longger than response timeout setting.

It's very easy to repeat the situation. seems like sanic change involve this.

Code snippet

from sanic import Blueprint, Sanic
from sanic.request import Request
from sanic.response import HTTPResponse
from sanic.response import text


class AsyncNorthHandler():
    FUNCCOUNT = 0

async def http_handler(request):
    print("handling the request")
    await asyncio.sleep(100)
    return text('ok')

bp = Blueprint("async_north")
bp.add_route(http_handler, '/', methods=['GET'], name='handler')

@bp.middleware("request")
async def set_req_header(request):
    request: Request        
    AsyncNorthHandler.FUNCCOUNT = AsyncNorthHandler.FUNCCOUNT + 1
    print("enter the function {} time".format(AsyncNorthHandler.FUNCCOUNT))


app = Sanic("TEST")
app.blueprint(bp)
app.run(host='0.0.0.0', port=8888)

Expected Behavior

entery the reqeust middlewire 1 time every request

How do you run Sanic?

As a module

Operating System

linux

Sanic Version

22.9.1

Additional context

No response

[ahopkins]

Confirmed this. I think the fix should be simple and is related specifically to the response timeout.

            request_middleware = not isinstance(exception, ServiceUnavailable)
            try:
                await app.handle_exception(
                    self.request, exception, request_middleware
                )

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

Will need to look closer at the logic to make sure there are not other use cases being impacted.

[GabrielCappelli]

Hi @ahopkins, I'm afraid I still see this issue on 22.12.0

This is my info from sanic startup:

Sanic v22.12.0
mode: production, single worker
server: sanic, HTTP/1.1
python: 3.10.9
platform: Linux-5.15.83.1-microsoft-standard-WSL2-x86_64-with-glibc2.31
packages: sanic-routing==22.8.0

This is the client I am using to test:

import asyncio

import aiohttp

TIMEOUT_SECONDS = 1

async def main():
    async with aiohttp.ClientSession(timeout=aiohttp.ClientTimeout(total=TIMEOUT_SECONDS)) as session:
        try:
            async with session.get('http://localhost:8888/') as resp:
                response = await resp.text()
                print(response)
        except asyncio.TimeoutError:
            print(f"The request timed out after {TIMEOUT_SECONDS} seconds")

if __name__ == "__main__":
    asyncio.run(main())

Using curl and doing control + c also works to reproduce the issue.

[GabrielCappelli]

@ahopkins I have added a breakpoint to this line https://github.com/sanic-org/sanic/pull/2615/files#diff-6deec8643e3c922c89e98687d5149d00e86c2b8a051fa5cf47f8ae80c4999ddfR432

The exception that's reaching that line is RequestCancelled