Merge lp:~elopio/selenium-simple-test/logging into lp:selenium-simple-test

[Leo Arias]

Use a logger for SST messages.

I added logging facilities instead, so messages can go to the log instead of just priting them.
Currently it just have a basic configuration so it will still go to the command line.
And currently the runner accepts only the -q option, that will set a high logging level so nothing is printed in the command line. Default level is DEBUG, but in the future we should handle this better.

[Leo Arias (elopio)]

This branch was born because we need to set the logging level while running tests in U1.
That's done here: https://code.launchpad.net/~elopio/ubuntuone-servers/acceptance_tests_logger/+merge/147710

[lp:~elopio/selenium-simple-test/logging]

365. By Leo Arias on 2013-02-11

Fixed the retry on stale element test.

366. By Leo Arias on 2013-02-11

Merged with trunk.

367. By Leo Arias on 2013-02-11

Indent the log messages with 4 spaces and print a newline. This is almost the same behavior as before the log.

[Corey Goldberg (coreygoldberg)]

thanks.
this looks nice.

review: Approve

=== modified file 'src/sst/actions.py'
--- src/sst/actions.py	2013-01-29 19:45:06 +0000
+++ src/sst/actions.py	2013-02-11 20:53:24 +0000
@@ -1,5 +1,5 @@
 #
-#   Copyright (c) 2011-2012 Canonical Ltd.
+#   Copyright (c) 2011,2012,2013 Canonical Ltd.
 #
 #   This file is part of: SST (selenium-simple-test)
 #   https://launchpad.net/selenium-simple-test
@@ -37,13 +37,13 @@
 """
 
 
+import logging
 import os
 import re
 import time
 
 from datetime import datetime
 from pdb import set_trace as debug
-from textwrap import TextWrapper
 from urlparse import urljoin, urlparse
 
 from selenium import webdriver
@@ -97,7 +97,8 @@
 
 BASE_URL = 'http://localhost:8000/'
 __DEFAULT_BASE_URL__ = BASE_URL
-VERBOSE = True
+
+logger = logging.getLogger('SST')
 
 
 class EndTest(StandardError):
@@ -114,7 +115,7 @@
 
 
 def _raise(msg):
-    _print(msg)
+    logger.debug(msg)
     raise AssertionError(msg)
 
 
@@ -133,7 +134,7 @@
         try:
             return func(*args, **kwargs)
         except StaleElementReferenceException as e:
-            _print('Retrying after catching: %r' % e)
+            logger.warning('Retrying after catching: %r' % e)
             return func(*args, **kwargs)
     return wrapped
 
@@ -143,7 +144,7 @@
     global BASE_URL
     if not url.startswith('http') and not url.startswith('file'):
         url = 'http://' + url
-    _print('Setting base url to: %r' % url)
+    logger.debug('Setting base url to: %r' % url)
     BASE_URL = url
 
 
@@ -174,16 +175,6 @@
     _test.skipTest(reason)
 
 
-def _print(text):
-    if VERBOSE:
-        text_wrapper = TextWrapper(
-            width=80,
-            initial_indent=(' ' * 4),
-            subsequent_indent=(' ' * 8),
-        )
-        print text_wrapper.fill(text)
-
-
 def start(browser_type=None, browser_version='',
           browser_platform='ANY', session_name='',
           javascript_disabled=False, assume_trusted_cert_issuer=False,
@@ -197,8 +188,14 @@
     if browser_type is None:
         browser_type = config.browser_type
 
-    _print('')
-    _print('Starting browser: %s' % browser_type)
+    if logger.isEnabledFor(logging.DEBUG):
+        # XXX We print a new line because otherwise the first debug message
+        # will be printed on the same line as the name of the test. This is 
+        # hacky and doesn't cover cases when the script logs things higher 
+        # than debug, but this way we are keeping the same behavior we had
+        # before adding the log.
+        print
+    logger.debug('Starting browser: %s' % browser_type)
 
     if webdriver_remote is None:
         if browser_type == 'Firefox':
@@ -244,13 +241,13 @@
     global browser
     global browsermob_proxy
 
-    _print('Stopping browser')
+    logger.debug('Stopping browser')
     # quit calls close() and does cleanup
     browser.quit()
     browser = None
 
     if browsermob_proxy is not None:
-        _print('Closing http proxy')
+        logger.debug('Closing http proxy')
         browsermob_proxy.close()
         browsermob_proxy = None
 
@@ -263,17 +260,17 @@
     available after the click. You can switch off this behaviour by passing
     `wait=False`."""
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Refreshing current page')
+    logger.debug('Refreshing current page')
     browser.refresh()
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name())
 
