Feat(Fix): Multi-Tenant Zerotier Org Setups

Imports Network From Zerotier
Async Emails
Migration guardrails
Admin to see all approvals states

gatehouse_app/services/zerotier_reconciliation_service.py

@@ -1,6 +1,7 @@
 """ZeroTier reconciliation service — polling loop to sync state with the controller."""
 
 import logging
+import time
 from datetime import datetime, timezone
 
 from gatehouse_app.extensions import db
@@ -34,16 +35,24 @@ def reconcile_expired_activations() -> int:
         ActivationSession.deleted_at.is_(None),
     ).all()
 
+    logger.debug(f"[Reconciliation] Expiry check: {len(expired)} overdue session(s) found.")
+
     count = 0
     for session in expired:
         try:
             _expire_session(session)
             count += 1
         except Exception as exc:
-            logger.error(f"[Reconciliation] Failed to expire session {session.id}: {exc}")
+            logger.error(
+                f"[Reconciliation] Failed to expire session {session.id} "
+                f"(user={session.user_id} membership={session.device_network_membership_id}): {exc}",
+                exc_info=True,
+            )
 
     if count > 0:
-        logger.info(f"[Reconciliation] Expired {count} activation sessions.")
+        logger.info(f"[Reconciliation] Expired {count} activation session(s).")
+    else:
+        logger.debug("[Reconciliation] No activation sessions to expire.")
 
     return count
 
