.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`))
wkt/land_binance_usdm_feed
Gud Boi 2026-10-28 13:13:26 -04:00
parent b95e7c796e
commit 032580bfa5
6 changed files with 204 additions and 6 deletions

View File

@ -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.

View File

@ -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.

View File

@ -194,6 +194,7 @@ async def _reconnect_forever(
''' '''
# after so many msg recv timeouts, reset the connection # after so many msg recv timeouts, reset the connection
timeouts: int = 0 timeouts: int = 0
first_message: bool = True
while True: while True:
with trio.move_on_after( with trio.move_on_after(
@ -203,6 +204,11 @@ async def _reconnect_forever(
try: try:
msg: Any = await ws.get_message() msg: Any = await ws.get_message()
await snd.send(msg) await snd.send(msg)
if first_message:
log.info(
f'Websocket first message relayed: {url!r}'
)
first_message = False
except nobsws.recon_errors: except nobsws.recon_errors:
log.exception( log.exception(
f'{src_mod}\n' f'{src_mod}\n'
@ -221,7 +227,8 @@ async def _reconnect_forever(
if timeouts > reset_after: if timeouts > reset_after:
log.error( log.error(
f'{src_mod}\n' 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() rent_cs.cancel()
@ -295,6 +302,7 @@ async def _reconnect_forever(
# indicate to wrapper / opener that we are up and block # indicate to wrapper / opener that we are up and block
# to let tasks run **inside** the ws open block above. # to let tasks run **inside** the ws open block above.
log.info(f'Websocket ready: {url!r}')
nobsws._connected.set() nobsws._connected.set()
await trio.sleep_forever() await trio.sleep_forever()

View File

@ -485,14 +485,15 @@ async def open_feed_bus(
if loglevel is None: if loglevel is None:
loglevel: str = tractor.current_actor().loglevel loglevel: str = tractor.current_actor().loglevel
# XXX: required to propagate ``tractor`` loglevel to piker # Configure the shared piker.data logger used by ._util.log,
# logging # including websocket tasks. A per-client verbosity must not
# demote actor-wide transport diagnostics below daemon verbosity.
get_console_log( get_console_log(
level=(loglevel level=(tractor.current_actor().loglevel
or or
tractor.current_actor().loglevel loglevel
), ),
name=__name__, name=log.name,
) )
# local state sanity checks # local state sanity checks

View File

@ -2,7 +2,11 @@
Package logger namespace regression tests. Package logger namespace regression tests.
''' '''
import logging
from types import SimpleNamespace
import pytest import pytest
import trio
from piker.log import ( from piker.log import (
get_console_log, get_console_log,
@ -42,3 +46,67 @@ def test_package_logger_name(
log = factory(name=name) log = factory(name=name)
assert log.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)

View File

@ -190,6 +190,7 @@ def test_reconnect_cancellation_bypasses_error_throttle(
@pytest.mark.parametrize('shutdown', ['recover', 'reader', 'retry']) @pytest.mark.parametrize('shutdown', ['recover', 'reader', 'retry'])
def test_reader_ping_close_recovery( def test_reader_ping_close_recovery(
monkeypatch: pytest.MonkeyPatch, monkeypatch: pytest.MonkeyPatch,
caplog: pytest.LogCaptureFixture,
shutdown: str, shutdown: str,
) -> None: ) -> None:
''' '''
@ -214,6 +215,8 @@ def test_reader_ping_close_recovery(
readers, cancellation, reconnect tasks and delivery remain real. readers, cancellation, reconnect tasks and delivery remain real.
''' '''
caplog.set_level('INFO', logger=_web_bs.log.name)
async def main() -> None: async def main() -> None:
connections: int = 0 connections: int = 0
ping_entered = trio.Event() ping_entered = trio.Event()
@ -289,3 +292,13 @@ def test_reader_ping_close_recovery(
tn.cancel_scope.cancel() tn.cancel_scope.cancel()
trio.run(main) 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