Speedup by checking the page only when necessary; Logging update.

src/widgetastic/browser.py

@@ -21,7 +21,8 @@
 from .exceptions import (
     NoSuchElementException, UnexpectedAlertPresentException, MoveTargetOutOfBoundsException,
     StaleElementReferenceException, NoAlertPresentException, LocatorNotImplemented)
-from .log import create_widget_logger, null_logger
+from .log import create_widget_logger, logged, null_logger
+from .utils import repeat_once_on_exceptions
 from .xpath import normalize_space
 
 
@@ -243,6 +244,7 @@ def elements(
 
         return result
 
+    @repeat_once_on_exceptions(NoSuchElementException, check_safe=True)
     def element(self, locator, *args, **kwargs):
         """Returns one :py:class:`selenium.webdriver.remote.webelement.WebElement`
 
@@ -254,6 +256,8 @@ def element(self, locator, *args, **kwargs):
         Raises:
             :py:class:`selenium.common.exceptions.NoSuchElementException`
         """
+        if 'check_safe' not in kwargs:
+            kwargs['check_safe'] = False
         try:
             vcheck = self._locator_force_visibility_check(locator)
             if vcheck is not None:
@@ -268,18 +272,18 @@ def element(self, locator, *args, **kwargs):
             else:
                 return elements[0]
         except IndexError:
-            raise NoSuchElementException('Could not find an element {}'.format(repr(locator)))
+            raise NoSuchElementException('Could not find an element {!r}'.format(locator))
 
     def perform_click(self):
         """Clicks the left mouse button at the current mouse position."""
         ActionChains(self.selenium).click().perform()
 
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
     def click(self, locator, *args, **kwargs):
         """Clicks at a specific element using two separate events (mouse move, mouse click).
 
         Args: See :py:meth:`elements`
         """
-        self.logger.debug('click: %r', locator)
         ignore_ajax = kwargs.pop('ignore_ajax', False)
         el = self.move_to_element(locator, *args, **kwargs)
         self.plugin.before_click(el)
@@ -295,12 +299,12 @@ def click(self, locator, *args, **kwargs):
         except (StaleElementReferenceException, UnexpectedAlertPresentException):
             pass
 
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
     def raw_click(self, locator, *args, **kwargs):
         """Clicks at a specific element using the direct event.
 
         Args: See :py:meth:`elements`
         """
-        self.logger.debug('raw_click: %r', locator)
         ignore_ajax = kwargs.pop('ignore_ajax', False)
         el = self.element(locator, *args, **kwargs)
         self.plugin.before_click(el)
@@ -343,6 +347,10 @@ def is_displayed(self, locator, *args, **kwargs):
         # Just in case
         return False
 
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
+    @repeat_once_on_exceptions(
+        StaleElementReferenceException, MoveTargetOutOfBoundsException,
+        check_safe=True)
     def move_to_element(self, locator, *args, **kwargs):
         """Moves the mouse cursor to the middle of the element represented by the locator.
 
@@ -351,23 +359,31 @@ def move_to_element(self, locator, *args, **kwargs):
 
         Args: See :py:meth:`elements`
 
+        Keywords:
+            workaround: Default True, tells whether it can or can not perform the JS workaround.
+
         Returns:
             :py:class:`selenium.webdriver.remote.webelement.WebElement`
         """
-        self.logger.debug('move_to_element: %r', locator)
+        if 'check_safe' not in kwargs:
+            kwargs['check_safe'] = False
+        workaround = kwargs.pop('workaround', True)
         el = self.element(locator, *args, **kwargs)
         if el.tag_name == "option":
             # Instead of option, let's move on its parent <select> if possible
-            parent = self.element("..", parent=el)
+            parent = self.element("..", parent=el, check_safe=False)
             if parent.tag_name == "select":
-                self.move_to_element(parent)
+                self.move_to_element(parent, workaround=workaround)
                 return el
         move_to = ActionChains(self.selenium).move_to_element(el)
         try:
             move_to.perform()
         except MoveTargetOutOfBoundsException:
+            if not workaround:
+                # No workaround, reraise
+                raise
             # ff workaround
-            self.execute_script("arguments[0].scrollIntoView();", el)
+            self.execute_script("arguments[0].scrollIntoView();", el, silent=True)
             try:
                 move_to.perform()
             except MoveTargetOutOfBoundsException:  # This has become desperate now.
@@ -376,16 +392,20 @@ def move_to_element(self, locator, *args, **kwargs):
                         locator))
         return el
 
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
     def move_by_offset(self, x, y):
