rewrite debug tracing, add to all machines

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)

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)

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)

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

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

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)

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

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

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:
+        self._debug("R.connected")
-            dmsg(self._side, "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":
+        #if self.DEBUG and msg["type"]!="ack":
-            dmsg(self._side, "R.rx(%s %s%s)" %
+        #    dmsg(self._side, "R.rx(%s %s%s)" %
-                 (msg["type"], msg.get("phase",""),
+        #         (msg["type"], msg.get("phase",""),
-                  "[mine]" if msg.get("side","") == self._side else "",
+        #          "[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:
+        self._debug("R.lost")
-            dmsg(self._side, "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:
+        self._debug("R.tx(%s %s)" % (mtype.upper(), kwargs.get("phase", "")))
-            dmsg(self._side, "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)

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 = []

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

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):
+        w1.debug_set_trace("W1")
-            print("W1._M[%s].%s -> [%s]" % (old_state, input, new_state))
-        w1._boss._M.setTrace(trace)
         w1.allocate_code(2)
         code = yield w1.when_code()
         print("code:", code)

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