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:
+74
-66
@@ -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}'
|
||||||
|
|||||||
Reference in New Issue
Block a user