Restarting the daemon excepts all jobs (aiida-core 1.6, python 3.7)

[giovannipizzi]

Edit: this issue only occurs in python 3.7, so unitl the issue is fuly resolved, a "fix" is to upgrade to python 3.8

---

Steps to reproduce

Steps to reproduce the behavior:

1. Submit a job to the daemon
2. Start the daemon, if not already running
3. Stop or restart the daemon

Expected behavior

The daemon stops in a reasonably short time, and the job is "frozen" and will safely continue when the daemon restarts.

Actual problematic behaviour

Instead, when stopping and/or restarting the deamon, I get a TIMEOUT.
Then, I get things like this from verdi process list:

  PK  Created    Process label    Process State    Process status
----  ---------  ---------------  ---------------  -------------------------------------
 184  20h ago    PwCalculation    ⨯ Excepted       Transport task update was interrupted
 189  1h ago     PwCalculation    ⨯ Excepted       Transport task submit was interrupted

and verdi process report shows this:

$ verdi process report 184
*** 184: None
*** Scheduler output: N/A
*** Scheduler errors: N/A
*** 3 LOG MESSAGES:
+-> ERROR at 2021-01-08 18:53:56.557646+00:00
 | Traceback (most recent call last):
 |   File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 171, in exponential_backoff_retry
 |     result = await coro()
 |   File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 177, in do_update
 |     job_info = await cancellable.with_interrupt(update_request)
 |   File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 87, in with_interrupt
 |     result = await next(wait_iter)
 |   File "/usr/lib/python3.7/asyncio/tasks.py", line 560, in _wait_for_one
 |     return f.result()  # May raise f.exception().
 | concurrent.futures._base.CancelledError
+-> REPORT at 2021-01-08 18:53:36.744091+00:00
 | [184|PwCalculation|on_except]: Traceback (most recent call last):
 |   File "/home/pizzi/.virtualenvs/aiida-dev/lib/python3.7/site-packages/plumpy/processes.py", line 1072, in step
 |     next_state = await self._run_task(self._state.execute)
 |   File "/home/pizzi/.virtualenvs/aiida-dev/lib/python3.7/site-packages/plumpy/processes.py", line 498, in _run_task
 |     result = await coro(*args, **kwargs)
 |   File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 358, in execute
 |     job_done = await self._launch_task(task_update_job, node, self.process.runner.job_manager)
 |   File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 394, in _launch_task
 |     result = await self._task
 |   File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
 |     future.result()
 | concurrent.futures._base.CancelledError
+-> ERROR at 2021-01-08 18:53:36.535279+00:00
 | Traceback (most recent call last):
 |   File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 171, in exponential_backoff_retry
 |     result = await coro()
 |   File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 177, in do_update
 |     job_info = await cancellable.with_interrupt(update_request)
 |   File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 87, in with_interrupt
 |     result = await next(wait_iter)
 |   File "/usr/lib/python3.7/asyncio/tasks.py", line 556, in _wait_for_one
 |     f = await done.get()
 |   File "/usr/lib/python3.7/asyncio/queues.py", line 159, in get
 |     await getter
 |   File "/usr/lib/python3.7/asyncio/futures.py", line 263, in __await__
 |     yield self  # This tells Task to wait for completion.
 |   File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
 |     future.result()
 |   File "/usr/lib/python3.7/asyncio/futures.py", line 176, in result
 |     raise CancelledError
 | concurrent.futures._base.CancelledError

Further notes

I think this is actually the main problem that also manifested itself in #4595 and #4345

