Fix/issue54 (#55)

* guard waiting for watchmen via events

In rare occasions, a race can occure where watchmen callbacks are
running while the main-thread already consumes the update-state message.
This commit guards those callback by an additional event on which target
wait() is waiting for.
However, there may still be a small TOCTOU-window on that event, as the
waiting is using a timeout (for state-updates which are not generating
watchmen callbacks).

Hence, in the long run, the full code dealing with state updates could
benefit from refactoring.

* added smoketest for #54 (thanks @redfast00)

* Remove manual keystone-library copy from CI

It seems that keystone version 0.9.2 (as in pypi) has fixed the issues
regarding the installation path of keystone.

* Various fixes found by CI

* Add processing_callbacks to dictify-ignore list
Event()-Objects cannot be serialized, so it should either be private or
part of the ignore list. As the watchman are independently accessing
this Event, it's added to the ignore list

* Fix assert statement in smoketest to be py2-compliant

* Set environment variables for the smoketest

.travis.yml

@@ -32,10 +32,6 @@ install:
     - docker exec ubuntu pip2 install ./avatar2/
     - docker exec ubuntu pip3 install ./avatar2/
 
-    ## Ugly hackery to fix keystone install paths on ubuntu
-    - docker exec ubuntu bash -c 'cp /usr/local/lib/python2.7/dist-packages/usr/lib/python2.7/dist-packages/keystone/libkeystone.so /usr/local/lib/python2.7/dist-packages/keystone'
-    - docker exec ubuntu bash -c 'cp /usr/local/lib/python3.6/dist-packages/usr/lib/python3/dist-packages/keystone/libkeystone.so /usr/local/lib/python3.6/dist-packages/keystone'
-
 script:
     - docker exec ubuntu bash -c 'cd avatar2/ && nosetests-2.7 ./tests/test_remote_memoryprotocol.py'
     - docker exec ubuntu bash -c 'cd avatar2/ && nosetests-2.7 ./tests/test_gdbprotocol.py'
@@ -66,3 +62,5 @@ script:
     - docker exec ubuntu bash -c 'cd avatar2/ && nosetests-2.7 --processes=-1 --process-timeout=20 ./tests/smoke/target_wait.py'
     - docker exec ubuntu bash -c 'cd avatar2/ && nosetests-3.4 --processes=-1 --process-timeout=20 ./tests/smoke/target_wait.py'
 
+    - docker exec ubuntu bash -c 'cd avatar2/ && AVATAR2_GDB_EXECUTABLE=gdb-multiarch AVATAR2_QEMU_EXECUTABLE=./targets/build/panda/panda/arm-softmmu/panda-system-arm nosetests-2.7 --processes=-1 --process-timeout=20 ./tests/smoke/54_sync_hooks.py'
+    - docker exec ubuntu bash -c 'cd avatar2/ && AVATAR2_GDB_EXECUTABLE=gdb-multiarch AVATAR2_QEMU_EXECUTABLE=./targets/build/panda/panda/arm-softmmu/panda-system-arm nosetests-3.4 --processes=-1 --process-timeout=20 ./tests/smoke/54_sync_hooks.py'

avatar2/targets/target.py

@@ -212,7 +212,7 @@ def __init__(self, avatar, name=None):  # type: ('Avatar', str) -> None
         self.protocols = TargetProtocolStore()
 
         self.state = TargetStates.CREATED
-        self._no_state_update_pending = Event()
+        self.processing_callbacks = Event()
 
         self.log = logging.getLogger('%s.targets.%s' % (avatar.log.name, self.name))
         log_file = logging.FileHandler('%s/%s.log' % (avatar.output_directory, self.name))
@@ -227,7 +227,8 @@ def dictify(self):
         Returns the memory range as *printable* dictionary for the config
         """
 
-        ignore = ['state', 'status', 'regs', 'protocols', 'log', 'avatar']
+        ignore = ['state', 'status', 'regs', 'protocols', 'log', 'avatar',
+                  'processing_callbacks']
         ignored_types = (MethodType)
         expected_types = (str, bool, int, list) 
         if version_info < (3, 0): expected_types += (unicode, )
@@ -448,12 +449,13 @@ def remove_breakpoint(self, bkptno):
     def update_state(self, state):
         self.log.info("State changed to to %s" % TargetStates(state))
         self.state = state
-        #self._no_state_update_pending.set()
 
     @watch('TargetWait')
     def wait(self, state=TargetStates.STOPPED|TargetStates.EXITED):
-        while self.state & state == 0:
-            pass
+        while True:
+            self.processing_callbacks.wait(.1)
+            if self.state & state != 0:
+                break
 
     def get_status(self):
         """

avatar2/watchmen.py

@@ -73,11 +73,15 @@ def watchtrigger(self, *args, **kwargs):
             elif isinstance(self, Target):
                 avatar = self.avatar
                 cb_kwargs['watched_target'] = self
+                self.processing_callbacks.clear()
 
             avatar.watchmen.t(watched_type, BEFORE, *args, **cb_kwargs)
             ret = func(self, *args, **kwargs)
             cb_kwargs.update({'watched_return': ret})
             cb_ret = avatar.watchmen.t(watched_type, AFTER, *args, **cb_kwargs)
+
+            if isinstance(self, Target):
+                self.processing_callbacks.set()
             return ret if cb_ret is None else cb_ret
 
         return watchtrigger

tests/smoke/54_sync_hooks.py

@@ -0,0 +1,96 @@
+import avatar2
+import os
+import logging
+import sys
+import time
+import threading
+import subprocess
+
+from nose.tools import *
+
+
+# The TargetLauncher is ripped from the avatar1-example
+# It is used to spawn and stop a qemu instance which is independent of avatar2.
+class TargetLauncher(object):
+    def __init__(self, cmd):
+        self._cmd = cmd
+        self._process = None
+        self._thread = threading.Thread(target=self.run)
+        self._thread.start()
+
+    def stop(self):
+        if self._process:
+            print(self._process.kill())
+
+    def run(self):
+        print("TargetLauncher is starting process %s" %
+              " ".join(['"%s"' % x for x in self._cmd]))
+        self._process = subprocess.Popen(self._cmd)
+
+
+
+
+
+
+def test_race():
+
+    def hook_callback(avatar, *args, **kwargs):
+        gdb = avatar.targets['gdbtest']
+        pc = gdb.read_register("pc")
+        assert pc is not None, "ILLEGAL STATE %s" % gdb.get_status()
+
+
+
+    avatar = avatar2.Avatar(arch=avatar2.ARM)
+
+    qemu = TargetLauncher([avatar.arch.get_qemu_executable(),
+                           "-machine",  "virt",
+                           "-gdb", "tcp::1234",
+                           "-S",
+                           "-nographic",
+                           "-bios", "./tests/binaries/qemu_arm_test"])
+
+    gdb = avatar.add_target(avatar2.GDBTarget,
+                              name='gdbtest',
+                              gdb_port=1234,
+                              gdb_verbose_mi=False,
+                              gdb_executable='/usr/bin/gdb-multiarch'
+                            )
+
+    # add breakpoint callback
+    avatar.watchmen.add('BreakpointHit', when='after', callback=hook_callback, is_async=False)
+
+
+    print("Init avatar targets...")
+    avatar.init_targets()
+
+    gdb.set_breakpoint(0x4)
+
+    gdb.write_register('pc', 0)
+    # Start running
+    gdb.cont()
+
+    # wait until we hit a breakpoint, once we hit the breakpoint, continue this python script
+    print("waiting until we hit a breakpoint")
+    gdb.wait()
+    # add two breakpoints
+    gdb.set_breakpoint(0x8)
+    gdb.set_breakpoint(0xc)
+
+    gdb.set_breakpoint(0x1000)
+
+    # Continue executing from main
+    gdb.cont()
+    while True:
+        # Wait until we hit a breakpoint
+        gdb.wait()
+        if gdb.regs.pc == 0x1000:
+            break
+        gdb.cont()
+
+
+    qemu.stop()
+    avatar.shutdown()
+
+if __name__ == '__main__':
+    test_race()