Add logs for update_engine, devserver, and cros_run_vm_update to test artifacts.

Change-Id: Ib5617612be38bb6d7dafcb2edab887c998a676ab

BUG=chromium-os:12951
TEST=Ran it with Simple.  Saw logs generated (1_update) and in root/dev_server.log.  Ran unittests for cros_build_lib.

Committed: http://chrome-svn/viewvc/chromeos?view=rev&revision=f53a8c7

Review URL: http://codereview.chromium.org/6672007

bin/au_test_harness/au_test.py

@@ -58,12 +58,16 @@ class AUTest(unittest.TestCase):
     elif not os.path.exists(cls.target_image_path):
       cros_lib.Die('%s does not exist' % cls.target_image_path)
 
-    # Initialize test root.
+    # Initialize test root.  Test root path must be in the chroot.
     if not cls.test_results_root:
       if options.test_results_root:
+        assert 'chroot/tmp' in options.test_results_root, \
+          'Must specify a test results root inside tmp in a chroot.'
         cls.test_results_root = options.test_results_root
       else:
-        cls.test_results_root = tempfile.mkdtemp(prefix='au_test_harness')
+        cls.test_results_root = tempfile.mkdtemp(
+            prefix='au_test_harness',
+            dir=cros_lib.PrependChrootPath('/tmp'))
 
       cros_lib.Info('Using %s as the test results root' % cls.test_results_root)
 

bin/au_test_harness/au_worker.py

@@ -192,14 +192,18 @@ class AUWorker(object):
       cmd.append('--image=%s' % image_path)
       if src_image_path: cmd.append('--src_image=%s' % src_image_path)
 
-  def RunUpdateCmd(self, cmd):
+  def RunUpdateCmd(self, cmd, log_directory=None):
     """Runs the given update cmd given verbose options.
 
     Raises an update_exception.UpdateException if the update fails.
     """
     if self.verbose:
       try:
-        cros_lib.RunCommand(cmd)
+        if log_directory:
+          cros_lib.RunCommand(cmd, log_to_file=os.path.join(log_directory,
+                                                            'update.log'))
+        else:
+          cros_lib.RunCommand(cmd)
       except Exception as e:
         Warning(str(e))
         raise update_exception.UpdateException(1, str(e))
@@ -236,14 +240,20 @@ class AUWorker(object):
     self.results_count = 0
 
   def GetNextResultsPath(self, label):
-    """Returns a new results path based for this label.
+    """Returns a path for the results directory for this label.
 
     Prefixes directory returned for worker with time called i.e. 1_label,
