Calculation job can be submitted twice if first submission succeeds but communication of result from scheduler to AiiDA times out

[Zeleznyj]

I've encountered an issue where sometimes a calculation will show as finished in aiida, but the actual calculation on remote computer is still running. Aiida will retrieve the files and run parser without showing any error. This happened with ssh transport and slurm scheduler. I'm not sure if the problem is necessarily related to slurm though, since we are now not using other schedulers much. The calculations are using our own FPLO calculation plugins. It is possible that the issue is somehow related to some problem in the plugins, but to me it seems like a problem with aiida, since everything on our side is working fine. The calculation is submitted correctly and finishes correctly, the only problem is that the results are retrieved before the remote calculation is finished. This thus looks like a problem with parsing the queue status. The problem happens randomly, when we resubmit a calculation, it will usually finish fine.

I've noticed the problem after checking out the develop branch couple days ago, but most likely the problem existed also before, when I was using the 1.0.06b version.

I can try to include more details, but I'm not sure where to start about debugging this.

[sphuber]

So just to be sure, you are using the standard slurm plugin that ships with aiida-core?

Are all the files you expect present in the retrieved folder? You can check by first getting the corresponding pk from verdi process show. The retrieved node should be listed under outputs. Then with verdi node repo ls you can show its contents. Are the files in there complete or do they contain only partial output. Could you also share the output of verdi node attributes <calcjob_pk>?

[Zeleznyj]

Yes, I'm using the default slurm plugin.

All files in the retrieved node are present, but they contain only partial output. When I use verdi calcjob gotocomputer to check the remote, there the files contain full output, however, the retrieved files are not complete since they have been retrieved before the calculation has finished.

Here is the output of verdi node attributes command:

{
    "append_text": "",
    "custom_scheduler_commands": "",
    "environment_variables": {},
    "exit_status": 0,
    "import_sys_environment": true,
    "job_id": "176740",
    "last_jobinfo": "{\"job_id\": \"176740\", \"wallclock_time_seconds\": 1456, \"title\": \"aiida-5941\", \"num_machines\": 1, \"detailedJobinfo\": null, \"queue_name\": \"newnodes\", \"num_mpiprocs\": 1, \"allocated_machines_raw\": \"node98\", \"submission_time\": {\"date\": \"2019-10-09T14:05:39.000000\", \"timezone\": null}, \"job_owner\": \"zeleznyj\", \"annotation\": \"None\", \"requested_wallclock_time_seconds\": 259200, \"raw_data\": [\"176740\", \"R\", \"None\", \"node98\", \"zeleznyj\", \"1\", \"1\", \"node98\", \"newnodes\", \"3-00:00:00\", \"24:16\", \"2019-10-09T14:05:40\", \"aiida-5941\", \"2019-10-09T14:05:39\"], \"job_state\": \"running\", \"dispatch_time\": {\"date\": \"2019-10-09T14:05:40.000000\", \"timezone\": null}}",
    "max_memory_kb": 3000000,
    "max_wallclock_seconds": 259200,
    "mpirun_extra_params": [],
    "output_filename": "fplo_out",
    "parser_name": "fplo",
    "prepend_text": "",
    "process_label": "FploCalculation",
    "process_state": "finished",
    "queue_name": "newnodes",
    "remote_workdir": "/zfs_data/zeleznyj/aiida_pc109/5f/1b/8ab9-7abe-4680-8b1b-7ba964bb5946",
    "resources": {
        "default_mpiprocs_per_machine": 24,
        "num_machines": 1,
        "num_mpiprocs_per_machine": 1
    },
    "retrieve_list": [
        "fplo_out",
        "=.dens",
        "=.in",
        "_scheduler-stdout.txt",
        "_scheduler-stderr.txt"
    ],
    "retrieve_temporary_list": [],
    "scheduler_lastchecktime": "2019-10-09T12:30:12.371370+00:00",
    "scheduler_state": "done",
    "scheduler_stderr": "_scheduler-stderr.txt",
    "scheduler_stdout": "_scheduler-stdout.txt",
    "sealed": true,
    "version": {
        "core": "1.0.0b6",
        "plugin": "0.5.5"
    },
    "withmpi": false
}

