Creating Task API task sometimes fails with timeout

etam commented 4 years ago

Description

Golem Version: c1e5cf2f2

OS: Linux

Branch: b0.23

Description of the issue:

Creating Task API sometimes fails with:

2020-04-23 18:19:34 ERROR    golem.task.requestedtaskmanager     Failed to shut down client. app_id='6b39331ac73484ff596447cefdfba9e5'
Traceback (most recent call last):
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 301, in _task_creation_ctx
    await async_generator.yield_()
  File "/home/etam/code/github/golemfactory/golem/b0.23/venv/lib/python3.6/site-packages/async_generator/_impl.py", line 106, in yield_
    return await _yield_(value)
  File "/home/etam/code/github/golemfactory/golem/b0.23/venv/lib/python3.6/site-packages/async_generator/_impl.py", line 99, in _yield_
    return (yield _wrap(value))
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 264, in init_task
    await self._init_task(task_id)
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 280, in _init_task
    app_client = await self._get_app_client(task.app_id)
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 825, in _get_app_client
    self._app_clients[app_id] = await RequestorAppClient.create(service)
  File "/home/etam/code/github/golemfactory/golem/b0.23/venv/lib/python3.6/site-packages/golem_task_api/client.py", line 204, in create
    ssl_context)
  File "/home/etam/code/github/golemfactory/golem/b0.23/venv/lib/python3.6/site-packages/golem_task_api/client.py", line 133, in open_channel
    ssl_context=ssl_context)
  File "/home/etam/code/github/golemfactory/golem/b0.23/venv/lib/python3.6/site-packages/golem_task_api/client.py", line 82, in _wait_for_channel
    raise TimeoutError
TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 314, in _task_creation_ctx
    await self._shutdown_app_client(app_id)
  File "/home/etam/code/github/golemfactory/golem/b0.23/golem/task/requestedtaskmanager.py", line 977, in _shutdown_app_client
    await self._app_clients[app_id].shutdown()
KeyError: '6b39331ac73484ff596447cefdfba9e5'

Actual result:

Task is not being processed further

Steps To Reproduce

Run golem.task_api integration test.

Expected behavior

It should work. I see no good reason for it to timeout.

Logs and any additional context

golem.log

maaktweluit commented 4 years ago

Checked the logs and see 2 things:

there is a benchmark running, maybe this blocks the task-api task from starting
The timeout is on starting the blenderapp server, could you also provide the logs from this server? /home/etam/code/github/golemfactory/golem/b0.23/.requestor/rinkeby/logs/docker_cpu/984f46bfbd72d4404884c094d2a1dde7f846fcd5e6ef186d1ac5927b2ebeacdb_stdout.txt and ..._stderr.txt

etam commented 4 years ago

It's my laptop, running integration tests. I wiped logs and it's not reproducing right now. I'll upload those logs if it happens again.

golemfactory / clay