I think that many interruptions that should be "safe" are instead considered exceptions (here in the specific case of stopping the daemon, but also in other cases like SSH errors like maybe in #4345).

@muhrin @sphuber @unkcpz @chrisjsewell

[unkcpz]

thanks for the report! I encounter the timeout problem but not the process except. In you case, will the issue reproduce if you exchange the step 1 and 2, means you submit the process after daemon start? I have a feeling this issue is related to the code of closing all running  Tasks when calling daemon stop. I?ll check it next week. On Sat, Jan 9, 2021 at 23:31 Giovanni Pizzi <notifications@github.com> wrote: Steps to reproduce Steps to reproduce the behavior: Submit a job to the daemonStart the daemon, if not already runningStop or restart the daemon Expected behavior The daemon stops in a reasonably short time, and the job is "frozen" and will safely continue when the daemon restarts. Actual problematic behaviour Instead, when stopping and/or restarting the deamon, I get a TIMEOUT. Then, I get things like this from verdi process list: PK Created Process label Process State Process status

…

---- --------- --------------- --------------- ------------------------------------- 184 20h ago PwCalculation ? Excepted Transport task update was interrupted 189 1h ago PwCalculation ? Excepted Transport task submit was interrupted and verdi process report shows this: $ verdi process report 184 *** 184: None *** Scheduler output: N/A *** Scheduler errors: N/A *** 3 LOG MESSAGES: +-> ERROR at 2021-01-08 18:53:56.557646+00:00 | Traceback (most recent call last): | File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 171, in exponential_backoff_retry | result = await coro() | File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 177, in do_update | job_info = await cancellable.with_interrupt(update_request) | File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 87, in with_interrupt | result = await next(wait_iter) | File "/usr/lib/python3.7/asyncio/tasks.py", line 560, in _wait_for_one | return f.result() # May raise f.exception(). | concurrent.futures._base.CancelledError +-> REPORT at 2021-01-08 18:53:36.744091+00:00 | [184|PwCalculation|on_except]: Traceback (most recent call last): | File "/home/pizzi/.virtualenvs/aiida-dev/lib/python3.7/site-packages/plumpy/processes.py", line 1072, in step | next_state = await self._run_task(self._state.execute) | File "/home/pizzi/.virtualenvs/aiida-dev/lib/python3.7/site-packages/plumpy/processes.py", line 498, in _run_task | result = await coro(*args, **kwargs) | File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 358, in execute | job_done = await self._launch_task(task_update_job, node, self.process.runner.job_manager) | File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 394, in _launch_task | result = await self._task | File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup | future.result() | concurrent.futures._base.CancelledError +-> ERROR at 2021-01-08 18:53:36.535279+00:00 | Traceback (most recent call last): | File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 171, in exponential_backoff_retry | result = await coro() | File "/home/pizzi/git/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 177, in do_update | job_info = await cancellable.with_interrupt(update_request) | File "/home/pizzi/git/aiida-core/aiida/engine/utils.py", line 87, in with_interrupt | result = await next(wait_iter) | File "/usr/lib/python3.7/asyncio/tasks.py", line 556, in _wait_for_one | f = await done.get() | File "/usr/lib/python3.7/asyncio/queues.py", line 159, in get | await getter | File "/usr/lib/python3.7/asyncio/futures.py", line 263, in __await__ | yield self # This tells Task to wait for completion. | File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup | future.result() | File "/usr/lib/python3.7/asyncio/futures.py", line 176, in result | raise CancelledError | concurrent.futures._base.CancelledError Further notes I think this is actually the main problem that also manifested itself in #4595 and #4345 I think that many interruptions that should be "safe" are instead considered exceptions (here in the specific case of stopping the daemon, but also in other cases like SSH errors like maybe in #4345). @muhrin @sphuber @unkcpz @chrisjsewell ?You are receiving this because you were mentioned.Reply to this email directly, view it on GitHub, or unsubscribe.

[giovannipizzi]

Hi @unkcpz - yes, the calculation crashed in my case also if it the daemon was already running. If you run the daemon after submitting, instead, it picks up correctly the job.
So I agree with you this is something happening when trying to pause the job. My guess is that the exception might be thrown, but if it originates from a shutdown of the daemon it should not except.
Note also #4649, even if maybe it is unrelated?

[unkcpz]

hi @giovannipizzi I cannot reproduce this with a more simple example like:

from aiida.engine import run, submit

CODENAME_ADD = 'add@localhost'
ArithmeticAddCalculation = CalculationFactory('arithmetic.add')

code = load_code(CODENAME_ADD)
inputs = {
    'x': Int(1),
    'y': Int(2),
    'code': code,
}

submit(ArithmeticAddCalculation, **inputs)

I think it is all the same right? Moreover, I have run my sssp workflow in latest develop branch which also have PwCalculation and verdi daemon stop very often, but never experience your problem.

[giovannipizzi]

Could you maybe try with an SSH computer/transport, where things are slower and there are non-zero safe intervals etc.? Maybe on a local transport they are all set to zero and the error occurs there.

In the meantime, I'll probably need to retry with the most recent version of develop.

[mbercx]

I've tried to reproduce this error as well, but don't seem to run into any issues. However, trying to restart the daemon, the operation times out. Here are the steps I execute:

1. Submit a PwRelaxWorkChain. The code for this work chain is set up to run on a remote computer via SSH transport (Piz Daint).
2. Check the calculation:

$ verdi process list
PK  Created    Process label     Process State    Process status
----  ---------  ----------------  ---------------  ---------------------------------------
1775  11s ago    PwRelaxWorkChain  ⏵ Waiting        Waiting for child processes: 1778
1778  10s ago    PwBaseWorkChain   ⏵ Waiting        Waiting for child processes: 1783
1783  9s ago     PwCalculation     ⏵ Waiting        Waiting for transport task: upload

3. Restart the daemon:

$ verdi daemon restart --reset
Profile: dev2
Waiting for the daemon to shut down... TIMEOUT
Starting the daemon... TIMEOUT

So here the connection to the daemon times out. However, it is stopped:

$ verdi status
 ✔ config dir:  /home/mbercx/.virtualenvs/aiida-dev/.aiida
 ✔ profile:     On profile dev2
 ✔ repository:  /home/mbercx/.virtualenvs/aiida-dev/.aiida/repository/dev2
 ✔ postgres:    Connected as mbercx@localhost:5432
 ✔ rabbitmq:    Connected as amqp://guest:guest@127.0.0.1:5672?heartbeat=600
 ⏺ daemon:      The daemon is not running

At this point the PwCalculation is in the transport task: submit state:

$ verdi process list
  PK  Created    Process label     Process State    Process status
----  ---------  ----------------  ---------------  ---------------------------------------
1775  1m ago     PwRelaxWorkChain  ⏵ Waiting        Waiting for child processes: 1778
1778  1m ago     PwBaseWorkChain   ⏵ Waiting        Waiting for child processes: 1783
1783  1m ago     PwCalculation     ⏵ Waiting        Waiting for transport task: submit

4. Start the daemon:

$ verdi daemon start
Starting the daemon... RUNNING

After waiting a bit, the daemon picks up the PwCalculation:

$ verdi process list
  PK  Created    Process label     Process State    Process status
----  ---------  ----------------  ---------------  ---------------------------------------
1775  13m ago    PwRelaxWorkChain  ⏵ Waiting        Waiting for child processes: 1778
1778  13m ago    PwBaseWorkChain   ⏵ Waiting        Waiting for child processes: 1783
1783  13m ago    PwCalculation     ⏵ Waiting        Monitoring scheduler: job state RUNNING

The log also looks fine:

$ verdi process report 1783
*** 1783: CalcJobState.WITHSCHEDULER, scheduler state: JobState.RUNNING
*** Scheduler output: N/A
*** Scheduler errors: N/A
*** 0 LOG MESSAGES

EDIT: I tried to reproduce the issue in Quantum Mobile, but no timeout there. After restarting my rabbitmq server on my work station the issue also seems to be fixed! I spoke too soon, seems I was (accidentally) in a different environment here. I keep on getting TIMEOUTs for my daemon when trying to restart (or stop) it. I tried reinstalling my Python environment but the problem persists. When I install aiida-core==1.5.2 however, the problem is no longer there. Should I open another issue for this?

[unkcpz]

@mbercx thanks for the report! I have the same timeout issue but just cannot assure the issue comes from the new version, thanks for compare and check!

Should I open another issue for this?

It doesn't seem necessary for now, I working on it. I think they have the same problem root, let's see if solve this one will fix the other ;)

