From 032580bfa50a95ff60c63f8e5a860f9e6a4e0ebc Mon Sep 17 00:00:00 2001 From: goodboy Date: Wed, 28 Oct 2026 13:13:26 -0400 Subject: [PATCH] .data: expose websocket reconnect progress at INFO An INFO pikerd still hid websocket connection-success messages. The shared ._util.log emitter is piker.data, but open_feed_bus() configured piker.data.feed. Errors reached bare stderr while INFO diagnostics remained disabled on the actual emitter. Configure the shared logger by its exact log.name and prefer the actor's loglevel over a quieter per-client request for these actor-wide transport diagnostics. Preserve the selected client level passed to provider feed startup. Also, - retain the existing handshake-success report and add URL-tagged readiness after fixture setup and first-message relay once per connection, including replacement sockets. - include the URL in receive-timeout reset errors so Binance's independent bookTicker and aggTrade routes are distinguishable. - prove real console INFO visibility through production feed startup, stopping before provider lookup, then restore logging state; the original code fails with the emitter at WARNING. - extend the loopback recovery test to verify both readiness reports and the first relay from the replacement connection. First-message relay is raw websocket traffic, not proof that parsed market data or chart updates have recovered. The 18 logging/Binance/websocket cases pass; live reporting qualification remains separate. This is a local follow-up, not a downstream cherry-pick. The 54da2973 websocket cleanup and 5adf77a9 namespace fix do not configure this shared emitter. Relevant local histories and dirty IB-history/TIPC deltas contain no equivalent wiring fix. Prompt-IO: ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.md (this patch was generated in some part by `opencode` using `gpt-6.1-sol` (`openai`)) --- ...1028T165638Z_b95e7c79_reconnect_logging.md | 70 +++++++++++++++++++ ...T165638Z_b95e7c79_reconnect_logging.raw.md | 38 ++++++++++ piker/data/_web_bs.py | 10 ++- piker/data/feed.py | 11 +-- tests/test_logging.py | 68 ++++++++++++++++++ tests/test_websocket.py | 13 ++++ 6 files changed, 204 insertions(+), 6 deletions(-) create mode 100644 ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.md create mode 100644 ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.raw.md diff --git a/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.md b/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.md new file mode 100644 index 00000000..b14f4069 --- /dev/null +++ b/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.md @@ -0,0 +1,70 @@ +--- +created_at: 2026-10-28T16:56:38Z +generated_by: + harness: opencode + provider: openai + model: openai/gpt-6.1-sol +git_ref: b95e7c79 +scope: code +substantive: true +raw_file: 20261028T165638Z_b95e7c79_reconnect_logging.raw.md +--- + +## Prompt + +The human reported that the live Binance Pong-in-LOCAL_CLOSING +error now logged a retry without crashing. They requested visible +re-establishment reporting under `pikerd -l info --pdb`, and asked +to check for existing downstream work before adding a fix. + +## Response summary + +The existing `Connection success` INFO message already identifies +handshake completion. Feed startup configured piker.data.feed, +while shared websocket diagnostics use ._util.log on piker.data. +Configure that actual emitter and prefer the daemon's verbosity +over a quieter client request for these shared transport tasks. + +Add a readiness INFO message after fixture setup and a first-message +INFO report once per connection after actual relay. Include the URL +in the receive-timeout reset error. Do not call first raw websocket +traffic a parsed quote or proof of restored market-data freshness. + +## Existing-work audit + +Compared `_web_bs.py`, `_util.py`, `piker.log` and daemon logging +against the evaluated downstream tip and relevant all-ref histories. +`54da2973` contains logging/type cleanup, not this emitter fix. +`5adf77a9` / landing equivalents address package-name correctness, +but not configuration of the shared data emitter at feed startup. +All-ref searches for this actual emitter/readiness/first-relay +implementation found no existing commit. The dirty IB history +worktree has only an unrelated f-string correction in `_web_bs.py`; +the TIPC worktree has no dirty delta in these two feed/websocket +files. No downstream work was overwritten or imported wholesale. + +## Files changed + +- `piker/data/feed.py`: shared transport logger startup/verbosity. +- `piker/data/_web_bs.py`: readiness, first-relay and timeout URL. +- `tests/test_logging.py`: actual emitter/console startup regression. +- `tests/test_websocket.py`: recovery milestones on real loopback. +- This prompt provenance pair. + +## Verification + +The new logging regression against original b95e7c79 source fails: +the actual websocket emitter remains at WARNING and rejects INFO. +It passes with the logger wiring fix. Provider lookup is stopped +before network work, while logger factories and console emission +are real. Global logger state is restored after the check. + +18 cases pass across tests/test_logging.py, tests/test_websocket.py +and tests/test_binance.py. git diff --check passes. Live verification +after restarting the daemon with these edits remains human-owned. + +## Human edits + +No direct manual source edits observed. The human supplied live +recovery evidence, selected INFO verbosity, requested downstream +reuse inspection, and retains live-test and commit ownership. diff --git a/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.raw.md b/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.raw.md new file mode 100644 index 00000000..90f9c9c0 --- /dev/null +++ b/ai/prompt-io/opencode/20261028T165638Z_b95e7c79_reconnect_logging.raw.md @@ -0,0 +1,38 @@ +--- +created_at: 2026-10-28T16:56:38Z +generated_by: + harness: opencode + provider: openai + model: openai/gpt-6.1-sol +git_ref: b95e7c79 +diff_cmd: git diff HEAD~1..HEAD +--- + +Confirmed the existing INFO handshake-success log was hidden by +logger wiring: websocket code emits on piker.data, while feed +startup configured piker.data.feed. The baseline regression leaves +the emitter at WARNING for an INFO daemon and ERROR client. + +> `git diff HEAD~1..HEAD -- piker/data/feed.py` + +Configure the actual shared ._util.log namespace, with daemon +verbosity taking priority over client verbosity for actor-wide +transport diagnostics. + +> `git diff HEAD~1..HEAD -- piker/data/_web_bs.py` + +Keep the existing handshake-success message. Add INFO readiness +after fixture setup and first-message relay once per connection. +Include the URL in the receive-timeout reset diagnostic. + +> `git diff HEAD~1..HEAD -- tests/test_logging.py tests/test_websocket.py` + +Prove production startup enables real console INFO on the websocket +emitter without contacting a provider. Extend the real loopback +recovery test to require readiness for both connections and one +first-message report for the connection delivering fresh data. + +All 18 targeted logging/Binance/websocket cases passed. No live +provider/daemon operations were performed by the agent. First relay +is raw websocket traffic; parsed market-data recovery remains a +separate live observation. diff --git a/piker/data/_web_bs.py b/piker/data/_web_bs.py index 0cd11082..0a981900 100644 --- a/piker/data/_web_bs.py +++ b/piker/data/_web_bs.py @@ -194,6 +194,7 @@ async def _reconnect_forever( ''' # after so many msg recv timeouts, reset the connection timeouts: int = 0 + first_message: bool = True while True: with trio.move_on_after( @@ -203,6 +204,11 @@ async def _reconnect_forever( try: msg: Any = await ws.get_message() await snd.send(msg) + if first_message: + log.info( + f'Websocket first message relayed: {url!r}' + ) + first_message = False except nobsws.recon_errors: log.exception( f'{src_mod}\n' @@ -221,7 +227,8 @@ async def _reconnect_forever( if timeouts > reset_after: log.error( f'{src_mod}\n' - 'WS feed seems down and slow af.. reconnecting\n' + f'WS feed seems down and slow af.. reconnecting\n' + f'{url!r}\n' ) rent_cs.cancel() @@ -295,6 +302,7 @@ async def _reconnect_forever( # indicate to wrapper / opener that we are up and block # to let tasks run **inside** the ws open block above. + log.info(f'Websocket ready: {url!r}') nobsws._connected.set() await trio.sleep_forever() diff --git a/piker/data/feed.py b/piker/data/feed.py index aff0424a..eb17babe 100644 --- a/piker/data/feed.py +++ b/piker/data/feed.py @@ -485,14 +485,15 @@ async def open_feed_bus( if loglevel is None: loglevel: str = tractor.current_actor().loglevel - # XXX: required to propagate ``tractor`` loglevel to piker - # logging + # Configure the shared piker.data logger used by ._util.log, + # including websocket tasks. A per-client verbosity must not + # demote actor-wide transport diagnostics below daemon verbosity. get_console_log( - level=(loglevel + level=(tractor.current_actor().loglevel or - tractor.current_actor().loglevel + loglevel ), - name=__name__, + name=log.name, ) # local state sanity checks diff --git a/tests/test_logging.py b/tests/test_logging.py index 43755446..c8049343 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -2,7 +2,11 @@ Package logger namespace regression tests. ''' +import logging +from types import SimpleNamespace + import pytest +import trio from piker.log import ( get_console_log, @@ -42,3 +46,67 @@ def test_package_logger_name( log = factory(name=name) assert log.name == name + + +def test_feed_startup_configures_transport_logger( + monkeypatch: pytest.MonkeyPatch, + capsys: pytest.CaptureFixture, +) -> None: + ''' + Daemon INFO did not enable websocket reconnection diagnostics. + + Feed startup configured piker.data.feed, but ._util.log and + ._web_bs.log emit on piker.data. Errors fell back to bare stderr + while connection-success INFO stayed hidden. Client verbosity + must also not demote that shared actor-wide transport logger. + + Run production feed startup and logger configuration with an INFO + actor and ERROR client. Stop at feed-bus lookup before touching + any provider. Use real logging/console emission, not mocked logger + methods, to prove INFO from the websocket emitter is visible. + + ''' + from piker.data import feed, _web_bs + + saved = {} + for name in ('piker.data', 'piker.data.feed', 'tractor'): + logger = logging.getLogger(name) + saved[logger] = (logger.level, list(logger.handlers)) + + boundary = RuntimeError('stop before provider lookup') + + def stop_at_bus(brokername: str): + raise boundary + + monkeypatch.setattr( + feed.tractor, + 'current_actor', + lambda **kwargs: SimpleNamespace( + name='brokerd.binance', loglevel='info', + ), + ) + monkeypatch.setattr(feed, 'get_feed_bus', stop_at_bus) + + async def main() -> None: + with pytest.raises(RuntimeError) as caught: + await feed.open_feed_bus( + ctx=None, brokername='binance', symbols=[], + loglevel='error', + ) + assert caught.value is boundary + + try: + logging.getLogger('piker.data').setLevel(logging.WARNING) + trio.run(main) + assert _web_bs.log.isEnabledFor(logging.INFO) + _web_bs.log.info('websocket INFO visibility probe') + assert 'websocket INFO visibility probe' in ( + capsys.readouterr().err + ) + finally: + for logger, (level, handlers) in saved.items(): + for handler in list(logger.handlers): + if handler not in handlers: + logger.removeHandler(handler) + handler.close() + logger.setLevel(level) diff --git a/tests/test_websocket.py b/tests/test_websocket.py index ad52a022..a6f12512 100644 --- a/tests/test_websocket.py +++ b/tests/test_websocket.py @@ -190,6 +190,7 @@ def test_reconnect_cancellation_bypasses_error_throttle( @pytest.mark.parametrize('shutdown', ['recover', 'reader', 'retry']) def test_reader_ping_close_recovery( monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, shutdown: str, ) -> None: ''' @@ -214,6 +215,8 @@ def test_reader_ping_close_recovery( readers, cancellation, reconnect tasks and delivery remain real. ''' + caplog.set_level('INFO', logger=_web_bs.log.name) + async def main() -> None: connections: int = 0 ping_entered = trio.Event() @@ -289,3 +292,13 @@ def test_reader_ping_close_recovery( tn.cancel_scope.cancel() trio.run(main) + if shutdown == 'recover': + messages = [record.getMessage() for record in caplog.records] + assert sum( + message.startswith('Websocket ready:') + for message in messages + ) == 2 + assert sum( + message.startswith('Websocket first message relayed:') + for message in messages + ) == 1