Sanic: Sanic crashes when other asyncio tasks are running

[rudineirk]

Sanic version: 0.4.1
Python: 3.6.0
OS: Fedora Linux 25

I have an app were I have to start serving requests before the database (in this case MongoDB) connection fully started, replying with an adequate error message on requests. The problem is that sanic stops listening for tcp connections (the port closes), I don't know exactly what is causing it, but here is an example code that causes the problem:

import asyncio
import uvloop
from sanic import Sanic
from sanic.response import json
from motor.motor_asyncio import AsyncIOMotorClient
from pymongo.errors import CollectionInvalid, ServerSelectionTimeoutError

DB_NAME = 'testdb'
COLLECTION_NAME = 'testcoll'

asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

loop = asyncio.get_event_loop()
conn = AsyncIOMotorClient(
    host='127.0.0.1',
    port=27017,
    connectTimeoutMS=2000,
    serverSelectionTimeoutMS=5000,
)
db = conn['testdb']
collection = db['testcoll']

app = Sanic()


async def start_db():
    print('connecting to mongodb!')
    try:
        await db.create_collection(COLLECTION_NAME)
    except CollectionInvalid:
        pass
    except ServerSelectionTimeoutError:
        await asyncio.sleep(0.5)
        print('trying to connect to mongodb again...')
        loop.create_task(start_db())
        return

    # Indexes are supposed to be created here

    print('connected to mongodb!')


@app.route('/')
async def handler(request):
    data = await collection.find().to_list(None)
    return json(data)


def main():
    server = app.create_server(
        host='127.0.0.1',
        port=5000,
        debug=True,
        loop=loop,
    )
    loop.create_task(start_db())
    asyncio.ensure_future(server, loop=loop)

    # Start other asyncio things here
    loop.run_forever()


if __name__ == '__main__':
    main()

with sanic debug enabled, a warning about tcp server resource unclosed appear on the terminal:

connecting to mongodb!
~/.local/lib/python3.6/site-packages/sanic/app.py:524: DeprecationWarning: Passing a loop will be deprecated in version 0.4.0 https://github.com/channelcat/sanic/pull/335 has more information.
  DeprecationWarning)
2017-03-06 16:15:19,518: DEBUG:
sanic drawing here
2017-03-06 16:15:19,518: INFO: Goin' Fast @ http://127.0.0.1:5000
trying to connect to mongodb again...
/usr/lib64/python3.6/traceback.py:352: ResourceWarning: unclosed resource <TCPServer closed=False 0x7f7dcbf4b448>; object created at (most recent call last):
  File "example_sanic.py", line 64, in <module>
    main()
  File "example_sanic.py", line 60, in main
    loop.run_forever()
  File "~/.local/lib/python3.6/site-packages/sanic/app.py", line 509, in create_server
    return await serve(**server_settings)
  filename, lineno, name, lookup_line=False, locals=f_locals))
connecting to mongodb!
trying to connect to mongodb again...

EDIT: Forgot to mention, this error happens after the first mongo connection retry

[abuckenheimer]

I think your issue is similar too https://github.com/channelcat/sanic/issues/435, try using the 'before_server_start' hook to initialize your mongo client. An example shown with aiocache here https://github.com/channelcat/sanic/blob/master/examples/cache_example.py

[rudineirk]

I should have explained it better, this is not exactly my use case, I just created it as a minimal example that causes the same problem.

My use case is that I'm starting a amqp listener (and writer) in the same process as sanic. I don't need multiple workers, I want everything in one thread, I manage workers using docker swarm mode (I have load balancing on nginx).

The problem with the before_server_start hook is that it requires sanic to start everything. I think it's not very practical to do this, for example, if another framework takes the same approach as sanic and requires everything asyncio related to be started in it's hooks, how would I start both sanic and this framework on the same event loop?

[seemethere]

You'd start Sanic first and then use get_event_loop to get the currently running event loop? Is there a big issue with doing that? Also the hook only exists as a nice way for people to establish all the things there app needs. You don't necessarily have to use it since (with Python 3.6) get_event_loop gets the already running event loop.

[rudineirk]

It should'nt make any difference if you get the event loop before sanic start, but anyway, the error still happens because app.create_server does not execute anything before the loop starts (it is a coroutine). I changed the code to do what you said:

import asyncio
import uvloop
from sanic import Sanic
from sanic.response import json
from motor.motor_asyncio import AsyncIOMotorClient
from pymongo.errors import CollectionInvalid, ServerSelectionTimeoutError

DB_NAME = 'testdb'
COLLECTION_NAME = 'testcoll'

asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

conn = AsyncIOMotorClient(
    host='127.0.0.1',
    port=27017,
    connectTimeoutMS=2000,
    serverSelectionTimeoutMS=5000,
)
db = conn['testdb']
collection = db['testcoll']

app = Sanic()


async def start_db(loop):
    print('connecting to mongodb!')
    try:
        await db.create_collection(COLLECTION_NAME)
    except CollectionInvalid:
        pass
    except ServerSelectionTimeoutError:
        await asyncio.sleep(0.5)
        print('trying to connect to mongodb again...')
        loop.create_task(start_db(loop))
        return

    # Indexes are supposed to be created here

    print('connected to mongodb!')