@@ -284,7 +281,7 @@
     when running in `-s` mode.
 
     Return the path to the saved screenshot."""
-    _print('Capturing Screenshot')
+    logger.debug('Capturing Screenshot')
     _make_results_dir()
     if add_timestamp:
         filename = _add_time_stamp(filename)
@@ -305,7 +302,7 @@
     Called automatically on failures when running `-s` mode.
 
     Return the path to the saved file."""
-    _print('Saving page source')
+    logger.debug('Saving page source')
     _make_results_dir()
     if add_timestamp:
         filename = _add_time_stamp(filename)
@@ -328,7 +325,7 @@
     """
     Delay execution for a given number of seconds. The argument may be a
     floating point number for subsecond precision."""
-    _print('Sleeping %s secs' % secs)
+    logger.debug('Sleeping %s secs' % secs)
     time.sleep(secs)
 
 
@@ -387,7 +384,7 @@
     when `run_test` returns."""
     # delayed import to workaround circular imports
     from sst import context
-    _print('Executing test: %s' % name)
+    logger.debug('Executing test: %s' % name)
     return context.run_test(name, kwargs)
 
 
@@ -418,17 +415,17 @@
     url = _fix_url(url)
 
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Going to... %s' % url)
+    logger.debug('Going to... %s' % url)
     browser.get(url)
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name(url))
 
@@ -441,17 +438,17 @@
     available after the click. You can switch off this behaviour by passing
     `wait=False`."""
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Going back one step in browser history')
+    logger.debug('Going back one step in browser history')
     browser.back()
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name())
 
@@ -485,7 +482,7 @@
     Toggle the checkbox value. Takes an element id or object. Raises a failure
     exception if the element specified doesn't exist or isn't a checkbox."""
     checkbox = assert_checkbox(id_or_elem)
-    _print('Toggling checkbox: %r' % _get_text(checkbox))
+    logger.debug('Toggling checkbox: %r' % _get_text(checkbox))
     before = checkbox.is_selected()
     checkbox.click()
     after = checkbox.is_selected()
@@ -500,7 +497,8 @@
     Set a checkbox to a specific value, either True or False. Raises a failure
     exception if the element specified doesn't exist or isn't a checkbox."""
     checkbox = assert_checkbox(id_or_elem)
-    _print('Setting checkbox %r to %r' % (_get_text(checkbox), new_value))
+    logger.debug(
+        'Setting checkbox %r to %r' % (_get_text(checkbox), new_value))
     # There is no method to 'unset' a checkbox in the browser object
     current_value = checkbox.is_selected()
     if new_value != current_value:
@@ -528,7 +526,7 @@
     key_element = _get_elem(id_or_elem)
     msg = 'Simulating keypress on %r with %r key' \
         % (_get_text(key_element), key_to_press)
-    _print(msg)
+    logger.debug(msg)
     key_code = _make_keycode(key_to_press)
     key_element.send_keys(key_code)
 
@@ -560,7 +558,7 @@
     textfield = assert_textfield(id_or_elem)
     msg = 'Writing to textfield %r with text %r' \
         % (_get_text(textfield), new_text)
-    _print(msg)
+    logger.debug(msg)
 
     # clear field like this, don't use clear()
     if clear:
@@ -573,7 +571,7 @@
         textfield.send_keys(str(new_text))
     if not check:
         return
-    _print('Check text wrote correctly')
+    logger.debug('Check text wrote correctly')
     current_text = textfield.get_attribute('value')
     if current_text != new_text:
         msg = 'Textfield: %r - did not write. Text was: %r' \
@@ -597,7 +595,7 @@
 
 def get_link_url(id_or_elem):
     """Return the URL from a link."""
-    _print('Getting url from link %r' % id_or_elem)
+    logger.debug('Getting url from link %r' % id_or_elem)
     link = assert_link(id_or_elem)
     link_url = link.get_attribute('href')
     return link_url
@@ -621,17 +619,17 @@
     link_url = link.get_attribute('href')
 
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        _logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Clicking link %r' % _get_text(link))
+    logger.debug('Clicking link %r' % _get_text(link))
     link.click()
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name())
 
@@ -665,17 +663,17 @@
     elem = _get_elem(id_or_elem)
 
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Clicking element %r' % _get_text(elem))
+    logger.debug('Clicking element %r' % _get_text(elem))
     elem.click()
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name())
 
@@ -746,7 +744,7 @@
     msg = 'Setting wait timeout to %rs' % timeout
     if poll is not None:
         msg += ('. Setting poll time to %rs' % poll)
-    _print(msg)
+    logger.debug(msg)
     _set_wait_timeout(timeout, poll)
 
 
@@ -771,10 +769,9 @@
 
 
 def _wait_for(condition, refresh_page, timeout, poll, *args, **kwargs):
-    global VERBOSE
-    _print('Waiting for %r' % _get_name(condition))
-    original = VERBOSE
-    VERBOSE = False
+    logger.debug('Waiting for %r' % _get_name(condition))
+    # Disable logging levels equal to or lower than INFO.
+    logging.disable(logging.INFO)
     try:
         max_time = time.time() + timeout
         msg = _get_name(condition)
@@ -797,7 +794,8 @@
                 _raise(error)
             time.sleep(poll)
     finally:
-        VERBOSE = original
+        # Re-enable logging.
+        logging.disable(logging.NOTSET)
 
 
 @retry_on_stale_element
@@ -850,7 +848,7 @@
     `fails` succeeds. If the function does *not* raise an AssertionError then
     this action raises the appropriate failure exception. Alll other
     exceptions will be propagated normally."""
-    _print('Trying action failure: %s' % _get_name(action))
+    logger.debug('Trying action failure: %s' % _get_name(action))
     try:
         action(*args, **kwargs)
     except AssertionError:
@@ -892,7 +890,8 @@
 def set_dropdown_value(id_or_elem, text=None, value=None):
     """Set the select drop-list to a text or value specified."""
     elem = assert_dropdown(id_or_elem)
-    _print('Setting %r option list to %r' % (_get_text(elem), text or value))
+    logger.debug(
+        'Setting %r option list to %r' % (_get_text(elem), text or value))
     if text and not value:
         for element in elem.find_elements_by_tag_name('option'):
             if element.text == text:
@@ -954,7 +953,7 @@
 def set_radio_value(id_or_elem):
     """Select the specified radio button."""
     elem = assert_radio(id_or_elem)
-    _print('Selecting radio button item %r' % _get_text(elem))
+    logger.debug('Selecting radio button item %r' % _get_text(elem))
     elem.click()
 
 
@@ -1154,17 +1153,17 @@
     button = assert_button(id_or_elem)
 
     if browsermob_proxy is not None:
-        _print('Capturing http traffic...')
+        logger.debug('Capturing http traffic...')
         browsermob_proxy.new_har()
 
-    _print('Clicking button %r' % _get_text(button))
+    logger.debug('Clicking button %r' % _get_text(button))
     button.click()
 
     if wait:
         _waitforbody()
 
     if browsermob_proxy is not None:
-        _print('Saving HAR output')
+        logger.debug('Saving HAR output')
         _make_results_dir()
         browsermob_proxy.save_har(_make_useable_har_name())
 
@@ -1216,7 +1215,7 @@
 
 def close_window():
     """ Closes the current window """
-    _print('Closing the current window')
+    logger.debug('Closing the current window')
     browser.close()
 
 
@@ -1226,7 +1225,7 @@
 
     if no window is given, switch focus to the default window."""
     if index_or_name is None:
-        _print('Switching to default window')
+        logger.debug('Switching to default window')
         browser.switch_to_window('')
     elif isinstance(index_or_name, int):
         index = index_or_name
@@ -1236,7 +1235,7 @@
             _raise(msg)
         window = window_handles[index]
         try:
-            _print('Switching to window: %r' % window)
+            logger.debug('Switching to window: %r' % window)
             browser.switch_to_window(window)
         except NoSuchWindowException:
             msg = 'Could not find window: %r' % window
@@ -1244,7 +1243,7 @@
     else:
         name = index_or_name
         try:
-            _print('Switching to window: %r' % name)
+            logger.debug('Switching to window: %r' % name)
             browser.switch_to_window(name)
         except NoSuchWindowException:
             msg = 'Could not find window: %r' % name
@@ -1257,10 +1256,10 @@
 
     if no frame is given, switch focus to the default content frame."""
     if index_or_name is None:
-        _print('Switching to default content frame')
+        logger.debug('Switching to default content frame')
         browser.switch_to_default_content()
     else:
-        _print('Switching to frame: %r' % index_or_name)
+        logger.debug('Switching to frame: %r' % index_or_name)
         try:
             browser.switch_to_frame(index_or_name)
         except NoSuchFrameException:
@@ -1301,7 +1300,7 @@
     Note that the action that opens the alert should not wait for a page with
     a body element. This means that you should call functions like
     click_element with the argument wait=Fase."""
-    _print('Accepting Alert')
+    logger.debug('Accepting Alert')
     _alert_action('accept', expected_text, text_to_write)
 
 
@@ -1315,7 +1314,7 @@
     Note that the action that opens the alert should not wait for a page with
     a body element. This means that you should call functions like
     click_element with the argument wait=Fase."""
-    _print('Dismissing Alert')
+    logger.debug('Dismissing Alert')
     _alert_action('dismiss', expected_text, text_to_write)
 
 
@@ -1324,7 +1323,7 @@
     Assert table `id_or_elem` has headers (<th> tags) where the text matches
     the sequence `headers`.
     """
