Timeout and Retry FTL failures and mark flakiness

Author: sunmou99

.github/workflows/integration_tests.yml

@@ -840,6 +840,7 @@ jobs:
         if: steps.get-device-type.outputs.device_type == 'real'
         uses: google-github-actions/setup-gcloud@master
       - name: Run Android integration tests on Real Device via FTL
+        timeout-minutes: 60
         if: steps.get-device-type.outputs.device_type == 'real'
         run: |
           python scripts/gha/restore_secrets.py --passphrase "${{ secrets.TEST_SECRET }}"
@@ -934,6 +935,8 @@ jobs:
         if: steps.get-device-type.outputs.device_type == 'real'
         uses: google-github-actions/setup-gcloud@master
       - name: Run iOS integration tests on Real Device via FTL
+        # max 3 retry and 10m timeout for each testapp, plus other steps
+        timeout-minutes: 60 
         if: steps.get-device-type.outputs.device_type == 'real'
         run: |
           python scripts/gha/restore_secrets.py --passphrase "${{ secrets.TEST_SECRET }}"

scripts/gha/integration_testing/test_validation.py

@@ -150,6 +150,7 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
   successes = []
   failures = []
   errors = []
+  success_testapp_paths = set()
 
   for test in tests:
     results = validate_results(test.logs, platform)
@@ -160,6 +161,7 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
       failures.append(test_result_pair)
     else:
       successes.append(test_result_pair)
+      success_testapp_paths.add(test.testapp_path)
 
   # First log the successes, then the failures and errors, then the summary.
   # This way, debugging will involve checking the summary at the bottom,
@@ -174,6 +176,11 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
   for test, _ in errors:
     logging.info("%s didn't finish normally.\n%s", test.testapp_path, test.logs)
 
+  # Testapps that failed first, but succeed after retry. (max 3 retry)
+  flaky_testapps = []
+  failures_exclude_flakiness = []
+  errors_exclude_flakiness = []
+
   # The summary is much more terse, to minimize the time it takes to understand
   # what went wrong, without necessarily providing full debugging context.
   summary = []
@@ -184,7 +191,12 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
   if errors:
     summary.append("\n%d TESTAPPS EXPERIENCED ERRORS:" % len(errors))
     for test, results in errors:
-      summary.append("%s:" % test.testapp_path)
+      summary.append("\n%s:" % test.testapp_path)
+      if test.testapp_path in success_testapp_paths:
+        summary.append("THIS TESTAPP IS FLAKY")
+        flaky_testapps.append((test, results))
+      else:
+        errors_exclude_flakiness.append((test, results))
       if hasattr(test, "ftl_link") and test.ftl_link:
         summary.append("ftl_link: %s" % test.ftl_link)
       if hasattr(test, "raw_result_link") and test.raw_result_link:
@@ -198,7 +210,12 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
   if failures:
     summary.append("\n%d TESTAPPS FAILED:" % len(failures))
     for test, results in failures:
-      summary.append(test.testapp_path)
+      summary.append("\n%s:" % test.testapp_path)
+      if test.testapp_path in success_testapp_paths:
+        summary.append("THIS TESTAPP IS FLAKY")
+        flaky_testapps.append((test, results))
+      else:
+        failures_exclude_flakiness.append((test, results))
       if hasattr(test, "ftl_link") and test.ftl_link:
         summary.append("ftl_link: %s" % test.ftl_link)
       if hasattr(test, "raw_result_link") and test.raw_result_link:
@@ -208,44 +225,72 @@ def summarize_test_results(tests, platform, summary_dir, file_name="summary.log"
       "%d TESTAPPS TOTAL: %d PASSES, %d FAILURES, %d ERRORS"
       % (len(tests), len(successes), len(failures), len(errors)))
 
+  if len(flaky_testapps) > 0 and len(flaky_testapps) == len(failures) + len(errors):
+    logging.info("All failures and errors are due to flakiness.")
+    summary.append("ALL THE FOLLOWING FAILURES AND ERRORS ARE DUE TO FLAKINESS:(")
+
   # summary_json format:
   #   { "type": "test",
   #     "testapps": [testapp],
