diff --git a/NEWS.rst b/NEWS.rst index e546649..3e97a2a 100644 --- a/NEWS.rst +++ b/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 diff --git a/src/fowl/_proto.py b/src/fowl/_proto.py index 20d2c19..e982ab1 100644 --- a/src/fowl/_proto.py +++ b/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) diff --git a/src/fowl/test/test_commands.py b/src/fowl/test/test_commands.py index 6988ab4..cbc3dc0 100644 --- a/src/fowl/test/test_commands.py +++ b/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" + )