@app.route('/')
async def handler(request):
    data = await collection.find().to_list(None)
    return json(data)


def main():
    server = app.create_server(
        host='127.0.0.1',
        port=5000,
        debug=True,
    )

    asyncio.ensure_future(server)
    loop = asyncio.get_event_loop()
    loop.create_task(start_db(loop))

    # Start other asyncio things here
    loop.run_forever()


if __name__ == '__main__':
    main()

The other option would be to run the app.run method, but this method is blocking, it runs the loop.run_forever method, so I can't get the event loop after that.

[abuckenheimer]

I'm still not entirely sure if this is what your looking for but there is some trickery with creating an event loop and using app.run() as app.run() always creates a It always creates a new loop here: https://github.com/channelcat/sanic/blob/master/sanic/server.py#L343 . I've constructed a minimal bug with the following

from sanic import Sanic
from sanic.response import text
import uvloop
import asyncio

class ChattyPolicy(uvloop.EventLoopPolicy):
    def get_event_loop(self):
        loop = super().get_event_loop()
        print('getting event loop {}'.format(id(loop)))
        return loop

    def set_event_loop(self, loop):
        super().set_event_loop(loop)
        print('setting event loop {}'.format(id(loop)))

    def new_event_loop(self):
        loop = super().new_event_loop()
        print('new event loop {}'.format(id(loop)))
        return loop

asyncio.set_event_loop_policy(ChattyPolicy())
app = Sanic()
loop = asyncio.get_event_loop()

async def initalizer():
    return 'initalized'

f = asyncio.ensure_future(initalizer())

@app.route('/')
async def root(request):
    print(await f)
    return text('hello world')

if __name__ == '__main__':
    app.run(host="0.0.0.0", port=8000, loop=loop)

try using the ChattyPolicy to see if that shows you more than one id. For example I get the following output

new event loop 12603544
setting event loop 12603544
getting event loop 12603544
getting event loop 12603544
getting event loop 12603544
2017-03-07 13:12:57,593: INFO: Goin' Fast @ http://0.0.0.0:8000
setting event loop 12869464
2017-03-07 13:12:57,596: INFO: Starting worker [3451]
2017-03-07 13:13:00,328: ERROR: Traceback (most recent call last):
  File "path/to/sanic.py", line 329, in handle_request
    response = await response
  File "i_test.py", line 34, in root
    print(await f)
  File "uvloop/future.pyx", line 241, in __await__ (uvloop/loop.c:104128)
RuntimeError: Task <Task pending coro=<Sanic.handle_request() running at /path/to/sanic.py:329>> got Future <Task pending coro=<initalizer() running at i_test.py:27>> attached to a different loop
2017-03-07 13:14:00,328: ERROR: NoneType

I start with event loop 12603544 but then app.run() creates loop 12869464

[rudineirk]

Yes, I'm aware that using app.run always create a new event loop, that is why I'm using the app.create_server method. The problem is that after the ResourceWarning error message sanic stops listening on the port, this only happens when there are other tasks running in the same event loop.

Running the last example I gave with @abuckenheimer custom event loop policy, it seems that only one event loop is being created. I got the following log running it:

new event loop 93971158371896
setting event loop 93971158371896
getting event loop 93971158371896
getting event loop 93971158371896
getting event loop 93971158371896
~/.local/lib/python3.6/site-packages/sanic/app.py:524: DeprecationWarning: Passing a loop will be deprecated in version 0.4.0 https://github.com/channelcat/sanic/pull/335 has more information.
  DeprecationWarning)
2017-03-07 15:24:34,720: DEBUG:
sanic logo
2017-03-07 15:24:34,720: INFO: Goin' Fast @ http://127.0.0.1:5000
connecting to mongodb!
~/.local/lib/python3.6/tokenize.py:381: ResourceWarning: unclosed resource <TCPServer closed=False 0x7fefeb0e24c8>; object created at (most recent call last):
  File "example_sanic.py", line 83, in <module>
    main()
  File "example_sanic.py", line 79, in main
    loop.run_forever()
  File "~/.local/lib/python3.6/site-packages/sanic/app.py", line 509, in create_server
    return await serve(**server_settings)
  return readline()
trying to connect to mongodb again...
connecting to mongodb!
trying to connect to mongodb again...
connecting to mongodb!

[abuckenheimer]

You are right! I'm debugging the wrong problem. will look into this

[nszceta]

I suggest you give my approach a shot and please give me feedback.

My method does not allow for multiprocessing but this is no problem for production purposes as you will want to start multiple independent Python interpreter instances using a supervisor such as supervisord

https://gist.github.com/nszceta/087a14d8896e47bc6e7e441fd60b6ff4

[rudineirk]

After some testing, I discovered that the problem is not related to sanic code, the same problem also happened with a similar code using aiohttp. The one causing this bug is the uvloop module, removing the line below fixes the problem (it makes the process run with the default python event loop).

asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

I created an issue on the uvloop project to track this error MagicStack/uvloop#81

[nszceta]

@r0fls can we close this issue?

[r0fls]

Thanks @nszceta. Closing, will reopen if needed.