From: Kamoltat Sirivadhna Date: Thu, 30 Sep 2021 14:34:50 +0000 (-0400) Subject: orch/run: Added scan_unit_test_error X-Git-Url: http://git.apps.os.sepia.ceph.com/?a=commitdiff_plain;h=19e2759e79ee9cd7805b97c66a34e14355322153;p=teuthology.git 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 --- diff --git a/teuthology/exceptions.py b/teuthology/exceptions.py index a33cec0415..7b3c85f210 100644 --- 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 f31dfd0d7f..27412a0f0e 100644 --- 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 index 0000000000..ac5f9e67ae --- /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 ") + + @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 index 0000000000..b11e01bdf0 --- /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 index 0000000000..5070136627 --- /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 +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() +