dispatcher: mark nodes down on ansible hardware failures

We already mark a node down after it fails to reimage 10 times in a row.
When ceph-cm-ansible's "Ensure we found enough OSD disks" task fails,
though, we know right away that the node is missing a disk, and every
job that lands on it until someone notices will fail the same way.

Teach FailureAnalyzer to spot failure messages that mean the hardware
itself is broken, and have the supervisor mark those nodes down once the
job process exits. The job process only archives the ansible failure log
as it always has; node manipulation stays on the supervisor side so that
a running job never depends on the lock server being reachable.

Only the node's status is updated. The job still holds the lock at that
point, and unlock_targets() refuses to unlock a node whose description
no longer matches the job's archive path.

The behavior can be turned off with mark_down_on_hardware_failure, and
is documented in docs/node_health.rst.

Fixes: https://tracker.ceph.com/issues/75669
Signed-off-by: David Galloway <david.galloway@ibm.com>

Author: djgalloway

docs/index.rst

@@ -14,6 +14,7 @@ Content Index
    downburst_vms.rst
    INSTALL.rst
    LAB_SETUP.rst
+   node_health.rst
    exporter.rst
    commands/list.rst
    ChangeLog.rst

docs/node_health.rst

@@ -0,0 +1,95 @@
+.. _node_health:
+
+===================
+Marking Nodes Down
+===================
+
+Every node in the lock server (paddles) has an ``up`` flag. A node that is
+marked down is never handed out to a job, so a broken machine stops eating
+scheduled jobs until someone looks at it. Nodes are marked down by hand with
+``teuthology-lock --update --status down <node>``, and automatically by
+``teuthology-supervisor`` in the two cases described below.
+
+All of this happens in the supervisor process, not in the job process. Tasks
+never talk to paddles about node status: a job should not depend on the lock
+server being reachable, and the supervisor is what owns the nodes for the
+duration of a job anyway.
+
+Repeated reimaging failures
+===========================
+
+If reimaging a node fails, the supervisor asks paddles for that node's last 10
+jobs. If all 10 of them failed to reimage, the node is marked down with the
+description ``reimage failed 10 times``. See
+``check_for_reimage_failures_and_mark_down()`` in
+``teuthology/dispatcher/supervisor.py``.
+
+Hardware failures reported by ansible
+=====================================
+
+Some ansible failures tell us right away that the node itself is broken - a
+disk that is missing or dead, for example. Waiting for such a node to fail ten
+more jobs is pure waste, so the supervisor marks it down as soon as it sees
+one.
+
+How it works
+------------
+
+#. The ``ansible`` task sets ``ANSIBLE_FAILURE_LOG`` when it runs
+   ``ansible-playbook``. ceph-cm-ansible's ``failure_log`` callback plugin
+   (``callback_plugins/failure_log.py``) writes every task failure to that
+   file as YAML.
+#. When the playbook fails, the task archives the log to
+   ``ansible_failures.yaml`` in the job's archive directory.
+#. After the job process exits, the supervisor reads that file back and passes
+   it to ``FailureAnalyzer.find_hardware_failures()``, in
+   ``teuthology/task/ansible.py``.
+#. Any node whose failure message matches a known hardware-failure pattern is
+   marked down, as long as it is one of the job's own targets. This is
+   ``check_for_hardware_failures_and_mark_down()`` in
+   ``teuthology/dispatcher/supervisor.py``.
+
+Only the node's status is changed; its lock description is left alone. The job
+still holds the lock at that point, and ``unlock_targets()`` refuses to unlock
+a node whose description no longer matches the job's archive path.
+
+Expected format
+---------------
+
+The failure log is a YAML document keyed by hostname, with each value being the
+ansible result dict for the failed task. Only the ``msg`` field is examined -
+either on the record itself, or on each entry of its ``results`` list::
+
+    trial007.front.sepia.ceph.com:
+      _ansible_no_log: false
+      changed: false
+      msg: 'Wanted 2 disks of ~1700 GB (rotational=False), but only matched 1: [''nvme1n1'']'
+
+Note that the callback plugin records the result, not the name of the task that
+produced it, so matching is done on the message text. Whitespace in ``msg`` is
+collapsed before matching, because ansible wraps long messages across lines.
+
+The patterns themselves live in ``FailureAnalyzer.hardware_failure_patterns``.
+Each is a regular expression matched case-insensitively against the message.
+Currently there is one:
+
+.. list-table::
+   :header-rows: 1
+
+   * - Pattern
+     - Produced by
+   * - ``Wanted \d+ disks? of .+ but only matched \d+``
+     - ceph-cm-ansible's ``Ensure we found enough OSD disks`` task, in
+       ``roles/testnode/tasks/configure_lvm.yml``
+
+This is a coupling worth keeping in mind: adding a pattern here means relying
+on the exact wording of a task in ceph-cm-ansible, so changing one of those
+messages means changing the matching pattern too. Only add patterns for
+failures that really do mean the hardware is broken - a node marked down stays
+down until a human brings it back up.
+
+Disabling it
+------------
+
+Set ``mark_down_on_hardware_failure: false`` in :ref:`site_config` to turn this
+behavior off. The failure log is still archived either way.