[mbercx]

It doesn't seem necessary for now, I working on it. I think they have the same problem root, let's see if solve this one will fix the other ;)

@ramirezfranciscof was having similar issues, so he opened #4667 where you can find some more information on the daemon log (the error there is the same for both of us). If the problems do have the same root, you can now fix two issues in one PR! 😅

[mbercx]

Could you maybe try with an SSH computer/transport, where things are slower and there are non-zero safe intervals etc.? Maybe on a local transport they are all set to zero and the error occurs there.

I was able to reproduce the issue when increasing the safe-interval of the localhost computer:

$  verdi computer configure local localhost --safe-interval 10 -n

Then, stop the daemon and run the simple example you showed previously:

from aiida.engine import submit

ArithmeticAddCalculation = CalculationFactory('arithmetic.add')

inputs = {
    'x': Int(1),
    'y': Int(2),
    'code': load_code('add@localhost'),
}

submit(ArithmeticAddCalculation, **inputs)

Next, start the daemon, sleep for 2 seconds and restart it:

$ verdi daemon start; sleep 2; verdi daemon restart --reset
Starting the daemon... RUNNING
Profile: generic
Waiting for the daemon to shut down... OK
Starting the daemon... RUNNING
(dev-test) max@7e5d5794c8bd:~/codes/aiida-core$ verdi process list -ap1
  PK  Created    Process label             Process State    Process status
