Error while releasing lock

[vineetgoel]

Saw this issue in one of the production boxes. This is not reproducible.

[2018-05-09 13:51:45,694: INFO]: [^--Consumer]: Waiting for lock to pause partitions
[2018-05-09 13:51:45,694: INFO]: [^--Consumer]: Acquired lock to pause partitions
[2018-05-09 13:51:45,694: INFO]: [^--Consumer]: Released pause partitions lock
[2018-05-09 13:51:45,694: INFO]: [^--Fetcher]: Starting...
[2018-05-09 13:51:45,695: INFO]: [^-App]: Restarted fetcher
[2018-05-09 13:51:45,696: INFO]: [^--TableManager]: Triggered recovery in background
[2018-05-09 13:51:45,697: INFO]: [^--TableManager]: New assignments found
[2018-05-09 13:51:45,697: INFO]: [^--Consumer]: Waiting for lock to pause partitions
[2018-05-09 13:51:45,697: INFO]: [^--Consumer]: Acquired lock to pause partitions
[2018-05-09 13:51:45,697: INFO]: [^--Consumer]: Released pause partitions lock
[2018-05-09 13:51:45,698: INFO]: [^--TableManager]: Restoring state from changelog topics...
[2018-05-09 13:51:45,698: INFO]: [^--TableManager]: Waiting for restore to finish...
[2018-05-09 13:51:45,698: INFO]: [^--TableManager]: Done reading all changelogs
[2018-05-09 13:51:45,698: INFO]: [^--TableManager]: Done reading from changelog topics
[2018-05-09 13:51:45,699: INFO]: [^--TableManager]: Stopped restoring
[2018-05-09 13:51:45,699: INFO]: [^--TableManager]: Restore complete!
[2018-05-09 13:51:45,706: INFO]: [^--TableManager]: Attempting to start standbys
[2018-05-09 13:51:45,706: INFO]: [^--TableManager]: New assignments handled
[2018-05-09 13:51:45,706: INFO]: [^--Consumer]: Waiting for lock to resume partitions
[2018-05-09 13:51:45,707: INFO]: [^--Consumer]: Acquired lock to resume partitions
[2018-05-09 13:51:45,707: INFO]: [^--Consumer]: Released resume partitions lock
[2018-05-09 13:51:45,729: ERROR]: Unexpected error in fetcher routine
Traceback (most recent call last):
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/consumer/fetcher.py", line 328, in _fetch_requests_routine
    yield from task
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/consumer/fetcher.py", line 624, in _update_fetch_positions
    node_id, topic_data)
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/consumer/fetcher.py", line 747, in _proc_offset_request
    response = yield from self._client.send(node_id, request)
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/client.py", line 403, in send
    if not (yield from self.ready(node_id, group=group)):
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/client.py", line 381, in ready
    conn = yield from self._get_conn(node_id, group=group)
  File "/home/robinhood/env/lib/python3.6/site-packages/aiokafka/client.py", line 369, in _get_conn
    max_idle_ms=self._connections_max_idle_ms)
  File "/home/robinhood/python-3.6.3/lib/python3.6/asyncio/locks.py", line 38, in __exit__
    self._lock.release()
  File "/home/robinhood/python-3.6.3/lib/python3.6/asyncio/locks.py", line 201, in release
    raise RuntimeError('Lock is not acquired.')
RuntimeError: Lock is not acquired.

Retarting the app worked.

[vineetgoel]

This was an aiokafka issue. We now close the fetcher upon this issue ("Unexpected error in fetcher routine") and handle that case in Faust.