-        self.logger.debug('move_by_offset X:%r Y:%r', x, y)
-        ActionChains(self.selenium).move_by_offset(x, y)
+        """Moves mouse pointer by given values."""
+        ActionChains(self.selenium).move_by_offset(x, y).perform()
+        self.plugin.ensure_page_safe()
 
     def execute_script(self, script, *args, **kwargs):
         """Executes a script."""
         if not kwargs.pop('silent', False):
-            self.logger.debug('execute_script: %r', script)
+            self.logger.debug('execute_script(%r)', script)
         return self.selenium.execute_script(dedent(script), *args, **kwargs)
 
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
     def classes(self, locator, *args, **kwargs):
         """Return a list of classes attached to the element.
 
@@ -394,11 +414,11 @@ def classes(self, locator, *args, **kwargs):
         Returns:
             A :py:class:`set` of strings with classes.
         """
-        result = set(self.execute_script(
+        return set(self.execute_script(
             "return arguments[0].classList;", self.element(locator, *args, **kwargs), silent=True))
-        self.logger.debug('css classes for %r => %r', locator, result)
-        return result
 
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
     def tag(self, *args, **kwargs):
         """Returns the tag name of the element represented by the locator passed.
 
@@ -409,7 +429,9 @@ def tag(self, *args, **kwargs):
         """
         return self.element(*args, **kwargs).tag_name
 
-    def text(self, *args, **kwargs):
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
+    def text(self, locator, *args, **kwargs):
         """Returns the text inside the element represented by the locator passed.
 
         The returned text is normalized with :py:func:`widgetastic.xpath.normalize_space` as defined
@@ -421,45 +443,56 @@ def text(self, *args, **kwargs):
             :py:class:`str` with the text
         """
         try:
-            text = self.element(*args, **kwargs).text
+            text = self.move_to_element(locator, *args, **dict(kwargs, workaround=False)).text
         except MoveTargetOutOfBoundsException:
             text = ''
 
         if not text:
             # It is probably invisible
             text = self.execute_script(
                 'return arguments[0].textContent || arguments[0].innerText;',
-                self.element(*args, **kwargs))
+                self.element(locator, *args, **kwargs),
+                silent=True)
             if text is None:
                 text = ''
 
         return normalize_space(text)
 
-    def get_attribute(self, attr, *args, **kwargs):
-        return self.element(*args, **kwargs).get_attribute(attr)
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
+    def get_attribute(self, attr, locator, *args, **kwargs):
+        """Get attribute value from an element."""
+        return self.element(locator, *args, **kwargs).get_attribute(attr)
 
-    def set_attribute(self, attr, value, *args, **kwargs):
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
+    def set_attribute(self, attr, value, locator, *args, **kwargs):
         return self.execute_script(
             "arguments[0].setAttribute(arguments[1], arguments[2]);",
-            self.element(*args, **kwargs), attr, value)
+            self.element(locator, *args, **kwargs), attr, value)
 
-    def size_of(self, *args, **kwargs):
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
+    def size_of(self, locator, *args, **kwargs):
         """Returns element's size as a tuple of width/height."""
-        size = self.element(*args, **kwargs).size
+        size = self.element(locator, *args, **kwargs).size
         return Size(size['width'], size['height'])
 
+    @logged(log_args=True, only_after=True, debug_only=True, log_full_exception=False)
     def clear(self, locator, *args, **kwargs):
         """Clears a text input with given locator."""
-        self.logger.debug('clear: %r', locator)
         el = self.element(locator, *args, **kwargs)
         self.plugin.before_keyboard_input(el, None)
         result = el.clear()
+        self.plugin.ensure_page_safe()
         self.plugin.after_keyboard_input(el, None)
         return result
 
-    def is_selected(self, *args, **kwargs):
-        return self.element(*args, **kwargs).is_selected()
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
+    def is_selected(self, locator, *args, **kwargs):
+        return self.element(locator, *args, **kwargs).is_selected()
 
+    @logged(log_args=True, debug_only=True, log_full_exception=False)
     def send_keys(self, text, locator, *args, **kwargs):
         """Sends keys to the element. Detects the file inputs automatically.
 
@@ -481,8 +514,9 @@ def send_keys(self, text, locator, *args, **kwargs):
                 self.selenium.file_detector = LocalFileDetector()
             el = self.move_to_element(locator, *args, **kwargs)
             self.plugin.before_keyboard_input(el, text)
-            self.logger.debug('send_keys %r to %r', text, locator)
             result = el.send_keys(text)
+            # Ensure the page input was safe
+            self.plugin.ensure_page_safe()
             if Keys.ENTER not in text:
                 try:
                     self.plugin.after_keyboard_input(el, text)
@@ -510,6 +544,8 @@ def get_alert(self):
         return self.selenium.switch_to_alert()
 
     @property
+    @logged(
+        log_args=True, log_result=True, only_after=True, debug_only=True, log_full_exception=False)
     def alert_present(self):
         """Checks whether there is any alert present.
 
