orch/run: Added scan_unit_test_error

Currently when a unittest in RemoteProcess
fails it will throw a CommandFailure with
no information regarding which unittest
failed.

This PR will enable the CommandFailure to scan
for unittest failures in teuthology.log
and output them to paddles.

Currently only supports these unittests:
- gtest c++
- python nose

Signed-off-by: Kamoltat Sirivadhna <ksirivad@redhat.com>

diff --git a/teuthology/exceptions.py b/teuthology/exceptions.py
index a33cec041583b55e6a6f4dff815f63966180cc97..7b3c85f21057297d91dc2d2572ae10dda5192867 100644 (file)
--- a/teuthology/exceptions.py
+++ b/teuthology/exceptions.py
@@ -50,11 +50,14 @@ class CommandFailedError(Exception):
     """
     Exception thrown on command failure
     """
-    def __init__(self, command, exitstatus, node=None, label=None):
+    def __init__(
+        self, command, exitstatus, node=None, label=None, unit_test_error=None
+        ):
         self.command = command
         self.exitstatus = exitstatus
         self.node = node
         self.label = label
+        self.unit_test_error = unit_test_error
 
     def __str__(self):
         prefix = "Command failed"
@@ -62,6 +65,12 @@ class CommandFailedError(Exception):
             prefix += " ({label})".format(label=self.label)
         if self.node:
             prefix += " on {node}".format(node=self.node)
