From e8da064d63cc9ced9e27e9356d249e162fc27210 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20P=C3=A9rez?= Date: Sun, 20 Sep 2026 10:30:02 -0300 Subject: [PATCH] fix(obp-proxy): drop per-packet RX debug for voice, not once-per-stream MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #82 logged the RX debug line once per stream_id per bridge, but a bridge with BOTH_SLOTS/several concurrent talkgroups interleaves packets from multiple calls, so the "last seen" stream flips almost every packet and the line logs nearly as often as before the fix — confirmed against production output (three interleaved streams on OBP-CL). DMRD/DMRE demux by NETWORK_ID, which is never ambiguous, and *CALL START*/*CALL END* (application/routing_use_cases.py, application/routing/obp_forward.py) already log once per real call with better detail (SUB, TGID, TS, duration). Drop the fan-in RX line for voice frames entirely instead of trying to approximate "once per call" with no session state; control frames (BCKA/BCSQ/BCST/BCVE) keep logging every time, since they are rare and that visibility mattered for the #79 fix. --- .../infrastructure/proxy/obp_fanin.py | 35 ++++++------------- tests/infrastructure/test_obp_proxy.py | 28 ++++++++------- 2 files changed, 26 insertions(+), 37 deletions(-) diff --git a/src/adn_server/infrastructure/proxy/obp_fanin.py b/src/adn_server/infrastructure/proxy/obp_fanin.py index 2c3de3e..ca71e95 100644 --- a/src/adn_server/infrastructure/proxy/obp_fanin.py +++ b/src/adn_server/infrastructure/proxy/obp_fanin.py @@ -181,7 +181,6 @@ class ObpFanInDemux: self._registry = registry self.debug = debug self._log = logger or _logger - self._last_stream: dict[str, bytes] = {} def deliver( self, @@ -210,29 +209,17 @@ class ObpFanInDemux: entry = self._registry.bridges.get(system_name) if entry is None: return - if self.debug: - opcode = data[:4] - if opcode in (DMRD, DMRE) and len(data) >= 20: - stream_id = data[16:20] - if self._last_stream.get(system_name) != stream_id: - self._last_stream[system_name] = stream_id - self._log.debug( - "(OBP_PROXY) RX %s from %s:%s stream=%s -> %s", - opcode, - host, - port, - stream_id.hex(), - system_name, - ) - else: - self._log.debug( - "(OBP_PROXY) RX %s from %s:%s len=%d -> %s", - opcode, - host, - port, - len(data), - system_name, - ) + if self.debug and data[:4] not in (DMRD, DMRE): + # DMRD/DMRE demux by NETWORK_ID, never ambiguous; *CALL START*/*CALL END* + # (routing_use_cases.py) already give once-per-call visibility for those. + self._log.debug( + "(OBP_PROXY) RX %s from %s:%s len=%d -> %s", + data[:4], + host, + port, + len(data), + system_name, + ) entry.reply_transport.note_ingress(transport) entry.sink.inject(data, addr) diff --git a/tests/infrastructure/test_obp_proxy.py b/tests/infrastructure/test_obp_proxy.py index f750be9..4a804b1 100644 --- a/tests/infrastructure/test_obp_proxy.py +++ b/tests/infrastructure/test_obp_proxy.py @@ -22,6 +22,8 @@ from __future__ import annotations +import logging + import pytest from tests.conftest import minimal_valid_config @@ -570,11 +572,12 @@ def test_control_frame_prefers_configured_peer_over_relaxed_target() -> None: assert not protocols["OBP-FR"].packets -def test_debug_rx_log_once_per_stream(caplog) -> None: - """A call sends many DMRD/DMRE packets; the RX debug line must fire once per - stream_id, not once per packet, or an active call floods the log.""" - import logging as _logging - +def test_debug_does_not_log_voice_packets(caplog) -> None: + """DMRD/DMRE demux by NETWORK_ID, never ambiguous, and *CALL START*/*CALL END* + (routing_use_cases.py) already give once-per-call visibility. Concurrent calls + on the same bridge (BOTH_SLOTS, several TGs) interleave stream_ids packet by + packet, so any per-stream tracking here would still log almost every packet — + so voice frames are not logged at all, only control frames are.""" receiver = _RecordingObp() transport = _RecordingTransport() registry = ObpBridgeRegistry() @@ -588,13 +591,12 @@ def test_debug_rx_log_once_per_stream(caplog) -> None: ) ) demux = ObpFanInDemux(registry, debug=True) - caplog.set_level(_logging.DEBUG) + caplog.set_level(logging.DEBUG) - wire_a = build_dmrd_v1(_sample_dmr_voice(stream_id=0x11111111), _NETWORK, _PASS) - for _ in range(5): - demux.deliver(wire_a, _ADDR, local_port=62032, transport=transport) - assert sum("RX" in r.getMessage() for r in caplog.records) == 1 + for stream in (0x11111111, 0x22222222, 0x11111111, 0x22222222): + wire = build_dmrd_v1(_sample_dmr_voice(stream_id=stream), _NETWORK, _PASS) + demux.deliver(wire, _ADDR, local_port=62032, transport=transport) + assert not any("RX" in r.getMessage() for r in caplog.records) - wire_b = build_dmrd_v1(_sample_dmr_voice(stream_id=0x22222222), _NETWORK, _PASS) - demux.deliver(wire_b, _ADDR, local_port=62032, transport=transport) - assert sum("RX" in r.getMessage() for r in caplog.records) == 2 + demux.deliver(build_bcka(_PASS), _ADDR, local_port=62032, transport=transport) + assert sum("RX" in r.getMessage() for r in caplog.records) == 1