@@ -524,6 +560,7 @@ def alert_present(self):
         else:
             return True
 
+    @logged(log_args=True, log_full_exception=False)
     def dismiss_any_alerts(self):
         """Loops until there are no further alerts present to dismiss.
 
@@ -537,6 +574,7 @@ def dismiss_any_alerts(self):
         except NoAlertPresentException:  # Just in case. alert_present should be reliable
             pass
 
+    @logged(log_args=True, log_result=True, log_full_exception=False)
     def handle_alert(self, cancel=False, wait=30.0, squash=False, prompt=None, check_present=False):
         """Handles an alert popup.
 

src/widgetastic/log.py

@@ -50,7 +50,9 @@ def create_widget_logger(widget_path, logger=None):
         {'widget_path': widget_path})
 
 
-def logged(log_args=False, log_result=False):
+def logged(
+        log_args=False, log_result=False, only_after=False, debug_only=False,
+        log_full_exception=True):
     """Decorator that logs entry and exit to a method and also times the execution.
 
     It assumes that the object where you decorate the methods on has a ``.logger`` attribute.
@@ -63,34 +65,46 @@ def logged(log_args=False, log_result=False):
     Args:
         log_args: Whether to log args passed to the method
         log_result: Whether to log the result value returned from the method.
+        only_after: Whether to log only after the method finished.
+        debug_only: Use only debug log level at max.
+        log_full_exception: Whether to log the full exceptions.
     """
     def g(f):
         @wraps(f)
         def wrapped(self, *args, **kwargs):
+            if debug_only:
+                info_logger = self.logger.debug
+            else:
+                info_logger = self.logger.info
             start_time = time.time()
             signature = f.__name__ + (call_sig(args, kwargs) if log_args else '')
-            self.logger.debug('%s started', signature)
+            if not only_after:
+                self.logger.debug('%s started', signature)
             try:
                 result = f(self, *args, **kwargs)
             except DoNotReadThisWidget:
                 elapsed_time = (time.time() - start_time) * 1000.0
-                self.logger.info(
+                info_logger(
                     '%s not read on widget\'s request (elapsed %.0f ms)',
                     signature, elapsed_time)
                 raise
             except Exception as e:
                 elapsed_time = (time.time() - start_time) * 1000.0
-                self.logger.error(
-                    'An exception happened during %s call (elapsed %.0f ms)',
-                    signature, elapsed_time)
-                self.logger.exception(e)
+                if log_full_exception:
+                    self.logger.exception(
+                        'An exception happened during %s call (elapsed %.0f ms)',
+                        signature, elapsed_time)
+                else:
+                    self.logger.error(
+                        'An exception %s happened during %s call (elapsed %.0f ms)',
+                        str(e), signature, elapsed_time)
                 raise
             else:
                 elapsed_time = (time.time() - start_time) * 1000.0
                 if log_result:
-                    self.logger.info('%s -> %r (elapsed %.0f ms)', signature, result, elapsed_time)
+                    info_logger('%s -> %r (elapsed %.0f ms)', signature, result, elapsed_time)
                 else:
-                    self.logger.info('%s (elapsed %.0f ms)', signature, elapsed_time)
+                    info_logger('%s (elapsed %.0f ms)', signature, elapsed_time)
                 return result
 
         wrapped.original_function = f

src/widgetastic/utils.py

@@ -5,6 +5,7 @@
 import re
 import string
 from cached_property import cached_property
+from functools import wraps
 from smartloc import Locator
 from threading import Lock
 
@@ -441,3 +442,34 @@ def normalize_space(text):
         string.*
     """
     return _replace_spaces_with(text.strip(), ' ')
+
+
+def repeat_once_on_exceptions(*exception_classes, **set_key_to_what):
+    """This decorator serves as DRY repeater of method or function execution.
+
+    Works the way that when any of the exception classes is caught, the kwargs of the method call
+    is updated with ``set_key_to_what`` and invoked once more.
+
+    Args:
+        *exception_classes: Exception classes on which this decorator should react
+        **set_key_to_what: kwargs override used when the exception is hit and call retried.
+
+    Returns:
+        Whatever the wrapped function/method returns.
+
+    """
+    if not set_key_to_what:
+        raise TypeError('set_key_to_what is not set!')
+
+    def g(f):
+        @wraps(f)
+        def wrapped(*args, **kwargs):
+            try:
+                return f(*args, **kwargs)
+            except exception_classes:
+                kwargs.update(set_key_to_what)
+                return f(*args, **kwargs)
+
+        return wrapped
+
+    return g