orch/run: Scan teuthology log files for unit test errors

- Scan teuthology log files from bottom	up
- Keep a flag to keep track of line-number till	which logs were	last scanned
  Do not scan above this flag index.
- Raise UnitTestError with error message found in log files

Signed-off-by: Vallari Agrawal <val.agl002@gmail.com>

diff --git a/teuthology/exceptions.py b/teuthology/exceptions.py
index 3939ba53c6434202b266cc7f2a26f14358c67c8d..c02eed4f68aa4c6f17861659905d93ec1ce0ca33 100644 (file)
--- a/teuthology/exceptions.py
+++ b/teuthology/exceptions.py
@@ -205,3 +205,27 @@ class NoRemoteError(Exception):
 
     def __str__(self):
         return self.message
+
+
+class UnitTestError(Exception):
+    """
+    Exception thrown on unit test failure
+    """
+    def __init__(self, command, exitstatus, node=None, label=None, message=""):
+        self.command = command
+        self.exitstatus = exitstatus
+        self.node = node
+        self.label = label
+        self.message = message
+
+    def __str__(self):
+        prefix = "Unit test failed"
+        if self.label:
+            prefix += " ({label})".format(label=self.label)
+        if self.node:
+            prefix += " on {node}".format(node=self.node)
+        return "{prefix} with status {status}: {message}".format(
+            prefix=prefix,
+            status=self.exitstatus,
+            message=self.message,
+        )

diff --git a/teuthology/orchestra/run.py b/teuthology/orchestra/run.py
index f31dfd0d7fc1db89feab1f67abdc95c809a9731d..eab28ed4951a020c473726f1743c5e138e886151 100644 (file)
--- a/teuthology/orchestra/run.py
+++ b/teuthology/orchestra/run.py
@@ -2,7 +2,7 @@
 Paramiko run support
 """
 
-import io
+import io, re
 
 from paramiko import ChannelFile
 
@@ -15,7 +15,7 @@ import shutil
 
 from teuthology.contextutil import safe_while
 from teuthology.exceptions import (CommandCrashedError, CommandFailedError,
-                                   ConnectionLostError)
+                                   ConnectionLostError, UnitTestError)
 
 log = logging.getLogger(__name__)
 
@@ -34,30 +34,33 @@ class RemoteProcess(object):
         # for orchestra.remote.Remote to place a backreference
         'remote',
         'label',
+        'scan_tests_errors',
         ]
 
     deadlock_warning = "Using PIPE for %s without wait=False would deadlock"
 
     def __init__(self, client, args, check_status=True, hostname=None,
-                 label=None, timeout=None, wait=True, logger=None, cwd=None):
+                 label=None, timeout=None, wait=True, logger=None, cwd=None, scan_tests_errors=[]):
         """
         Create the object. Does not initiate command execution.
 
-        :param client:       paramiko.SSHConnection to run the command with
-        :param args:         Command to run.
-        :type args:          String or list of strings
-        :param check_status: Whether to raise CommandFailedError on non-zero
-                             exit status, and . Defaults to True. All signals
-                             and connection loss are made to look like SIGHUP.
-        :param hostname:     Name of remote host (optional)
-        :param label:        Can be used to label or describe what the
-                             command is doing.
-        :param timeout:      timeout value for arg that is passed to
-                             exec_command of paramiko
-        :param wait:         Whether self.wait() will be called automatically
-        :param logger:       Alternative logger to use (optional)
-        :param cwd:          Directory in which the command will be executed
-                             (optional)
+        :param client:            paramiko.SSHConnection to run the command with
+        :param args:              Command to run.
+        :type args:               String or list of strings
+        :param check_status:      Whether to raise CommandFailedError on non-zero
+                                  exit status, and . Defaults to True. All signals
+                                  and connection loss are made to look like SIGHUP.
+        :param hostname:          Name of remote host (optional)
+        :param label:             Can be used to label or describe what the
+                                  command is doing.
+        :param timeout:           timeout value for arg that is passed to
+                                  exec_command of paramiko
+        :param wait:              Whether self.wait() will be called automatically
+        :param logger:            Alternative logger to use (optional)
+        :param cwd:               Directory in which the command will be executed
+                                  (optional)
+        :param scan_tests_errors: name of unit tests for which logs need to 
+                                  be scanned to look for errors (optional)
         """
         self.client = client
         self.args = args
@@ -84,6 +87,7 @@ class RemoteProcess(object):
         self.returncode = self.exitstatus = None
         self._wait = wait
         self.logger = logger or log
+        self.scan_tests_errors = scan_tests_errors
 
     def execute(self):
         """
