search

leporo / tornado-redis

Asynchronous Redis client that works within Tornado IO loop.
666 stars 162 forks source link

Disconnecting from Redis while receiving data can lead to deadlocks #59

Open apolloFER opened 10 years ago

apolloFER commented 10 years ago

Issue: Tornado server no longer responds to HTTP requests.

Backtracking: Debugged the Tornado process with gdb. Managed to backtrace the code to a mutex deadlock in IOLoop's addCallback. It happens when a Redis command receives the response (in my case a BLPOP) and adds the callback to the ioloop. During the partial wrapping in the IOLoop's addCallback method the Tornado-Redis client becomes deleted (del is called) which disconnects the Connection object. The disconnected Connection object then tries to add another callback to IOLoop. Since addCallback has been called already, the mutex is locked. The second call to addCallback stops indefinitely at the Mutex. I have provided the following gdb backtrack:

#5 Frame 0x17d4e50, for file /usr/local/lib/python2.7/dist-packages/tornado/ioloop.py, line 714, in add_callback (self=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader=<file at remote 0x15d2390>) at remote 0x15ead90>, _stopped=False, _...(truncated)
    with self._callback_lock:
#9 Frame 0x17f73f0, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 369, in _run_callback (self=<IOStream(_write_buffer=<collections.deque at remote 0x19bee50>, _close_callback=None, _pending_callbacks=1, _read_bytes=None, _closed=True, _write_callback=None, _state=None, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lo...(truncated)
    self.io_loop.add_callback(wrapper)
#13 Frame 0x16e1360, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 266, in _maybe_run_close_callback (self=<IOStream(_write_buffer=<collections.deque at remote 0x19bee50>, _close_callback=None, _pending_callbacks=1, _read_bytes=None, _closed=True, _write_callback=None, _state=None, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_loc...(truncated)
    self._run_callback(cb)
#17 Frame 0x16e0810, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 257, in close (self=<IOStream(_write_buffer=<collections.deque at remote 0x19bee50>, _close_callback=None, _pending_callbacks=1, _read_bytes=None, _closed=True, _write_callback=None, _state=None, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at re...(truncated)
    self._maybe_run_close_callback()
#21 (frame information optimized out)
#24 Frame 0x181ef80, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/client.py, line 243, in __del__ (self=<Client(_pipeline=None, selected_db=0, subscribed=set([]), _io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader...(truncated)
    connection.disconnect()
#44 Frame 0x16473f0, for file /usr/local/lib/python2.7/dist-packages/tornado/ioloop.py, line 719, in add_callback (self=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader=<file at remote 0x15d2390>) at remote 0x15ead90>, _stopped=False, _...(truncated)
    stack_context.wrap(callback), *args, **kwargs))
#48 Frame 0x16470b0, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 369, in _run_callback (self=<IOStream(_write_buffer=<collections.deque at remote 0x19b8280>, _close_callback=<function at remote 0x19adb18>, _pending_callbacks=1, _read_bytes=None, _closed=False, _write_callback=None, _state=25, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, ...(truncated)
    self.io_loop.add_callback(wrapper)
#52 Frame 0x16d60a0, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 569, in _handle_write (self=<IOStream(_write_buffer=<collections.deque at remote 0x19b8280>, _close_callback=<function at remote 0x19adb18>, _pending_callbacks=1, _read_bytes=None, _closed=False, _write_callback=None, _state=25, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, ...(truncated)
    self._run_callback(callback)
#56 Frame 0x16d5b70, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 220, in write (self=<IOStream(_write_buffer=<collections.deque at remote 0x19b8280>, _close_callback=<function at remote 0x19adb18>, _pending_callbacks=1, _read_bytes=None, _closed=False, _write_callback=None, _state=25, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callbac...(truncated)
    self._handle_write()
#60 Frame 0x16d5e90, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/connection.py, line 124, in write (self=<Connection(info={'db': 0, 'pass': None}, _event_handler=<weakproxy at remote 0x1a546d8>, _stream=<IOStream(_write_buffer=<collections.deque at remote 0x19b8280>, _close_callback=<function at remote 0x19adb18>, _pending_callbacks=1, _read_bytes=None, _closed=False, _write_callback=None, _state=25, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 2...(truncated)
    self._stream.write(data, callback=cb)
#65 Frame 0x1a0aa70, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 371, in start (self=<Task(runner=<Runner(pending_callbacks=set([<object at remote 0x7fbcb309f9c0>]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1cf8>, gen=<generator at remote 0x1a55140>, yield_point=<...>) at remote 0x19b6bd0>, args=('*3\r\n$5\r\nBLPOP\r\n$24\r\na_redis_key\r\n$1\r\n0\r\n',), key=<object at remote 0x7fbcb309f9c0>, func=<instancemethod at remote 0x19abf50>, kwargs={'callback': <function at remote 0x1a561b8>}) at remote 0x1a50190>, runner=<...>)
    self.func(*self.args, **self.kwargs)
#69 Frame 0x19e4d20, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 533, in run (self=<Runner(pending_callbacks=set([<object at remote 0x7fbcb309f9c0>]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1cf8>, gen=<generator at remote 0x1a55140>, yield_point=<Task(runner=<...>, args=('*3\r\n$5\r\nBLPOP\r\n$24\r\na_redis_key\r\n$1\r\n0\r\n',), key=<object at remote 0x7fbcb309f9c0>, func=<instancemethod at remote 0x19abf50>, kwargs={'callback': <function at remote 0x1a561b8>}) at remote 0x1a50190>) at remote 0x19b6bd0>, next=None, yielded=<...>)
    self.yield_point.start(self)
#73 Frame 0x1907e50, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 153, in wrapper (args=(<weakproxy at remote 0x1a546d8>, 'BLPOP', 'a_redis_key', 0), kwargs={'callback': <function at remote 0x19a1f50>}, handle_exception=<function at remote 0x19a1488>, result=<generator at remote 0x1a55140>, final_callback=<function at remote 0x19a1cf8>)
    runner.run()
#80 Frame 0x16d2400, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/client.py, line 734, in blpop (self=<weakproxy at remote 0x1a546d8>, keys='a_redis_key', timeout=0, callback=<function at remote 0x19a1f50>, tokens=['a_redis_key', 0])
    self.execute_command('BLPOP', *tokens, callback=callback)
#87 Frame 0x17aae50, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 371, in start (self=<Task(runner=<Runner(pending_callbacks=set([<object at remote 0x7fbcb309f970>]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19add70>, gen=<generator at remote 0x19abd70>, yield_point=<...>) at remote 0x19b6190>, args=('a_redis_key',), key=<object at remote 0x7fbcb309f970>, func=<functools.partial at remote 0x1a54628>, kwargs={'callback': <function at remote 0x19a1f50>}) at remote 0x19b6510>, runner=<...>)
    self.func(*self.args, **self.kwargs)
#91 Frame 0x195cb80, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 533, in run (self=<Runner(pending_callbacks=set([<object at remote 0x7fbcb309f970>]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19add70>, gen=<generator at remote 0x19abd70>, yield_point=<Task(runner=<...>, args=('a_redis_key',), key=<object at remote 0x7fbcb309f970>, func=<functools.partial at remote 0x1a54628>, kwargs={'callback': <function at remote 0x19a1f50>}) at remote 0x19b6510>) at remote 0x19b6190>, next={u'a_redis_key': u'redis_response_data'}, yielded=<...>)
    self.yield_point.start(self)
#95 Frame 0x196ef50, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 476, in set_result (self=<Runner(pending_callbacks=set([<object at remote 0x7fbcb309f970>]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19add70>, gen=<generator at remote 0x19abd70>, yield_point=<Task(runner=<...>, args=('a_redis_key',), key=<object at remote 0x7fbcb309f970>, func=<functools.partial at remote 0x1a54628>, kwargs={'callback': <function at remote 0x19a1f50>}) at remote 0x19b6510>) at remote 0x19b6190>, key=<object at remote 0x7fbcb309fa40>, result={u'a_redis_key': u'redis_response_data'})
    self.run()
#99 Frame 0x19ddb30, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 550, in inner (args=({u'a_redis_key': u'redis_response_data'},), kwargs={}, result={...})
    self.set_result(key, result)
#104 Frame 0x192bfb0, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=({u'a_redis_key': u'redis_response_data'},), kwargs={}, ret=None, current_state=((), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), None), exception_handler=<function at remote 0x19ad398>) at remote 0x19b6610>), exception_handler=<function at remote 0x19a10c8>) at remote 0x19b6a10>), contexts=((...), <...>), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#108 Frame 0x1a18370, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/client.py, line 433, in execute_command (self=<weakproxy at remote 0x1a546d8>, cmd='BLPOP', args=('a_redis_key', 0), kwargs={}, result={u'a_redis_key': u'redis_response_data'}, execute_pending=True, callback=<function at remote 0x19a1500>, cmd_line=<CmdLine(cmd='BLPOP', args=('a_redis_key', 0), kwargs={}) at remote 0x19b6e50>, n_tries=1, command='*3\r\n$5\r\nBLPOP\r\n$24\r\na_redis_key\r\n$1\r\n0\r\n', listening=set([]), data='*2\r\n', resp=[u'a_redis_key', u'redis_response_data'])
    callback(result)