-  #     "errors": {testapp:{"log": error_log, "ftl_link": ftl_link, "raw_result_link": raw_result_link}},
-  #     "failures": {testapp:{"log": error_log, "ftl_link": ftl_link, "raw_result_link": raw_result_link,
-  #                           "failed_tests": {falied_test: test_log}}}}}
+  #     "errors": {testapp:{"logs": [error_log], "ftl_links": [ftl_link], "raw_result_links": [raw_result_link]}},
+  #     "failures": {testapp:{"logs": [error_log], "ftl_links": [ftl_link], "raw_result_links": [raw_result_link],
+  #                           "failed_tests": {failed_test: test_log}}},
+  #     "flakiness": {testapp:{"logs": [error_log], "ftl_links": [ftl_link], "raw_result_links": [raw_result_link],
+  #                           "flaky_tests": {flaky_test: test_log}}}}
   summary_json = {}
   summary_json["type"] = "test"
   summary_json["testapps"] = [get_name(test.testapp_path) for test in tests]
-  summary_json["errors"] = {get_name(test.testapp_path):{"logs": results.summary} for (test, results) in errors}
-  for (test, results) in errors:
+  summary_json["errors"] = {get_name(test.testapp_path):{"logs": [], "ftl_links": [], "raw_result_links": []} for (test, _) in errors_exclude_flakiness}
+  for (test, results) in errors_exclude_flakiness:
     testapp = get_name(test.testapp_path)
+    summary_json["errors"][testapp]["logs"].append(results.summary)
     if hasattr(test, "ftl_link") and test.ftl_link:
-      summary_json["errors"][testapp]["ftl_link"] = test.ftl_link
+      summary_json["errors"][testapp]["ftl_links"].append(test.ftl_link)
     if hasattr(test, "raw_result_link") and test.raw_result_link:
-      summary_json["errors"][testapp]["raw_result_link"] = test.raw_result_link   
-  summary_json["failures"] = {get_name(test.testapp_path):{"logs": results.summary, "failed_tests": dict()} for (test, results) in failures}
-  for (test, results) in failures:
+      summary_json["errors"][testapp]["raw_result_links"].append(test.raw_result_link)
+  summary_json["failures"] = {get_name(test.testapp_path):{"logs": [], "ftl_links": [], "raw_result_links": [], "failed_tests": dict()} for (test, _) in failures_exclude_flakiness}
+  for (test, results) in failures_exclude_flakiness:
     testapp = get_name(test.testapp_path)
+    summary_json["failures"][testapp]["logs"].append(results.summary)
     if hasattr(test, "ftl_link") and test.ftl_link:
-      summary_json["failures"][testapp]["ftl_link"] = test.ftl_link
+      summary_json["failures"][testapp]["ftl_links"].append(test.ftl_link)
     if hasattr(test, "raw_result_link") and test.raw_result_link:
-      summary_json["failures"][testapp]["raw_result_link"] = test.raw_result_link
+      summary_json["failures"][testapp]["raw_result_links"].append(test.raw_result_link)
     failed_tests = re.findall(r"\[  FAILED  \] (.+)[.](.+)", results.summary)
     for failed_test in failed_tests:
       failed_test = failed_test[0] + "." + failed_test[1]
       pattern = fr'\[ RUN      \] {failed_test}(.*?)\[  FAILED  \] {failed_test}'
       failure_log = re.search(pattern, test.logs, re.MULTILINE | re.DOTALL)
       summary_json["failures"][testapp]["failed_tests"][failed_test] = failure_log.group()
       summary.append("\n%s FAILED:\n%s\n" % (failed_test, failure_log.group()))
+  summary_json["flakiness"] = {get_name(test.testapp_path):{"logs": [], "ftl_links": [], "raw_result_links": [], "flaky_tests": dict()} for (test, _) in flaky_testapps}
+  for (test, results) in flaky_testapps:
+    testapp = get_name(test.testapp_path)
+    summary_json["flakiness"][testapp]["logs"].append(results.summary)
+    if hasattr(test, "ftl_link") and test.ftl_link:
+      summary_json["flakiness"][testapp]["ftl_links"].append(test.ftl_link)
+    if hasattr(test, "raw_result_link") and test.raw_result_link:
+      summary_json["flakiness"][testapp]["raw_result_links"].append(test.raw_result_link)
+    flaky_tests = re.findall(r"\[  FAILED  \] (.+)[.](.+)", results.summary)
+    for flaky_test in flaky_tests:
+      flaky_test = flaky_test[0] + "." + flaky_test[1]
+      pattern = fr'\[ RUN      \] {flaky_test}(.*?)\[  FAILED  \] {flaky_test}'
+      failure_log = re.search(pattern, test.logs, re.MULTILINE | re.DOTALL)
+      if failure_log:
+        summary_json["flakiness"][testapp]["flaky_tests"][flaky_test] = failure_log.group()
+        summary.append("\n%s FAILED:\n%s\n" % (flaky_test, failure_log.group()))
 
   with open(os.path.join(summary_dir, file_name+".json"), "a") as f:
     f.write(json.dumps(summary_json, indent=2))
 
   summary = "\n".join(summary)
   write_summary(summary_dir, summary, file_name)
 
