Obtain host-log file-names from stdout of host-start process.

Recently, the location where me2me host logs are written changed on the Swarming bots (root-cause not yet clear). To be more resilient to such changes, to get the host log file-name we'll parse the output of the process that starts the host.

Also, in order to rule out replication delay as a cause of test failures, we'll check the JID used by a test and, if it is different from the JID logged by the host for that execution, sleep for 30-seconds and rerun the test if it failed.

BUG=

Review URL: https://codereview.chromium.org/1375373006

Cr-Commit-Position: refs/heads/master@{#353409}

2 files changed, 128 insertions, 25 deletions

diff --git a/testing/chromoting/browser_tests_launcher.py b/testing/chromoting/browser_tests_launcher.py
index a5a2ff3..4e7b34c 100644
--- a/testing/chromoting/browser_tests_launcher.py
+++ b/testing/chromoting/browser_tests_launcher.py
@@ -5,7 +5,9 @@
 
 """Utility script to launch browser-tests on the Chromoting bot."""
 import argparse
+import time
 
+from chromoting_test_utilities import GetJidListFromTestResults
 from chromoting_test_utilities import InitialiseTestMachineForLinux
 from chromoting_test_utilities import PrintHostLogContents
 from chromoting_test_utilities import PROD_DIR_ID
@@ -25,21 +27,73 @@ MAX_RETRIES = 1
 def LaunchBTCommand(args, command):
   """Launches the specified browser-test command.
 
-      If the execution failed because a browser-instance was not launched, retry
-      once.
+    Retry if the execution failed because a browser-instance was not launched or
+    because the JID used did not match the host-JID.
   Args:
     args: Command line args, used for test-case startup tasks.
     command: Browser-test command line.
+
+  Returns:
+    host_log_file_names: Array of host logs created for this command, including
+         retries.
   """
   global TEST_FAILURE, FAILING_TESTS
+  host_log_file_names = []
 
   retries = 0
+  host_jid_mismatch = False
+  host_jid = None
   while retries <= MAX_RETRIES:
-    TestCaseSetup(args)
+    # TestCaseSetup restarts the me2me host, and sets up user-profile dir.
+    # It returns the file-name of the me2me host log.
+    # If we are attempting to run this test because of a JID-mismatch, don't
+    # restart host.
+    if not host_jid_mismatch:
+      host_log_file_names.append(TestCaseSetup(args))
+      # Parse the me2me host log to obtain the JID that the host registered.
+      host_jid = None
+      with open(host_log_file_names[retries], 'r') as host_log_file:
+        for line in host_log_file:
+          # The host JID will be recorded in a line saying 'Signaling
+          # connected'.
+          if 'Signaling connected. ' in line:
+            components = line.split('/')
+            host_jid = components[-1]
+            break
+
     results = RunCommandInSubProcess(command)
 
+    # Get the JID used by this test to connect a remote-host, if any.
+    jids_used = GetJidListFromTestResults(results)
+
+    # Check for JID mismatch before checking for test success, so that we may
+    # record instances where a test passed despite a JID mismatch.
+    if jids_used and host_jid.rstrip() not in jids_used:
+      host_jid_mismatch = True
+      print 'Host JID mismatch. JID in host log = %s.' % host_jid.rstrip()
+      print 'Host JIDs used by test:'
+      for jid in jids_used:
+        print jid
+
+    if host_jid_mismatch:
+      # The JID for the remote-host did not match the JID that was used for this
+      # execution of the test. This happens because of a replication delay in
+      # updating all instances of the Chromoting Directory Server. To
+      # work-around this, sleep for 30s, which, based off a recent (08/2015)
+      # query for average replication delay for Chromoting, should be sufficient
+      # for the current JID value to have fully propagated.
+      retries += 1
+      time.sleep(30)
+      continue
+    elif jids_used:
+      print 'JID used by test matched me2me host JID: %s' % host_jid
+    else:
+      # There wasn't a mismatch and no JIDs were returned. If no JIDs were
+      # returned, that means the test didn't use any JIDs, so there is nothing
+      # further for us to do.
+      pass
+
     if SUCCESS_INDICATOR in results:
-      # Test passed.
       break
 
     # Sometimes, during execution of browser-tests, a browser instance is
@@ -62,21 +116,24 @@ def LaunchBTCommand(args, command):
     # Add this command-line to list of tests that failed.
     FAILING_TESTS += command
 
+  return host_log_file_names
+
 
 def main(args):
 
   InitialiseTestMachineForLinux(args.cfg_file)
 
+  host_log_files = []
   with open(args.commands_file) as f:
     for line in f:
       # Replace the PROD_DIR value in the command-line with
       # the passed in value.
       line = line.replace(PROD_DIR_ID, args.prod_dir)
       # Launch specified command line for test.
-      LaunchBTCommand(args, line)
+      host_log_files.extend(LaunchBTCommand(args, line))
 
   # All tests completed. Include host-logs in the test results.
-  PrintHostLogContents()
+  PrintHostLogContents(host_log_files)
 
   if TEST_FAILURE:
     print '++++++++++AT LEAST 1 TEST FAILED++++++++++'
@@ -84,6 +141,8 @@ def main(args):
     print '++++++++++++++++++++++++++++++++++++++++++'
     raise Exception('At least one test failed.')
 
+  return host_log_files
+
 if __name__ == '__main__':
 
   parser = argparse.ArgumentParser()
@@ -101,8 +160,9 @@ if __name__ == '__main__':
       '-u', '--user_profile_dir',
       help='path to user-profile-dir, used by connect-to-host tests.')
   command_line_args = parser.parse_args()
