Improve integration test logging

These makes a couple of changes, all with the end goal of making it easier to debug failures:

1) Separate the building of desktop integration tests and their execution into separate steps. It was unintuitive that the build step ran desktop tests, but not mobile tests. A new script desktop_tester.py finds and executes desktop tests. Separating them into steps also organizes the logs better.

2) Rearrange log output for tests. Previously tests output logs in arbitrary order: now successes will report first, failures last, so that when scrolling up from the overall summary, one will immediately see the failures.

3) Add a workflow step to report terse summaries. This will make it possible to quickly determine what went wrong without trudging through multiple steps and long logs. It may still be necessary to go through detailed logs for more context, but this should help with determining if that's necessary.

To achieve this, every build/test script will report a summary, which gets written to a local file (summary.log in the top level output directory where the tests are built). The final step logs the contents of this file.

The new function in test_validation.py, 'summarize_tests_results' standardizes how all test runners output results.

Author: anonymous-akorn

.github/workflows/integration_tests.yml

@@ -116,13 +116,17 @@ jobs:
           pip install -r scripts/gha/requirements.txt
           python scripts/gha/restore_secrets.py --passphrase "${{ secrets.TEST_SECRET }}"
 
-      - name: Build integration tests (and run Desktop tests)
+      - name: Build integration tests
         # The set up script for Android will download the NDK here.
         env:
           NDK_ROOT: '/tmp/android-ndk-r16b'
         run: |
-          python scripts/gha/build_testapps.py --t ${{ github.event.inputs.apis }} --p ${{ matrix.target_platform }} --output_directory ${{ github.workspace }} --use_vcpkg --execute_desktop_testapp --noadd_timestamp
+          python scripts/gha/build_testapps.py --t ${{ github.event.inputs.apis }} --p ${{ matrix.target_platform }} --output_directory ${{ github.workspace }} --use_vcpkg --noadd_timestamp
 
+      - name: Run desktop integration tests
+        if: matrix.target_platform == 'Desktop' && !cancelled()
+        run: |
+          python scripts/gha/desktop_tester.py --testapp_dir testapps
       # Workaround for https://github.com/GoogleCloudPlatform/github-actions/issues/100
       # Must be run after the Python setup action
       - name: Set CLOUDSDK_PYTHON (Windows)
@@ -139,3 +143,7 @@ jobs:
         if: matrix.target_platform != 'Desktop' && !cancelled()
         run: |
           python scripts/gha/test_lab.py --android_model ${{ github.event.inputs.android_device }} --android_api ${{ github.event.inputs.android_api }} --ios_model ${{ github.event.inputs.ios_device }} --ios_version ${{ github.event.inputs.ios_version }} --testapp_dir ${{ github.workspace }}/testapps --code_platform cpp --key_file ${{ github.workspace }}/scripts/gha-encrypted/gcs_key_file.json
+      - name: Summarize build and test results
+        if: ${{ !cancelled() }}
+        shell: bash
+        run: cat testapps/summary.log

scripts/gha/build_testapps.py

@@ -69,7 +69,6 @@
 import datetime
 from distutils import dir_util
 import os
-import pathlib
 import platform
 import shutil
 import subprocess
@@ -81,7 +80,7 @@
 import attr
 
 from integration_testing import config_reader
-from integration_testing import provisioning
+from integration_testing import test_validation
 from integration_testing import xcodebuild
 
 # Environment variables
@@ -145,11 +144,6 @@
     " the local spec repos available on this machine. Must also include iOS"
     " in platforms flag.")
 
-flags.DEFINE_bool(
-    "execute_desktop_testapp", True,
-    "(Desktop only) Run the testapp after building it. Will return non-zero"
-    " code if any tests fail inside the testapp.")
-
 flags.DEFINE_string(
     "compiler", None,
     "(Desktop only) Specify the compiler with CMake during the testapps build."
@@ -187,6 +181,7 @@ def main(argv):
     timestamp = datetime.datetime.now().strftime("%Y_%m_%d-%H_%M_%S")
   else:
     timestamp = ""
+  output_dir = os.path.join(output_dir, "testapps" + timestamp)
 
   ios_framework_dir = os.path.join(sdk_dir, "frameworks")
   ios_framework_exist = os.path.isdir(ios_framework_dir)
@@ -195,7 +190,7 @@ def main(argv):
 
   if update_pod_repo and _IOS in platforms:
     _run(["pod", "repo", "update"])
-    
+
   config = config_reader.read_config()
   cmake_flags = _get_desktop_compiler_flags(FLAGS.compiler, config.compilers)
   if _DESKTOP in platforms and FLAGS.use_vcpkg:
@@ -214,25 +209,22 @@ def main(argv):
         output_dir=output_dir,
         sdk_dir=sdk_dir,
         ios_framework_exist=ios_framework_exist,
-        timestamp=timestamp,
         root_dir=root_dir,
         ios_sdk=FLAGS.ios_sdk,
-        cmake_flags=cmake_flags,
-        execute_desktop_testapp=FLAGS.execute_desktop_testapp)
+        cmake_flags=cmake_flags)
     logging.info("END building for %s", testapp)
 