[sphuber]

Is there anything peculiar in the content of the scheduler output files?
You can display those with verdi calcjob outputcat <PK> _scheduler-stderr.txt and verdi calcjob outputcat <PK> _scheduler-stdout.txt.

Does this happen for all calculations of all types? Or only of this type? Or even only for some calculations of this type?

It would be good if you have no calculations running anymore to set verdi config logging.aiida_loglevel DEBUG followed by verdi daemon restart --reset. Then submit 1 calculation and run verdi daemon logshow and copy the output printed there while that calculation is running to a file and paste it here.

[Zeleznyj]

The scheduler output files are empty.

We have seen this happening with one calculation type only and with one remote computer. However, this doesn't have to mean anything since vast majority of calculations we have done so far were with this calculation and remote computer.

It seems to be happening randomly with most calculations having no issue. If I repeat exactly the same calculation where the problem occurred it will usually finish fine.

I will try to turn on the debugging and will post the output once the problem occurs.

[Zeleznyj]

I have managed to reproduce the issue again, so I can provide some more info. The issue happens also with different remote computer, with the pbspro scheduler and with a different calculation plugin. We used a slightly modified version of the pbspro scheduler, but I don't think the issue is related to the scheduler since the issue seems to be exactly the same with the slurm scheduler: Aiida at some points starts to retrieve the calculation even though the calculation is still running or in the queue.

I was unable to reproduce the issue at first, it seems to be quite random, however, now I've run hundreds of calculations and can see the issue in some. Because of this, the whole log file is massive, so I'm uploading only parts relevant to some of the calculation where the issue occurred. I can provide the whole file if necessary, but it has over 1GB. Even the cut parts are still quite large so I put them in dropbox. The files are named according to the process pk for which the process occurred.

I often see the following error in verdi process report

+-> ERROR at 2019-10-17 22:42:48.875613+00:00
 | Traceback (most recent call last):
 |   File "/jakzel/aiida/aiida_code/aiida-core/aiida/engine/utils.py", line 176, in exponential_backoff_retry
 |     result = yield coro()
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/gen.py", line 1055, in run
 |     value = future.result()
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/concurrent.py", line 238, in result
 |     raise_exc_info(self._exc_info)
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/gen.py", line 1063, in run
 |     yielded = self.gen.throw(*exc_info)
 |   File "/jakzel/aiida/aiida_code/aiida-core/aiida/engine/processes/calcjobs/tasks.py", line 175, in do_update
 |     job_info = yield cancellable.with_interrupt(update_request)
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/gen.py", line 1055, in run
 |     value = future.result()
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/concurrent.py", line 238, in result
 |     raise_exc_info(self._exc_info)
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/gen.py", line 1063, in run
 |     yielded = self.gen.throw(*exc_info)
 |   File "/jakzel/aiida/aiida_code/aiida-core/aiida/engine/utils.py", line 93, in with_interrupt
 |     result = yield wait_iterator.next()  # pylint: disable=stop-iteration-return
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/gen.py", line 1055, in run
 |     value = future.result()
 |   File "/jakzel/aiida/virtualenvs/aiida/lib/python2.7/site-packages/tornado/concurrent.py", line 238, in result
 |     raise_exc_info(self._exc_info)
 |   File "<string>", line 3, in raise_exc_info
 | SchedulerError: Error during squeue parsing (_parse_joblist_output function)

but it seems to be unrelated since it also happens with calculations that finish fine, and not all calculations that have the issue have this error.

[Zeleznyj]

Are there some things I could try to fix this issue or to investigate more?