@@ -178,6 +182,14 @@ class RemoteProcess(object):
                 # signal; sadly SSH does not tell us which signal
                 raise CommandCrashedError(command=self.command)
             if self.returncode != 0:
+                if self.scan_tests_errors:
+                    error = ErrorScanner(self.scan_tests_errors).scan()
+                    if error:
+                        raise UnitTestError(
+                            command=self.command, exitstatus=self.returncode,
+                            node=self.hostname, label=self.label,
+                            message=error,
+                        )            
                 raise CommandFailedError(
                     command=self.command, exitstatus=self.returncode,
                     node=self.hostname, label=self.label
@@ -221,6 +233,46 @@ class RemoteProcess(object):
             name=self.hostname,
             )
 
+class ErrorScanner(object):
+    """
+    Scan for unit tests errors in teuthology.log 
+    """
+    __flag__ = 0
+    def __init__(self, test_names=[]):
+        self.test_names = test_names
+
+    def scan(self):
+        logfile = self.__logfile__
+        if not logfile or not self.test_names:
+            return None
+        
+        ERROR_PATTERN = {
+            "nose": r"ERROR:\s",
+            "gtest":  r"\[\s\sFAILED\s\s\]",
+        }
+        logs = []
+        with open(logfile, 'r') as f:
+            logs = f.readlines()
+
+        for line_number in range(len(logs) - 1, ErrorScanner.__flag__, -1):
+            line = logs[line_number]
+            for test in self.test_names:
+                pattern = ERROR_PATTERN[test]
+                error = re.search(pattern, line)
+                if error:
+                    ErrorScanner.__flag__ = line_number
+                    return line[error.start():].strip()
+        ErrorScanner.__flag__ = len(logs) - 1
+        return None 
+
+    @property
+    def __logfile__(self):
+        loggers = logging.getLogger()
+        for h in loggers.handlers:
+            if isinstance(h, logging.FileHandler):
+                return h.stream.name
+        return None
+
 
 class Raw(object):
 
@@ -394,6 +446,7 @@ def run(
     quiet=False,
     timeout=None,
     cwd=None,
+    scan_tests_errors=[],
     # omit_sudo is used by vstart_runner.py
     omit_sudo=False
 ):
@@ -429,6 +482,8 @@ def run(
     :param timeout: timeout value for args to complete on remote channel of
                     paramiko
     :param cwd: Directory in which the command should be executed.
+    :param scan_tests_errors: List of unit-tests names for which teuthology logs would 
+                              be scanned to look for errors.
     """
     try:
         transport = client.get_transport()
@@ -446,7 +501,7 @@ def run(
         log.info("Running command with timeout %d", timeout)
     r = RemoteProcess(client, args, check_status=check_status, hostname=name,
                       label=label, timeout=timeout, wait=wait, logger=logger,
-                      cwd=cwd)
+                      cwd=cwd, scan_tests_errors=scan_tests_errors)
     r.execute()
     r.setup_stdin(stdin)
     r.setup_output_stream(stderr, 'stderr', quiet)

diff --git a/teuthology/orchestra/test/log_files/test_scan_gtest.log b/teuthology/orchestra/test/log_files/test_scan_gtest.log
new file mode 100644 (file)
index 0000000..ed2504f
--- /dev/null
+++ b/teuthology/orchestra/test/log_files/test_scan_gtest.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  ] FIRST 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:35.317 INFO:tasks.workunit.client.0.smithi063.stdout:[  FAILED  ] SECOND TestLibRBD.TestEncryptionLUKS2 (12236 ms)
+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
\ No newline at end of file

diff --git a/teuthology/orchestra/test/log_files/test_scan_nose.log b/teuthology/orchestra/test/log_files/test_scan_nose.log
new file mode 100644 (file)
index 0000000..0569dd2
--- /dev/null
+++ b/teuthology/orchestra/test/log_files/test_scan_nose.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: FIRST 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.563 INFO:teuthology.orchestra.run.smithi053.stderr:ERROR: SECOND suite for <module 's3tests_boto3.functional' from '/home/ubuntu/cephtest/s3-tests/s3tests_boto3/functional/__init__.py'>
+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()
\ No newline at end of file