-  _summarize_results(testapps, platforms, failures)
+  _summarize_results(testapps, platforms, failures, output_dir)
   return 1 if failures else 0
 
 
 def _build(
-    testapp, platforms, api_config, output_dir, sdk_dir, ios_framework_exist, 
-    timestamp, root_dir, ios_sdk, cmake_flags, execute_desktop_testapp):
+    testapp, platforms, api_config, output_dir, sdk_dir, ios_framework_exist,
+    root_dir, ios_sdk, cmake_flags):
   """Builds one testapp on each of the specified platforms."""
   testapp_dir = os.path.join(root_dir, api_config.testapp_path)
   project_dir = os.path.join(
-      output_dir, "testapps" + timestamp, api_config.full_name,
-      os.path.basename(testapp_dir))
+      output_dir, api_config.full_name, os.path.basename(testapp_dir))
 
   logging.info("Copying testapp project to %s", project_dir)
   os.makedirs(project_dir)
@@ -249,8 +241,6 @@ def _build(
     logging.info("BEGIN %s, %s", testapp, _DESKTOP)
     try:
       _build_desktop(sdk_dir, cmake_flags)
-      if execute_desktop_testapp:
-        _execute_desktop_testapp(project_dir)
     except subprocess.SubprocessError as e:
       failures.append(
           Failure(testapp=testapp, platform=_DESKTOP, error_message=str(e)))
@@ -287,36 +277,30 @@ def _build(
   return failures
 
 
-def _summarize_results(testapps, platforms, failures):
+def _summarize_results(testapps, platforms, failures, output_dir):
   """Logs a readable summary of the results of the build."""
-  logging.info(
-      "FINISHED BUILDING TESTAPPS.\n\n\n"
-      "Tried to build these testapps: %s\n"
-      "On these platforms: %s",
-      ", ".join(testapps), ", ".join(platforms))
+  summary = []
+  summary.append("BUILD SUMMARY:")
+  summary.append("TRIED TO BUILD: " + ",".join(testapps))
+  summary.append("ON PLATFORMS: " + ",".join(platforms))
+
   if not failures:
-    logging.info("No failures occurred")
+    summary.append("ALL BUILDS SUCCEEDED")
   else:
-    # Collect lines, then log once, to reduce logging noise from timestamps etc.
-    lines = ["Some failures occurred:"]
+    summary.append("SOME FAILURES OCCURRED:")
     for i, failure in enumerate(failures, start=1):
-      lines.append("%d: %s" % (i, failure.describe()))
-    logging.info("\n".join(lines))
+      summary.append("%d: %s" % (i, failure.describe()))
+  summary = "\n".join(summary)
+
+  logging.info(summary)
+  test_validation.write_summary(output_dir, summary)
 
 
 def _build_desktop(sdk_dir, cmake_flags):
   _run(["cmake", ".", "-DFIREBASE_CPP_SDK_DIR=" + sdk_dir] + cmake_flags)
   _run(["cmake", "--build", "."])
 
 
-def _execute_desktop_testapp(project_dir):
-  if platform.system() == "Windows":
-    testapp_path = os.path.join(project_dir, "Debug", "integration_test.exe")
-  else:
-    testapp_path = os.path.join(project_dir, "integration_test")
-  _run([testapp_path], timeout=300)
-
-
 def _get_desktop_compiler_flags(compiler, compiler_table):
   """Returns the command line flags for this compiler."""
   if not compiler:  # None is an acceptable default value
@@ -362,31 +346,45 @@ def _validate_android_environment_variables():
   """Checks environment variables that may be required for Android."""
   # Ultimately we let the gradle build be the source of truth on what env vars
   # are required, but try to repair holes and log warnings if we can't.
-  logging.info("Checking environment variables for the Android build")
-  if not os.environ.get(_ANDROID_NDK_HOME):
-    ndk_root = os.environ.get(_NDK_ROOT)
-    if ndk_root:  # Use NDK_ROOT as a backup for ANDROID_NDK_HOME
-      os.environ[_ANDROID_NDK_HOME] = ndk_root
-      logging.info("%s not found, using %s", _ANDROID_NDK_HOME, _NDK_ROOT)
-    else:
-      logging.warning("Neither %s nor %s is set.", _ANDROID_NDK_HOME, _NDK_ROOT)
+  android_home = os.environ.get(_ANDROID_HOME)
   if not os.environ.get(_JAVA_HOME):
     logging.warning("%s not set", _JAVA_HOME)
   if not os.environ.get(_ANDROID_SDK_HOME):
-    android_home = os.environ.get(_ANDROID_HOME)
     if android_home:  # Use ANDROID_HOME as backup for ANDROID_SDK_HOME
       os.environ[_ANDROID_SDK_HOME] = android_home
       logging.info("%s not found, using %s", _ANDROID_SDK_HOME, _ANDROID_HOME)
     else:
-      logging.warning(
-          "Neither %s nor %s is set", _ANDROID_SDK_HOME, _ANDROID_HOME)
+      logging.warning("Missing: %s and %s", _ANDROID_SDK_HOME, _ANDROID_HOME)
+  # Different environments may have different NDK env vars specified. We look
+  # for these, in this order, and set the others to the first found.
+  # If none are set, we check the default location for the ndk.
+  ndk_path = None
+  ndk_vars = [_NDK_ROOT, _ANDROID_NDK_HOME]
+  for env_var in ndk_vars:
+    val = os.environ.get(env_var)
+    if val:
+      ndk_path = val
+      break
+  if not ndk_path:
+    if android_home:
+      default_ndk_path = os.path.join(android_home, "ndk-bundle")
+      if os.path.isdir(default_ndk_path):
+        ndk_path = default_ndk_path
+  if ndk_path:
+    logging.info("Found ndk: %s", ndk_path)
+    for env_var in ndk_vars:
+      if os.environ.get(env_var) != ndk_path:
+        logging.info("Setting %s to %s", env_var, ndk_path)
+        os.environ[env_var] = ndk_path
+  else:
+    logging.warning("No NDK env var set. Set one of %s", ", ".join(ndk_vars))
 
 
-# If sdk_dir contains no framework, consider it is Github repo, then 
+# If sdk_dir contains no framework, consider it is Github repo, then
 # generate makefiles for ios frameworks
 def _generate_makefiles_from_repo(sdk_dir):
   ios_framework_builder = os.path.join(
-    sdk_dir, "build_scripts", "ios", "build.sh")
+      sdk_dir, "build_scripts", "ios", "build.sh")
 
   framework_builder_args = [
       ios_framework_builder,
@@ -400,15 +398,15 @@ def _generate_makefiles_from_repo(sdk_dir):
 # build required ios frameworks based on makefiles
 def _build_ios_framework_from_repo(sdk_dir, api_config):
   ios_framework_builder = os.path.join(
-    sdk_dir, "build_scripts", "ios", "build.sh")
-  
+      sdk_dir, "build_scripts", "ios", "build.sh")
+
   # build only required targets to save time
   target = set()
   for framework in api_config.frameworks:
     target.add(os.path.splitext(framework)[0])
   # firebase is not a target in CMake, firebase_app is the target
-  # firebase_app will be built by other target as well 
-  target.remove("firebase") 
+  # firebase_app will be built by other target as well
+  target.remove("firebase")
 
   framework_builder_args = [
       ios_framework_builder,
@@ -421,10 +419,10 @@ def _build_ios_framework_from_repo(sdk_dir, api_config):
 
 def _build_ios(
     sdk_dir, ios_framework_exist, project_dir, root_dir, api_config, ios_sdk):
+  """Builds an iOS application (.app, .ipa or both)."""
   if not ios_framework_exist:
     _build_ios_framework_from_repo(sdk_dir, api_config)
 
-  """Builds an iOS application (.app, .ipa or both)."""
   build_dir = os.path.join(project_dir, "ios_build")
   os.makedirs(build_dir)
 
@@ -439,14 +437,10 @@ def _build_ios(
 
   podfile_tool_path = os.path.join(
       root_dir, "scripts", "gha", "integration_testing", "update_podfile.py")
-  sdk_podfile_path = os.path.join(
-      root_dir, "ios_pod", "Podfile")
-  app_podfile_path = os.path.join(
-      project_dir, "Podfile")
   podfile_patcher_args = [
       "python", podfile_tool_path,
-      "--sdk_podfile", sdk_podfile_path,
-      "--app_podfile", app_podfile_path
+      "--sdk_podfile", os.path.join(root_dir, "ios_pod", "Podfile"),
+      "--app_podfile", os.path.join(project_dir, "Podfile")
   ]
   _run(podfile_patcher_args)
   _run(["pod", "install"])
@@ -487,7 +481,8 @@ def _build_ios(
             ios_sdk=_IOS_SDK_DEVICE,
             configuration="Debug"))
 
-    xcodebuild.generate_unsigned_ipa(output_dir=build_dir, configuration="Debug")
+    xcodebuild.generate_unsigned_ipa(
+        output_dir=build_dir, configuration="Debug")
 
 
 # This script is responsible for copying shared files into the integration

scripts/gha/desktop_tester.py

@@ -0,0 +1,112 @@
+# Copyright 2020 Google LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""Runs and validates desktop C++ testapps.
+
+Usage:
+  python desktop_tester.py --testapp_dir ~/Downloads/testapps
+
+This will search --testapp_dir for files whose name is given by --testapp_name
+(default: "integration_test", or "integration_test.exe" on Windows), execute
+them, parse their log output according to the C++ test summary format, and
+report a summary of results.
+
+"""
+
+import os
+import platform
+import subprocess
+import threading
+
+from absl import app
+from absl import flags
+from absl import logging
+import attr
+
+from integration_testing import test_validation
+
+FLAGS = flags.FLAGS
+
+flags.DEFINE_string("testapp_dir", None, "Look for testapps in this directory.")
+flags.DEFINE_string("testapp_name", "integration_test", "Name of the testapps.")
+
+
+def main(argv):
+  if len(argv) > 1:
+    raise app.UsageError("Too many command-line arguments.")
+
+  testapp_dir = _fix_path(FLAGS.testapp_dir)
+
+  testapp_name = FLAGS.testapp_name
+  if platform.system() == "Windows":
+    testapp_name += ".exe"
+
+  testapps = []
+  for file_dir, _, file_names in os.walk(testapp_dir):
+    for file_name in file_names:
+      if file_name == testapp_name:
+        testapps.append(os.path.join(file_dir, file_name))
+  if not testapps:
+    logging.error("No testapps found.")
+    test_validation.write_summary(testapp_dir, "Desktop tests: none found.")
+    return 1
+  logging.info("Testapps found: %s\n", "\n".join(testapps))
+
+  tests = [Test(testapp_path=testapp) for testapp in testapps]
+
+  logging.info("Running tests...")
+  threads = []
+  for test in tests:
+    thread = threading.Thread(target=test.run)
+    threads.append(thread)
+    thread.start()
+  for thread in threads:
+    thread.join()
+
+  return test_validation.summarize_test_results(
+      tests, test_validation.CPP, testapp_dir)
+
+
+def _fix_path(path):
+  """Expands ~, normalizes slashes, and converts relative paths to absolute."""
+  return os.path.abspath(os.path.expanduser(path))
+
+
+@attr.s(frozen=False, eq=False)
+class Test(object):
+  """Holds data related to the testing of one testapp."""
+  testapp_path = attr.ib()
+  # This will be populated after the test completes, instead of initialization.
+  logs = attr.ib(init=False, default=None)
+
+  # This runs in a separate thread, so instead of returning values we store
+  # them as fields so they can be accessed from the main thread.
+  def run(self):
+    """Executes this testapp."""
+    result = subprocess.run(
+        args=[self.testapp_path],
+        cwd=os.path.dirname(self.testapp_path),  # Testapp checks CWD for config
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        text=True,
+        check=False,
+        timeout=300)
+    logging.info("Finished running %s", self.testapp_path)
+
+    self.logs = result.stdout
+    self.return_code = result.returncode
+
+
+if __name__ == "__main__":
+  app.run(main)