Add timestamps to debug trace output

NEWS.rst

@@ -11,7 +11,7 @@ Integration with other programs should use ``fowld`` exclusively.
 Unreleased
 ----------
 
-* (Put new changelog items here)
+* Add elapsed timestamps to ``--debug`` state-machine trace output (#111)
 
 
 25.10.0: October 23, 2025

src/fowl/_proto.py

@@ -94,6 +94,34 @@ def _sequential_id():
 allocate_connection_id = partial(next, _sequential_id())
 
 
+class _TimestampedWriter:
+    """
+    Wrap a writable stream and prefix each line with elapsed time.
+    """
+
+    def __init__(self, reactor, writable, start_time):
+        self._reactor = reactor
+        self._writable = writable
+        self._start_time = start_time
+        self._at_line_start = True
+
+    def write(self, data):
+        written = 0
+        for chunk in data.splitlines(keepends=True):
+            if self._at_line_start:
+                elapsed = self._reactor.seconds() - self._start_time
+                written += self._writable.write(f"{elapsed:.3f} ")
+            written += self._writable.write(chunk)
+            self._at_line_start = chunk.endswith("\n")
+        return written
+
+    def flush(self):
+        return self._writable.flush()
+
+    def __getattr__(self, name):
+        return getattr(self._writable, name)
+
+
 #@frozen
 @define  ## could be @frozen, but for "policy" ... hmmm
 class _Config:
@@ -1734,7 +1762,11 @@ def command_message(msg):
 
     if config.debug_file:
         kind = "invite" if config.code is None else "accept"
-        w.debug_set_trace(kind, which="B N M S O K SK R RC L C T", file=config.debug_file)
+        w.debug_set_trace(
+            kind,
+            which="B N M S O K SK R RC L C T",
+            file=_TimestampedWriter(reactor, config.debug_file, start_time),
+        )
 
     from .api import create_coop
     coop = create_coop(reactor, w, fowl_status_tracker)

src/fowl/test/test_commands.py

@@ -1,10 +1,11 @@
 import json
+from io import StringIO
 
 from hypothesis.strategies import one_of, integers, lists, sampled_from, builds, text, just
 from hypothesis import given
 
 
-from fowl._proto import parse_fowld_command, fowld_command_to_json
+from fowl._proto import _TimestampedWriter, parse_fowld_command, fowld_command_to_json
 
 
 def command_messages():
@@ -96,3 +97,26 @@ def test_roundtrip(og_cmd):
     """
     parsed_cmd = parse_fowld_command(json.dumps(fowld_command_to_json(og_cmd)))
     assert parsed_cmd == og_cmd, "Command mismatch"
+
+
+def test_timestamped_writer_prefixes_each_line():
+    class Reactor:
+        now = 123.0
+
+        def seconds(self):
+            return self.now
+
+    reactor = Reactor()
+    stream = StringIO()
+    writer = _TimestampedWriter(reactor, stream, start_time=123.0)
+
+    writer.write("first\nsecond")
+    reactor.now = 124.25
+    writer.write(" continued\n")
+    writer.write("third\n")
+
+    assert stream.getvalue() == (
+        "0.000 first\n"
+        "0.000 second continued\n"
+        "1.250 third\n"
+    )