Repository: MatterMiners/tardis

Issue:
Drones go into `Error` state when a slurm batch job times out
If a slurm batch job runs out of walltime it will report status `TIMEOUT` in `squeue`. This is not properly recognized by tardis which puts the corresponding VM into `Error` state and repeatedly tries to `scancel` the job (which reports success, since from a slurm point of view things are already as they should be). Tardis keeps the VM in `Error` state until `squeue -o -h -t all` stops reporting the job ID (takes approx. 15 minutes in the case I observed). If that happens proper cleanup seems to happen.

A few snippets from a log file to illustrate things:

- Job creation:
```console
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 10:45:43 jureca sbatch returned {'stdout': 'Submitted batch job 10367673\n', 'stderr': '', 'exit_code': 0}
cobald.runtime.tardis.plugins.sqliteregistry: 2022-04-13 10:45:43 Drone: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 10, 45, 43, 732464), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Booting: 1>} has changed state to BootingState
```

The queue / partition this is submitted to has a walltime limit of 2 hours (the corresponding cobald/tardis configuration is set to `115` minutes). After approx 2 hours the job is still reported as running:
```console
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:40:39 jureca has status {'JobId': '10367673', 'Host': 'jrc0728', 'State': 'RUNNING'}.
cobald.runtime.tardis.resources.dronestates: 2022-04-13 12:40:39 Resource attributes: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 40, 39, 229941), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Running: 2>}
```

Shortly after that the job times out on the slurm batch system, sending the resource into `Error` status
```console
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:41:39 Slurm status update finished.
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:41:39 jureca has status {'JobId': '10367673', 'Host': 'jrc0728', 'State': 'TIMEOUT'}.
cobald.runtime.tardis.resources.dronestates: 2022-04-13 12:41:39 Resource attributes: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 41, 39, 963501), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Error: 5>}
```

After this tardis repeatedly tries to cancel the resource:
```console
asyncssh: 2022-04-13 12:42:41 [conn=0, chan=323]   Command: scancel 10367673
asyncssh: 2022-04-13 12:42:41 [conn=0, chan=323] Received exit status 0
```
this seems to send the resource into `CleanupState` temporarily
```console
cobald.runtime.tardis.resources.dronestates: 2022-04-13 12:43:41 Drone {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 42, 41, 513820), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Stopped: 3>} in CleanupState
```

But the next `squeue` query resets that to `Error`:
```console
asyncssh: 2022-04-13 12:43:41 [conn=0, chan=324]   Command: squeue -o "%A|%N|%T" -h -t all
asyncssh: 2022-04-13 12:43:42 [conn=0, chan=324] Received exit status 0
asyncssh: 2022-04-13 12:43:42 [conn=0, chan=324] Received channel close
asyncssh: 2022-04-13 12:43:42 [conn=0, chan=324] Channel closed
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:43:42 Slurm status update finished.
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:43:42 jureca has status {'JobId': '10367673', 'Host': 'jrc0728', 'State': 'TIMEOUT'}.
cobald.runtime.tardis.resources.dronestates: 2022-04-13 12:43:42 Resource attributes: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 43, 42, 508553), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Error: 5>}
```

The last two points then repeat until `squeue` no longer reports the `JobId`, when that happens tardis seems to treat this as `COMPLETED` (or slurm starts to report this as `COMPLETED`(?)) and deletes the resource
```console
cobald.runtime.tardis.adapters.sites.slurm: 2022-04-13 12:58:57 jureca has status {'JobID': 10367673, 'State': 'COMPLETED'}.
cobald.runtime.tardis.resources.dronestates: 2022-04-13 12:58:57 Resource attributes: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 58, 57, 307470), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Deleted: 4>}
cobald.runtime.tardis.plugins.sqliteregistry: 2022-04-13 12:58:57 Drone: {'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 58, 57, 307754), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Deleted: 4>} has changed state to DownState
cobald.runtime.tardis.plugins.sqliteregistry: 2022-04-13 12:58:57 DELETE FROM Resources
        WHERE drone_uuid = :drone_uuid
        AND site_id = (SELECT site_id from Sites WHERE site_name = :site_name),{'state': 'DownState', 'site_name': 'jureca', 'machine_type': 'default', 'obs_machine_meta_data_translation_mapping': {'Cores': 1, 'Memory': 1024, 'Disk': 1048576}, 'remote_resource_uuid': 10367673, 'created': datetime.datetime(2022, 4, 13, 10, 45, 43, 732421), 'updated': datetime.datetime(2022, 4, 13, 12, 58, 57, 307754), 'drone_uuid': 'jureca-0af69344e7', 'resource_status': <ResourceStatus.Deleted: 4>} executed
```

Discussion:
giffels: FYI: Flake will be fixed once #238 is merged and the deployment test are currently not working due to a feature/bug of the Github action (see #239)

Patch:
diff --git a/docs/source/changelog.rst b/docs/source/changelog.rst
index a09a9a3..70c6322 100644
--- a/docs/source/changelog.rst
+++ b/docs/source/changelog.rst
@@ -1,4 +1,4 @@
-.. Created by changelog.py at 2022-03-09, command
+.. Created by changelog.py at 2022-04-13, command
    '/Users/giffler/.cache/pre-commit/repor6pnmwlm/py_env-default/bin/changelog docs/source/changes compile --output=docs/source/changelog.rst'
    based on the format of 'https://keepachangelog.com/'
 
@@ -6,7 +6,7 @@
 CHANGELOG
 #########
 
-[Unreleased] - 2022-03-09
+[Unreleased] - 2022-04-13
 =========================
 
 Added
diff --git a/tardis/adapters/sites/slurm.py b/tardis/adapters/sites/slurm.py
index dc8c6b0..f5fd0b8 100644
--- a/tardis/adapters/sites/slurm.py
+++ b/tardis/adapters/sites/slurm.py
@@ -92,6 +92,7 @@ class SlurmAdapter(SiteAdapter):
                 STAGE_OUT=ResourceStatus.Running,
                 STOPPED=ResourceStatus.Stopped,
                 SUSPENDED=ResourceStatus.Stopped,
+                TIMEOUT=ResourceStatus.Deleted,
             ): translator.get(x, default=ResourceStatus.Error),
             JobId=lambda x: int(x),
         )


Test patch:
diff --git a/tests/adapters_t/sites_t/test_slurm.py b/tests/adapters_t/sites_t/test_slurm.py
index 7a979cf..a372abb 100644
--- a/tests/adapters_t/sites_t/test_slurm.py
+++ b/tests/adapters_t/sites_t/test_slurm.py
@@ -323,7 +323,7 @@ class TestSlurmAdapter(TestCase):
             "STAGE_OUT": ResourceStatus.Running,
             "STOPPED": ResourceStatus.Stopped,
             "SUSPENDED": ResourceStatus.Stopped,
-            "TIMEOUT": ResourceStatus.Error,
+            "TIMEOUT": ResourceStatus.Deleted,
         }
 
         for id, value in enumerate(state_translations.values()):