#111 Frame 0x1a216f0, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 507, in run (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1758>, gen=<generator at remote 0x19abe60>, yield_point=None) at remote 0x19b6990>, next=[u'a_redis_key', u'redis_response_data'])
    yielded = self.gen.send(next)
#115 Frame 0x18ab510, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 476, in set_result (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1758>, gen=<generator at remote 0x19abe60>, yield_point=None) at remote 0x19b6990>, key=<object at remote 0x7fbcb309fa30>, result=[u'a_redis_key', u'redis_response_data'])
    self.run()
#119 Frame 0x1a9e970, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 550, in inner (args=([u'a_redis_key', u'redis_response_data'],), kwargs={}, result=[...])
    self.set_result(key, result)
#124 Frame 0x196f1c0, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=([u'a_redis_key', u'redis_response_data'],), kwargs={}, ret=None, current_state=((), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), None), exception_handler=<function at remote 0x19ad398>) at remote 0x19b6610>), exception_handler=<function at remote 0x19a10c8>) at remote 0x19b6a10>), exception_handler=<function at remote 0x19ad1b8>) at remote 0x19b6c10>), contexts=((...), <...>), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#128 Frame 0x18fc450, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/client.py, line 490, in consume_multibulk (self=<weakproxy at remote 0x1a546d8>, length=2, cmd_line=<CmdLine(cmd='BLPOP', args=('a_redis_key', 0), kwargs={}) at remote 0x19b6e50>, callback=<function at remote 0x19ad578>, tokens=[u'a_redis_key', u'redis_response_data'], data='$62\r\n', token=u'redis_response_data')
    callback(tokens)
#131 Frame 0x1914da0, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 507, in run (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1ed8>, gen=<generator at remote 0x1a550a0>, yield_point=None) at remote 0x19b65d0>, next=u'redis_response_data')
    yielded = self.gen.send(next)
#135 Frame 0x1915010, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 476, in set_result (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1ed8>, gen=<generator at remote 0x1a550a0>, yield_point=None) at remote 0x19b65d0>, key=<object at remote 0x7fbcb309f9f0>, result=u'redis_response_data')
    self.run()
#139 Frame 0x178f8e0, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 550, in inner (args=(u'redis_response_data',), kwargs={}, result=u'redis_response_data')
    self.set_result(key, result)
#144 Frame 0x19468b0, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=(u'redis_response_data',), kwargs={}, ret=None, current_state=((), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), None), exception_handler=<function at remote 0x19ad398>) at remote 0x19b6610>), exception_handler=<function at remote 0x19a10c8>) at remote 0x19b6a10>), exception_handler=<function at remote 0x19ad1b8>) at remote 0x19b6c10>), exception_handler=<function at remote 0x19a1d70>) at remote 0x19b6c90>), contexts=((...), <...>), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#148 Frame 0x16f5950, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/client.py, line 445, in _consume_bulk (self=<weakproxy at remote 0x1a546d8>, tail='62', callback=<function at remote 0x19a1e60>, response=u'redis_response_data')
    callback(response)
#151 Frame 0x195de10, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 507, in run (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1410>, gen=<generator at remote 0x1a55190>, yield_point=None) at remote 0x19b6dd0>, next='redis_response_data\r\n')
    yielded = self.gen.send(next)
#155 Frame 0x1a06c60, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 476, in set_result (self=<Runner(pending_callbacks=set([]), had_exception=False, finished=False, results={}, running=True, exc_info=None, final_callback=<function at remote 0x19a1410>, gen=<generator at remote 0x1a55190>, yield_point=None) at remote 0x19b6dd0>, key=<object at remote 0x7fbcb309f9e0>, result='redis_response_data\r\n')
    self.run()
#159 Frame 0x17dc140, for file /usr/local/lib/python2.7/dist-packages/tornado/gen.py, line 550, in inner (args=('redis_response_data\r\n',), kwargs={}, result='redis_response_data\r\n')
    self.set_result(key, result)
