From dce01174ebbdba090bca2d414cecac26d9316932 Mon Sep 17 00:00:00 2001 From: Brian Warner Date: Wed, 14 Feb 2018 00:32:49 -0800 Subject: [PATCH 1/3] improve debug_set_trace: add Allocate and Input events Also log events at the beginning and end of Input.choose_nameplate and Input.choose_words, since those are the two big locally-driven (UI) triggers that cause multiple messages to be fired and lots of work to happen. --- src/wormhole/_boss.py | 6 ++++-- src/wormhole/_input.py | 11 +++++++++++ src/wormhole/wormhole.py | 3 ++- 3 files changed, 17 insertions(+), 3 deletions(-) diff --git a/src/wormhole/_boss.py b/src/wormhole/_boss.py index 6ec3298..b18ba2d 100644 --- a/src/wormhole/_boss.py +++ b/src/wormhole/_boss.py @@ -108,14 +108,16 @@ class Boss(object): def _set_trace(self, client_name, which, file): names = {"B": self, "N": self._N, "M": self._M, "S": self._S, "O": self._O, "K": self._K, "SK": self._K._SK, "R": self._R, - "RC": self._RC, "L": self._L, "C": self._C, - "T": self._T} + "RC": self._RC, "L": self._L, "A": self._A, "I": self._I, + "C": self._C, "T": self._T} for machine in which.split(): t = (lambda old_state, input, new_state, machine=machine: self._print_trace(old_state, input, new_state, client_name=client_name, machine=machine, file=file)) names[machine].set_trace(t) + if machine == "I": + self._I.set_debug(t) ## def serialize(self): ## raise NotImplemented diff --git a/src/wormhole/_input.py b/src/wormhole/_input.py index 8c2ef1e..d2c6379 100644 --- a/src/wormhole/_input.py +++ b/src/wormhole/_input.py @@ -22,6 +22,13 @@ class Input(object): self._nameplate = None self._wordlist = None self._wordlist_waiters = [] + self._trace = None + + def set_debug(self, f): + self._trace = f + def _debug(self, what): + if self._trace: + self._trace(old_state="", input=what, new_state="") def wire(self, code, lister): self._C = _interfaces.ICode(code) @@ -238,10 +245,14 @@ class Helper(object): def get_nameplate_completions(self, prefix): return self._input.get_nameplate_completions(prefix) def choose_nameplate(self, nameplate): + self._input._debug("I.choose_nameplate") self._input.choose_nameplate(nameplate) + self._input._debug("I.choose_nameplate finished") def when_wordlist_is_available(self): return self._input.when_wordlist_is_available() def get_word_completions(self, prefix): return self._input.get_word_completions(prefix) def choose_words(self, words): + self._input._debug("I.choose_words") self._input.choose_words(words) + self._input._debug("I.choose_words finished") diff --git a/src/wormhole/wormhole.py b/src/wormhole/wormhole.py index 7d19dc2..e58107f 100644 --- a/src/wormhole/wormhole.py +++ b/src/wormhole/wormhole.py @@ -214,7 +214,8 @@ class _DeferredWormhole(object): self._boss.close() # only need to close if it wasn't already return d - def debug_set_trace(self, client_name, which="B N M S O K SK R RC L C T", + def debug_set_trace(self, client_name, + which="B N M S O K SK R RC L A I C T", file=sys.stderr): self._boss._set_trace(client_name, which, file) From 3847339f43fde782d4c7f314df204995bb286985 Mon Sep 17 00:00:00 2001 From: Brian Warner Date: Wed, 14 Feb 2018 00:39:26 -0800 Subject: [PATCH 2/3] _input: reject attempts to call Helper from a non-main thread This causes two threads to use the reactor at the same time, with horrible results. The _rlcompleter code currently violates this requirement, causing occasional failures if the messages arrive in just the wrong way (refs #280). --- src/wormhole/_input.py | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/wormhole/_input.py b/src/wormhole/_input.py index d2c6379..56e0f96 100644 --- a/src/wormhole/_input.py +++ b/src/wormhole/_input.py @@ -1,4 +1,8 @@ from __future__ import print_function, absolute_import, unicode_literals +# We use 'threading' defensively here, to detect if we're being called from a +# non-main thread. _rlcompleter.py is the only internal Wormhole code that +# deliberately creates a new thread. +import threading from zope.interface import implementer from attr import attrs, attrib from attr.validators import provides @@ -240,19 +244,28 @@ class Input(object): class Helper(object): _input = attrib() + def __attrs_post_init__(self): + self._main_thread = threading.current_thread().ident + def refresh_nameplates(self): + assert threading.current_thread().ident == self._main_thread self._input.refresh_nameplates() def get_nameplate_completions(self, prefix): + assert threading.current_thread().ident == self._main_thread return self._input.get_nameplate_completions(prefix) def choose_nameplate(self, nameplate): + assert threading.current_thread().ident == self._main_thread self._input._debug("I.choose_nameplate") self._input.choose_nameplate(nameplate) self._input._debug("I.choose_nameplate finished") def when_wordlist_is_available(self): + assert threading.current_thread().ident == self._main_thread return self._input.when_wordlist_is_available() def get_word_completions(self, prefix): + assert threading.current_thread().ident == self._main_thread return self._input.get_word_completions(prefix) def choose_words(self, words): + assert threading.current_thread().ident == self._main_thread self._input._debug("I.choose_words") self._input.choose_words(words) self._input._debug("I.choose_words finished") From af406a600e8d3a871adb95afc7d7505bfbb4ddda Mon Sep 17 00:00:00 2001 From: Brian Warner Date: Wed, 14 Feb 2018 00:40:18 -0800 Subject: [PATCH 3/3] _rlcompleter: use blockingCallFromThread for all Helper APIs We were missing two (the calls to choose_nameplate() and choose_words() that happen after the input() function has finished, but while we're still inside the thread that makes it safe for input() to block). This almost certainly caused the crash seen in issue #280. Update the tests to match: CodeInputter.finish must now be called with deferToThread from inside tests, or the internal blockingCallFromThread must be stubbed out. --- src/wormhole/_rlcompleter.py | 6 ++++-- src/wormhole/test/test_rlcompleter.py | 10 ++++++++-- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/src/wormhole/_rlcompleter.py b/src/wormhole/_rlcompleter.py index 95288dc..c717ed1 100644 --- a/src/wormhole/_rlcompleter.py +++ b/src/wormhole/_rlcompleter.py @@ -134,11 +134,13 @@ class CodeInputter(object): raise AlreadyInputNameplateError("nameplate (%s-) already entered, cannot go back" % self._committed_nameplate) else: debug(" choose_nameplate(%s)" % nameplate) - self._input_helper.choose_nameplate(nameplate) + self.bcft(self._input_helper.choose_nameplate, nameplate) debug(" choose_words(%s)" % words) - self._input_helper.choose_words(words) + self.bcft(self._input_helper.choose_words, words) def _input_code_with_completion(prompt, input_helper, reactor): + # reminder: this all occurs in a separate thread. All calls to input_helper + # must go through blockingCallFromThread() c = CodeInputter(input_helper, reactor) if readline is not None: if readline.__doc__ and "libedit" in readline.__doc__: diff --git a/src/wormhole/test/test_rlcompleter.py b/src/wormhole/test/test_rlcompleter.py index f21e55f..41f0abf 100644 --- a/src/wormhole/test/test_rlcompleter.py +++ b/src/wormhole/test/test_rlcompleter.py @@ -147,11 +147,15 @@ def get_completions(c, prefix): return completions completions.append(text) +def fake_blockingCallFromThread(f, *a, **kw): + return f(*a, **kw) + class Completion(unittest.TestCase): def test_simple(self): # no actual completion helper = mock.Mock() c = CodeInputter(helper, "reactor") + c.bcft = fake_blockingCallFromThread c.finish("1-code-ghost") self.assertFalse(c.used_completion) self.assertEqual(helper.mock_calls, @@ -164,6 +168,7 @@ class Completion(unittest.TestCase): # check that it calls _commit_and_build_completions correctly helper = mock.Mock() c = CodeInputter(helper, "reactor") + c.bcft = fake_blockingCallFromThread # pretend nameplates: 1, 12, 34 @@ -304,12 +309,13 @@ class Completion(unittest.TestCase): self.assertEqual(gwc.mock_calls, [mock.call("and-b")]) gwc.reset_mock() - c.finish("12-and-bat") + yield deferToThread(c.finish, "12-and-bat") self.assertEqual(cw.mock_calls, [mock.call("and-bat")]) def test_incomplete_code(self): helper = mock.Mock() c = CodeInputter(helper, "reactor") + c.bcft = fake_blockingCallFromThread with self.assertRaises(KeyFormatError) as e: c.finish("1") self.assertEqual(str(e.exception), "incomplete wormhole code") @@ -349,7 +355,7 @@ class Completion(unittest.TestCase): self.assertEqual(matches, ["1-code", "1-court"]) helper.reset_mock() with self.assertRaises(AlreadyInputNameplateError) as e: - c.finish("2-code") + yield deferToThread(c.finish, "2-code") self.assertEqual(str(e.exception), "nameplate (1-) already entered, cannot go back") self.assertEqual(helper.mock_calls, [])