docs/siteconfig.rst

@@ -96,6 +96,10 @@ Here is a sample configuration with many of the options set and documented::
     # it is killed by the supervisor process.
     max_job_time: 259200
 
+    # Whether the supervisor should mark a node down when ansible reports a
+    # hardware failure on it. See :ref:`node_health`.
+    mark_down_on_hardware_failure: true
+
     # The template from which the URL of the repository containing packages
     # is built.
     #

tests/dispatcher/test_hardware_failure_mark_machine_down.py

@@ -0,0 +1,88 @@
+import os
+import yaml
+
+from unittest.mock import patch
+
+from teuthology.dispatcher import supervisor
+
+
+HARDWARE_FAILURE = {
+    'trial007.front.sepia.ceph.com': {
+        '_ansible_no_log': False,
+        'changed': False,
+        'msg': "Wanted 2 disks of ~1700 GB (rotational=False), but only"
+               " matched 1: ['nvme1n1']",
+    },
+}
+
+OTHER_FAILURE = {
+    'trial007.front.sepia.ceph.com': {
+        'changed': False,
+        'msg': 'Failure talking to yum: failure',
+    },
+}
+
+
+class TestCheckHardwareFailureMarkDown(object):
+    def setup_method(self):
+        self.the_function = supervisor.check_for_hardware_failures_and_mark_down
+
+    def job_config(self, tmp_path, failure_log=None, targets=None):
+        if failure_log is not None:
+            path = os.path.join(str(tmp_path), supervisor.FAILURE_LOG_NAME)
+            with open(path, 'w') as f:
+                yaml.safe_dump(failure_log, f)
+        if targets is None:
+            targets = {
+                'ubuntu@trial007.front.sepia.ceph.com': 'ssh-ed25519',
+            }
+        return dict(
+            archive_path=str(tmp_path),
+            targets=targets,
+        )
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_hardware_failure(self, m_update_lock, tmp_path):
+        job_config = self.job_config(tmp_path, HARDWARE_FAILURE)
+        self.the_function(job_config)
+        m_update_lock.assert_called_once_with('trial007', status='down')
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_other_failure(self, m_update_lock, tmp_path):
+        job_config = self.job_config(tmp_path, OTHER_FAILURE)
+        self.the_function(job_config)
+        assert m_update_lock.called is False
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_no_failure_log(self, m_update_lock, tmp_path):
+        job_config = self.job_config(tmp_path)
+        self.the_function(job_config)
+        assert m_update_lock.called is False
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_host_is_not_a_target(self, m_update_lock, tmp_path):
+        job_config = self.job_config(
+            tmp_path,
+            HARDWARE_FAILURE,
+            targets={'ubuntu@trial008.front.sepia.ceph.com': 'ssh-ed25519'},
+        )
+        self.the_function(job_config)
+        assert m_update_lock.called is False
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_disabled(self, m_update_lock, tmp_path):
+        job_config = self.job_config(tmp_path, HARDWARE_FAILURE)
+        with patch.object(
+            supervisor.teuth_config, 'mark_down_on_hardware_failure', False
+        ):
+            self.the_function(job_config)
+        assert m_update_lock.called is False
+
+    @patch('teuthology.lock.ops.update_lock')
+    def test_unparseable_failure_log(self, m_update_lock, tmp_path):
+        job_config = self.job_config(tmp_path)
+        path = os.path.join(str(tmp_path), supervisor.FAILURE_LOG_NAME)
+        with open(path, 'w') as f:
+            f.write('{not: valid: yaml')
+        self.the_function(job_config)
+        assert m_update_lock.called is False

tests/task/test_ansible.py

@@ -56,6 +56,75 @@ def test_lines(self, line, result):
         obj = self.klass()
         assert obj.analyze_line(line) == result
 