----  ---------  ------------------------  ---------------  -------------------------------------
 189  38s ago    ArithmeticAddCalculation  ⨯ Excepted       Transport task upload was interrupted

Total results: 1

Info: last time an entry changed state: 8s ago (at 11:27:25 on 2021-01-21)

Now the calcjob has been Excepted during the transport task. Here's the error log of the daemon:

01/21/2021 11:27:25 AM <2527> aiida.orm.nodes.process.calculation.calcjob.CalcJobNode: [REPORT] [189|ArithmeticAddCalc
ulation|on_except]: Traceback (most recent call last):
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/plumpy/processes.py", line 1171, in step
    next_state = await self._run_task(self._state.execute)
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/plumpy/processes.py", line 549, in _run_task
    result = await coro(*args, **kwargs)
  File "/home/max/codes/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 339, in execute
    skip_submit = await self._launch_task(task_upload_job, self.process, transport_queue)
  File "/home/max/codes/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 394, in _launch_task
    result = await self._task
  File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
    future.result()
concurrent.futures._base.CancelledError

01/21/2021 11:27:25 AM <2527> aiida.engine.transports: [ERROR] Exception whilst using transport:
Traceback (most recent call last):
  File "/home/max/codes/aiida-core/aiida/engine/transports.py", line 101, in request_transport
    yield transport_request.future
  File "/home/max/codes/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 70, in do_upload
    transport = await cancellable.with_interrupt(request)
  File "/home/max/codes/aiida-core/aiida/engine/utils.py", line 87, in with_interrupt
    result = await next(wait_iter)
  File "/usr/lib/python3.7/asyncio/tasks.py", line 556, in _wait_for_one
    f = await done.get()
  File "/usr/lib/python3.7/asyncio/queues.py", line 159, in get
    await getter
  File "/usr/lib/python3.7/asyncio/futures.py", line 263, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
    future.result()
  File "/usr/lib/python3.7/asyncio/futures.py", line 176, in result
    raise CancelledError
concurrent.futures._base.CancelledError

01/21/2021 11:27:28 AM <2621> kiwipy.rmq.tasks: [ERROR] Exception occurred while processing task.
Traceback (most recent call last):
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/kiwipy/rmq/tasks.py", line 166, in _on_task
    result = await result
  File "/usr/lib/python3.7/asyncio/futures.py", line 263, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
    future.result()
  File "/usr/lib/python3.7/asyncio/futures.py", line 181, in result
    raise self._exception
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/kiwipy/rmq/threadcomms.py", line 252, in done
    result = kiwi_future.result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/kiwipy/futures.py", line 54, in capture_exceptions
    yield
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/plumpy/communications.py", line 48, in on_done
    result = plum_future.result()
  File "/usr/lib/python3.7/asyncio/futures.py", line 181, in result
    raise self._exception
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/kiwipy/futures.py", line 54, in capture_exceptions
    yield
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/plumpy/futures.py", line 73, in run_task
    res = await coro()
  File "/home/max/.virtualenvs/dev-test/lib/python3.7/site-packages/plumpy/process_comms.py", line 539, in __call__
    return await self._continue(communicator, **task.get(TASK_ARGS, {}))
  File "/home/max/codes/aiida-core/aiida/manage/external/rmq.py", line 203, in _continue
    return future.result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