+        if self.unit_test_error:
+            return "{prefix} with status {status}: {unit_test_error}".format(
+                status=self.exitstatus,
+                unit_test_error=self.unit_test_error,
+                prefix=prefix,
+                )
         return "{prefix} with status {status}: {cmd!r}".format(
             status=self.exitstatus,
             cmd=self.command,

diff --git a/teuthology/orchestra/run.py b/teuthology/orchestra/run.py
index f31dfd0d7fc1db89feab1f67abdc95c809a9731d..27412a0f0ea3403d093c25b3c85115a6d58c88cf 100644 (file)
--- a/teuthology/orchestra/run.py
+++ b/teuthology/orchestra/run.py
@@ -3,7 +3,7 @@ Paramiko run support
 """
 
 import io
-
+import re
 from paramiko import ChannelFile
 
 import gevent
@@ -161,6 +161,29 @@ class RemoteProcess(object):
         self._raise_for_status()
         return status
 
+    def _open_file_path_from_handler(self):
+        log2 = logging.getLogger()
+        for h in log2.handlers:
+            # check the handler is a file handler
+            # h.stream should be an open file handle, it's name is the path
+            if isinstance(h, logging.FileHandler):
+                return h.stream.name
+        return None
+
+    def _scan_unittest_error(self):
+        file_path = self._open_file_path_from_handler()
+        if file_path:
+            with open(file_path, 'r') as f:
+                for line in f.readlines():
+                    # python nose test
+                    ret1 = re.search("ERROR:\s", line)
+                    if ret1:
+                        return line[ret1.start():].strip()
+                    # gtest c++
+                    ret2 = re.search("\[\s\sFAILED\s\s\]", line)
+                    if ret2:
+                        return line[ret2.start():].strip()
+        return None
     def _raise_for_status(self):
         if self.returncode is None:
             self._get_exitstatus()
@@ -180,7 +203,8 @@ class RemoteProcess(object):
             if self.returncode != 0:
                 raise CommandFailedError(
                     command=self.command, exitstatus=self.returncode,
-                    node=self.hostname, label=self.label
+                    node=self.hostname, label=self.label,
+                    unit_test_error=self._scan_unittest_error()
                 )
 
     def _get_exitstatus(self):

diff --git a/teuthology/orchestra/test/test_scan_unittest_error.py b/teuthology/orchestra/test/test_scan_unittest_error.py
new file mode 100644 (file)
index 0000000..ac5f9e6
--- /dev/null
+++ b/teuthology/orchestra/test/test_scan_unittest_error.py
@@ -0,0 +1,29 @@
+import os
+from unittest.mock import patch
+from teuthology.orchestra import run
+
+class TestScanUnittestError(object):
+
+    def setup(self):
+        self.remote_process = run.RemoteProcess(None, None, hostname="hostname")
+        self.the_function = self.remote_process._scan_unittest_error
+
+    @patch('teuthology.orchestra.run.RemoteProcess._open_file_path_from_handler')
+    def test_s3_nose_test_failure(self, m_open_file_path):
+        m_open_file_path.return_value = os.path.join(
+            os.path.dirname(os.path.abspath(__file__)),
+            "teuth_log/s3_failure_teuth.log"
+        )
+        assert self.the_function() == ("ERROR: test suite for <module " 
+                                       "'s3tests_boto3.functional' "
+                                       "from '/home/ubuntu/cephtest/"
+                                       "s3-tests/s3tests_boto3/functional/"
+                                       "__init__.py'>")
+
+    @patch('teuthology.orchestra.run.RemoteProcess._open_file_path_from_handler')
+    def test_rbd_gtest_failure(self, m_open_file_path):
+        m_open_file_path.return_value = os.path.join(
+            os.path.dirname(os.path.abspath(__file__)),
+            "teuth_log/gtest_failure_teuth.log"
+        )
+        assert self.the_function() == "[  FAILED  ] TestLibRBD.TestEncryptionLUKS2 (12236 ms)"

diff --git a/teuthology/orchestra/test/teuth_log/gtest_failure_teuth.log b/teuthology/orchestra/test/teuth_log/gtest_failure_teuth.log
new file mode 100644 (file)
index 0000000..b11e01b
--- /dev/null
+++ b/teuthology/orchestra/test/teuth_log/gtest_failure_teuth.log
@@ -0,0 +1,54 @@
+2021-11-26T03:42:35.308 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:35.308 INFO:tasks.workunit.client.0.smithi063.stdout:started writesame
+2021-11-26T03:42:35.308 INFO:tasks.workunit.client.0.smithi063.stdout:write completion cb called!
+2021-11-26T03:42:35.309 INFO:tasks.workunit.client.0.smithi063.stdout:return value is: 0
+2021-11-26T03:42:35.309 INFO:tasks.workunit.client.0.smithi063.stdout:finished writesame
+2021-11-26T03:42:35.309 INFO:tasks.workunit.client.0.smithi063.stdout:to verify the data
+2021-11-26T03:42:35.309 INFO:tasks.workunit.client.0.smithi063.stdout:verified
+2021-11-26T03:42:35.309 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:35.310 INFO:tasks.workunit.client.0.smithi063.stdout:started writesame
+2021-11-26T03:42:35.310 INFO:tasks.workunit.client.0.smithi063.stdout:expected fail, finished writesame
+2021-11-26T03:42:35.310 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:35.310 INFO:tasks.workunit.client.0.smithi063.stdout:started writesame
+2021-11-26T03:42:35.311 INFO:tasks.workunit.client.0.smithi063.stdout:expected fail, finished writesame
+2021-11-26T03:42:35.311 INFO:tasks.workunit.client.0.smithi063.stdout:read completion cb called!
+2021-11-26T03:42:35.311 INFO:tasks.workunit.client.0.smithi063.stdout:read completion cb called!
+2021-11-26T03:42:35.311 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:35.312 INFO:tasks.workunit.client.0.smithi063.stdout:read completion cb called!
+2021-11-26T03:42:35.312 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 4
+2021-11-26T03:42:35.312 INFO:tasks.workunit.client.0.smithi063.stdout:read: 4
+2021-11-26T03:42:35.312 INFO:tasks.workunit.client.0.smithi063.stdout:read: --42
+2021-11-26T03:42:35.313 INFO:tasks.workunit.client.0.smithi063.stdout:expected: test
+2021-11-26T03:42:35.313 INFO:tasks.workunit.client.0.smithi063.stdout:/build/ceph-16.2.6-681-gfdc003bc/src/test/librbd/test_librbd.cc:364: Failure
+2021-11-26T03:42:35.313 INFO:tasks.workunit.client.0.smithi063.stdout:Expected equality of these values:
+2021-11-26T03:42:35.313 INFO:tasks.workunit.client.0.smithi063.stdout:  0
+2021-11-26T03:42:35.313 INFO:tasks.workunit.client.0.smithi063.stdout:  memcmp(result, expected, len)
+2021-11-26T03:42:35.314 INFO:tasks.workunit.client.0.smithi063.stdout:    Which is: -1
+2021-11-26T03:42:35.317 INFO:tasks.workunit.client.0.smithi063.stdout:[  FAILED  ] TestLibRBD.TestEncryptionLUKS2 (12236 ms)
+2021-11-26T03:42:35.317 INFO:tasks.workunit.client.0.smithi063.stdout:[ RUN      ] TestLibRBD.TestIOWithIOHint
+2021-11-26T03:42:35.318 INFO:tasks.workunit.client.0.smithi063.stdout:using new format!
+2021-11-26T03:42:37.857 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:37.858 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:37.858 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:37.858 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:37.858 INFO:tasks.workunit.client.0.smithi063.stdout:wrote: 512
+2021-11-26T03:42:37.859 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:37.859 INFO:tasks.workunit.client.0.smithi063.stdout:started write
+2021-11-26T03:42:37.859 INFO:tasks.workunit.client.0.smithi063.stdout:write completion cb called!
+2021-11-26T03:42:37.859 INFO:tasks.workunit.client.0.smithi063.stdout:return value is: 0
+2021-11-26T03:42:37.859 INFO:tasks.workunit.client.0.smithi063.stdout:finished write
+2021-11-26T03:42:37.860 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:37.860 INFO:tasks.workunit.client.0.smithi063.stdout:started write
+2021-11-26T03:42:37.860 INFO:tasks.workunit.client.0.smithi063.stdout:write completion cb called!
+2021-11-26T03:42:37.860 INFO:tasks.workunit.client.0.smithi063.stdout:return value is: 0
+2021-11-26T03:42:37.861 INFO:tasks.workunit.client.0.smithi063.stdout:finished write
+2021-11-26T03:42:37.861 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:37.861 INFO:tasks.workunit.client.0.smithi063.stdout:started write
+2021-11-26T03:42:37.861 INFO:tasks.workunit.client.0.smithi063.stdout:write completion cb called!
+2021-11-26T03:42:37.862 INFO:tasks.workunit.client.0.smithi063.stdout:return value is: 0
+2021-11-26T03:42:37.862 INFO:tasks.workunit.client.0.smithi063.stdout:finished write
+2021-11-26T03:42:37.862 INFO:tasks.workunit.client.0.smithi063.stdout:created completion
+2021-11-26T03:42:37.862 INFO:tasks.workunit.client.0.smithi063.stdout:started write
+2021-11-26T03:42:37.862 INFO:tasks.workunit.client.0.smithi063.stdout:write completion cb called!
+2021-11-26T03:42:37.863 INFO:tasks.workunit.client.0.smithi063.stdout:return value is: 0
+

diff --git a/teuthology/orchestra/test/teuth_log/s3_failure_teuth.log b/teuthology/orchestra/test/teuth_log/s3_failure_teuth.log
new file mode 100644 (file)
index 0000000..5070136
--- /dev/null
+++ b/teuthology/orchestra/test/teuth_log/s3_failure_teuth.log
@@ -0,0 +1,49 @@
+2021-11-29T07:42:27.833 INFO:teuthology.orchestra.run.smithi053.stdout:Best match: botocore 1.23.14
+2021-11-29T07:42:27.833 INFO:teuthology.orchestra.run.smithi053.stdout:Adding botocore 1.23.14 to easy-install.pth file
+2021-11-29T07:42:27.833 INFO:teuthology.orchestra.run.smithi053.stdout:
+2021-11-29T07:42:27.833 INFO:teuthology.orchestra.run.smithi053.stdout:Using /home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages
+2021-11-29T07:42:27.834 INFO:teuthology.orchestra.run.smithi053.stdout:Searching for urllib3==1.26.7
+2021-11-29T07:42:27.834 INFO:teuthology.orchestra.run.smithi053.stdout:Best match: urllib3 1.26.7
+2021-11-29T07:42:27.834 INFO:teuthology.orchestra.run.smithi053.stdout:Adding urllib3 1.26.7 to easy-install.pth file
+2021-11-29T07:42:27.834 INFO:teuthology.orchestra.run.smithi053.stdout:
+2021-11-29T07:42:27.835 INFO:teuthology.orchestra.run.smithi053.stdout:Using /home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages
+2021-11-29T07:42:27.835 INFO:teuthology.orchestra.run.smithi053.stdout:Searching for python-dateutil==2.8.2
+2021-11-29T07:42:27.835 INFO:teuthology.orchestra.run.smithi053.stdout:Best match: python-dateutil 2.8.2
+2021-11-29T07:42:27.835 INFO:teuthology.orchestra.run.smithi053.stdout:Adding python-dateutil 2.8.2 to easy-install.pth file
+2021-11-29T07:42:27.836 INFO:teuthology.orchestra.run.smithi053.stdout:
+2021-11-29T07:42:27.836 INFO:teuthology.orchestra.run.smithi053.stdout:Using /home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages
+2021-11-29T07:42:27.836 INFO:teuthology.orchestra.run.smithi053.stdout:Finished processing dependencies for s3tests==0.0.1
+2021-11-29T07:42:27.840 DEBUG:teuthology.orchestra.run.smithi053:> set -ex
+2021-11-29T07:42:27.840 DEBUG:teuthology.orchestra.run.smithi053:> dd of=/home/ubuntu/cephtest/archive/s3-tests.client.0.conf
+2021-11-29T07:42:27.855 INFO:tasks.s3tests:Configuring boto...
+2021-11-29T07:42:27.856 DEBUG:teuthology.orchestra.run.smithi053:> set -ex
+2021-11-29T07:42:27.856 DEBUG:teuthology.orchestra.run.smithi053:> dd of=/home/ubuntu/cephtest/boto.cfg
+2021-11-29T07:42:27.910 DEBUG:teuthology.orchestra.run.smithi053:s3 tests against rgw> S3TEST_CONF=/home/ubuntu/cephtest/archive/s3-tests.client.0.conf BOTO_CONFIG=/home/ubuntu/cephtest/boto.cfg REQUESTS_CA_BUNDLE=/etc/pki/tls/certs/ca-bundle.crt /home/ubuntu/cephtest/s3-tests/virtualenv/bin/python -m nose -w /home/ubuntu/cephtest/s3-tests -v -a test_of_sts
+2021-11-29T07:42:28.691 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_get_session_token ... ok
+2021-11-29T07:42:28.722 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_get_session_token_permanent_creds_denied ... ok
+2021-11-29T07:42:28.852 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_assume_role_allow ... ok
+2021-11-29T07:42:28.954 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_assume_role_deny ... ok
+2021-11-29T07:57:29.138 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_assume_role_creds_expiry ... ok
+2021-11-29T07:57:29.258 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_assume_role_deny_head_nonexistent ... ok
+2021-11-29T07:57:29.561 INFO:teuthology.orchestra.run.smithi053.stderr:s3tests_boto3.functional.test_sts.test_assume_role_allow_head_nonexistent ... ok
+2021-11-29T07:57:29.561 INFO:teuthology.orchestra.run.smithi053.stderr:ERROR
+2021-11-29T07:57:29.562 INFO:teuthology.orchestra.run.smithi053.stderr:
+2021-11-29T07:57:29.562 INFO:teuthology.orchestra.run.smithi053.stderr:======================================================================
+2021-11-29T07:57:29.563 INFO:teuthology.orchestra.run.smithi053.stderr:ERROR: test suite for <module 's3tests_boto3.functional' from '/home/ubuntu/cephtest/s3-tests/s3tests_boto3/functional/__init__.py'>
+2021-11-29T07:57:29.563 INFO:teuthology.orchestra.run.smithi053.stderr:----------------------------------------------------------------------
+2021-11-29T07:57:29.563 INFO:teuthology.orchestra.run.smithi053.stderr:Traceback (most recent call last):
+2021-11-29T07:57:29.564 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages/nose/suite.py", line 229, in run
+2021-11-29T07:57:29.564 INFO:teuthology.orchestra.run.smithi053.stderr:    self.tearDown()
+2021-11-29T07:57:29.564 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages/nose/suite.py", line 352, in tearDown
+2021-11-29T07:57:29.565 INFO:teuthology.orchestra.run.smithi053.stderr:    self.teardownContext(ancestor)
+2021-11-29T07:57:29.565 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages/nose/suite.py", line 368, in teardownContext
+2021-11-29T07:57:29.566 INFO:teuthology.orchestra.run.smithi053.stderr:    try_run(context, names)
+2021-11-29T07:57:29.566 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/virtualenv/lib/python3.6/site-packages/nose/util.py", line 471, in try_run
+2021-11-29T07:57:29.566 INFO:teuthology.orchestra.run.smithi053.stderr:    return func()
+2021-11-29T07:57:29.567 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/s3tests_boto3/functional/__init__.py", line 259, in teardown
+2021-11-29T07:57:29.567 INFO:teuthology.orchestra.run.smithi053.stderr:    nuke_prefixed_buckets(prefix=prefix, client=alt_client)
+2021-11-29T07:57:29.568 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/s3tests_boto3/functional/__init__.py", line 148, in nuke_prefixed_buckets
+2021-11-29T07:57:29.569 INFO:teuthology.orchestra.run.smithi053.stderr:    buckets = get_buckets_list(client, prefix)
+2021-11-29T07:57:29.569 INFO:teuthology.orchestra.run.smithi053.stderr:  File "/home/ubuntu/cephtest/s3-tests/s3tests_boto3/functional/__init__.py", line 54, in get_buckets_list
+2021-11-29T07:57:29.569 INFO:teuthology.orchestra.run.smithi053.stderr:    response = client.list_buckets()
+