+    @mark.parametrize(
+        'failure_log,result',
+        [
+            [
+                "",
+                {},
+            ],
+            [
+                yaml.safe_dump({
+                    "smithi001.front.sepia.ceph.com": {
+                        "changed": False,
+                        "msg": "Failure talking to yum: failure",
+                    },
+                }),
+                {},
+            ],
+            [
+                yaml.safe_dump({
+                    "trial007.front.sepia.ceph.com": {
+                        "_ansible_no_log": False,
+                        "changed": False,
+                        "msg": "Wanted 2 disks of ~1700 GB (rotational=False),"
+                               " but only matched 1: ['nvme1n1']",
+                    },
+                }),
+                {
+                    "trial007.front.sepia.ceph.com":
+                        "Wanted 2 disks of ~1700 GB (rotational=False), but"
+                        " only matched 1: ['nvme1n1']",
+                },
+            ],
+            [
+                # ansible wraps the message onto multiple lines
+                yaml.safe_dump({
+                    "trial007.front.sepia.ceph.com": {
+                        "msg": "Wanted 2 disks of ~1700 GB\n"
+                               "(rotational=False), but only matched\n"
+                               "1: ['nvme1n1']",
+                    },
+                }),
+                {
+                    "trial007.front.sepia.ceph.com":
+                        "Wanted 2 disks of ~1700 GB (rotational=False), but"
+                        " only matched 1: ['nvme1n1']",
+                },
+            ],
+            [
+                yaml.safe_dump({
+                    "trial007.front.sepia.ceph.com": {
+                        "results": [
+                            {"msg": "Failure talking to yum: failure"},
+                            {"msg": "Wanted 2 disks of ~1700 GB"
+                                    " (rotational=False), but only matched 0:"
+                                    " []"},
+                        ],
+                    },
+                }),
+                {
+                    "trial007.front.sepia.ceph.com":
+                        "Wanted 2 disks of ~1700 GB (rotational=False), but"
+                        " only matched 0: []",
+                },
+            ],
+        ]
+    )
+    def test_find_hardware_failures(self, failure_log, result):
+        obj = self.klass()
+        assert obj.find_hardware_failures(failure_log) == result
+
 
 class TestAnsibleTask(TestTask):
     klass = Ansible

teuthology/config.py

@@ -165,6 +165,7 @@ class TeuthologyConfig(YamlConfig):
         'job_threshold': 500,
         'lab_domain': 'front.sepia.ceph.com',
         'lock_server': 'https://paddles.front.sepia.ceph.com/',
+        'mark_down_on_hardware_failure': True,
         'max_job_age': 1209600,  # 2 weeks
         'max_job_time': 259200,  # 3 days
         'nsupdate_url': 'https://nsupdate.front.sepia.ceph.com/update',

teuthology/dispatcher/supervisor.py

@@ -16,6 +16,7 @@
 from teuthology.config import FakeNamespace
 from teuthology.lock import ops as lock_ops
 from teuthology.task import internal
+from teuthology.task.ansible import FailureAnalyzer, FAILURE_LOG_NAME
 from teuthology.misc import decanonicalize_hostname as shortname
 from teuthology.lock import query
 from teuthology.util import sentry
@@ -181,6 +182,7 @@ def run_job(job_config: dict,
     else:
         log.info('Success!')
     if 'targets' in job_config:
+        check_for_hardware_failures_and_mark_down(job_config)
         unlock_targets(job_config)
     return p.returncode
 
@@ -227,6 +229,48 @@ def check_for_reimage_failures_and_mark_down(targets, count=10):
         )
 
 
+def check_for_hardware_failures_and_mark_down(job_config):
+    """
+    Mark nodes down as soon as ansible tells us their hardware is broken,
+    instead of waiting for them to fail a whole streak of jobs first.
+
+    The job process itself never talks to paddles about this; it just archives
+    the ansible failure log, which we read back here. See docs/node_health.rst.
+
+    :param job_config: dict, job config data
+    """
+    if not teuth_config.mark_down_on_hardware_failure:
+        return
+    failure_log = os.path.join(job_config['archive_path'], FAILURE_LOG_NAME)
+    if not os.path.exists(failure_log):
+        return
+    try:
+        with open(failure_log) as f:
+            failures = FailureAnalyzer().find_hardware_failures(f.read())
+    except Exception:
+        log.exception("Failed to check %s for hardware failures", failure_log)
+        return
+    targets = set(shortname(t) for t in job_config.get('targets', dict()))
+    for hostname, msg in sorted(failures.items()):
+        machine_name = shortname(hostname)
+        if machine_name not in targets:
+            log.warning(
+                "Not marking %s down; it is not a target of this job",
+                machine_name,
+            )
+            continue
+        log.error(
+            "Marking %s down due to a hardware failure: %s", machine_name, msg
+        )
+        # Only the status is updated here: the job still holds the lock, and
+        # unlock_targets() refuses to unlock a node whose description no longer
+        # matches the job's archive path.
+        try:
+            lock_ops.update_lock(machine_name, status='down')
+        except Exception:
+            log.exception("Failed to mark %s down", machine_name)
+
+
 def reimage(job_config):
     # Reimage the targets specified in job config
     # and update their keys in config after reimaging