From 4793208d4e9741aa135a5e939348f371c336dc9c Mon Sep 17 00:00:00 2001 From: Brian Warner Date: Wed, 1 Mar 2017 19:55:13 -0800 Subject: [PATCH] rewrite debug tracing, add to all machines --- src/wormhole/_boss.py | 13 ++++++++++ src/wormhole/_code.py | 2 ++ src/wormhole/_key.py | 2 ++ src/wormhole/_mailbox.py | 2 +- src/wormhole/_nameplate.py | 2 +- src/wormhole/_nameplate_lister.py | 2 ++ src/wormhole/_order.py | 2 ++ src/wormhole/_receive.py | 2 ++ src/wormhole/_rendezvous.py | 33 ++++++++++++++++---------- src/wormhole/_send.py | 2 ++ src/wormhole/_terminator.py | 2 +- src/wormhole/test/test_wormhole_new.py | 5 ++-- src/wormhole/wormhole.py | 12 ++++++++++ 13 files changed, 63 insertions(+), 18 deletions(-) diff --git a/src/wormhole/_boss.py b/src/wormhole/_boss.py index 2b5d0a0..9dd1611 100644 --- a/src/wormhole/_boss.py +++ b/src/wormhole/_boss.py @@ -34,6 +34,8 @@ class Boss(object): _journal = attrib(validator=provides(_interfaces.IJournal)) _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def __attrs_post_init__(self): self._N = Nameplate() @@ -70,6 +72,17 @@ class Boss(object): def start(self): self._RC.start() + def _set_trace(self, client_name, which, logger): + names = {"B": self, "N": self._N, "M": self._M, "S": self._S, + "O": self._O, "K": self._K, "R": self._R, + "RC": self._RC, "NL": self._NL, "C": self._C, + "T": self._T} + for machine in which.split(): + def tracer(old_state, input, new_state, machine=machine): + print("%s.%s[%s].%s -> [%s]" % (client_name, machine, + old_state, input, new_state)) + names[machine].set_trace(tracer) + # and these are the state-machine transition functions, which don't take # args @m.state(initial=True) diff --git a/src/wormhole/_code.py b/src/wormhole/_code.py index 544685b..3dab38c 100644 --- a/src/wormhole/_code.py +++ b/src/wormhole/_code.py @@ -25,6 +25,8 @@ def make_code(nameplate, code_length): class Code(object): _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def wire(self, boss, rendezvous_connector, nameplate_lister): self._B = _interfaces.IBoss(boss) diff --git a/src/wormhole/_key.py b/src/wormhole/_key.py index 016bc86..49fa9e2 100644 --- a/src/wormhole/_key.py +++ b/src/wormhole/_key.py @@ -59,6 +59,8 @@ class Key(object): _side = attrib(validator=instance_of(type(u""))) _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def wire(self, boss, mailbox, receive): self._B = _interfaces.IBoss(boss) diff --git a/src/wormhole/_mailbox.py b/src/wormhole/_mailbox.py index 9dc8493..db7de74 100644 --- a/src/wormhole/_mailbox.py +++ b/src/wormhole/_mailbox.py @@ -11,7 +11,7 @@ class Mailbox(object): _side = attrib(validator=instance_of(type(u""))) m = MethodicalMachine() @m.setTrace() - def setTrace(): pass + def set_trace(): pass def __attrs_post_init__(self): self._mailbox = None diff --git a/src/wormhole/_nameplate.py b/src/wormhole/_nameplate.py index 0b9ef8c..8e25801 100644 --- a/src/wormhole/_nameplate.py +++ b/src/wormhole/_nameplate.py @@ -7,7 +7,7 @@ from . import _interfaces class Nameplate(object): m = MethodicalMachine() @m.setTrace() - def setTrace(): pass + def set_trace(): pass def __init__(self): self._nameplate = None diff --git a/src/wormhole/_nameplate_lister.py b/src/wormhole/_nameplate_lister.py index ee9631c..27d064c 100644 --- a/src/wormhole/_nameplate_lister.py +++ b/src/wormhole/_nameplate_lister.py @@ -6,6 +6,8 @@ from . import _interfaces @implementer(_interfaces.INameplateLister) class NameplateListing(object): m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def wire(self, rendezvous_connector, code): self._RC = _interfaces.IRendezvousConnector(rendezvous_connector) diff --git a/src/wormhole/_order.py b/src/wormhole/_order.py index 987649f..c4df241 100644 --- a/src/wormhole/_order.py +++ b/src/wormhole/_order.py @@ -11,6 +11,8 @@ class Order(object): _side = attrib(validator=instance_of(type(u""))) _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def __attrs_post_init__(self): self._key = None diff --git a/src/wormhole/_receive.py b/src/wormhole/_receive.py index 5405531..8445756 100644 --- a/src/wormhole/_receive.py +++ b/src/wormhole/_receive.py @@ -12,6 +12,8 @@ class Receive(object): _side = attrib(validator=instance_of(type(u""))) _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def __attrs_post_init__(self): self._key = None diff --git a/src/wormhole/_rendezvous.py b/src/wormhole/_rendezvous.py index 44d7b75..e9a183c 100644 --- a/src/wormhole/_rendezvous.py +++ b/src/wormhole/_rendezvous.py @@ -70,9 +70,9 @@ class RendezvousConnector(object): _reactor = attrib() _journal = attrib(validator=provides(_interfaces.IJournal)) _timing = attrib(validator=provides(_interfaces.ITiming)) - DEBUG = True def __attrs_post_init__(self): + self._trace = None self._ws = None f = WSFactory(self, self._url) f.setProtocolOptions(autoPingInterval=60, autoPingTimeout=600) @@ -80,6 +80,12 @@ class RendezvousConnector(object): ep = self._make_endpoint(p.hostname, p.port or 80) self._connector = internet.ClientService(ep, f) + def set_trace(self, f): + self._trace = f + def _debug(self, what): + if self._trace: + self._trace(old_state="", input=what, new_state="") + def _make_endpoint(self, hostname, port): # TODO: Tor goes here return endpoints.HostnameEndpoint(self._reactor, hostname, port) @@ -130,8 +136,7 @@ class RendezvousConnector(object): # from our WSClient (the WebSocket protocol) def ws_open(self, proto): - if self.DEBUG: - dmsg(self._side, "R.connected") + self._debug("R.connected") self._ws = proto self._tx("bind", appid=self._appid, side=self._side) self._C.connected() @@ -141,11 +146,17 @@ class RendezvousConnector(object): def ws_message(self, payload): msg = bytes_to_dict(payload) - if self.DEBUG and msg["type"]!="ack": - dmsg(self._side, "R.rx(%s %s%s)" % - (msg["type"], msg.get("phase",""), - "[mine]" if msg.get("side","") == self._side else "", - )) + #if self.DEBUG and msg["type"]!="ack": + # dmsg(self._side, "R.rx(%s %s%s)" % + # (msg["type"], msg.get("phase",""), + # "[mine]" if msg.get("side","") == self._side else "", + # )) + if msg["type"] != "ack": + self._debug("R.rx(%s %s%s)" % + (msg["type"], msg.get("phase",""), + "[mine]" if msg.get("side","") == self._side else "", + )) + self._timing.add("ws_receive", _side=self._side, message=msg) mtype = msg["type"] meth = getattr(self, "_response_handle_"+mtype, None) @@ -156,8 +167,7 @@ class RendezvousConnector(object): return meth(msg) def ws_close(self, wasClean, code, reason): - if self.DEBUG: - dmsg(self._side, "R.lost") + self._debug("R.lost") self._ws = None self._C.lost() self._N.lost() @@ -176,8 +186,7 @@ class RendezvousConnector(object): # are so few messages, 16 bits is enough to be mostly-unique. kwargs["id"] = bytes_to_hexstr(os.urandom(2)) kwargs["type"] = mtype - if self.DEBUG: - dmsg(self._side, "R.tx(%s %s)" % (mtype.upper(), kwargs.get("phase", ""))) + self._debug("R.tx(%s %s)" % (mtype.upper(), kwargs.get("phase", ""))) payload = dict_to_bytes(kwargs) self._timing.add("ws_send", _side=self._side, **kwargs) self._ws.sendMessage(payload, False) diff --git a/src/wormhole/_send.py b/src/wormhole/_send.py index fd3e590..76617a3 100644 --- a/src/wormhole/_send.py +++ b/src/wormhole/_send.py @@ -12,6 +12,8 @@ class Send(object): _side = attrib(validator=instance_of(type(u""))) _timing = attrib(validator=provides(_interfaces.ITiming)) m = MethodicalMachine() + @m.setTrace() + def set_trace(): pass def __attrs_post_init__(self): self._queue = [] diff --git a/src/wormhole/_terminator.py b/src/wormhole/_terminator.py index 45496f4..92c037a 100644 --- a/src/wormhole/_terminator.py +++ b/src/wormhole/_terminator.py @@ -7,7 +7,7 @@ from . import _interfaces class Terminator(object): m = MethodicalMachine() @m.setTrace() - def setTrace(): pass + def set_trace(): pass def __attrs_post_init__(self): self._mood = None diff --git a/src/wormhole/test/test_wormhole_new.py b/src/wormhole/test/test_wormhole_new.py index c917109..4333d61 100644 --- a/src/wormhole/test/test_wormhole_new.py +++ b/src/wormhole/test/test_wormhole_new.py @@ -26,6 +26,7 @@ class New(ServerBase, unittest.TestCase): @inlineCallbacks def test_allocate(self): w = wormhole.deferred_wormhole(APPID, self.relayurl, reactor) + w.debug_set_trace("W1") w.allocate_code(2) code = yield w.when_code() print("code:", code) @@ -40,9 +41,7 @@ class New(ServerBase, unittest.TestCase): @inlineCallbacks def test_basic(self): w1 = wormhole.deferred_wormhole(APPID, self.relayurl, reactor) - def trace(old_state, input, new_state): - print("W1._M[%s].%s -> [%s]" % (old_state, input, new_state)) - w1._boss._M.setTrace(trace) + w1.debug_set_trace("W1") w1.allocate_code(2) code = yield w1.when_code() print("code:", code) diff --git a/src/wormhole/wormhole.py b/src/wormhole/wormhole.py index 1977d16..36456a3 100644 --- a/src/wormhole/wormhole.py +++ b/src/wormhole/wormhole.py @@ -29,6 +29,10 @@ from ._boss import Boss, WormholeError # wormhole(delegate=app, delegate_prefix="wormhole_", # delegate_args=(args, kwargs)) +def _log(client_name, machine_name, old_state, input, new_state): + print("%s.%s[%s].%s -> [%s]" % (client_name, machine_name, + old_state, input, new_state)) + @attrs @implementer(IWormhole) class _DelegatedWormhole(object): @@ -51,6 +55,10 @@ class _DelegatedWormhole(object): def close(self): self._boss.close() + def debug_set_trace(self, client_name, which="B N M S O K R RC NL C T", + logger=_log): + self._boss.set_trace(client_name, which, logger) + # from below def got_code(self, code): self._delegate.wormhole_got_code(code) @@ -115,6 +123,10 @@ class _DeferredWormhole(object): self._closed_observers.append(d) return d + def debug_set_trace(self, client_name, which="B N M S O K R RC NL C T", + logger=_log): + self._boss._set_trace(client_name, which, logger) + # from below def got_code(self, code): self._code = code