#164 Frame 0x19cf540, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=('redis_response_data\r\n',), kwargs={}, ret=None, current_state=((), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), None), exception_handler=<function at remote 0x19ad398>) at remote 0x19b6610>), exception_handler=<function at remote 0x19a10c8>) at remote 0x19b6a10>), exception_handler=<function at remote 0x19ad1b8>) at remote 0x19b6c10>), exception_handler=<function at remote 0x19a1d70>) at remote 0x19b6c90>), contexts=((...), <...>), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#169 Frame 0x195e080, for file /usr/local/lib/python2.7/dist-packages/tornadoredis/connection.py, line 148, in read_callback (self=<Connection(info={'db': 0, 'pass': None}, _event_handler=<weakproxy at remote 0x1a546d8>, _stream=<IOStream(_write_buffer=<collections.deque at remote 0x19b8280>, _close_callback=<function at remote 0x19adb18>, _pending_callbacks=1, _read_bytes=None, _closed=False, _write_callback=None, _state=25, max_buffer_size=104857600, io_loop=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b...(truncated)
    callback(*args, **kwargs)
#178 Frame 0x1a10280, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=('some_response_data',), kwargs={}, ret=None, current_state=((), None), contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), <ExceptionStackContext(active=True, new_contexts=None, old_contexts=((...), None), exception_handler=<function at remote 0x19ad398>) at remote 0x19b6610>), exception_handler=<function at remote 0x19a10c8>) at remote 0x19b6a10>), exception_handler=<function at remote 0x19ad1b8>) at remote 0x19b6c10>), exception_handler=<function at remote 0x19a1d70>) at remote 0x19b6c90>), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#183 Frame 0x1a0fc30, for file /usr/local/lib/python2.7/dist-packages/tornado/iostream.py, line 341, in wrapper ()
    callback(*args)
#188 Frame 0x1a108c0, for file /usr/local/lib/python2.7/dist-packages/tornado/stack_context.py, line 302, in wrapped (args=(), kwargs={}, ret=None, current_state=((...), None), contexts=((...), None), exc=(None, None, None), top=None, last_ctx=0, stack=(...))
    ret = fn(*args, **kwargs)
#196 Frame 0x17c5ae0, for file /usr/local/lib/python2.7/dist-packages/tornado/ioloop.py, line 458, in _run_callback (self=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader=<file at remote 0x15d2390>) at remote 0x15ead90>, _stopped=False, ...(truncated)
    callback()
#200 Frame 0x1648130, for file /usr/local/lib/python2.7/dist-packages/tornado/ioloop.py, line 607, in start (self=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader=<file at remote 0x15d2390>) at remote 0x15ead90>, _stopped=False, _closing...(truncated)
    self._run_callback(callback)
#204 Frame 0x1647f50, for file /usr/local/lib/python2.7/dist-packages/zmq/eventloop/ioloop.py, line 160, in start (self=<ZMQIOLoop(_impl=<ZMQPoller(_poller=<Poller(sockets=[(5, 5), (<Socket at remote 0x15f1598>, 4), (3, 5), (4, 5), (15, 5), (16, 5), (13, 5), (26, 5), (27, 5)], _map={3: 2, 4: 3, 5: 0, 13: 6, 15: 4, 16: 5, <...>: 1, 26: 7, 27: 8}) at remote 0x15eaa10>) at remote 0x15ea310>, _handlers={3: <function at remote 0x169cc80>, 4: <function at remote 0x169cd70>, 5: <function at remote 0x15ebc80>, 13: <function at remote 0x19ad7d0>, 15: <function at remote 0x16a2938>, 16: <function at remote 0x16a21b8>, <...>: <function at remote 0x15ebd70>, 26: <function at remote 0x19b20c8>, 27: <function at remote 0x19adc80>}, _running=True, _callbacks=[], _thread_ident=140448435238656, _callback_lock=<thread.lock at remote 0x13ad890>, _cancellations=3, _events={}, time_func=<built-in function time>, _waker=<Waker(writer=<file at remote 0x15d2420>, reader=<file at remote 0x15d2390>) at remote 0x15ead90>, _stopped=False, _c...(truncated)
    super(ZMQIOLoop, self).start()
#208 Frame 0x10f4270, for file /root/server.py, line 81, in <module> ()
    tornado.ioloop.IOLoop.instance().start()
maximebf commented 9 years ago

I'm having exactly the same issue which is very blocking for me. I used the same debugging method as apolloFER and I have the same stack trace

apolloFER commented 9 years ago

This issues has stopped appearing at our end. Don't know if some of the updates we did fixed it or if Tornado 4.0 solved the problem.

maximebf commented 9 years ago

I also managed to fix it. The project started on brukva and after migrating to tornado-redis, some changes in the unsubscribe callback triggered this error. However, it still shows a possible lock in the ioloop