Extract log output from xcodebuild runs after failures (#4867)

.github/workflows/firestore.yml

@@ -27,7 +27,8 @@ on:
     - 'CMakeLists.txt'
     - 'cmake/**'
 
-    # Build scripts
+    # Build scripts to which Firestore is sensitive
+    #
     # Note that this doesn't include check scripts because changing those will
     # already trigger the check workflow.
     - 'scripts/binary_to_array.py'
@@ -39,6 +40,7 @@ on:
     - 'scripts/setup_*'
     - 'scripts/sync_project.rb'
     - 'scripts/test_quickstart.sh'
+    - 'scripts/xcresult_logs.py'
 
     # This workflow
     - '.github/workflows/firestore.yml'

scripts/build.sh

@@ -115,17 +115,74 @@ function RunXcodebuild() {
     xcpretty_cmd+=(-f $(xcpretty-travis-formatter))
   fi
 
-  xcodebuild "$@" | tee xcodebuild.log | "${xcpretty_cmd[@]}"; result=$?
+  result=0
+  xcodebuild "$@" | tee xcodebuild.log | "${xcpretty_cmd[@]}" || result=$?
   if [[ $result == 65 ]]; then
+    ExportLogs "$@"
+
     echo "xcodebuild exited with 65, retrying" 1>&2
     sleep 5
 
-    xcodebuild "$@" | tee xcodebuild.log | "${xcpretty_cmd[@]}"; result=$?
+    result=0
+    xcodebuild "$@" | tee xcodebuild.log | "${xcpretty_cmd[@]}" || result=$?
   fi
   if [[ $result != 0 ]]; then
+
     echo "xcodebuild exited with $result; raw log follows" 1>&2
+    OpenFold Raw log
     cat xcodebuild.log
-    exit $result
+    CloseFold
+
+    ExportLogs "$@"
+    return $result
+  fi
+}
+
+# Exports any logs output captured in the xcresult
+function ExportLogs() {
+  OpenFold XCResult
+
+  exporter="${scripts_dir}/xcresult_logs.py"
+  python "$exporter" "$@"
+
+  CloseFold
+}
+
+current_group=none
+current_fold=0
+
+# Prints a command for CI environments to group log output in the logs
+# presentation UI.
+function OpenFold() {
+  description="$*"
+  current_group="$(echo "$description" | tr '[A-Z] ' '[a-z]_')"
+
+  if [[ -n "${GITHUB_ACTIONS:-}" ]]; then
+    echo "::group::description"
+
+  elif [[ -n "${TRAVIS:-}" ]]; then
+    # Travis wants groups to be numbered.
+    current_group="${current_group}.${current_fold}"
+    let current_fold++
+
+    # Show description in yellow.
+    echo "travis_fold:start:${current_group}\033[33;1m${description}\033[0m"
+
+  else
+    echo "===== $description Start ====="
+  fi
+}
+
+# Closes the current fold opened by `OpenFold`.
+function CloseFold() {
+  if [[ -n "${GITHUB_ACTIONS:-}" ]]; then
+    echo "::endgroup::"
+
+  elif [[ -n "${TRAVIS:-}" ]]; then
+    echo "travis_fold:end:${current_group}"
+
+  else
+    echo "===== $description End ====="
   fi
 }
 

scripts/if_changed.sh

@@ -159,6 +159,7 @@ fi
 check_changes '^.travis.yml'
 check_changes '^Gemfile.lock'
 check_changes '^scripts/(build|install_prereqs|pod_lib_lint).(rb|sh)'
+check_changes '^scripts/xcresult_logs.py'
 
 if [[ "$run" == true ]]; then
   "$@"

scripts/xcresult_logs.py

@@ -0,0 +1,250 @@
+#!/usr/bin/env python
+
+# 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.
+
+"""Prints logs from test runs captured in Apple .xcresult bundles.
+
+USAGE: xcresult_logs.py -workspace <path> -scheme <scheme> [other flags...]
+
+xcresult_logs.py finds and displays the log output associated with an xcodebuild
+invocation. Pass your entire xcodebuild command-line as arguments to this script
+and it will find the output associated with the most recent invocation.
+"""
+
+import json
+import logging
+import os
+import subprocess
+import sys
+
+from lib import command_trace
+
+_logger = logging.getLogger('xcresult')
+
+
+def main():
+  args = sys.argv[1:]
+  if not args:
+    sys.stdout.write(__doc__)
+    sys.exit(1)
+
+  logging.basicConfig(format='%(message)s', level=logging.DEBUG)
+
+  flags = parse_xcodebuild_flags(args)
+
+  # If the result bundle path is specified in the xcodebuild flags, use that
+  # otherwise, deduce
+  xcresult_path = flags.get('-resultBundlePath')
+  if xcresult_path is None:
+    project = project_from_workspace_path(flags['-workspace'])
+    scheme = flags['-scheme']
+    xcresult_path = find_xcresult_path(project, scheme)
+
+  log_id = find_log_id(xcresult_path)
+  log = export_log(xcresult_path, log_id)
+  sys.stdout.write(log)
+
+
+# Most flags on the xcodebuild command-line are uninteresting, so only pull
+# flags with known behavior with names in this set.
+INTERESTING_FLAGS = {
+    '-resultBundlePath',
+    '-scheme',
+    '-workspace',
+}
+
+
+def parse_xcodebuild_flags(args):
+  """Parses the xcodebuild command-line.
+
+  Extracts flags like -workspace and -scheme that dictate the location of the
+  logs.
+  """
+  result = {}
+  key = None
+  for arg in args:
+    if arg.startswith('-'):
+      if arg in INTERESTING_FLAGS:
+        key = arg
+    elif key is not None:
+      result[key] = arg
+      key = None
+
+  return result
+
+
+def project_from_workspace_path(path):
+  """Extracts the project name from a workspace path.
+  Args:
+    path: The path to a .xcworkspace file
+
+  Returns:
+    The project name from the basename of the path. For example, if path were
+    'Firestore/Example/Firestore.xcworkspace', returns 'Firestore'.
+  """
+  root, ext = os.path.splitext(os.path.basename(path))
+  if ext == '.xcworkspace':
+    _logger.debug('Using project %s from workspace %s', root, path)
+    return root
+
+  raise ValueError('%s is not a valid workspace path' % path)
+
+
+def find_xcresult_path(project, scheme):
+  """Finds an xcresult bundle for the given project and scheme.
+
+  Args:
+    project: The project name, like 'Firestore'
+    scheme: The Xcode scheme that was tested
+
+  Returns:
+    The path to the newest xcresult bundle that matches.
+  """
+  project_path = find_project_path(project)
+  bundle_dir = os.path.join(project_path, 'Logs/Test')
+  prefix = 'Run-' + scheme + '-'
+
+  _logger.debug('Logging for xcresult bundles in %s', bundle_dir)
+  xcresult = find_newest_matching_prefix(bundle_dir, prefix)
+  if xcresult is None:
+    raise LookupError(
+        'Could not find xcresult bundle for %s in %s' % (scheme, bundle_dir))
+
+  _logger.debug('Found xcresult: %s', xcresult)
+  return xcresult
+
+
+def find_project_path(project):
+  """Finds the newest project output within Xcode's DerivedData.
+
+  Args:
+    project: A project name; the Foo in Foo.xcworkspace
+
+  Returns:
+    The path containing the newest project output.
+  """
+  path = os.path.expanduser('~/Library/Developer/Xcode/DerivedData')
+  prefix = project + '-'
+
+  # DerivedData has directories like Firestore-csljdukzqbozahdjizcvrfiufrkb. Use
+  # the most recent one if there are more than one such directory matching the
+  # project name.
+  result = find_newest_matching_prefix(path, prefix)
+  if result is None:
+    raise LookupError(
+        'Could not find project derived data for %s in %s' % (project, path))
+
+  _logger.debug('Using project derived data in %s', result)
+  return result
+
+
+def find_newest_matching_prefix(path, prefix):
+  """Lists the given directory and returns the newest entry matching prefix.
+
+  Args:
+    path: A directory to list
+    prefix: The starting part of any filename to consider
+
+  Returns:
+    The path to the newest entry in the directory whose basename starts with
+    the prefix.
+  """
+  entries = os.listdir(path)
+  result = None
+  for entry in entries:
+    if entry.startswith(prefix):
+      fq_entry = os.path.join(path, entry)
+      if result is None:
+        result = fq_entry
+      else:
+        result_mtime = os.path.getmtime(result)
+        entry_mtime = os.path.getmtime(fq_entry)
+        if entry_mtime > result_mtime:
+          result = fq_entry
+
+  return result
+
+
+def find_log_id(xcresult_path):
+  """Finds the id of the last action's logs.
+
+  Args:
+    xcresult_path: The path to an xcresult bundle.
+
+  Returns:
+    The id of the log output, suitable for use with xcresulttool get --id.
+  """
+  parsed = xcresulttool_json('get', '--path', xcresult_path)
+  actions = parsed['actions']['_values']
+  action = actions[-1]
+
+  result = action['actionResult']['logRef']['id']['_value']
+  _logger.debug('Using log id %s', result)
+  return result
+
+
+def export_log(xcresult_path, log_id):
+  """Exports the log data with the given id from the xcresult bundle.
+
+  Args:
+    xcresult_path: The path to an xcresult bundle.
+    log_id: The id that names the log output (obtained by find_log_id)
+
+  Returns:
+    The logged output, as a string.
+  """
+  contents = xcresulttool_json('get', '--path', xcresult_path, '--id', log_id)
+
+  result = []
+  collect_log_output(contents, result)
+  return ''.join(result)
+
+
+def collect_log_output(activity_log, result):
+  """Recursively collects emitted output from the activity log.
+
+  Args:
+    activity_log: Parsed JSON of an xcresult activity log.
+    result: An array into which all log data should be appended.
+  """
+  output = activity_log.get('emittedOutput')
+  if output:
+    result.append(output['_value'])
+  else:
+    subsections = activity_log.get('subsections')
+    if subsections:
+      for subsection in subsections['_values']:
+        collect_log_output(subsection, result)
+
+
+def xcresulttool(*args):
+  """Runs xcresulttool and returns its output as a string."""
+  cmd = ['xcrun', 'xcresulttool']
+  cmd.extend(args)
+
+  command_trace.log(cmd)
+
+  return subprocess.check_output(cmd)
+
+
+def xcresulttool_json(*args):
+  """Runs xcresulttool and its output as parsed JSON."""
+  args = list(args) + ['--format', 'json']
+  contents = xcresulttool(*args)
+  return json.loads(contents)
+
+
+if __name__ == '__main__':
+  main()