Add loganalyzer for sairedis for advanced reboot tests

ansible/roles/test/files/tools/loganalyzer/loganalyzer.py

@@ -105,6 +105,11 @@ def is_filename_stdin(self, file_name):
 
     #---------------------------------------------------------------------
 
+    def is_filename_sairedis_rec(self, file_name):
+        return "sairedis.rec" in file_name
+
+    #---------------------------------------------------------------------
+
     def create_end_marker(self):
         return self.end_marker_prefix + "-" + self.run_id
     #---------------------------------------------------------------------
@@ -313,6 +318,7 @@ def analyze_file(self, log_file_path, match_messages_regex, ignore_messages_rege
 
         #-- indicates whether log analyzer currently is in the log range between start
         #-- and end marker. see analyze_file method.
+        is_sairedis_rec = self.is_filename_sairedis_rec(log_file_path)
         in_analysis_range = False
         stdin_as_input = self.is_filename_stdin(log_file_path)
         matching_lines = []
@@ -354,15 +360,19 @@ def analyze_file(self, log_file_path, match_messages_regex, ignore_messages_rege
                     in_analysis_range = False
                     break
 
-            if in_analysis_range :
+            if in_analysis_range or is_sairedis_rec:
+                # Skip long logs in sairedis recording since most likely they are bulk set operations for non-default routes
+                # without much insight while they are time consuming to analyze
+                if is_sairedis_rec and len(rev_line) > 1000:
+                    continue
                 if self.line_is_expected(rev_line, expect_messages_regex):
                     expected_lines.append(rev_line)
 
                 elif self.line_matches(rev_line, match_messages_regex, ignore_messages_regex):
                     matching_lines.append(rev_line)
 
-        # care about the markers only if input is not stdin
-        if not stdin_as_input:
+        # care about the markers only if input is not stdin or sairedis recording
+        if not stdin_as_input and not is_sairedis_rec:
             if (not found_start_marker):
                 print 'ERROR: start marker was not found'
                 sys.exit(err_no_start_marker)

tests/common/plugins/loganalyzer/loganalyzer.py

@@ -17,15 +17,14 @@
 COMMON_EXPECT = join(split(__file__)[0], "loganalyzer_common_expect.txt")
 SYSLOG_TMP_FOLDER = "/tmp/syslog"
 
-
 class LogAnalyzerError(Exception):
     """Raised when loganalyzer found matches during analysis phase."""
     def __repr__(self):
         return pprint.pformat(self.message)
 
 
 class LogAnalyzer:
-    def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp", start_marker=None):
+    def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp", start_marker=None, additional_files=[], additional_start_str=[]):
         self.ansible_host = ansible_host
         self.dut_run_dir = dut_run_dir
         self.extracted_syslog = os.path.join(self.dut_run_dir, "syslog")
@@ -40,6 +39,10 @@ def __init__(self, ansible_host, marker_prefix, dut_run_dir="/tmp", start_marker
         self.expected_matches_target = 0
         self._markers = []
         self.fail = True
+        self.additional_files = additional_files
+        self.additional_start_str = additional_start_str
+        if self.additional_files and self.additional_start_str and len(self.additional_files) != len(self.additional_start_str):
+            raise Exception("Additional file length does not match additional start markers")
 
     def _add_end_marker(self, marker):
         """
@@ -176,7 +179,8 @@ def analyze(self, marker, fail=True):
                             "expect_messages": {},
                             "unused_expected_regexp": []
                             }
-        tmp_folder = ".".join((SYSLOG_TMP_FOLDER, time.strftime("%Y-%m-%d-%H:%M:%S", time.gmtime())))
+        timestamp = time.strftime("%Y-%m-%d-%H:%M:%S", time.gmtime())
+        tmp_folder = ".".join((SYSLOG_TMP_FOLDER, timestamp))
         marker = marker.replace(' ', '_')
         self.ansible_loganalyzer.run_id = marker
 
@@ -209,22 +213,39 @@ def analyze(self, marker, fail=True):
 
             # On DUT extract syslog files from /var/log/ and create one file by location - /tmp/syslog
             self.ansible_host.extract_log(directory='/var/log', file_prefix='syslog', start_string=start_string, target_filename=self.extracted_syslog)
+            for idx, path in enumerate(self.additional_files):
+                file_dir, file_name = split(path)
+                extracted_file_name = os.path.join(self.dut_run_dir, file_name)
+                if self.additional_start_str and self.additional_start_str[idx] != '':
+                    start_str = self.additional_start_str[idx]
+                else:
+                    start_str = start_string
+                self.ansible_host.extract_log(directory=file_dir, file_prefix=file_name, start_string=start_str, target_filename=extracted_file_name)
         finally:
             # Enable logrotate cron task back
             self.ansible_host.command("sed -i 's/^#//g' /etc/cron.d/logrotate")
 
         # Download extracted logs from the DUT to the temporal folder defined in SYSLOG_TMP_FOLDER
         self.save_extracted_log(dest=tmp_folder)
+        file_list = [tmp_folder]
+
+        for idx, path in enumerate(self.additional_files):
+            file_dir, file_name = split(path)
+            extracted_file_name = os.path.join(self.dut_run_dir, file_name)
+            tmp_folder = ".".join((extracted_file_name, timestamp))
+            self.save_extracted_file(dest=tmp_folder, src=extracted_file_name)
+            file_list.append(tmp_folder)
 
         match_messages_regex = re.compile('|'.join(self.match_regex)) if len(self.match_regex) else None
         ignore_messages_regex = re.compile('|'.join(self.ignore_regex)) if len(self.ignore_regex) else None
         expect_messages_regex = re.compile('|'.join(self.expect_regex)) if len(self.expect_regex) else None
 
-        analyzer_parse_result = self.ansible_loganalyzer.analyze_file_list([tmp_folder], match_messages_regex, ignore_messages_regex, expect_messages_regex)
-        # Print syslog file content and remove the file
-        with open(tmp_folder) as fo:
-            logging.debug("Syslog content:\n\n{}".format(fo.read()))
-        os.remove(tmp_folder)
+        analyzer_parse_result = self.ansible_loganalyzer.analyze_file_list(file_list, match_messages_regex, ignore_messages_regex, expect_messages_regex)
+        # Print file content and remove the file
+        for folder in file_list:
+            with open(folder) as fo:
+                logging.debug("{} file content:\n\n{}".format(folder, fo.read()))
+            os.remove(folder)
 
         total_match_cnt = 0
         total_expect_cnt = 0
@@ -262,3 +283,13 @@ def save_extracted_log(self, dest):
         @param dest: File path to store downloaded log file.
         """
         self.ansible_host.fetch(dest=dest, src=self.extracted_syslog, flat="yes")
+
+    def save_extracted_file(self, dest, src):
+        """
+        @summary: Download extracted file to the ansible host.
+
+        @param dest: File path to store downloaded file.
+
+        @param src: Source path to store downloaded file.
+        """
+        self.ansible_host.fetch(dest=dest, src=src, flat="yes")

tests/platform_tests/conftest.py

@@ -74,7 +74,8 @@ def advanceboot_loganalyzer(duthosts, rand_one_dut_hostname, request):
         rand_one_dut_hostname: hostname of a randomly selected DUT
     """
     duthost = duthosts[rand_one_dut_hostname]
-    loganalyzer = LogAnalyzer(ansible_host=duthost, marker_prefix="test_advanced_reboot")
+    loganalyzer = LogAnalyzer(ansible_host=duthost, marker_prefix="test_advanced_reboot", 
+                    additional_files=['/var/log/swss/sairedis.rec'], additional_start_str=['recording on: /var/log/swss/sairedis.rec'])
     marker = loganalyzer.init()
     loganalyzer.load_common_config()
 
@@ -91,69 +92,91 @@ def advanceboot_loganalyzer(duthosts, rand_one_dut_hostname, request):
     yield
 
     result = loganalyzer.analyze(marker, fail=False)
-    messages = result["expect_messages"].values()
-    if not messages:
-        logging.error("Expected messages not found in syslog")
-        return
-    messages = messages[0]
-
-    service_restart_times = dict()
-    service_patterns = {
-        "Stopping": re.compile(r'.*Stopping.*service.*'),
-        "Stopped": re.compile(r'.*Stopped.*service.*'),
-        "Starting": re.compile(r'.*Starting.*service.*'),
-        "Started": re.compile(r'.*Started.*service.*')
-    }
-
-    def service_time_check(message, status):
-        time = message.split(duthost.hostname)[0].strip()
-        service_name = message.split(status + " ")[1].split()[0]
-        service_dict = service_restart_times.get(service_name, {"timestamp": {}})
-        timestamps = service_dict.get("timestamp")
-        if status in timestamps:
-            service_dict[status+" count"] = service_dict.get(status+" count", 1) + 1
-        timestamps[status] = time
-        service_restart_times.update({service_name: service_dict})
-
-    for message in messages:
-        for status, pattern in service_patterns.items():
-            if re.search(pattern, message):
-                service_time_check(message, status)
-
-    loganalyzer.save_extracted_log(dest="/tmp/log/syslog")
-    logging.info(json.dumps(service_restart_times, indent=4))
-
-    FMT = "%b %d %H:%M:%S.%f"
-    for _, timings in service_restart_times.items():
-        timestamps = timings["timestamp"]
-        timings["stop_time"] = (datetime.strptime(timestamps["Stopped"], FMT) -\
-            datetime.strptime(timestamps["Stopping"], FMT)).total_seconds() \
-                if "Stopped" in timestamps and "Stopping" in timestamps else None
-
-        timings["start_time"] = (datetime.strptime(timestamps["Started"], FMT) -\
-            datetime.strptime(timestamps["Starting"], FMT)).total_seconds() \
-                if "Started" in timestamps and "Starting" in timestamps else None
-
-        timings["reboot_time"] = (datetime.strptime(timestamps["Started"], FMT) -\
-            datetime.strptime(timestamps["Stopped"], FMT)).total_seconds() \
-                if "Started" in timestamps and "Stopped" in timestamps else None
-
-    files = glob.glob('/tmp/*-report.json')
-    if files:
-        filepath = files[0]
-        with open(filepath) as json_file:
-            report = json.load(json_file)
-            service_restart_times.update(report)
-    result = service_restart_times
-    logging.info(json.dumps(result, indent=4))
+    analyze_result = dict()
+    for key, messages in result["expect_messages"].items():
+        if "syslog" in key:
+            if not messages:
+                logging.error("Expected messages not found in syslog")
+                return
+
+            service_restart_times = dict()
+            service_patterns = {
+                "Stopping": re.compile(r'.*Stopping.*service.*'),
+                "Stopped": re.compile(r'.*Stopped.*service.*'),
+                "Starting": re.compile(r'.*Starting.*service.*'),
+                "Started": re.compile(r'.*Started.*service.*')
+            }
+
+            def service_time_check(message, status):
+                time = message.split(duthost.hostname)[0].strip()
+                service_name = message.split(status + " ")[1].split()[0]
+                service_dict = service_restart_times.get(service_name, {"timestamp": {}})
+                timestamps = service_dict.get("timestamp")
+                if status in timestamps:
+                    service_dict[status+" count"] = service_dict.get(status+" count", 1) + 1
+                timestamps[status] = time
+                service_restart_times.update({service_name: service_dict})
+
+            for message in messages:
+                for status, pattern in service_patterns.items():
+                    if re.search(pattern, message):
+                        service_time_check(message, status)
+
+            loganalyzer.save_extracted_log(dest="/tmp/log/syslog")
+            logging.info(json.dumps(service_restart_times, indent=4))
+
+            FMT = "%b %d %H:%M:%S.%f"
+            for _, timings in service_restart_times.items():
+                timestamps = timings["timestamp"]
+                timings["stop_time"] = (datetime.strptime(timestamps["Stopped"], FMT) -\
+                    datetime.strptime(timestamps["Stopping"], FMT)).total_seconds() \
+                        if "Stopped" in timestamps and "Stopping" in timestamps else None
+
+                timings["start_time"] = (datetime.strptime(timestamps["Started"], FMT) -\
+                    datetime.strptime(timestamps["Starting"], FMT)).total_seconds() \
+                        if "Started" in timestamps and "Starting" in timestamps else None
+
+                timings["reboot_time"] = (datetime.strptime(timestamps["Started"], FMT) -\
+                    datetime.strptime(timestamps["Stopped"], FMT)).total_seconds() \
+                        if "Started" in timestamps and "Stopped" in timestamps else None
+
+            files = glob.glob('/tmp/*-report.json')
+            if files:
+                filepath = files[0]
+                with open(filepath) as json_file:
+                    report = json.load(json_file)
+                    service_restart_times.update(report)
+            analyze_result["Services"] = service_restart_times
+            logging.info(json.dumps(analyze_result["Services"], indent=4))
+
+        elif "sairedis.rec" in key:
+            state_times = dict()
+            state_patterns = {
+                "Start creating switch": re.compile(r'.*\|c\|SAI_OBJECT_TYPE_SWITCH.*'),
+                "Finish creating switch": re.compile(r'.*\|g\|SAI_OBJECT_TYPE_SWITCH.*SAI_SWITCH_ATTR_DEFAULT_VIRTUAL_ROUTER_ID.*'),
+                "Set default route": re.compile(r'.*\|S\|SAI_OBJECT_TYPE_ROUTE_ENTRY.*0\.0\.0\.0/0.*SAI_ROUTE_ENTRY_ATTR_PACKET_ACTION=SAI_PACKET_ACTION_FORWARD.*')
+            }
+            states = ["Start creating switch", "Finish creating switch", "Set default route"]
+
+            for message in messages:
+                for state, pattern in state_patterns.items():
+                    if re.search(pattern, message):
+                        timestamp = message.split("|")[0].strip()
+                        state_times[state] = timestamp
+
+            for state in states:
+                logging.info("{:25s} : {}".format(state, state_times[state] if state in state_times else "N/A"))
+
+            analyze_result["sairedis_state"] = state_times
+
     report_file_name = request.node.name + "_report.json"
     report_file_dir = os.path.realpath((os.path.join(os.path.dirname(__file__),\
         "../logs/platform_tests/")))
     report_file_path = report_file_dir + "/" + report_file_name
     if not os.path.exists(report_file_dir):
         os.makedirs(report_file_dir)
     with open(report_file_path, 'w') as fp:
-        json.dump(result, fp, indent=4)
+        json.dump(analyze_result, fp, indent=4)
 
 
 def pytest_addoption(parser):

tests/platform_tests/templates/expect_boot_messages

@@ -1,4 +1,7 @@
 r, ".* NOTICE admin: (Stopping|Stopped|Starting|Started).* (?!syncd|swss|gbsyncd).* service.*"
 r, ".* NOTICE admin: Stopped.* swss.* service.*"
 r, ".* NOTICE root: (Stopping|Stopped|Starting|Started).* (swss|syncd|gbsyncd).* service.*"
-r, ".* NOTICE root: WARMBOOT_FINALIZER.*"
+r, ".* NOTICE root: WARMBOOT_FINALIZER.*"
+r, ".*\|c\|SAI_OBJECT_TYPE_SWITCH.*"
+r, ".*\|g\|SAI_OBJECT_TYPE_SWITCH.*SAI_SWITCH_ATTR_DEFAULT_VIRTUAL_ROUTER_ID.*"
+r, ".*\|S\|SAI_OBJECT_TYPE_ROUTE_ENTRY.*0\.0\.0\.0/0.*SAI_ROUTE_ENTRY_ATTR_PACKET_ACTION=SAI_PACKET_ACTION_FORWARD.*"