It seems that we only see this issue on one particular computer (though it's hard to be sure because of the randomness), which is running on Debian 10, whereas otherwise we have been using computers running Ubuntu. Is it possible that the issue is related to the operating system, or to version of some package like RabbitMQ? I can try to experiment with this, but it's quite time consuming, because it's necessary to run a lot of calculations to verify whether the issue is there.

[sphuber]

Sorry for not responding earlier @Zeleznyj I have been swamped with the release of aiida-core==1.0.0 of next week. I will try to have a look after that, but I am afraid that as it is already difficult for you to reproduce, even moreso for me. I will have to base a potential cause on speculation and then see if there is anyway to probe/test this. I will think about it and come back to you with hopefully something that you can test.

[ltalirz]

@danieleongari at LSMO seems to run into the same issue, i.e. this seems confirmed.
We're investigating to get an idea of what could be going wrong...

[ltalirz]

@Zeleznyj thanks for your report.

Aiida at some points starts to retrieve the calculation even though the calculation is still running or in the queue.

Just to be absolutely sure (since this is important): You are definitely positive that the calculations were still running (also shown as such in slurm), rather than the problem being that the calculations were finished correctly but then AiiDA, for some reason, retrieved the files incompletely?
That would indeed be very helpful information.

[ltalirz]

If the issue turns out to be related to the scheduler receiving too many requests, and AiiDA misinterpreting its output (or it gets hanging for some reason), it may help to increase the safe_interval using verdi computer configure ssh <computername> (see current value in verdi computer configure show <computername>).
The default value is 5s (per daemon worker), which could lead to issues if you have a lot of workers active.

Of course, this would just be a workaround, not a solution of the underlying problem.

P.S. The safe_interval limits the overall rate of SSH connections per worker, which is not strictly necessary here.
I would be enough to just increase the interval between polls of the scheduler - there is no cli for it yet (we should add this #3541) but you can do it from the verdi shell:

In [1]: c = load_computer(1)

In [2]: c.get_minimum_job_poll_interval()
Out[2]: 10.0

In [3]: c.set_minimum_job_poll_interval(30)

[Zeleznyj]

The issue is definitely that the calculations are still running and are shown as such in slurm or pbspro when aiida retrieves them. I've seen it hundreds of times now.

I have in fact increased the safe interval to 60s for one of the computers we use. This didn't seem to have any influence on the issue as far as I can say. It is definitely still present.This is a computer that uses pbspro and the qstat command is sometimes responding very slowly. Interestingly, it seems that the qstat command is only slow when I have aiida calculations running on this computer, though this may be a coincidence. Is it possible that even with increasing the safe_interval to 60s, aiida is flooding the pbspro server with too many requests? It seems strange to me since this is a large supercomputer with many users and hundreds of jobs in the queue.

I can try to increase the safe_interval even more.

The other computer we use is a smaller cluster, which uses slurm. There the slurm is very responsive, but sometimes the ssh connection to the cluster is unstable and can drop out suddenly.

Perhaps I should also mention that the issue persists when upgrading to aiida v1.0.0 and that I'm using python2.

[ltalirz]

Thanks @Zeleznyj, this is really helpful to know and we absolutely need to look into this.

I have in fact increased the safe interval to 60s for one of the computers we use. This didn't seem to have any influence on the issue as far as I can say.

Hm... can you try what I suggested above (to increase the minimum job poll interval) instead (increase e.g. to 120s - or some value that is reasonable given the typical duration of your calculations)?
I happen to know that @sphuber , who has not been experiencing this issue in ~5000 calculations, has increased this value.

@sphuber I wonder: What does currently happen when you have a very low minimum_job_poll_interval and a high safety_interval (say, 10x higher).
When the next SSH connection is allowed, is it possible that AiiDA tries to poll the scheduler 10 times within the same connection?

Also, is the status obtained from the scheduler shared between workers?

[sphuber]

@sphuber I wonder: What does currently happen when you have a very low minimum_job_poll_interval and a high safety_interval (say, 10x higher).
When the next SSH connection is allowed, is it possible that AiiDA tries to poll the scheduler 10 times within the same connection?
Also, is the status obtained from the scheduler shared between workers?

No, there is no sharing of information between workers on this level. Each worker has an instance of a JobManager which takes care of polling the scheduler. The processes run by a daemon worker, will request an update of their status with this JobManager which will poll the scheduler, respecting the minimum_job_interval set on the given computer. To do so, it will first request a transport from the TransportQueue. This latter one ensure that the safe_interval is respected. So in the worst case, a new scheduler update will occur every safe_interval + minimum_job_interval seconds.