Sanic: WARNING: Executing Handle TaskSendMethWrapper

[seanpar203]

I'm noticing some strange behaviour when using SQLAlchemy orm for database queries instead of SQLAlchemy core.

Both approaches are using a context manager to manage cleaning up the session.

@contextmanager
def scoped_session():
    session = Session()
    try:
        yield session
        session.commit()
    except:
        session.rollback()
        raise
    finally:
        session.close()

Below is a post method which creates a user using the Core insert.

``py async def post(self, request): """ Creates a new user based on theemail` key

    Args:
        request (object): contains data pertaining request.

    Returns:
        json: containing key `msg` with success info & email.
    """
    # Grab request data.
    email = request.json.get('email')
    password = request.json.get('password')

    with scoped_session() as session:
        # Create Stmt.
        stmt = User.__table__.insert()
        user = {
            'email': email,
            'password': password,
            'auth_token': uuid4()
        }

        # Add to session.
        session.execute(stmt, user)

    # Return json response.
    return json({'msg': f'Successfully created {email}'})

Execution Time: I received a success response back in **34ms**.
``` bash
http :8000/api/user email='[email protected]' pass='pass1234'  0.25s user 0.03s system 97% cpu 0.287 total

Below is the same post method using the SQLAlchemy ORM insert.

    async def post(self, request):
        """ Creates a new user based on the `email` key

        Args:
            request (object): contains data pertaining request.

        Returns:
            json: containing key `msg` with success info & email.
        """
        # Grab request data.
        email = request.json.get('email')
        password = request.json.get('password')

        with scoped_session() as session:
            # Create user.
            user = User(email, password)
            session.add(user)

        # Return json response.
        return json({'msg': f'Successfully created {email}'})

Execution Time: I received a success response back in 272ms.

http :8000/api/user email='[email protected]' password='pass1234'  0.26s user 0.03s system 43% cpu 0.663 total

A strange debug error shows in the Sanic log:

I've searched my the entire project and all dependencies and couldn't find a class called TaskSendMethWrapper, I'm unsure why this is only a issue with the orm and not the core.

2016-12-28 11:48:00,520: WARNING: Executing <Handle <TaskSendMethWrapper object at 0x103b76c88> created at /Users/Admin/development/funharvest_sanic/venv/lib/python3.6/site-packages/sanic/server.py:144> took 0.265 seconds

The method at sanic/server.py line 144 is:

def on_message_complete(self):
        self._request_handler_task = self.loop.create_task(
            self.request_handler(self.request, self.write_response))

[seanpar203]

The TaskSendMethWrapper is part of the CPython asyncio module, I don't know why it's having an issue with SQLAlchemy orm and not the core. Although most Python users pair SQLAlchemy together with a micro framework. Maybe there's some steps we can take to get SQLAlchemy working great with Sanic, I'll look into it some more.

[seanpar203]

I must've had some weird local environmental issues because this isn't happening anymore.

[jackfischer]

In case anyone else is looking at this, I am also experiencing this fairly consistently using ordinary peewee ORM

[mike-hart]

Also getting a fair few of these. I'm using aiohttp to make a GET request within a view, not sure if related:
A number of WARNING Executing <Handle <TaskSendMethWrapper object at 0x7ff12fcb4668> created at /usr/lib/python3.6/site-packages/sanic/server.py:185> took 0.125 seconds and some Executing <Handle <TaskWakeupMethWrapper object at 0x7ff13011d978> created at /usr/lib/python3.6/site-packages/aiohttp/streams.py:469> took 0.127 seconds

14 total warnings from 1000 requests (just threw apache bench at it with concurrency 20 and 1000 requests), Sanic 0.5.4

[garyo]

I'm getting these too -- I'm using SQLAlchemy, but not sure if or how it's related. Even while the server is basically idle I get some simple websocket asyncio processing taking 0.8 sec when it should be instant (<1ms).
I don't see them always, more on one test Mac -- not sure how to debug.

[ramSeraph]

Seeing the same with aioredis, could this be related to GC?
https://bugs.python.org/issue33115