-    2_label, etc.
+    2_label, etc.  The directory returned is outside the chroot so if passing
+    to an script that is called with enther_chroot, make sure to use
+    ReinterpretPathForChroot.
     """
     self.results_count += 1
-    return os.path.join(self.results_directory, '%s_%s' % (self.results_count,
-                                                           label))
+    dir = os.path.join(self.results_directory, '%s_%s' % (self.results_count,
+                                                          label))
+    if not os.path.exists(dir):
+      os.makedirs(dir)
+
+    return dir
 
   # --- PRIVATE HELPER FUNCTIONS ---
 

bin/au_test_harness/cros_au_test_harness.py

@@ -280,7 +280,8 @@ def main():
   update_cache = _PregenerateUpdates(options)
   au_worker.AUWorker.SetUpdateCache(update_cache)
 
-  my_server = dev_server_wrapper.DevServerWrapper()
+  my_server = dev_server_wrapper.DevServerWrapper(
+      au_test.AUTest.test_results_root)
   my_server.start()
   try:
     if options.type == 'vm':

bin/au_test_harness/dev_server_wrapper.py

@@ -5,6 +5,7 @@
 """Module containing methods and classes to interact with a devserver instance.
 """
 
+import os
 import threading
 
 import cros_build_lib as cros_lib
@@ -19,8 +20,9 @@ def GenerateUpdateId(target, src, key):
 class DevServerWrapper(threading.Thread):
   """A Simple wrapper around a dev server instance."""
 
-  def __init__(self):
+  def __init__(self, test_root):
     self.proc = None
+    self.test_root = test_root
     threading.Thread.__init__(self)
 
   def run(self):
@@ -32,7 +34,9 @@ class DevServerWrapper(threading.Thread):
                          '--archive_dir=./static',
                          '--client_prefix=ChromeOSUpdateEngine',
                          '--production',
-                        ], enter_chroot=True, print_cmd=False)
+                         ], enter_chroot=True, print_cmd=False,
+                         log_to_file=os.path.join(self.test_root,
+                                                  'dev_server.log'))
 
   def Stop(self):
     """Kills the devserver instance."""

bin/au_test_harness/vm_au_worker.py

@@ -58,6 +58,7 @@ class VMAUWorker(au_worker.AUWorker):
   def UpdateImage(self, image_path, src_image_path='', stateful_change='old',
                   proxy_port='', private_key_path=None):
     """Updates VM image with image_path."""
+    log_directory = self.GetNextResultsPath('update')
     stateful_change_flag = self.GetStatefulChangeFlag(stateful_change)
     if src_image_path and self._first_update:
       src_image_path = self.vm_image_path
@@ -65,6 +66,7 @@ class VMAUWorker(au_worker.AUWorker):
 
     cmd = ['%s/cros_run_vm_update' % self.crosutilsbin,
            '--vm_image_path=%s' % self.vm_image_path,
+           '--update_log=%s' % os.path.join(log_directory, 'update_engine.log'),
            '--snapshot',
            self.graphics_flag,
            '--persist',
@@ -74,15 +76,17 @@ class VMAUWorker(au_worker.AUWorker):
           ]
     self.AppendUpdateFlags(cmd, image_path, src_image_path, proxy_port,
                            private_key_path)
-    self.RunUpdateCmd(cmd)
+    self.RunUpdateCmd(cmd, log_directory)
 
   def UpdateUsingPayload(self, update_path, stateful_change='old',
                          proxy_port=None):
     """Updates a vm image using cros_run_vm_update."""
+    log_directory = self.GetNextResultsPath('update')
     stateful_change_flag = self.GetStatefulChangeFlag(stateful_change)
     cmd = ['%s/cros_run_vm_update' % self.crosutilsbin,
            '--payload=%s' % update_path,
            '--vm_image_path=%s' % self.vm_image_path,
+           '--update_log=%s' % os.path.join(log_directory, 'update_engine.log'),
            '--snapshot',
            self.graphics_flag,
            '--persist',
@@ -91,11 +95,12 @@ class VMAUWorker(au_worker.AUWorker):
            stateful_change_flag,
            ]
     if proxy_port: cmd.append('--proxy_port=%s' % proxy_port)
-    self.RunUpdateCmd(cmd)
+    self.RunUpdateCmd(cmd, log_directory)
 
   def VerifyImage(self, unittest, percent_required_to_pass=100):
     """Runs vm smoke suite to verify image."""
-    test_directory = self.GetNextResultsPath('verify')
+    log_directory = self.GetNextResultsPath('verify')
+    (_, _, log_directory_in_chroot) = log_directory.rpartition('chroot')
     # image_to_live already verifies lsb-release matching.  This is just
     # for additional steps.
     commandWithArgs = ['%s/cros_run_vm_test' % self.crosutilsbin,
@@ -104,7 +109,7 @@ class VMAUWorker(au_worker.AUWorker):
                        '--persist',
                        '--kvm_pid=%s' % self._kvm_pid_file,
                        '--ssh_port=%s' % self._ssh_port,
-                       '--results_dir_root=%s' % test_directory,
+                       '--results_dir_root=%s' % log_directory_in_chroot,
                        self.verify_suite,
                       ]
     if self.graphics_flag: commandWithArgs.append(self.graphics_flag)

bin/cros_run_vm_update

@@ -36,6 +36,8 @@ DEFINE_string src_image "" \
   "Create a delta update by passing in the image on the remote machine."
 DEFINE_string stateful_update_flag "" "Flags to pass to stateful update." s
 DEFINE_string image "" "Path of the image to update to." u
+DEFINE_string update_log "update_engine.log" \
+  "Path to log for the update_engine."
 DEFINE_string update_url "" "Full url of an update image."
 DEFINE_string vm_image_path "" "Path of the VM image to update from." v
 
@@ -70,6 +72,7 @@ fi
   --ssh_port=${FLAGS_ssh_port} \
   --stateful_update_flag=${FLAGS_stateful_update_flag} \
   --src_image="${FLAGS_src_image}" \
+  --update_log="${FLAGS_update_log}" \
   --update_url="${FLAGS_update_url}" \
   --verify \
   ${IMAGE_ARGS}

lib/cros_build_lib.py

@@ -27,7 +27,8 @@ def GetCallerName():
 
 def RunCommand(cmd, print_cmd=True, error_ok=False, error_message=None,
                exit_code=False, redirect_stdout=False, redirect_stderr=False,
-               cwd=None, input=None, enter_chroot=False, num_retries=0):
+               cwd=None, input=None, enter_chroot=False, num_retries=0,
+               log_to_file=None):
   """Runs a shell command.
 
   Arguments:
@@ -44,6 +45,7 @@ def RunCommand(cmd, print_cmd=True, error_ok=False, error_message=None,
     enter_chroot: this command should be run from within the chroot.  If set,
       cwd must point to the scripts directory.
     num_retries: the number of retries to perform before dying
+    log_to_file: Redirects all stderr and stdout to file specified by this path.
 
   Returns:
     If exit_code is True, returns the return code of the shell command.
@@ -51,24 +53,36 @@ def RunCommand(cmd, print_cmd=True, error_ok=False, error_message=None,
 
   Raises:
     Exception:  Raises RunCommandException on error with optional error_message,
+
                 but only if exit_code, and error_ok are both False. 
   """
   # Set default for variables.
   stdout = None
   stderr = None
   stdin = None
+  file_handle = None
   output = ''
 
   # Modify defaults based on parameters.
-  if redirect_stdout:  stdout = subprocess.PIPE
-  if redirect_stderr:  stderr = subprocess.PIPE
+  if log_to_file:
+    file_handle = open(log_to_file, 'w+')
+    stdout = file_handle
+    stderr = file_handle
+  else:
+    if redirect_stdout:  stdout = subprocess.PIPE
+    if redirect_stderr:  stderr = subprocess.PIPE
+
   if input:  stdin = subprocess.PIPE
   if enter_chroot:  cmd = ['./enter_chroot.sh', '--'] + cmd
 
   # Print out the command before running.
+  cmd_string = 'PROGRAM(%s) -> RunCommand: %r in dir %s' % (GetCallerName(),
+                                                            cmd, cwd)
   if print_cmd:
-    Info('PROGRAM(%s) -> RunCommand: %r in dir %s' %
-         (GetCallerName(), cmd, cwd))
+    if not log_to_file:
+      Info(cmd_string)
+    else:
+      Info('%s -- Logging to %s' % (cmd_string, log_to_file))
 
   for retry_count in range(num_retries + 1):
 
@@ -85,6 +99,8 @@ def RunCommand(cmd, print_cmd=True, error_ok=False, error_message=None,
     if proc.returncode == 0:
       break
 
+  if file_handle: file_handle.close()
+
   # If they asked for an exit_code, give it to them on success or failure
   if exit_code:
     return proc.returncode
@@ -256,6 +272,15 @@ def ReinterpretPathForChroot(path):
   return new_path
 
 
+def PrependChrootPath(path):
+  """Assumes path is a chroot path and prepends chroot to create full path."""
+  chroot_path = os.path.join(FindRepoDir(), '..', 'chroot')
+  if path.startswith('/'):
+    return os.path.realpath(os.path.join(chroot_path, path[1:]))
+  else:
+    return os.path.realpath(os.path.join(chroot_path, path))
+
+
 def GetIPAddress(device='eth0'):
   """Returns the IP Address for a given device using ifconfig.
 

lib/cros_build_lib_unittest.py

@@ -6,6 +6,8 @@
 
 """Unit tests for cros_build_lib."""
 
+import os
+import tempfile
 import unittest
 
 import cros_build_lib
@@ -87,6 +89,20 @@ class CrosBuildLibTest(unittest.TestCase):
                                        redirect_stderr=True)
     self.assertEqual(result, 'Hi')
 
+  def testRunCommandLogToFile(self):
+    """Test that RunCommand can log output to a file correctly."""
+    log_file = tempfile.mktemp()
+    cros_build_lib.RunCommand(['echo', '-n', 'Hi'],
+                               # Keep the test quiet options
+                               print_cmd=False,
+                               # Test specific options
+                               log_to_file=log_file)
+    log_fh = open(log_file)
+    log_data = log_fh.read()
+    self.assertEquals('Hi', log_data)
+    log_fh.close()
+    os.remove(log_file)
+
 
 if __name__ == '__main__':
   unittest.main()