+  host_logs = ''
   try:
-    main(command_line_args)
+    host_logs = main(command_line_args)
   finally:
     # Stop host and cleanup user-profile-dir.
-    TestMachineCleanup(command_line_args.user_profile_dir)
+    TestMachineCleanup(command_line_args.user_profile_dir, host_logs)
diff --git a/testing/chromoting/chromoting_test_utilities.py b/testing/chromoting/chromoting_test_utilities.py
index ea183f1..24d88e1 100644
--- a/testing/chromoting/chromoting_test_utilities.py
+++ b/testing/chromoting/chromoting_test_utilities.py
@@ -4,10 +4,10 @@
 
 """Utility script to run tests on the Chromoting bot."""
 
-import glob
 import hashlib
 import os
 from os.path import expanduser
+import re
 import shutil
 import socket
 import subprocess
@@ -16,7 +16,6 @@ import psutil
 
 PROD_DIR_ID = '#PROD_DIR#'
 CRD_ID = 'chrome-remote-desktop'  # Used in a few file/folder names
-CHROMOTING_HOST_PATH = './remoting/host/linux/linux_me2me_host.py'
 HOST_READY_INDICATOR = 'Host ready to receive connections.'
 BROWSER_TEST_ID = 'browser_tests'
 HOST_HASH_VALUE = hashlib.md5(socket.gethostname()).hexdigest()
@@ -26,7 +25,14 @@ NATIVE_MESSAGING_DIR = 'NativeMessagingHosts'
 # has a random name, which we'll store here for use later.
 # Note that the test-execution always starts from the testing/chromoting folder
 # under the temp folder.
+ISOLATE_CHROMOTING_HOST_PATH = 'remoting/host/linux/linux_me2me_host.py'
 ISOLATE_TEMP_FOLDER = os.path.abspath(os.path.join(os.getcwd(), '../..'))
+CHROMOTING_HOST_PATH = os.path.join(ISOLATE_TEMP_FOLDER,
+                                    ISOLATE_CHROMOTING_HOST_PATH)
+
+
+class HostOperationFailedException(Exception):
+  pass
 
 
 def RunCommandInSubProcess(command):
@@ -49,17 +55,20 @@ def RunCommandInSubProcess(command):
   return results
 
 
-def TestMachineCleanup(user_profile_dir):
+def TestMachineCleanup(user_profile_dir, host_logs=None):
   """Cleans up test machine so as not to impact other tests.
 
   Args:
     user_profile_dir: the user-profile folder used by Chromoting tests.
+    host_logs: List of me2me host logs; these will be deleted.
   """
+
   # Stop the host service.
   RunCommandInSubProcess(CHROMOTING_HOST_PATH + ' --stop')
 
   # Cleanup any host logs.
