From db3a0428c0aa9dfd7794fbf5157d0e009540ed3a Mon Sep 17 00:00:00 2001 From: Walter Boring Date: Tue, 2 Jun 2026 11:17:24 -0400 Subject: [PATCH] Fix DupePacketFilter checking wrong packet's processed flag MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- aprsd/packets/filters/dupe_filter.py | 5 +- tests/packets/filters/test_dupe_filter.py | 63 +++++++++++++++++++++-- 2 files changed, 62 insertions(+), 6 deletions(-) diff --git a/aprsd/packets/filters/dupe_filter.py b/aprsd/packets/filters/dupe_filter.py index d02cf8b..adad551 100644 --- a/aprsd/packets/filters/dupe_filter.py +++ b/aprsd/packets/filters/dupe_filter.py @@ -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 diff --git a/tests/packets/filters/test_dupe_filter.py b/tests/packets/filters/test_dupe_filter.py index 54691d2..8d39a60 100644 --- a/tests/packets/filters/test_dupe_filter.py +++ b/tests/packets/filters/test_dupe_filter.py @@ -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)