mirror of
https://github.com/craigerl/aprsd.git
synced 2026-06-15 20:38:39 -04:00
Fix DupePacketFilter checking wrong packet's processed flag
DupePacketFilter.filter() was checking packet.processed (the newly arrived duplicate) instead of found.processed (the previously stored packet). Since all freshly decoded packets have processed=False by default, the dupe detection branch was never reachable — every duplicate message was passed through and re-processed. This caused KM6LYW's retransmit of msg:9028 (via a different digipeater path 63s after first receipt) to trigger NearestPlugin a second time, sending 4 reply packets instead of 2 and resetting the AckPacket retry counter back to (1 of 3). Fix: check found.processed instead of packet.processed. Update existing tests to reflect the correct variable under test. Add regression test test_filter_aprs_retransmit_via_different_digi that reproduces the exact production scenario.
This commit is contained in:
@@ -53,8 +53,9 @@ class DupePacketFilter:
|
||||
# We haven't seen this packet before, so we process it.
|
||||
return packet
|
||||
|
||||
if not packet.processed:
|
||||
# We haven't processed this packet through the plugins.
|
||||
if not found.processed:
|
||||
# The previously seen packet hasn't been processed yet,
|
||||
# so let this one through too.
|
||||
return packet
|
||||
elif abs(packet.timestamp - found.timestamp) < CONF.packet_dupe_timeout:
|
||||
# If the packet came in within N seconds of the
|
||||
|
||||
@@ -70,18 +70,22 @@ class TestDupePacketFilter(unittest.TestCase):
|
||||
self.assertEqual(result, packet)
|
||||
|
||||
def test_filter_duplicate_within_timeout(self):
|
||||
"""Test filter() with duplicate within timeout."""
|
||||
"""Test filter() with duplicate within timeout.
|
||||
|
||||
The found (previously stored) packet is already processed.
|
||||
The new incoming duplicate should be dropped.
|
||||
"""
|
||||
from oslo_config import cfg
|
||||
|
||||
CONF = cfg.CONF
|
||||
CONF.packet_dupe_timeout = 60
|
||||
|
||||
packet = fake.fake_packet(msg_number='123')
|
||||
packet.processed = True
|
||||
packet.timestamp = 1000
|
||||
|
||||
mock_list_instance = mock.MagicMock()
|
||||
found_packet = fake.fake_packet(msg_number='123')
|
||||
found_packet.processed = True # the stored packet was already processed
|
||||
found_packet.timestamp = 1050 # Within 60 second timeout
|
||||
mock_list_instance.find.return_value = found_packet
|
||||
self.filter.pl = mock_list_instance
|
||||
@@ -92,18 +96,23 @@ class TestDupePacketFilter(unittest.TestCase):
|
||||
mock_log.warning.assert_called()
|
||||
|
||||
def test_filter_duplicate_after_timeout(self):
|
||||
"""Test filter() with duplicate after timeout."""
|
||||
"""Test filter() with duplicate after timeout.
|
||||
|
||||
The found (previously stored) packet is already processed,
|
||||
but it arrived long ago (outside the dupe timeout window).
|
||||
The new incoming duplicate should be re-processed with a warning.
|
||||
"""
|
||||
from oslo_config import cfg
|
||||
|
||||
CONF = cfg.CONF
|
||||
CONF.packet_dupe_timeout = 60
|
||||
|
||||
packet = fake.fake_packet(msg_number='123')
|
||||
packet.processed = True
|
||||
packet.timestamp = 2000
|
||||
|
||||
mock_list_instance = mock.MagicMock()
|
||||
found_packet = fake.fake_packet(msg_number='123')
|
||||
found_packet.processed = True # the stored packet was already processed
|
||||
found_packet.timestamp = 1000 # More than 60 seconds ago
|
||||
mock_list_instance.find.return_value = found_packet
|
||||
self.filter.pl = mock_list_instance
|
||||
@@ -112,3 +121,49 @@ class TestDupePacketFilter(unittest.TestCase):
|
||||
result = self.filter.filter(packet)
|
||||
self.assertEqual(result, packet) # Should pass
|
||||
mock_log.warning.assert_called()
|
||||
|
||||
def test_filter_aprs_retransmit_via_different_digi(self):
|
||||
"""Regression test for the production duplicate-reply bug.
|
||||
|
||||
Scenario (observed 2026-06-02 in aprsd-REPEAT logs):
|
||||
09:49:14 RX MessagePacket:9028 KM6LYW→...→qAO→KM6LYW-2→REPEAT "N 2"
|
||||
→ processed, NearestPlugin replies sent (msg 2385, 2386)
|
||||
09:49:47 TX AckPacket:9028 (2 of 3) ← KM6LYW never got the ack
|
||||
09:50:17 RX MessagePacket:9028 KM6LYW→...→qAR→GTOWN→REPEAT "N 2"
|
||||
← same msgNo, different digipeater path, 63 seconds later
|
||||
→ BUG: DupePacketFilter passed it through because it was
|
||||
checking packet.processed (new packet, always False)
|
||||
instead of found.processed (stored packet, True)
|
||||
→ NearestPlugin ran again → 4 replies sent instead of 2
|
||||
|
||||
The fix: check found.processed, not packet.processed.
|
||||
"""
|
||||
from oslo_config import cfg
|
||||
|
||||
CONF = cfg.CONF
|
||||
CONF.packet_dupe_timeout = 300 # 5 minute default
|
||||
|
||||
# The retransmit arrives 63 seconds after the first receipt.
|
||||
first_timestamp = 1000.0
|
||||
retransmit_timestamp = first_timestamp + 63
|
||||
|
||||
# Incoming duplicate — freshly decoded, processed=False (always)
|
||||
retransmit = fake.fake_packet(msg_number='9028')
|
||||
retransmit.timestamp = retransmit_timestamp
|
||||
|
||||
# What PacketList holds from the first receipt — already processed
|
||||
first_receipt = fake.fake_packet(msg_number='9028')
|
||||
first_receipt.processed = True
|
||||
first_receipt.timestamp = first_timestamp
|
||||
|
||||
mock_list_instance = mock.MagicMock()
|
||||
mock_list_instance.find.return_value = first_receipt
|
||||
self.filter.pl = mock_list_instance
|
||||
|
||||
with mock.patch('aprsd.packets.filters.dupe_filter.LOG') as mock_log:
|
||||
result = self.filter.filter(retransmit)
|
||||
self.assertIsNone(result) # Must be dropped — no duplicate reply
|
||||
mock_log.warning.assert_called_once()
|
||||
warning_msg = mock_log.warning.call_args[0][0]
|
||||
self.assertIn('9028', warning_msg)
|
||||
self.assertIn('already tracked', warning_msg)
|
||||
|
||||
Reference in New Issue
Block a user