-  return 0 if len(tests) == len(successes) else 1
+  # success or only flakiness
+  if len(tests) == len(successes) or len(flaky_testapps) == len(failures) + len(errors):
+    return 0
+  else:
+    return 1
 
 
 def write_summary(testapp_dir, summary, file_name="summary.log"):

scripts/gha/it_workflow.py

@@ -60,13 +60,17 @@
 _LABEL_SUCCEED = "tests: succeeded"
 
 _COMMENT_TITLE_PROGESS = "### ⏳  Integration test in progress...\n"
+_COMMENT_TITLE_PROGESS_FLAKY = "### Integration test with FLAKINESS (but still ⏳  in progress)\n" 
 _COMMENT_TITLE_PROGESS_FAIL = "### ❌  Integration test FAILED (but still ⏳  in progress)\n" 
+_COMMENT_TITLE_FLAKY = "### Integration test with FLAKINESS (succeeded after retry)\n"
 _COMMENT_TITLE_FAIL = "### ❌  Integration test FAILED\n"
 _COMMENT_TITLE_SUCCEED = "### ✅  Integration test succeeded!\n"
-_COMMENT_TITLE_FAIL_SDK = "\n***\n### ❌  Integration test FAILED (build against SDK)\n"
-_COMMENT_TITLE_SUCCEED_SDK = "\n***\n### ✅  Integration test succeeded! (build against SDK)\n"
-_COMMENT_TITLE_FAIL_REPO = "### ❌  Integration test FAILED (build against repo)\n"
-_COMMENT_TITLE_SUCCEED_REPO = "### ✅  Integration test succeeded! (build against repo)\n"
+_COMMENT_TITLE_FLAKY_SDK = "\n***\n### [build against SDK] Integration test with FLAKINESS (succeeded after retry)\n"
+_COMMENT_TITLE_FAIL_SDK = "\n***\n### ❌  [build against SDK] Integration test FAILED\n"
+_COMMENT_TITLE_SUCCEED_SDK = "\n***\n### ✅  [build against SDK] Integration test succeeded!\n"
+_COMMENT_TITLE_FLAKY_REPO = "### [build against repo] Integration test with FLAKINESS (succeeded after retry)\n"
+_COMMENT_TITLE_FAIL_REPO = "### ❌  [build against repo] Integration test FAILED\n"
+_COMMENT_TITLE_SUCCEED_REPO = "### ✅  [build against repo] Integration test succeeded!\n"
 
 _COMMENT_FLAKY_TRACKER = "\n\nAdd flaky tests to **[go/fpl-cpp-flake-tracker](http://go/fpl-cpp-flake-tracker)**\n"
 
@@ -136,12 +140,19 @@ def test_start(token, issue_number, actor, commit, run_id):
 def test_progress(token, issue_number, actor, commit, run_id):
   """In PR, when some test failed, update failure info and 
   add label \"tests: failed\""""
-  log_summary = _get_summary_talbe(token, run_id)
-  if log_summary == 0:
+  success_or_only_flakiness, log_summary = _get_summary_table(token, run_id)
+  if success_or_only_flakiness and not log_summary:
+    # succeeded (without flakiness)
     return
   else:
-    github.add_label(token, issue_number, _LABEL_FAILED)
-    comment = (_COMMENT_TITLE_PROGESS_FAIL +
+    if success_or_only_flakiness:
+      # all failures/errors are due to flakiness (succeeded after retry)
+      title = _COMMENT_TITLE_PROGESS_FLAKY
+    else:
+      # failures/errors still exist after retry
+      title = _COMMENT_TITLE_PROGESS_FAIL
+      github.add_label(token, issue_number, _LABEL_FAILED)
+    comment = (title +
                _get_description(actor, commit, run_id) +
                log_summary +
                _COMMENT_FLAKY_TRACKER +
@@ -153,16 +164,24 @@ def test_end(token, issue_number, actor, commit, run_id, new_token):
   """In PR, when some test end, update Test Result Report and 
   update label: add \"tests: failed\" if test failed, add label
   \"tests: succeeded\" if test succeed"""
-  log_summary = _get_summary_talbe(token, run_id)
-  if log_summary == 0:
+  success_or_only_flakiness, log_summary = _get_summary_table(token, run_id)
+  if success_or_only_flakiness and not log_summary:
+    # succeeded (without flakiness)
     github.add_label(token, issue_number, _LABEL_SUCCEED)
     comment = (_COMMENT_TITLE_SUCCEED +
                _get_description(actor, commit, run_id) +
                _COMMENT_SUFFIX)
     _update_comment(token, issue_number, comment)
   else:
-    github.add_label(token, issue_number, _LABEL_FAILED)
-    comment = (_COMMENT_TITLE_FAIL +
+    if success_or_only_flakiness:
+      # all failures/errors are due to flakiness (succeeded after retry)
+      title = _COMMENT_TITLE_FLAKY
+      github.add_label(token, issue_number, _LABEL_SUCCEED)
+    else:
+      # failures/errors still exist after retry
+      title = _COMMENT_TITLE_FAIL
+      github.add_label(token, issue_number, _LABEL_FAILED)
+    comment = (title +
                _get_description(actor, commit, run_id) +
                log_summary +
                _COMMENT_FLAKY_TRACKER +
@@ -180,12 +199,18 @@ def test_report(token, actor, commit, run_id, build_against):
   issue_number = _get_issue_number(token, _REPORT_TITLE, _REPORT_LABEL)
   previous_comment = github.get_issue_body(token, issue_number)
   [previous_comment_repo, previous_comment_sdk] = previous_comment.split(_COMMENT_SUFFIX)
-  log_summary = _get_summary_talbe(token, run_id)
-  if log_summary == 0:
+  success_or_only_flakiness, log_summary = _get_summary_table(token, run_id)
+  if success_or_only_flakiness and not log_summary:
+    # succeeded (without flakiness)
     title = _COMMENT_TITLE_SUCCEED_REPO if build_against==_BUILD_AGAINST_REPO else _COMMENT_TITLE_SUCCEED_SDK
     comment = title + _get_description(actor, commit, run_id)
   else:
-    title = _COMMENT_TITLE_FAIL_REPO if build_against==_BUILD_AGAINST_REPO else _COMMENT_TITLE_FAIL_SDK
+    if success_or_only_flakiness:
+      # all failures/errors are due to flakiness (succeeded after retry)
+      title = _COMMENT_TITLE_FLAKY_REPO if build_against==_BUILD_AGAINST_REPO else _COMMENT_TITLE_FLAKY_SDK
+    else:
+      # failures/errors still exist after retry
+      title = _COMMENT_TITLE_FAIL_REPO if build_against==_BUILD_AGAINST_REPO else _COMMENT_TITLE_FAIL_SDK
     comment = title + _get_description(actor, commit, run_id) + log_summary + _COMMENT_FLAKY_TRACKER
 
   if build_against==_BUILD_AGAINST_REPO:
@@ -239,16 +264,10 @@ def _get_datetime():
   return pst_now.strftime("%a %b %e %H:%M %Z %G")
 
 
-def _get_summary_talbe(token, run_id):
+def _get_summary_table(token, run_id):
   """Test Result Report Body, which is failed test table with markdown format"""
-  # artifact_id only exist after workflow finishs running
-  # Thus, "down artifact" logic is in the workflow 
-  # artifact_id = _get_artifact_id(token, run_id, _LOG_ARTIFACT_NAME)
-  # artifact_path = _LOG_ARTIFACT_NAME + ".zip"
-  # github.download_artifact(token, artifact_id, artifact_path)
-  # shutil.unpack_archive(artifact_path, _LOG_OUTPUT_DIR)
-  summary_talbe = summarize.summarize_logs(dir=_LOG_OUTPUT_DIR, markdown=True)
-  return summary_talbe
+  # return (success_or_only_flakiness, failed_test_summary_table)
+  return summarize.summarize_logs(dir=_LOG_OUTPUT_DIR, markdown=True)
 
 
 def _get_artifact_id(token, run_id, name):

scripts/gha/summarize_test_results.py

@@ -200,50 +200,57 @@ def summarize_logs(dir, markdown=False, github_log=False):
   test_log_name_re = re.escape(
       os.path.join(dir,TEST_FILE_PATTERN)).replace("\\*", "(.*)")
 
-  any_failures = False
+  success_or_only_flakiness = True
   log_data = {}
   # log_data format:
   #   { testapps: {"build": [configs]},
   #               {"test": {"errors": [configs]},
-  #                        {"failures": {failed_test: [configs]}}}}
+  #                        {"failures": {failed_test: [configs]}},
+  #                        {"flakiness": {flaky_test: [configs]}}}}
   for build_log_file in build_log_files:
     configs = get_configs_from_file_name(build_log_file, build_log_name_re)
     with open(build_log_file, "r") as log_reader:
       log_text = log_reader.read()
       if "__SUMMARY_MISSING__" in log_text:
-        any_failures = True
+        success_or_only_flakiness = False
         log_data.setdefault(MISSING_LOG, {}).setdefault("build", []).append(configs)
       else:
         log_reader_data = json.loads(log_text)
-        for (testapp, error) in log_reader_data["errors"].items():
-          any_failures = True
+        for (testapp, _) in log_reader_data["errors"].items():
+          success_or_only_flakiness = False
           log_data.setdefault(testapp, {}).setdefault("build", []).append(configs)
 
   for test_log_file in test_log_files:
     configs = get_configs_from_file_name(test_log_file, test_log_name_re)
     with open(test_log_file, "r") as log_reader:
       log_text = log_reader.read()
       if "__SUMMARY_MISSING__" in log_text:
-        any_failures = True
+        success_or_only_flakiness = False
         log_data.setdefault(MISSING_LOG, {}).setdefault("test", {}).setdefault("errors", []).append(configs)
       else:
         log_reader_data = json.loads(log_text)
-        for (testapp, error) in log_reader_data["errors"].items():
-          any_failures = True
+        for (testapp, _) in log_reader_data["errors"].items():
+          success_or_only_flakiness = False
           log_data.setdefault(testapp, {}).setdefault("test", {}).setdefault("errors", []).append(configs)
         for (testapp, failures) in log_reader_data["failures"].items():
-          for (test, failure) in failures["failed_tests"].items():
-            any_failures = True
+          for (test, _) in failures["failed_tests"].items():
+            success_or_only_flakiness = False
             log_data.setdefault(testapp, {}).setdefault("test", {}).setdefault("failures", {}).setdefault(test, []).append(configs)
-
+        for (testapp, flakiness) in log_reader_data["flakiness"].items():
+          if flakiness["flaky_tests"].items():
+            for (test, _) in flakiness["flaky_tests"].items():
+              log_data.setdefault(testapp, {}).setdefault("test", {}).setdefault("flakiness", {}).setdefault(test, []).append(configs)
+          else:
+            log_data.setdefault(testapp, {}).setdefault("test", {}).setdefault("flakiness", {}).setdefault("CRASH/TIMEOUT", []).append(configs)
+
+  if success_or_only_flakiness and not log_data:
+    # No failures and no flakiness occurred, nothing to log.
+    return (success_or_only_flakiness, None)
+
+  # if failures (include flakiness) exist:
   # log_results format:
   #   { testapps: {configs: [failed tests]} }
   log_results = reorganize_log(log_data)
-
-  if not any_failures:
-    # No failures occurred, nothing to log.
-    return(0)
-
   log_lines = []
   if markdown:
     log_lines = print_markdown_table(log_results)
@@ -255,7 +262,7 @@ def summarize_logs(dir, markdown=False, github_log=False):
 
   log_summary = "\n".join(log_lines)
   print(log_summary)
-  return log_summary
+  return (success_or_only_flakiness, log_summary)
 
 
 def get_configs_from_file_name(file_name, file_name_re):
@@ -293,6 +300,13 @@ def reorganize_log(log_data):
           all_configs = [["TEST"], ["FAILURE"], [CAPITALIZATIONS[platform]]]
           all_configs.extend(config)
           log_results.setdefault(testapp, {}).setdefault(flat_config(all_configs), []).append(test)
+    for (test, configs) in errors.get("test",{}).get("flakiness",{}).items():
+      combined_configs = combine_configs(configs)
+      for (platform, configs) in combined_configs.items():
+        for config in configs:
+          all_configs = [["TEST"], ["FLAKINESS"], [CAPITALIZATIONS[platform]]]
+          all_configs.extend(config)
+          log_results.setdefault(testapp, {}).setdefault(flat_config(all_configs), []).append(test)
 
   return log_results