Observer code not terribly thread safe #5

Open
jtatum opened this Issue May 5, 2011 · 4 comments

Comments

Projects
None yet
2 participants
Owner

jtatum commented May 5, 2011

There may be some crashes when starting an observer on a thread. This needs to be investigated. We're using PyGILState_Ensure for calling Python code in a couple of places - I don't think that's correct. THe cfrunloop may need to be wrapped in GIL code perhaps? Need to do a lot of research here.

Owner

pekkle01 commented May 5, 2011

I have some python script examples that demonstrate thread usage with this both working and crashing. Where can I upload the files for others to download?

Owner

pekkle01 commented May 5, 2011

This sample script (below) should setup logging output to stdout, run TextEdit, open a new TextEdit window with the default name of 'Untitled 2,' and time it. This version should work.

#!/usr/bin/env python

import time
import Queue
import inspect
import logging
import threading

import AppKit

import pyatom
from pyatom.AXClasses import NativeUIElement
from pyatom.AXKeyCodeConstants import *


class RelaxedFormatter(logging.Formatter):
   def format(self, record):
      msg=logging.Formatter.format(self, record)
      if isinstance(msg, str):
         msg=msg.decode('utf8', 'replace')
      return msg


def setupLogging():
   shellHandler = logging.StreamHandler()
   logFormat = ('%(asctime)s.%(msecs)-3d: [%(threadName)s]: '
                '%(filename)s#%(lineno)d | %(message)s')
   dateFormat = '%Y-%m-%dT%H:%M:%S'
   formatter = RelaxedFormatter(logFormat, dateFormat)
   shellHandler.setLevel(logging.DEBUG)
   shellHandler.setFormatter(formatter)
   log = logging.getLogger('')
   log.setLevel(logging.DEBUG)
   for handler in log.handlers:
      log.removeHandler(handler)

   log.addHandler(shellHandler)


