From 9ac881c56c505ba2c187fa850e8529f3734b0936 Mon Sep 17 00:00:00 2001 From: Walter Boring Date: Fri, 12 Dec 2025 12:28:03 -0500 Subject: [PATCH] Update WatchList and NotifySeenPlugin The watchList was updating the last seen during RX time. This happens before the NotifySeenPlugin even sees the packet, so the callsign is never 'old'. this patch fixes that, so the watch list works. --- aprsd/cli_helper.py | 18 +++++++-- aprsd/packets/watch_list.py | 76 +++++++++++++++++++++++++++++------- aprsd/plugins/notify.py | 19 +++++---- tests/plugins/test_notify.py | 50 +++++++++++++++++++----- 4 files changed, 128 insertions(+), 35 deletions(-) diff --git a/aprsd/cli_helper.py b/aprsd/cli_helper.py index d49e398..5b96658 100644 --- a/aprsd/cli_helper.py +++ b/aprsd/cli_helper.py @@ -34,6 +34,12 @@ log_options = [ is_flag=True, help='Show log level in log format (disabled by default for listen).', ), + click.option( + '--show-location', + default=False, + is_flag=True, + help='Show location in log format (disabled by default for listen).', + ), ] common_options = [ @@ -124,9 +130,9 @@ def add_options(options): def setup_logging_with_options( show_thread: bool, show_level: bool, + show_location: bool, loglevel: str, quiet: bool, - include_location: bool = True, ) -> None: """Setup logging with custom format based on show_thread and show_level options. @@ -153,7 +159,7 @@ def setup_logging_with_options( # Message is always included parts.append(conf_log.DEFAULT_LOG_FORMAT_MESSAGE) - if include_location: + if show_location: parts.append(conf_log.DEFAULT_LOG_FORMAT_LOCATION) # Set the custom log format @@ -172,6 +178,7 @@ def process_standard_options(f: F) -> F: # Extract show_thread and show_level show_thread = kwargs.get('show_thread', False) show_level = kwargs.get('show_level', False) + show_location = kwargs.get('show_location', False) if kwargs['config_file']: default_config_files = [kwargs['config_file']] @@ -196,9 +203,9 @@ def process_standard_options(f: F) -> F: setup_logging_with_options( show_thread=show_thread, show_level=show_level, + show_location=show_location, loglevel=ctx.obj['loglevel'], quiet=ctx.obj['quiet'], - include_location=True, ) if CONF.trace_enabled: trace.setup_tracing(['method', 'api']) @@ -213,6 +220,7 @@ def process_standard_options(f: F) -> F: del kwargs['quiet'] del kwargs['show_thread'] del kwargs['show_level'] + del kwargs['show_location'] # Enable profiling if requested if profile_output is not None: @@ -247,6 +255,7 @@ def process_standard_options_no_config(f: F) -> F: # Extract show_thread and show_level show_thread = kwargs.get('show_thread', False) show_level = kwargs.get('show_level', False) + show_location = kwargs.get('show_location', False) # Initialize CONF without config file for log format access try: @@ -268,9 +277,9 @@ def process_standard_options_no_config(f: F) -> F: setup_logging_with_options( show_thread=show_thread, show_level=show_level, + show_location=show_location, loglevel=ctx.obj['loglevel'], quiet=ctx.obj['quiet'], - include_location=True, ) profile_output = kwargs.pop('profile_output', None) @@ -279,6 +288,7 @@ def process_standard_options_no_config(f: F) -> F: del kwargs['quiet'] del kwargs['show_thread'] del kwargs['show_level'] + del kwargs['show_location'] # Enable profiling if requested if profile_output is not None: diff --git a/aprsd/packets/watch_list.py b/aprsd/packets/watch_list.py index 4344e9c..d9a82d9 100644 --- a/aprsd/packets/watch_list.py +++ b/aprsd/packets/watch_list.py @@ -5,11 +5,10 @@ from oslo_config import cfg from aprsd import utils from aprsd.packets import core -from aprsd.utils import objectstore - +from aprsd.utils import objectstore, trace CONF = cfg.CONF -LOG = logging.getLogger("APRSD") +LOG = logging.getLogger('APRSD') class WatchList(objectstore.ObjectStoreMixin): @@ -17,40 +16,47 @@ class WatchList(objectstore.ObjectStoreMixin): _instance = None data = {} + initialized = False def __new__(cls, *args, **kwargs): if cls._instance is None: cls._instance = super().__new__(cls) return cls._instance + @trace.no_trace def __init__(self): super().__init__() - self._update_from_conf() + if not self.initialized: + self._update_from_conf() + self.initialized = True def _update_from_conf(self, config=None): with self.lock: if CONF.watch_list.enabled and CONF.watch_list.callsigns: for callsign in CONF.watch_list.callsigns: - call = callsign.replace("*", "") + call = callsign.replace('*', '') # FIXME(waboring) - we should fetch the last time we saw # a beacon from a callsign or some other mechanism to find # last time a message was seen by aprs-is. For now this # is all we can do. if call not in self.data: self.data[call] = { - "last": None, - "packet": None, + 'last': None, + 'packet': None, + 'was_old_before_update': False, } + @trace.no_trace def stats(self, serializable=False) -> dict: stats = {} + return self.data with self.lock: for callsign in self.data: stats[callsign] = { - "last": self.data[callsign]["last"], - "packet": self.data[callsign]["packet"], - "age": self.age(callsign), - "old": self.is_old(callsign), + 'last': self.data[callsign]['last'], + 'packet': self.data[callsign]['packet'], + 'age': self.age(callsign), + 'old': self.is_old(callsign), } return stats @@ -67,8 +73,25 @@ class WatchList(objectstore.ObjectStoreMixin): if self.callsign_in_watchlist(callsign): with self.lock: - self.data[callsign]["last"] = datetime.datetime.now() - self.data[callsign]["packet"] = packet + # Check if callsign was old BEFORE updating the timestamp + # This allows plugins to check if it was old before this update + # We check directly here to avoid nested locking + was_old = False + last_seen_time = self.data[callsign].get('last') + if last_seen_time: + age_delta = datetime.datetime.now() - last_seen_time + max_delta = self.max_delta() + if age_delta > max_delta: + was_old = True + + # Now update the timestamp and packet + if last_seen_time: + self.data[callsign]['age'] = str( + datetime.datetime.now() - last_seen_time + ) + self.data[callsign]['last'] = datetime.datetime.now() + self.data[callsign]['packet'] = packet + self.data[callsign]['was_old_before_update'] = was_old def tx(self, packet: type[core.Packet]) -> None: """We don't care about TX packets.""" @@ -76,7 +99,7 @@ class WatchList(objectstore.ObjectStoreMixin): def last_seen(self, callsign): with self.lock: if self.callsign_in_watchlist(callsign): - return self.data[callsign]["last"] + return self.data[callsign]['last'] def age(self, callsign): now = datetime.datetime.now() @@ -89,9 +112,32 @@ class WatchList(objectstore.ObjectStoreMixin): def max_delta(self, seconds=None): if not seconds: seconds = CONF.watch_list.alert_time_seconds - max_timeout = {"seconds": seconds} + max_timeout = {'seconds': seconds} return datetime.timedelta(**max_timeout) + def was_old_before_last_update(self, callsign): + """Check if the callsign was old before the last rx() update. + + This is useful for plugins that need to know if a callsign was + old before the current packet updated the timestamp. This allows + plugins to determine if they should notify about a callsign that + was previously old but is now being seen again. + """ + with self.lock: + if not self.callsign_in_watchlist(callsign): + return False + return self.data[callsign].get('was_old_before_update', False) + + def mark_as_new(self, callsign): + """Mark a callsign as new, resetting the was_old_before_update flag. + + This is useful after sending a notification to prevent duplicate + notifications until the callsign becomes old again. + """ + with self.lock: + if self.callsign_in_watchlist(callsign): + self.data[callsign]['was_old_before_update'] = False + def is_old(self, callsign, seconds=None): """Watch list callsign last seen is old compared to now? diff --git a/aprsd/plugins/notify.py b/aprsd/plugins/notify.py index 1a47f9f..30fb9cd 100644 --- a/aprsd/plugins/notify.py +++ b/aprsd/plugins/notify.py @@ -5,7 +5,7 @@ from oslo_config import cfg from aprsd import packets, plugin CONF = cfg.CONF -LOG = logging.getLogger("APRSD") +LOG = logging.getLogger('APRSD') class NotifySeenPlugin(plugin.APRSDWatchListPluginBase): @@ -17,10 +17,10 @@ class NotifySeenPlugin(plugin.APRSDWatchListPluginBase): seen was older than the configured age limit. """ - short_description = "Notify me when a CALLSIGN is recently seen on APRS-IS" + short_description = 'Notify me when a CALLSIGN is recently seen on APRS-IS' def process(self, packet: packets.MessagePacket): - LOG.info("NotifySeenPlugin") + LOG.info('NotifySeenPlugin') notify_callsign = CONF.watch_list.alert_callsign fromcall = packet.from_call @@ -29,14 +29,19 @@ class NotifySeenPlugin(plugin.APRSDWatchListPluginBase): age = wl.age(fromcall) if fromcall != notify_callsign: - if wl.is_old(fromcall): + # Check if the callsign was old BEFORE WatchList.rx() updated the timestamp + # This ensures we can detect when a previously old callsign is seen again + if wl.was_old_before_last_update(fromcall): LOG.info( - "NOTIFY {} last seen {} max age={}".format( + 'NOTIFY {} last seen {} max age={}'.format( fromcall, age, wl.max_delta(), ), ) + # Mark the callsign as new to prevent duplicate notifications + # until it becomes old again + wl.mark_as_new(fromcall) packet_type = packet.__class__.__name__ # we shouldn't notify the alert user that they are online. pkt = packets.MessagePacket( @@ -49,10 +54,10 @@ class NotifySeenPlugin(plugin.APRSDWatchListPluginBase): return pkt else: LOG.debug( - "Not old enough to notify on callsign " + 'Not old enough to notify on callsign ' f"'{fromcall}' : {age} < {wl.max_delta()}", ) return packets.NULL_MESSAGE else: - LOG.debug("fromcall and notify_callsign are the same, ignoring") + LOG.debug('fromcall and notify_callsign are the same, ignoring') return packets.NULL_MESSAGE diff --git a/tests/plugins/test_notify.py b/tests/plugins/test_notify.py index 7cdd31d..d15fc38 100644 --- a/tests/plugins/test_notify.py +++ b/tests/plugins/test_notify.py @@ -140,9 +140,7 @@ class TestNotifySeenPlugin(TestWatchListPlugin): expected = packets.NULL_MESSAGE self.assertEqual(expected, actual) - @mock.patch('aprsd.packets.WatchList.is_old') - def test_callsign_in_watchlist_not_old(self, mock_is_old): - mock_is_old.return_value = False + def test_callsign_in_watchlist_not_old(self): self.config_and_init( watchlist_enabled=True, watchlist_callsigns=['WB4BOR'], @@ -154,46 +152,77 @@ class TestNotifySeenPlugin(TestWatchListPlugin): message='ping', msg_number=1, ) + # Simulate WatchList.rx() being called first (with recent timestamp) + # This will set was_old_before_update to False since it's not old + packets.WatchList().rx(packet) actual = plugin.filter(packet) expected = packets.NULL_MESSAGE self.assertEqual(expected, actual) - @mock.patch('aprsd.packets.WatchList.is_old') - def test_callsign_in_watchlist_old_same_alert_callsign(self, mock_is_old): - mock_is_old.return_value = True + def test_callsign_in_watchlist_old_same_alert_callsign(self): + import datetime + self.config_and_init( watchlist_enabled=True, watchlist_alert_callsign='WB4BOR', watchlist_callsigns=['WB4BOR'], + watchlist_alert_time_seconds=60, ) plugin = notify_plugin.NotifySeenPlugin() + # Set up WatchList with an old timestamp + wl = packets.WatchList() + old_time = datetime.datetime.now() - datetime.timedelta(seconds=120) + with wl.lock: + wl.data['WB4BOR'] = { + 'last': old_time, + 'packet': None, + 'was_old_before_update': False, + } + packet = fake.fake_packet( fromcall='WB4BOR', message='ping', msg_number=1, ) + # Simulate WatchList.rx() being called first + # This will set was_old_before_update to True since it was old + wl.rx(packet) actual = plugin.filter(packet) expected = packets.NULL_MESSAGE self.assertEqual(expected, actual) - @mock.patch('aprsd.packets.WatchList.is_old') - def test_callsign_in_watchlist_old_send_alert(self, mock_is_old): - mock_is_old.return_value = True + def test_callsign_in_watchlist_old_send_alert(self): + import datetime + notify_callsign = fake.FAKE_TO_CALLSIGN fromcall = 'WB4BOR' self.config_and_init( watchlist_enabled=True, watchlist_alert_callsign=notify_callsign, watchlist_callsigns=['WB4BOR'], + watchlist_alert_time_seconds=60, ) plugin = notify_plugin.NotifySeenPlugin() + # Set up WatchList with an old timestamp + wl = packets.WatchList() + old_time = datetime.datetime.now() - datetime.timedelta(seconds=120) + with wl.lock: + wl.data[fromcall] = { + 'last': old_time, + 'packet': None, + 'was_old_before_update': False, + } + packet = fake.fake_packet( fromcall=fromcall, message='ping', msg_number=1, ) + # Simulate WatchList.rx() being called first + # This will set was_old_before_update to True since it was old + wl.rx(packet) packet_type = packet.__class__.__name__ actual = plugin.filter(packet) msg = f"{fromcall} was just seen by type:'{packet_type}'" @@ -202,3 +231,6 @@ class TestNotifySeenPlugin(TestWatchListPlugin): self.assertEqual(fake.FAKE_FROM_CALLSIGN, actual.from_call) self.assertEqual(notify_callsign, actual.to_call) self.assertEqual(msg, actual.message_text) + # Verify that mark_as_new was called to prevent duplicate notifications + # by checking that was_old_before_update is now False + self.assertFalse(wl.was_old_before_last_update(fromcall))