-    _print('Checking headers for %r' % (id_or_elem,))
+    logger.debug('Checking headers for %r' % (id_or_elem,))
     elem = _get_elem(id_or_elem)
     if not elem.tag_name == 'table':
         _raise('Element %r is not a table.' % (id_or_elem,))
@@ -1341,7 +1340,7 @@
     Assert the specified table has the specified number of rows (<tr> tags
     inside the <tbody>).
     """
-    _print('Checking table %r has %s rows' % (id_or_elem, num_rows))
+    logger.debug('Checking table %r has %s rows' % (id_or_elem, num_rows))
     elem = _get_elem(id_or_elem)
     if not elem.tag_name == 'table':
         _raise('Element %r is not a table.' % (id_or_elem,))
@@ -1368,7 +1367,8 @@
     The row will be looked for inside the <tbody>, to check headers use
     `assert_table_headers`.
     """
-    _print('Checking the contents of table %r, row %s.' % (id_or_elem, row))
+    logger.debug(
+        'Checking the contents of table %r, row %s.' % (id_or_elem, row))
     elem = _get_elem(id_or_elem)
     if not elem.tag_name == 'table':
         _raise('Element %r is not a table.' % (id_or_elem,))
@@ -1403,7 +1403,7 @@
     the attribute using a regular expression search.
     """
     elem = _get_elem(id_or_elem)
-    _print('Checking attribute %r of %r' % (attribute, _get_text(elem)))
+    logger.debug('Checking attribute %r of %r' % (attribute, _get_text(elem)))
     actual = elem.get_attribute(attribute)
     if not regex:
         success = value == actual
@@ -1423,8 +1423,9 @@
     the property using a regular expression search.
     """
     elem = _get_elem(id_or_elem)
-    _print('Checking css property %r: %r of %r' %
-           (property, value, _get_text(elem)))
+    logger.debug(
+        'Checking css property %r: %r of %r' % (
+            property, value, _get_text(elem)))
     actual = elem.value_of_css_property(property)
     # some browsers return string with space padded commas, some don't.
     actual = actual.replace(', ', ',')
@@ -1487,13 +1488,13 @@
 
 def clear_cookies():
     """Clear the cookies of current session."""
-    _print('Clearing browser session cookies')
+    logger.debug('Clearing browser session cookies')
     browser.delete_all_cookies()
 
 
 def set_window_size(width, height):
     """Resize the current window (width, height) in pixels."""
-    _print('Resizing window to: %s x %s' % (width, height))
+    logger.debug('Resizing window to: %s x %s' % (width, height))
     orig_width, orig_height = get_window_size()
     if (orig_width == width) and (orig_height == height):
         return (width, height)
@@ -1531,7 +1532,7 @@
 
     args will be made available to the script if given.
     """
-    _print('Executing script')
+    logger.debug('Executing script')
     return browser.execute_script(script, *args)
 
 

=== modified file 'src/sst/command.py'
--- src/sst/command.py	2013-01-24 06:16:28 +0000
+++ src/sst/command.py	2013-02-11 20:53:24 +0000
@@ -18,6 +18,7 @@
 #
 
 import __main__
+import logging
 import os
 import sys
 import shutil
@@ -158,8 +159,12 @@
         print 'run "%s -h" or "%s --help" to see run options.' % (prog, prog)
         sys.exit(1)
 
+    logging.basicConfig(format='    %(levelname)s:%(name)s:%(message)s')
+    logger = logging.getLogger('SST')
     if cmd_opts.quiet:
-        actions.VERBOSE = False
+        logger.setLevel(logging.WARNING)
+    else:
+        logger.setLevel(logging.DEBUG)
     if cmd_opts.disable_flags:
         actions._check_flags = False
 

=== modified file 'src/sst/tests/test_actions.py'
--- src/sst/tests/test_actions.py	2013-01-24 06:07:20 +0000
+++ src/sst/tests/test_actions.py	2013-02-11 20:53:24 +0000
@@ -18,7 +18,7 @@
 
 
 from cStringIO import StringIO
-import sys
+import logging
 
 
 import testtools
@@ -33,7 +33,8 @@
         super(TestRetryOnStale, self).setUp()
         self.out = StringIO()
         # Capture output from retry_on_stale_element calls
-        self.patch(sys, 'stdout', self.out)
+        logger = logging.getLogger('SST')
+        logger.addHandler(logging.StreamHandler(self.out))
         self.nb_calls = 0
 
     def raise_stale_element(self):
@@ -49,7 +50,7 @@
         self.assertEqual(2, self.nb_calls)
         # And we get some feedback about the exception
         self.assertIn(
-            '    Retrying after catching: StaleElementReferenceException()\n',
+            'Retrying after catching: StaleElementReferenceException()',
             self.out.getvalue())
 
     def test_retry_on_stale_only_once(self):