aiida.engine.exceptions.PastException: concurrent.futures._base.CancelledError

Moreover, very funky stuff is happening after this. It tells me the daemon is not running (without me stopping it):

$ verdi daemon status
Profile: generic
The daemon is not running

But it actually is! When submitting another ArithmeticAddCalculation, the daemon is definitely active:

$ verdi process list -ap1
  PK  Created    Process label             Process State    Process status
----  ---------  ------------------------  ---------------  -------------------------------------
 189  5m ago     ArithmeticAddCalculation  ⨯ Excepted       Transport task upload was interrupted
 192  6s ago     ArithmeticAddCalculation  ⏵ Waiting        Waiting for transport task: upload

Total results: 2

Info: last time an entry changed state: 6s ago (at 11:32:28 on 2021-01-21)
Warning: the daemon is not running
(dev-test) max@7e5d5794c8bd:~/.aiida/daemon/log$ verdi process list -ap1
  PK  Created    Process label             Process State    Process status
----  ---------  ------------------------  ---------------  -------------------------------------
 189  5m ago     ArithmeticAddCalculation  ⨯ Excepted       Transport task upload was interrupted
 192  13s ago    ArithmeticAddCalculation  ⏵ Waiting        Waiting for transport task: submit

Total results: 2

Info: last time an entry changed state: 2s ago (at 11:32:38 on 2021-01-21)
Warning: the daemon is not running

Finally, note that here restarting the daemon did not encounter any TIMEOUT problems. Looking at the log, the error also seems different. I was able to reproduce this TIMEOUT problem in QM as well, but then using a PwBaseWorkChain. I'll post the steps to reproduce in @ramirezfranciscof's issue (#4667).

[mbercx]

Note: the TIMEOUT problem, when reproduced in the QM environment, also had a similar error trace as in my previous message. So both issues are related to the same root cause, as @unkcpz thought.

You can also get TIMEOUT issues when running using Python 3.6, however, as discussed in #4667. Of course, from aiida-core v1.6, Python 3.6 is no longer supported.

[chrisjsewell]

@giovannipizzi/@mbercx I cannot reproduce the issue in https://github.com/aiidateam/aiida-integration-tests:

$ verdi daemon stop
$ aiida-sleep calc -n 2 --submit -p 100000
$ verdi daemon start
$ verdi daemon stop
$ verdi process list
1776  1m ago     SleepCalculation  ⏵ Waiting        Waiting for transport task: upload
1779  58s ago    SleepCalculation  ⏵ Waiting        Waiting for transport task: upload
$ verdi daemon start
$ verdi daemon stop
$ verdi process list
1776  1m ago     SleepCalculation  ⏵ Waiting        Waiting for transport task: submit
1779  1m ago     SleepCalculation  ⏵ Waiting        Waiting for transport task: submit

I feel it may be related to #4692, but then again I couldn't reproduce it before this commit either

As per #4667, can you confirm that you were not using python 3.6

Then can you try to reproduce on https://github.com/aiidateam/aiida-integration-tests.
If it cannot be reproduced there then I can't fix it.

[chrisjsewell]

yeh and just to double-check added the add@local code to aiidateam/aiida-integration-tests and run it exactly as #4648 (comment), and it was fine:

$ verdi process list -ap1
  PK  Created    Process label             Process State    Process status
----  ---------  ------------------------  ---------------  -------------------------------------
8517  42s ago    ArithmeticAddCalculation  ⏵ Waiting         Waiting for transport task: upload

so @mbercx, yeh give it a go again with the latest develop and if there is still an issue, perhaps try it on aiidateam/aiida-integration-tests and also compare your local setup to thats, e.g. what version of RabbitMQ you are using