Reduced logging and better log format for PyAuto WaitUntil().

chrome/test/pyautolib/pyauto.py

 #!/usr/bin/env python
 # Copyright (c) 2012 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """PyAuto: Python Interface to Chromium's Automation Proxy.
 
 PyAuto uses swig to expose Automation Proxy interfaces to Python.
 For complete documentation on the functionality available,
 run pydoc on this file.
@@ skipping 459 matching lines @@
       self.CloseChromeOnChromeOS()
       self.EnableChromeTestingOnChromeOS()
       self.SetUp()
       return
     # Not chromeos
     orig_clear_state = self.get_clear_profile()
     self.CloseBrowserAndServer()
     self.set_clear_profile(clear_profile)
     if pre_launch_hook:
       pre_launch_hook()
-    logging.debug('Restarting browser with clear_profile=%s' %
+    logging.debug('Restarting browser with clear_profile=%s',
                   self.get_clear_profile())
     self.LaunchBrowserAndServer()
     self.set_clear_profile(orig_clear_state)  # Reset to original state.
 
   @staticmethod
   def DataDir():
     """Returns the path to the data dir chrome/test/data."""
     return os.path.normpath(
         os.path.join(os.path.dirname(__file__), os.pardir, "data"))
 
@@ skipping 220 matching lines @@
       debug: if True, displays debug info at each retry.
 
     Returns:
       True, if returning when |function| evaluated to True
       False, when returning due to timeout
     """
     if timeout == -1:  # Default
       timeout = self.action_max_timeout_ms() / 1000.0
     assert callable(function), "function should be a callable"
     begin = time.time()
+    debug_begin = begin
     while timeout is None or time.time() - begin <= timeout:
       retval = function(*args)
       if (expect_retval is None and retval) or expect_retval == retval:
         return True
-      if debug:
-        logging.debug('WaitUntil(%s) still waiting. '
-                      'Expecting %s. Last returned %s.' % (
-                      function, expect_retval, retval))
+      if debug and time.time() - debug_begin > 5:
+        debug_begin += 5
+        if function.func_name == (lambda: True).func_name:
+          function_info = inspect.getsource(function).strip()
+        else:
+          function_info = '%s()' % function.func_name
+        logging.debug('WaitUntil(%s:%d %s) still waiting. '
+                      'Expecting %s. Last returned %s.',
+                      os.path.basename(inspect.getsourcefile(function)),
+                      inspect.getsourcelines(function)[1],
+                      function_info,
+                      True if expect_retval is None else expect_retval,
+                      retval)
       time.sleep(retry_sleep)
     return False
 
   def StartSyncServer(self):
     """Start a local sync server.
 
     Adds a dictionary attribute 'ports' in returned object.
 
     Returns:
       A handle to Sync Server, an instance of TestServer
     """
     sync_server = pyautolib.TestServer(pyautolib.TestServer.TYPE_SYNC,
         pyautolib.FilePath(''))
     assert sync_server.Start(), 'Could not start sync server'
     sync_server.ports = dict(port=sync_server.GetPort(),
                              xmpp_port=sync_server.GetSyncXmppPort())
-    logging.debug('Started sync server at ports %s.' % sync_server.ports)
+    logging.debug('Started sync server at ports %s.', sync_server.ports)
     return sync_server
 
   def StopSyncServer(self, sync_server):
     """Stop the local sync server."""
     assert sync_server, 'Sync Server not yet started'
     assert sync_server.Stop(), 'Could not stop sync server'
-    logging.debug('Stopped sync server at ports %s.' % sync_server.ports)
+    logging.debug('Stopped sync server at ports %s.', sync_server.ports)
 
   def StartFTPServer(self, data_dir):
     """Start a local file server hosting data files over ftp://
 
     Args:
       data_dir: path where ftp files should be served
 
     Returns:
       handle to FTP Server, an instance of TestServer
     """
     ftp_server = pyautolib.TestServer(pyautolib.TestServer.TYPE_FTP,
         pyautolib.FilePath(data_dir))
     assert ftp_server.Start(), 'Could not start ftp server'
-    logging.debug('Started ftp server at "%s".' % data_dir)
+    logging.debug('Started ftp server at "%s".', data_dir)
     return ftp_server
 
   def StopFTPServer(self, ftp_server):
     """Stop the local ftp server."""
     assert ftp_server, 'FTP Server not yet started'
     assert ftp_server.Stop(), 'Could not stop ftp server'
     logging.debug('Stopped ftp server.')
 
   def StartHTTPServer(self, data_dir):
     """Starts a local HTTP TestServer serving files from |data_dir|.
 
     Args:
       data_dir: path where the TestServer should serve files from. This will be
       appended to the source dir to get the final document root.
 
     Returns:
       handle to the HTTP TestServer
     """
     http_server = pyautolib.TestServer(pyautolib.TestServer.TYPE_HTTP,
         pyautolib.FilePath(data_dir))
     assert http_server.Start(), 'Could not start HTTP server'
-    logging.debug('Started HTTP server at "%s".' % data_dir)
+    logging.debug('Started HTTP server at "%s".', data_dir)
     return http_server
 
   def StopHTTPServer(self, http_server):
     assert http_server, 'HTTP server not yet started'
     assert http_server.Stop(), 'Cloud not stop the HTTP server'
     logging.debug('Stopped HTTP server.')
 
   class ActionTimeoutChanger(object):
     """Facilitate temporary changes to action_timeout_ms.
 
@@ skipping 3717 matching lines @@
 
   def _StartHTTPServer(self):
     """Start a local file server hosting data files over http://"""
     global _HTTP_SERVER
     assert not _HTTP_SERVER, 'HTTP Server already started'
     http_data_dir = _OPTIONS.http_data_dir
     http_server = pyautolib.TestServer(pyautolib.TestServer.TYPE_HTTP,
         pyautolib.FilePath(http_data_dir))
     assert http_server.Start(), 'Could not start http server'
     _HTTP_SERVER = http_server
-    logging.debug('Started http server at "%s".' % http_data_dir)
+    logging.debug('Started http server at "%s".', http_data_dir)
 
   def _StopHTTPServer(self):
     """Stop the local http server."""
     global _HTTP_SERVER
     assert _HTTP_SERVER, 'HTTP Server not yet started'
     assert _HTTP_SERVER.Stop(), 'Could not stop http server'
     _HTTP_SERVER = None
     logging.debug('Stopped http server.')
 
   def _ConnectToRemoteHosts(self, addresses):
@@ skipping 218 matching lines @@
       obj = getattr(obj, part)
 
     if type(obj) == types.ModuleType:
       return _GetTestsFromModule(obj)
     elif (isinstance(obj, (type, types.ClassType)) and
           issubclass(obj, PyUITest) and obj != PyUITest):
       return [module.__name__ + '.' + x for x in _GetTestsFromTestCase(obj)]
     elif type(obj) == types.UnboundMethodType:
       return [name]
     else:
-      logging.warn('No tests in "%s"' % name)
+      logging.warn('No tests in "%s"', name)
       return []
 
   def _ListMissingTests(self):
     """Print tests missing from PYAUTO_TESTS."""
     # Fetch tests from all test scripts
     all_test_files = filter(lambda x: x.endswith('.py'),
                             os.listdir(self.TestsDir()))
     all_tests_modules = [os.path.splitext(x)[0] for x in all_test_files]
     all_tests = reduce(lambda x, y: x + y,
                        map(self._ImportTestsFromName, all_tests_modules))
@@ skipping 40 matching lines @@
           ]
     """
     if not args:  # Load tests ourselves
       if self._HasTestCases('__main__'):    # we are running a test script
         module_name = os.path.splitext(os.path.basename(sys.argv[0]))[0]
         args.append(module_name)   # run the test cases found in it
       else:  # run tests from the test description file
         pyauto_tests_file = os.path.join(self.TestsDir(), self._tests_filename)
         logging.debug("Reading %s", pyauto_tests_file)
         if not os.path.exists(pyauto_tests_file):
-          logging.warn("%s missing. Cannot load tests." % pyauto_tests_file)
+          logging.warn("%s missing. Cannot load tests.", pyauto_tests_file)
         else:
           args = self._ExpandTestNamesFrom(pyauto_tests_file,
                                            self._options.suite)
     return args
 
   def _ExpandTestNamesFrom(self, filename, suite):
     """Load test names from the given file.
 
     Args:
       filename: the file to read the tests from
       suite: the name of the suite to load from |filename|.
 
     Returns:
       a list of test names
       [module.testcase.testX, module.testcase.testY, ..]
     """
     suites = PyUITest.EvalDataFrom(filename)
     platform = sys.platform
     if PyUITest.IsChromeOS():  # check if it's chromeos
       platform = 'chromeos'
     assert platform in self._platform_map, '%s unsupported' % platform
     def _NamesInSuite(suite_name):
-      logging.debug('Expanding suite %s' % suite_name)
+      logging.debug('Expanding suite %s', suite_name)
       platforms = suites.get(suite_name)
       names = platforms.get('all', []) + \
               platforms.get(self._platform_map[platform], [])
       ret = []
       # Recursively include suites if any.  Suites begin with @.
       for name in names:
         if name.startswith('@'):  # Include another suite
           ret.extend(_NamesInSuite(name[1:]))
         else:
           ret.append(name)
       return ret
 
     assert suite in suites, '%s: No such suite in %s' % (suite, filename)
     all_names = _NamesInSuite(suite)
     args = []
     excluded = []
     # Find all excluded tests.  Excluded tests begin with '-'.
     for name in all_names:
       if name.startswith('-'):  # Exclude
         excluded.extend(self._ImportTestsFromName(name[1:]))
       else:
         args.extend(self._ImportTestsFromName(name))
     for name in excluded:
       if name in args:
         args.remove(name)
       else:
-        logging.warn('Cannot exclude %s. Not included. Ignoring' % name)
+        logging.warn('Cannot exclude %s. Not included. Ignoring', name)
     if excluded:
-      logging.debug('Excluded %d test(s): %s' % (len(excluded), excluded))
+      logging.debug('Excluded %d test(s): %s', len(excluded), excluded)
     return args
 
   def _Run(self):
     """Run the tests."""
     if self._options.wait_for_debugger:
       raw_input('Attach debugger to process %s and hit <enter> ' % os.getpid())
 
     suite_args = [sys.argv[0]]
     chrome_flags = self._options.chrome_flags
     # Set CHROME_HEADLESS. It enables crash reporter on posix.
@@ skipping 18 matching lines @@
     successful = result.wasSuccessful()
     if not successful:
       pyauto_tests_file = os.path.join(self.TestsDir(), self._tests_filename)
       print >>sys.stderr, 'Tests can be disabled by editing %s. ' \
                           'Ref: %s' % (pyauto_tests_file, _PYAUTO_DOC_URL)
     sys.exit(not successful)
 
 
 if __name__ == '__main__':
   Main()