@@ -55,9 +64,14 @@ def reconcile_network(portal_network_id: str) -> dict:
     """
     network = PortalNetwork.query.get(portal_network_id)
     if not network or not network.is_active:
+        logger.debug(
+            f"[Reconciliation] Skipping portal_network_id={portal_network_id}: "
+            f"{'not found' if not network else 'inactive or deleted'}."
+        )
         return {"skipped": True, "reason": "network_inactive_or_deleted"}
 
     zerotier_network_id = network.zerotier_network_id
+    network_label = f"{network.name} ({zerotier_network_id})"
     actions = {
         "zt_members_checked": 0,
         "zt_members_added": 0,
@@ -67,15 +81,25 @@ def reconcile_network(portal_network_id: str) -> dict:
         "unknown_members": [],
     }
 
+    t_start = time.monotonic()
+    logger.debug(f"[Reconciliation] Starting network reconciliation for {network_label}.")
+
     # Get current ZT members
     try:
-        zt_members = {m.node_id: m for m in zt.list_members(zerotier_network_id)}
+        zt_members = {m.node_id: m for m in zt.list_members(zerotier_network_id,
+                                                              organization_id=network.organization_id)}
     except Exception as exc:
-        logger.error(f"[Reconciliation] Failed to list ZT members for {zerotier_network_id}: {exc}")
+        logger.error(
+            f"[Reconciliation] Failed to list ZT members for {network_label}: {exc}",
+            exc_info=True,
+        )
         actions["error"] = str(exc)
         return actions
 
     actions["zt_members_checked"] = len(zt_members)
+    logger.debug(
+        f"[Reconciliation] {network_label}: {len(zt_members)} member(s) fetched from ZT controller."
+    )
 
     # Get our portal memberships for this network
     our_memberships = {
@@ -87,13 +111,21 @@ def reconcile_network(portal_network_id: str) -> dict:
         if m.device and m.device.deleted_at is None
     }
 
+    logger.debug(
+        f"[Reconciliation] {network_label}: {len(our_memberships)} portal membership(s) to reconcile."
+    )
+
     # Reconcile each portal membership
     for node_id, membership in our_memberships.items():
         zt_member = zt_members.pop(node_id, None)
         device = membership.device
 
         if not zt_member:
-            # Member not seen in ZT yet
+            # Member not seen in ZT yet — could be freshly joined or never connected
+            logger.debug(
+                f"[Reconciliation] {network_label}: node {node_id} "
+                f"(device={device.display_name!r}, state={membership.state}) not yet seen in ZT controller."
+            )
             continue
 
         actions["join_seen_updated"] += 1
@@ -104,31 +136,67 @@ def reconcile_network(portal_network_id: str) -> dict:
         # Sync authorization state
         if membership.state == MembershipState.ACTIVE_AUTHORIZED:
             if not zt_member.is_authorized:
-                # We think it's active but ZT says it's not — re-authorize
+                # Portal says active but ZT disagrees — drift, re-authorize
+                logger.warning(
+                    f"[Reconciliation] {network_label}: DRIFT detected — portal=ACTIVE_AUTHORIZED "
+                    f"but ZT says unauthorized for node {node_id} (device={device.display_name!r}). Re-authorizing."
+                )
                 try:
-                    zt.authorize_member(zerotier_network_id, node_id)
+                    zt.authorize_member(zerotier_network_id, node_id,
+                                        organization_id=network.organization_id)
                     actions["authorized"] += 1
+                    logger.info(
+                        f"[Reconciliation] {network_label}: Re-authorized node {node_id} (device={device.display_name!r})."
+                    )
                 except Exception as exc:
-                    logger.warning(f"[Reconciliation] Re-authorize failed for {node_id}: {exc}")
+                    logger.warning(
+                        f"[Reconciliation] {network_label}: Re-authorize failed for node {node_id}: {exc}"
+                    )
+            else:
+                logger.debug(
+                    f"[Reconciliation] {network_label}: node {node_id} — portal=ACTIVE_AUTHORIZED, ZT=authorized. OK."
+                )
         else:
             if zt_member.is_authorized:
-                # We think it's not authorized but ZT says it is — deauthorize
-                # (could be manual override in ZT console)
+                # ZT says authorized but portal doesn't — could be manual override in ZT console
+                logger.warning(
+                    f"[Reconciliation] {network_label}: DRIFT detected — portal state={membership.state} "
+                    f"but ZT says authorized for node {node_id} (device={device.display_name!r}). Deauthorizing."
+                )
                 try:
-                    zt.deauthorize_member(zerotier_network_id, node_id)
+                    zt.deauthorize_member(zerotier_network_id, node_id,
+                                          organization_id=network.organization_id)
                     actions["deauthorized"] += 1
+                    logger.info(
+                        f"[Reconciliation] {network_label}: Deauthorized node {node_id} (device={device.display_name!r})."
+                    )
                 except Exception as exc:
-                    logger.warning(f"[Reconciliation] Deauthorize failed for {node_id}: {exc}")
+                    logger.warning(
+                        f"[Reconciliation] {network_label}: Deauthorize failed for node {node_id}: {exc}"
+                    )
+            else:
+                logger.debug(
+                    f"[Reconciliation] {network_label}: node {node_id} — "
+                    f"portal={membership.state}, ZT=unauthorized. OK."
+                )
 
-    # Unknown ZT members not in our portal
-    actions["unknown_members"] = list(zt_members.keys())
+    # Unknown ZT members not in our portal — log only, do not touch
+    unknown = list(zt_members.keys())
+    actions["unknown_members"] = unknown
+    if unknown:
+        logger.warning(
+            f"[Reconciliation] {network_label}: {len(unknown)} ZT member(s) not in portal — "
+            f"node IDs: {', '.join(unknown)}"
+        )
 
+    elapsed_ms = int((time.monotonic() - t_start) * 1000)
     logger.info(
-        f"[Reconciliation] Network {zerotier_network_id}: "
+        f"[Reconciliation] Network {network_label}: "
         f"checked={actions['zt_members_checked']} "
         f"authorized={actions['authorized']} "
         f"deauthorized={actions['deauthorized']} "
-        f"unknown={len(actions['unknown_members'])}"
+        f"unknown={len(actions['unknown_members'])} "
+        f"elapsed={elapsed_ms}ms"
     )
 
     return actions
@@ -144,16 +212,34 @@ def reconcile_all() -> dict:
         PortalNetwork.deleted_at.is_(None),
     ).all()
 
-    results = {"networks_processed": 0, "errors": 0}
+    logger.info(f"[Reconciliation] reconcile_all: {len(networks)} active network(s) to process.")
+
+    results = {"networks_processed": 0, "errors": 0, "authorized": 0, "deauthorized": 0, "unknown_members": []}
     for network in networks:
         try:
             result = reconcile_network(network.id)
             if "error" in result:
+                logger.error(
+                    f"[Reconciliation] Network {network.name} ({network.zerotier_network_id}) "
+                    f"failed: {result['error']}"
+                )
                 results["errors"] += 1
+            elif result.get("skipped"):
+                logger.debug(
+                    f"[Reconciliation] Network {network.name} ({network.zerotier_network_id}) "
+                    f"skipped: {result.get('reason')}"
+                )
             else:
                 results["networks_processed"] += 1
+                results["authorized"] += result.get("authorized", 0)
+                results["deauthorized"] += result.get("deauthorized", 0)
+                results["unknown_members"].extend(result.get("unknown_members", []))
         except Exception as exc:
-            logger.error(f"[Reconciliation] Failed to reconcile network {network.id}: {exc}")
+            logger.error(
+                f"[Reconciliation] Unhandled error reconciling network "
+                f"{network.name} ({network.id}): {exc}",
+                exc_info=True,
+            )
             results["errors"] += 1
 
     deleted_result = reconcile_deleted_memberships()
@@ -161,8 +247,11 @@ def reconcile_all() -> dict:
     results["delete_errors"] = deleted_result.get("errors", 0)
 
     logger.info(
-        f"[Reconciliation] Complete: {results['networks_processed']} networks processed, "
-        f"{results['errors']} errors, {results.get('deleted_memberships', 0)} memberships purged."
+        f"[Reconciliation] Complete: "
+        f"networks={results['networks_processed']} "
+        f"errors={results['errors']} "
+        f"purged={results.get('deleted_memberships', 0)} "
+        f"purge_errors={results.get('delete_errors', 0)}"
     )
 
     return results
@@ -180,8 +269,11 @@ def reconcile_deleted_memberships() -> dict:
     ).all()
 
     if not deleted:
+        logger.debug("[Reconciliation] No soft-deleted memberships to purge.")
         return {"deleted": 0, "errors": 0}
 
+    logger.info(f"[Reconciliation] Purging {len(deleted)} soft-deleted membership(s) from ZT and DB.")
+
     results = {"deleted": 0, "errors": 0}
     for membership in deleted:
         try:
@@ -189,30 +281,49 @@ def reconcile_deleted_memberships() -> dict:
             network = PortalNetwork.query.get(membership.portal_network_id)
 
             if not device or not network:
+                logger.warning(
+                    f"[Reconciliation] Membership {membership.id}: missing "
+                    f"{'device' if not device else 'network'} — hard-deleting record only."
+                )
                 db.session.delete(membership)
                 db.session.commit()
                 results["deleted"] += 1
                 continue
 
+            node_id = device.node_id
+            zt_network_id = network.zerotier_network_id
+            network_label = f"{network.name} ({zt_network_id})"
+
             try:
-                zt.delete_network_member(network.zerotier_network_id, device.node_id)
-                logger.info(f"[Reconciliation] Deleted {device.node_id} from ZT network {network.zerotier_network_id}")
+                zt.delete_network_member(zt_network_id, node_id,
+                                         organization_id=network.organization_id)
+                logger.info(
+                    f"[Reconciliation] Removed node {node_id} (device={device.display_name!r}) "
+                    f"from ZT network {network_label}."
+                )
             except Exception as zt_exc:
                 logger.warning(
-                    f"[Reconciliation] ZT delete failed for {device.node_id} "
-                    f"on {network.zerotier_network_id}: {zt_exc}"
+                    f"[Reconciliation] ZT delete failed for node {node_id} "
+                    f"on {network_label}: {zt_exc} — proceeding with DB hard-delete."
                 )
 
             db.session.delete(membership)
             db.session.commit()
             results["deleted"] += 1
+            logger.debug(
+                f"[Reconciliation] Hard-deleted membership {membership.id} "
+                f"(node={node_id}, network={network_label})."
+            )
 
         except Exception as exc:
-            logger.error(f"[Reconciliation] Failed to hard-delete membership {membership.id}: {exc}")
+            logger.error(
+                f"[Reconciliation] Failed to hard-delete membership {membership.id}: {exc}",
+                exc_info=True,
+            )
             results["errors"] += 1
 
     if results["deleted"] > 0:
-        logger.info(f"[Reconciliation] Purged {results['deleted']} memberships.")
+        logger.info(f"[Reconciliation] Purged {results['deleted']} membership(s).")
 
     return results
 
@@ -228,7 +339,12 @@ def _sync_zt_membership(membership: DeviceNetworkMembership, zt_member) -> None:
         ZeroTierMembership.deleted_at.is_(None),
     ).first()
 
-    if not zt_membership:
+    is_new = zt_membership is None
+    if is_new:
+        logger.debug(
+            f"[Reconciliation] Creating new ZeroTierMembership cache record for "
+            f"node {device.node_id} on network {network.zerotier_network_id}."
+        )
         zt_membership = ZeroTierMembership(
             organization_id=membership.organization_id,
             device_network_membership_id=membership.id,
@@ -236,6 +352,8 @@ def _sync_zt_membership(membership: DeviceNetworkMembership, zt_member) -> None:
             node_id=device.node_id,
         )
 
+    prev_authorized = zt_membership.authorized if not is_new else None
+
     zt_membership.member_seen = True
     zt_membership.authorized = zt_member.is_authorized
     zt_membership.last_synced_at = datetime.now(timezone.utc)
@@ -248,11 +366,27 @@ def _sync_zt_membership(membership: DeviceNetworkMembership, zt_member) -> None:
 
     zt_membership.save()
 
+    if not is_new and prev_authorized != zt_member.is_authorized:
+        logger.info(
+            f"[Reconciliation] ZT auth state changed for node {device.node_id} "
+            f"(device={device.display_name!r}): {prev_authorized} → {zt_member.is_authorized}"
+        )
+
     # Update membership join_seen flag
     if not membership.join_seen:
+        logger.info(
+            f"[Reconciliation] First join seen for node {device.node_id} "
+            f"(device={device.display_name!r}, membership={membership.id}). "
+            f"State: {membership.state} → {MembershipState.JOINED_DEAUTHORIZED}"
+        )
         membership.join_seen = True
         membership.state = MembershipState.JOINED_DEAUTHORIZED
         membership.save()
+    else:
+        logger.debug(
+            f"[Reconciliation] Synced ZT membership for node {device.node_id} "
+            f"(device={device.display_name!r}, authorized={zt_member.is_authorized})."
+        )
 
 
 def _expire_session(session: ActivationSession) -> None:
@@ -261,8 +395,19 @@ def _expire_session(session: ActivationSession) -> None:
     session.end_reason = ActivationEndReason.EXPIRED
     session.save()
 
+    logger.info(
+        f"[Reconciliation] Expiring activation session {session.id} "
+        f"(user={session.user_id}, membership={session.device_network_membership_id}, "
+        f"expired_at={session.expires_at.isoformat()})."
+    )
+
     membership = DeviceNetworkMembership.query.get(session.device_network_membership_id)
-    if membership:
+    if not membership:
+        logger.warning(
+            f"[Reconciliation] Session {session.id}: membership "
+            f"{session.device_network_membership_id} not found — skipping ZT deauth."
+        )
+    else:
         membership.state = MembershipState.ACTIVATION_EXPIRED
         membership.currently_authorized = False
         membership.save()
@@ -270,8 +415,14 @@ def _expire_session(session: ActivationSession) -> None:
         device = Device.query.get(membership.device_id)
         network = PortalNetwork.query.get(membership.portal_network_id)
         if device and network:
+            network_label = f"{network.name} ({network.zerotier_network_id})"
             try:
-                zt.deauthorize_member(network.zerotier_network_id, device.node_id)
+                zt.deauthorize_member(network.zerotier_network_id, device.node_id,
+                                      organization_id=network.organization_id)
+                logger.info(
+                    f"[Reconciliation] Deauthorized expired node {device.node_id} "
+                    f"(device={device.display_name!r}) on {network_label}."
+                )
 
                 # Update ZT membership cache
                 zt_membership = ZeroTierMembership.query.filter(
@@ -283,12 +434,24 @@ def _expire_session(session: ActivationSession) -> None:
                     zt_membership.authorized = False
                     zt_membership.last_synced_at = datetime.now(timezone.utc)
                     zt_membership.save()
+                else:
+                    logger.debug(
+                        f"[Reconciliation] No ZeroTierMembership cache record found for "
+                        f"node {device.node_id} on {network_label} — nothing to update."
+                    )
 
             except Exception as exc:
                 logger.warning(
-                    f"[_expire_session] Failed to deauthorize {device.node_id} "
-                    f"on {network.zerotier_network_id}: {exc}"
+                    f"[_expire_session] Failed to deauthorize node {device.node_id} "
+                    f"on {network_label}: {exc}",
+                    exc_info=True,
                 )
+        else:
+            logger.warning(
+                f"[Reconciliation] Session {session.id}: missing "
+                f"{'device' if not device else 'network'} for membership "
+                f"{membership.id} — ZT deauth skipped."
+            )
 
     from gatehouse_app.services.audit_service import AuditService
     AuditService.log_action(