class testNotificationClass(object):
   def __init__(self, appRef):
      self.appRef = appRef

   def _openWindow(self, t, a=1):
      ''' _openWindow: Function to open a TextEdit window

          Parameters: t (dummy parameter to test passing of parameters)
          Optional: a (dummy parameter to test passing of parameters)
          Returns: None
      '''
      logging.debug('Value of t: %s' % str(t))
      logging.debug('Value of a: %s' % str(a))
      self.appRef.AXFrontmost = True
      self.appRef.sendKeyWithModifiers('n', modifiers=[COMMAND])
      logging.debug('Completed opening new window')


   def timeUIActivity(self, e, t, q, ref, fname, *fargs):
      ''' timeUIActivity: function to time UI events based on Accessibility API
          notifications

          Parameters: e (threading.Event object); created in caller; used to
                         synchronize UI action and timing of it
                      t (timeout for queue usage)
                      q (Thread-safe Queue object to store the timing result;
                         created in caller)
                        (result is a 3-item tuple (func name (for id), result,
                         time waited))
                      ref (pyatom reference (timer functions are instance
                           methods))
                      fname (timing function to call on the reference)
                      *fargs (vararg list for timing function)
          Returns: None
          Side effects:  Result placed in the queue object
      '''
      logging.debug('Entered UI Timing function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()
      func = getattr(ref, fname)
      logging.debug('func: %s' % func.__name__)
      args = inspect.getargspec(func)
      logging.debug('List of args for func: %s' % str(args.args))
      logging.debug('About to start timing now!')

      # Set flag to allow the UI action to start
      e.set()
      startTime = time.time()
      result = None
      if (len(args.args) > 0):
         result = func(*fargs)
      else:
         result = func()
      delta = time.time() - startTime
      q.put((func.__name__, result, delta), timeout=t)
      logging.debug('Result of wait: %s' % result)
      logging.debug('Time waited: %s' % delta)
      del pool


   def uiActivity(self, e, t, f, *fargs):
      ''' uiActivity:  function to perform some UI action to change UI state of
                       the application

          Parameters: e (threading.Event object); created in caller
                      t (timeout value for the event wait)
                      f (function to call to perform the action
                      *fargs (var arg list to pass to the function to call)
          Returns: None
      '''
      logging.debug('Entered UI Activity function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()

      logging.debug('Determining what to pass to func')
      args = inspect.getargspec(f)
      logging.debug('List of args for func: %s' % str(args.args))

      # Wait until the timer function is ready
      e.wait(t)
      result = None
      if (len(args.args) > 0):
         result = f(*fargs)
      else:
         result = f()
      logging.debug('Result of UI activity: %s' % result)
      del pool


def main():
   setupLogging()

   q = Queue.Queue()
   e = threading.Event()
   timeout = 5
   winName = 'Untitled 2'

   # Start TextEdit first:
   NativeUIElement.launchAppByBundleId('com.apple.TextEdit')
   time.sleep(2)

   # Time how long it takes to launch a new window
   textEdit = pyatom.getAppRefByBundleId('com.apple.TextEdit')
   newN = testNotificationClass(textEdit)

   t1 = threading.Thread(name='timer', target=newN.timeUIActivity,
                         args=(e, timeout, q, textEdit, 'waitForWindowToAppear',
                         winName, timeout))

   t1.start()
   e.wait()
   newN._openWindow(timeout, 2)
   t1.join()

   logging.debug('\n\n\n*** NOW print the results of the test ***\n\n')
   while not q.empty():
      result = q.get(timeout=timeout)
      logging.debug('Results: %s' % str(result))


if __name__ == '__main__':
  main()
Owner

pekkle01 commented May 5, 2011

This version in which a class is instantiated to do the timing should also work in which the timing occurs on the main thread:

#!/usr/bin/env python

import time
import Queue
import inspect
import logging
import threading

import AppKit

import pyatom
from pyatom.AXClasses import NativeUIElement
from pyatom.AXKeyCodeConstants import *


class RelaxedFormatter(logging.Formatter):
   def format(self, record):
      msg=logging.Formatter.format(self, record)
      if isinstance(msg, str):
         msg=msg.decode('utf8', 'replace')
      return msg


def setupLogging():
   shellHandler = logging.StreamHandler()
   logFormat = ('%(asctime)s.%(msecs)-3d: [%(threadName)s]: '
                '%(filename)s#%(lineno)d | %(message)s')
   dateFormat = '%Y-%m-%dT%H:%M:%S'
   formatter = RelaxedFormatter(logFormat, dateFormat)
   shellHandler.setLevel(logging.DEBUG)
   shellHandler.setFormatter(formatter)
   log = logging.getLogger('')
   log.setLevel(logging.DEBUG)
   for handler in log.handlers:
      log.removeHandler(handler)

   log.addHandler(shellHandler)


class testNotificationClass(object):
   def __init__(self, appRef):
      self.appRef = appRef

   def _openWindow(self, t, a=1):
      ''' _openWindow: Function to open a TextEdit window

          Parameters: t (dummy parameter to test passing of parameters)
          Optional: a (dummy parameter to test passing of parameters)
          Returns: None
      '''
      logging.debug('Value of t: %s' % str(t))
      logging.debug('Value of a: %s' % str(a))
      self.appRef.AXFrontmost = True
      self.appRef.sendKeyWithModifiers('n', modifiers=[COMMAND])
      logging.debug('Completed opening new window')


   def timeUIActivity(self, e, t, q, ref, fname, *fargs):
      ''' timeUIActivity: function to time UI events based on Accessibility API
          notifications

          Parameters: e (threading.Event object); created in caller; used to
                         synchronize UI action and timing of it
                      t (timeout for queue usage)
                      q (Thread-safe Queue object to store the timing result;
                         created in caller)
                        (result is a 3-item tuple (func name (for id), result,
                         time waited))
                      ref (pyatom reference (timer functions are instance
                           methods)
                      fname (timing function to call on the reference)
                      *fargs (vararg list for timing function)
          Returns: None
          Side effects:  Result placed in the queue object
      '''
      logging.debug('Entered UI Timing function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()
      func = getattr(ref, fname)
      logging.debug('func: %s' % func.__name__)
      args = inspect.getargspec(func)
      logging.debug('List of args for func: %s' % str(args.args))
      logging.debug('About to start timing now!')

      # Set flag to allow the UI action to start
      e.set()
      startTime = time.time()
      result = None
      if (len(args.args) > 0):
         result = func(*fargs)
      else:
         result = func()
      delta = time.time() - startTime
      q.put((func.__name__, result, delta), timeout=t)
      logging.debug('Result of wait: %s' % result)
      logging.debug('Time waited: %s' % delta)
      del pool


   def uiActivity(self, e, t, f, *fargs):
      ''' uiActivity:  function to perform some UI action to change UI state of
                       the application

          Parameters: e (threading.Event object); created in caller
                      t (timeout value for the event wait)
                      f (function to call to perform the action
                      *fargs (var arg list to pass to the function to call)
          Returns: None
      '''
      logging.debug('Entered UI Activity function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()

      logging.debug('Determining what to pass to func')
      args = inspect.getargspec(f)
      logging.debug('List of args for func: %s' % str(args.args))

      # Wait until the timer function is ready
      e.wait(t)
      result = None
      if (len(args.args) > 0):
         result = f(*fargs)
      else:
         result = f()
      logging.debug('Result of UI activity: %s' % result)
      del pool


class timeUIEventClass(object):
   def __init__(self, appRef, timeout=5):
      self.appRef = appRef
      self.timeout = timeout

   def timeUIEvent(self, q, notification, *nargs):
      '''This variant spawns a thread for the UI activity as opposed to the
         UI timing
      '''
      e = threading.Event()
      newN = testNotificationClass(self.appRef)

      func = getattr(self.appRef, notification)
      logging.debug('func: %s' % func.__name__)
      args = inspect.getargspec(func)
      logging.debug('List of args for func: %s' % str(args.args))
      logging.debug('About to start timing now!')


      t1 = threading.Thread(name='activity', target=newN.uiActivity,
                            args=(e, self.timeout, newN._openWindow, self.timeout,
                                  2))
      t1.start()

      # Set flag to allow the UI action to start
      e.set()
      startTime = time.time()
      result = None
      if (len(args.args) > 0):
         result = func(*nargs)
      else:
         result = func()
      delta = time.time() - startTime
      q.put((func.__name__, result, delta), timeout=self.timeout)
      logging.debug('Result of wait: %s' % result)
      logging.debug('Time waited: %s' % delta)

      t1.join()

      return q

def main():
   setupLogging()

   q = Queue.Queue()
   timeout = 5
   winName = 'Untitled 2'

   # Start TextEdit first:
   NativeUIElement.launchAppByBundleId('com.apple.TextEdit')
   time.sleep(2)

   # Time how long it takes to launch a new window
   textEdit = pyatom.getAppRefByBundleId('com.apple.TextEdit')

   tuiec = timeUIEventClass(textEdit, timeout)
   tuiec.timeUIEvent(q, 'waitForWindowToAppear', winName, timeout)

   logging.debug('\n\n\n*** NOW print the results of the test ***\n\n')
   while not q.empty():
      result = q.get(timeout=timeout)
      logging.debug('Results: %s' % str(result))


if __name__ == '__main__':
  main()
Owner

pekkle01 commented May 5, 2011

This version (with timing be done by an instantiated class) will crash. This version has the timing occurring on a spawned (not main) thread:

#!/usr/bin/env python

import time
import Queue
import inspect
import logging
import threading

import AppKit

import pyatom
from pyatom.AXClasses import NativeUIElement
from pyatom.AXKeyCodeConstants import *


class RelaxedFormatter(logging.Formatter):
   def format(self, record):
      msg=logging.Formatter.format(self, record)
      if isinstance(msg, str):
         msg=msg.decode('utf8', 'replace')
      return msg


def setupLogging():
   shellHandler = logging.StreamHandler()
   logFormat = ('%(asctime)s.%(msecs)-3d: [%(threadName)s]: '
                '%(filename)s#%(lineno)d | %(message)s')
   dateFormat = '%Y-%m-%dT%H:%M:%S'
   formatter = RelaxedFormatter(logFormat, dateFormat)
   shellHandler.setLevel(logging.DEBUG)
   shellHandler.setFormatter(formatter)
   log = logging.getLogger('')
   log.setLevel(logging.DEBUG)
   for handler in log.handlers:
      log.removeHandler(handler)

   log.addHandler(shellHandler)


class testNotificationClass(object):
   def __init__(self, appRef):
      self.appRef = appRef

   def _openWindow(self, t, a=1):
      ''' _openWindow: Function to open a TextEdit window

          Parameters: t (dummy parameter to test passing of parameters)
          Optional: a (dummy parameter to test passing of parameters)
          Returns: None
      '''
      logging.debug('Value of t: %s' % str(t))
      logging.debug('Value of a: %s' % str(a))
      self.appRef.AXFrontmost = True
      self.appRef.sendKeyWithModifiers('n', modifiers=[COMMAND])
      logging.debug('Completed opening new window')


   def timeUIActivity(self, e, t, q, ref, fname, *fargs):
      ''' timeUIActivity: function to time UI events based on Accessibility API
          notifications

          Parameters: e (threading.Event object); created in caller; used to
                         synchronize UI action and timing of it
                      t (timeout for queue usage)
                      q (Thread-safe Queue object to store the timing result;
                         created in caller)
                        (result is a 3-item tuple (func name (for id), result,
                         time waited))
                      ref (pyatom reference (timer functions are instance
                           methods)
                      fname (timing function to call on the reference)
                      *fargs (vararg list for timing function)
          Returns: None
          Side effects:  Result placed in the queue object
      '''
      logging.debug('Entered UI Timing function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()
      func = getattr(ref, fname)
      logging.debug('func: %s' % func.__name__)
      args = inspect.getargspec(func)
      logging.debug('List of args for func: %s' % str(args.args))
      logging.debug('About to start timing now!')

      # Set flag to allow the UI action to start
      e.set()
      startTime = time.time()
      result = None
      if (len(args.args) > 0):
         result = func(*fargs)
      else:
         result = func()
      delta = time.time() - startTime
      q.put((func.__name__, result, delta), timeout=t)
      logging.debug('Result of wait: %s' % result)
      logging.debug('Time waited: %s' % delta)
      del pool


   def uiActivity(self, e, t, f, *fargs):
      ''' uiActivity:  function to perform some UI action to change UI state of
                       the application

          Parameters: e (threading.Event object); created in caller
                      t (timeout value for the event wait)
                      f (function to call to perform the action
                      *fargs (var arg list to pass to the function to call)
          Returns: None
      '''
      logging.debug('Entered UI Activity function!')
      pool = AppKit.NSAutoreleasePool.alloc().init()

      logging.debug('Determining what to pass to func')
      args = inspect.getargspec(f)
      logging.debug('List of args for func: %s' % str(args.args))

      # Wait until the timer function is ready
      e.wait(t)
      result = None
      if (len(args.args) > 0):
         result = f(*fargs)
      else:
         result = f()
      logging.debug('Result of UI activity: %s' % result)
      del pool


class timeUIEventClass(object):
   def __init__(self, appRef, timeout=5):
      self.appRef = appRef
      self.timeout = timeout

   def timeUIEvent(self, q, notification, *nargs):
      #q = Queue.Queue()
      e = threading.Event()
      newN = testNotificationClass(self.appRef)

      t1 = threading.Thread(name='timer', target=newN.timeUIActivity,
                            args=(e, self.timeout, q, self.appRef,
                                  notification, nargs))
      t1.start()
      e.wait()

      # TODO: Edit to be more general next:
      newN._openWindow(self.timeout, 2)

      t1.join()

      return q


def main():
   setupLogging()

   q = Queue.Queue()
   timeout = 5
   winName = 'Untitled 2'

   # Start TextEdit first:
   NativeUIElement.launchAppByBundleId('com.apple.TextEdit')
   time.sleep(2)

   # Time how long it takes to launch a new window
   textEdit = pyatom.getAppRefByBundleId('com.apple.TextEdit')

   tuiec = timeUIEventClass(textEdit, timeout)
   tuiec.timeUIEvent(q, 'waitForWindowToAppear', winName, timeout)

   logging.debug('\n\n\n*** NOW print the results of the test ***\n\n')
   while not q.empty():
      result = q.get(timeout=timeout)
      logging.debug('Results: %s' % str(result))


if __name__ == '__main__':
  main()

nagappan referenced this issue in ldtp/pyatom Oct 31, 2012

nagappan added a commit that referenced this issue Feb 24, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment