Fix P1 bugs in occupancy tracking: lock ordering deadlock, MAC normalization, and race condition

- P1-1: Fix lock ordering deadlock by establishing canonical order (known_lock → departure_lock → occupancy_lock). Refactor on_arrival() to acquire locks in correct order. Fix send_departure_alert() callback to hold occupancy_lock while updating state.
- P1-2: Add _normalize_mac() helper to strip colons/hyphens, apply to load_personal_macs_from_env() and is_personal_device() for consistent MAC comparison.
- P1-3: Remove occupancy_lock acquisition from _update_occupancy_state_unlocked() - callers must hold lock. Update all callers to acquire occupancy_lock before calling.

All individual tests pass. Fixes allow on_arrival() and timer callbacks to execute without deadlock.
This commit is contained in:
Cobra
2026-04-12 07:57:37 -04:00
parent f690370402
commit 0b468ee548
+74 -66
View File
@@ -365,17 +365,23 @@ def setup_logging():
return logger return logger
def _normalize_mac(mac: str) -> str:
"""Normalize MAC address: remove colons/hyphens, uppercase."""
return mac.replace(":", "").replace("-", "").upper()
def load_personal_macs_from_env() -> None: def load_personal_macs_from_env() -> None:
"""Parse NET_ALERTER_PERSONAL_MACS env var and add to personal_devices set.""" """Parse NET_ALERTER_PERSONAL_MACS env var and add to personal_devices set."""
macs_str = os.getenv("NET_ALERTER_PERSONAL_MACS", "") macs_str = os.getenv("NET_ALERTER_PERSONAL_MACS", "")
if not macs_str.strip(): if not macs_str.strip():
return return
macs = [m.strip().upper() for m in macs_str.split(",") if m.strip()] macs = [m.strip() for m in macs_str.split(",") if m.strip()]
with personal_lock: with personal_lock:
for mac in macs: for mac in macs:
personal_devices.add(mac) normalized = _normalize_mac(mac)
logging.info(f"Added personal device MAC: {mac}") personal_devices.add(normalized)
logging.info(f"Added personal device MAC: {normalized}")
def load_env(): def load_env():
@@ -418,12 +424,12 @@ def is_personal_device(mac: str) -> bool:
Returns True if device OUI is in MOBILE_DEVICE_OUIS OR mac is in personal_devices set. Returns True if device OUI is in MOBILE_DEVICE_OUIS OR mac is in personal_devices set.
""" """
# Normalize MAC # Normalize MAC
mac_upper = mac.replace(":", "").upper() mac_normalized = _normalize_mac(mac)
oui = mac_upper[:6] oui = mac_normalized[:6]
# Check personal_devices set first (manually configured) # Check personal_devices set first (manually configured)
with personal_lock: with personal_lock:
if mac_upper in personal_devices: if mac_normalized in personal_devices:
return True return True
# Check against MOBILE_DEVICE_OUIS # Check against MOBILE_DEVICE_OUIS
@@ -569,41 +575,41 @@ def format_departure(hostname: str, ip: str, vendor: str, mac: str, duration: st
def _update_occupancy_state_unlocked() -> None: def _update_occupancy_state_unlocked() -> None:
""" """
Internal: Update location occupancy state. Internal: Update location occupancy state.
Assumes known_lock is already held by caller. Assumes known_lock AND occupancy_lock are already held by caller.
""" """
global location_occupancy global location_occupancy
with occupancy_lock: # Count active personal devices (in known_devices, not marked departing)
# Count active personal devices (in known_devices, not marked departing) active_personal_count = 0
active_personal_count = 0 for mac, dev in known_devices.items():
for mac, dev in known_devices.items(): if not dev.get('departing', False) and is_personal_device(mac):
if not dev.get('departing', False) and is_personal_device(mac): active_personal_count += 1
active_personal_count += 1
# Determine new occupancy state # Determine new occupancy state
new_occupancy = "OCCUPIED" if active_personal_count > 0 else "VACANT" new_occupancy = "OCCUPIED" if active_personal_count > 0 else "VACANT"
# Fire alert on transitions (but not UNKNOWN → OCCUPIED on startup) # Fire alert on transitions (but not UNKNOWN → OCCUPIED on startup)
if new_occupancy != location_occupancy: if new_occupancy != location_occupancy:
if not (location_occupancy == "UNKNOWN" and new_occupancy == "OCCUPIED"): if not (location_occupancy == "UNKNOWN" and new_occupancy == "OCCUPIED"):
msg = f"[NET] Location: {new_occupancy}" msg = f"[NET] Location: {new_occupancy}"
logging.info(msg) logging.info(msg)
send_alert(msg) send_alert(msg)
else: else:
logging.debug(f"Suppressing startup occupancy alert: UNKNOWN → OCCUPIED") logging.debug(f"Suppressing startup occupancy alert: UNKNOWN → OCCUPIED")
location_occupancy = new_occupancy location_occupancy = new_occupancy
logging.info(f"Location occupancy updated to {location_occupancy} ({active_personal_count} personal devices active)") logging.info(f"Location occupancy updated to {location_occupancy} ({active_personal_count} personal devices active)")
def update_occupancy_state() -> None: def update_occupancy_state() -> None:
""" """
Update location occupancy state based on presence of personal devices. Update location occupancy state based on presence of personal devices.
Fires Matrix alerts on VACANT/OCCUPIED transitions (not on UNKNOWN transitions). Fires Matrix alerts on VACANT/OCCUPIED transitions (not on UNKNOWN transitions).
Thread-safe: acquires known_lock before checking devices. Thread-safe: acquires locks in order: known_lock, then occupancy_lock.
""" """
with known_lock: with known_lock:
_update_occupancy_state_unlocked() with occupancy_lock:
_update_occupancy_state_unlocked()
def on_arrival(mac: str, ip: str, hostname: str = "") -> None: def on_arrival(mac: str, ip: str, hostname: str = "") -> None:
@@ -622,34 +628,33 @@ def on_arrival(mac: str, ip: str, hostname: str = "") -> None:
hostname = hostname or ip hostname = hostname or ip
now = time.time() now = time.time()
# Silent re-arrival if device marked departing (rapid flap recovery) # Lock order: known_lock, then departure_lock, then occupancy_lock
with departure_lock: with known_lock:
if mac in known_devices and known_devices[mac].get('departing'): with departure_lock:
# Device returned during departure window — cancel timer, clear flag, no alert # Check if device marked departing (rapid flap recovery)
if mac in known_devices and known_devices[mac].get('departing'):
# Device returned during departure window — cancel timer, clear flag, no alert
if mac in departure_timers:
departure_timers[mac].cancel()
del departure_timers[mac]
known_devices[mac]['departing'] = False
with occupancy_lock:
_update_occupancy_state_unlocked()
last_departed_time.pop(mac, None)
logging.debug(f"Device {mac} re-arrived during departure window — suppressed alert")
return
# ALWAYS cancel any pending departure timer when device re-arrives
if mac in departure_timers: if mac in departure_timers:
departure_timers[mac].cancel() departure_timers[mac].cancel()
del departure_timers[mac] del departure_timers[mac]
with known_lock: logging.debug(f"Cancelled departure timer for {mac} — device re-arrived before debounce expired")
known_devices[mac]['departing'] = False
_update_occupancy_state_unlocked()
last_departed_time.pop(mac, None)
logging.debug(f"Device {mac} re-arrived during departure window — suppressed alert")
return
# Check re-arrival suppression BEFORE acquiring lock (avoid nested locks) if mac in last_departed_time:
with departure_lock: time_since_departure = now - last_departed_time[mac]
# ALWAYS cancel any pending departure timer when device re-arrives if time_since_departure < 300: # 5 min
if mac in departure_timers: logging.debug(f"Suppressing re-arrival alert for {mac} (departed {int(time_since_departure)}s ago)")
departure_timers[mac].cancel() # Re-add to known_devices to track presence
del departure_timers[mac]
logging.debug(f"Cancelled departure timer for {mac} — device re-arrived before debounce expired")
if mac in last_departed_time:
time_since_departure = now - last_departed_time[mac]
if time_since_departure < 300: # 5 min
logging.debug(f"Suppressing re-arrival alert for {mac} (departed {int(time_since_departure)}s ago)")
# Re-add to known_devices to track presence
with known_lock:
if mac not in known_devices: if mac not in known_devices:
vendor = lookup_oui(mac) vendor = lookup_oui(mac)
known_devices[mac] = { known_devices[mac] = {
@@ -661,10 +666,11 @@ def on_arrival(mac: str, ip: str, hostname: str = "") -> None:
} }
else: else:
known_devices[mac]['last_seen'] = now known_devices[mac]['last_seen'] = now
_update_occupancy_state_unlocked() with occupancy_lock:
return _update_occupancy_state_unlocked()
return
with known_lock: # Still inside known_lock, but not inside departure_lock now
if mac in known_devices: if mac in known_devices:
# Device is already known # Device is already known
dev = known_devices[mac] dev = known_devices[mac]
@@ -673,11 +679,13 @@ def on_arrival(mac: str, ip: str, hostname: str = "") -> None:
# DHCP renewal dedup: if last_seen < 30 min, skip alert # DHCP renewal dedup: if last_seen < 30 min, skip alert
if now - dev['first_seen'] < 1800: # 30 min if now - dev['first_seen'] < 1800: # 30 min
logging.debug(f"Skipping DHCP renewal alert for {mac} (seen {int(now - dev['first_seen'])}s ago)") logging.debug(f"Skipping DHCP renewal alert for {mac} (seen {int(now - dev['first_seen'])}s ago)")
_update_occupancy_state_unlocked() with occupancy_lock:
_update_occupancy_state_unlocked()
return return
# Not a re-arrival, update last_seen and don't alert (already known) # Not a re-arrival, update last_seen and don't alert (already known)
_update_occupancy_state_unlocked() with occupancy_lock:
_update_occupancy_state_unlocked()
return return
# New device # New device
@@ -731,27 +739,27 @@ def on_departure(mac: str) -> None:
def send_departure_alert(): def send_departure_alert():
"""Callback to send alert after debounce expires.""" """Callback to send alert after debounce expires."""
# Check if device re-arrived (departing flag cleared by on_arrival) # Lock order: known_lock, then departure_lock, then occupancy_lock
with known_lock: with known_lock:
if not known_devices.get(mac, {}).get('departing'): if not known_devices.get(mac, {}).get('departing'):
return # device re-arrived, departure was cancelled return # device re-arrived, departure was cancelled
# Device still departed — send alert and remove from tracking # Device still departed — send alert and remove from tracking
known_devices.pop(mac, None) known_devices.pop(mac, None)
with departure_lock:
last_departed_time[mac] = time.time()
if mac in departure_timers:
del departure_timers[mac]
# Update occupancy state after device removal (still inside known_lock)
with occupancy_lock:
_update_occupancy_state_unlocked()
duration = fmt_duration(time.time() - dev_copy['first_seen']) duration = fmt_duration(time.time() - dev_copy['first_seen'])
msg = format_departure(dev_copy['hostname'], dev_copy['ip'], dev_copy['vendor'] or "unknown", mac, duration) msg = format_departure(dev_copy['hostname'], dev_copy['ip'], dev_copy['vendor'] or "unknown", mac, duration)
logging.info(msg) logging.info(msg)
send_alert(msg) send_alert(msg)
# Record departure time for re-arrival suppression
with departure_lock:
last_departed_time[mac] = time.time()
if mac in departure_timers:
del departure_timers[mac]
# Update occupancy state after device removal
update_occupancy_state()
timer = threading.Timer(900.0, send_departure_alert) # 15 min = 900 sec timer = threading.Timer(900.0, send_departure_alert) # 15 min = 900 sec
timer.daemon = True timer.daemon = True
timer.name = f'departure-debounce-{mac}' timer.name = f'departure-debounce-{mac}'