-  RunCommandInSubProcess('rm /tmp/chrome_remote_desktop_*')
+  for host_log in host_logs:
+    RunCommandInSubProcess('rm %s' % host_log)
 
   # Remove the user-profile dir
   if os.path.exists(user_profile_dir):
@@ -97,19 +106,20 @@ def InitialiseTestMachineForLinux(cfg_file):
       os.path.join(default_config_file_location, default_config_file_name))
 
   # Make sure chromoting host is running.
-  if not RestartMe2MeHost():
-    # Host start failed. Don't run any tests.
-    raise Exception('Host restart failed.')
+  RestartMe2MeHost()
 
 
 def RestartMe2MeHost():
   """Stops and starts the Me2Me host on the test machine.
 
-  Waits to confirm that host is ready to receive connections before returning.
+  Launches the me2me start-host command, and parses the stdout of the execution
+  to obtain the host log-file name.
 
   Returns:
-    True: if HOST_READY_INDICATOR is found in stdout, indicating host is ready.
-    False: if HOST_READY_INDICATOR not found in stdout.
+    log_file: Host log file.
+
+  Raises:
+    Exception: If host-log does not contain string indicating host is ready.
   """
 
   # To start the host, we want to be in the temp-folder for this test execution.
@@ -120,14 +130,25 @@ def RestartMe2MeHost():
   # Stop chromoting host.
   RunCommandInSubProcess(CHROMOTING_HOST_PATH + ' --stop')
   # Start chromoting host.
+  print 'Starting chromoting host from %s' % CHROMOTING_HOST_PATH
   results = RunCommandInSubProcess(CHROMOTING_HOST_PATH + ' --start')
 
   os.chdir(previous_directory)
+
+  # Get log file from results of above command printed to stdout. Example:
+  # Log file: /tmp/tmp0c3EcP/chrome_remote_desktop_20150929_101525_B0o89t
+  start_of_host_log = results.index('Log file: ') + len('Log file: ')
+  log_file = results[start_of_host_log:].rstrip()
+
   # Confirm that the start process completed, and we got:
   # "Host ready to receive connections." in the log.
   if HOST_READY_INDICATOR not in results:
-    return False
-  return True
+    # Host start failed. Print out host-log. Don't run any tests.
+    with open(log_file, 'r') as f:
+      print f.read()
+    raise HostOperationFailedException('Host restart failed.')
+
+  return log_file
 
 
 def SetupUserProfileDir(me2me_manifest_file, it2me_manifest_file,
@@ -170,9 +191,9 @@ def PrintRunningProcesses():
     print process.name
 
 
-def PrintHostLogContents():
+def PrintHostLogContents(host_log_files=None):
   host_log_contents = ''
-  for log_file in sorted(glob.glob('/tmp/chrome_remote_desktop_*')):
+  for log_file in sorted(host_log_files):
     with open(log_file, 'r') as log:
       host_log_contents += '\nHOST LOG %s\n CONTENTS:\n%s' % (
           log_file, log.read())
@@ -181,10 +202,32 @@ def PrintHostLogContents():
 
 def TestCaseSetup(args):
   # Stop+start me2me host process.
-  if not RestartMe2MeHost():
-    # Host restart failed. Don't run any more tests.
-    raise Exception('Host restart failed.')
+  host_log_file = RestartMe2MeHost()
 
   # Reset the user profile directory to start each test with a clean slate.
   SetupUserProfileDir(args.me2me_manifest_file, args.it2me_manifest_file,
                       args.user_profile_dir)
+  return host_log_file
+
+
+def GetJidListFromTestResults(results):
+  """Parse the output of a test execution to obtain the JID used by the test.
+
+  Args:
+    results: stdio contents of test execution.
+
+  Returns:
+    jids_used: List of JIDs used by test; empty list if not found.
+  """
+
+  # Reg-ex defining the JID information in the string being parsed.
+  jid_re = '(Connecting to .*.gserviceaccount.com/)(chromoting.*)(. Local.*)'
+  jids_used = []
+  for line in results.split('\n'):
+    match = re.search(jid_re, line)
+    if match:
+      jid_used = match.group(2)
+      if jid_used not in jids_used:
+        jids_used.append(jid_used)
+
+  return jids_used