gatehouse-api/gatehouse_app/services/zerotier_reconciliation_service.py

"""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
from gatehouse_app.models import (
    Device,
    NetworkAccessRequest,
    ActivationSession,
    ZeroTierMembership,
    PortalNetwork,
)
from gatehouse_app.services import zerotier_api_service as zt
from gatehouse_app.utils.constants import (
    ActivationEndReason,
    ApprovalState,
)

logger = logging.getLogger(__name__)


def reconcile_expired_activations() -> int:
    """Find expired activation sessions and deactivate their memberships.

    Returns the number of sessions expired.
    """
    now = datetime.now(timezone.utc)
    expired = ActivationSession.query.filter(
        ActivationSession.expires_at < now,
        ActivationSession.ended_at.is_(None),
        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} "
                f"(user={session.user_id} request={session.network_access_request_id}): {exc}",
                exc_info=True,
            )

    if count > 0:
        logger.info(f"[Reconciliation] Expired {count} activation session(s).")
    else:
        logger.debug("[Reconciliation] No activation sessions to expire.")

    return count


def reconcile_network(portal_network_id: str) -> dict:
    """Full reconciliation for one portal network.

    Returns a dict with counts of actions taken.
    """
    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,
        "authorized": 0,
        "deauthorized": 0,
        "join_seen_updated": 0,
        "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,
                                                              organization_id=network.organization_id)}
    except Exception as 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 = {
        m.device.node_id: m
        for m in NetworkAccessRequest.query.filter(
            NetworkAccessRequest.portal_network_id == portal_network_id,
            NetworkAccessRequest.deleted_at.is_(None),
        ).all()
        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 — could be freshly joined or never connected
            logger.debug(
                f"[Reconciliation] {network_label}: node {node_id} "
                f"(device={device.display_name!r}, active={membership.active}) not yet seen in ZT controller."
            )
            continue

        actions["join_seen_updated"] += 1

        # Update observed ZT membership
        _sync_zt_membership(membership, zt_member)

        # Sync authorization state
        if membership.active:
            if not zt_member.is_authorized:
                # Portal says active but ZT disagrees — drift, re-authorize
                logger.warning(
                    f"[Reconciliation] {network_label}: DRIFT detected — portal=active "
                    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,
                                        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] {network_label}: Re-authorize failed for node {node_id}: {exc}"
                    )
            else:
                logger.debug(
                    f"[Reconciliation] {network_label}: node {node_id} — portal=active, ZT=authorized. OK."
                )
        else:
            if zt_member.is_authorized:
                # ZT says authorized but portal doesn't — could be manual override in ZT console
                logger.warning(
                    f"[Reconciliation] {network_label}: DRIFT detected — portal=inactive "
                    f"but ZT says authorized for node {node_id} (device={device.display_name!r}). Deauthorizing."
                )
                try:
                    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] {network_label}: Deauthorize failed for node {node_id}: {exc}"
                    )
            else:
                logger.debug(
                    f"[Reconciliation] {network_label}: node {node_id} — "
                    f"portal=inactive, ZT=unauthorized. OK."
                )

    # 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 {network_label}: "
        f"checked={actions['zt_members_checked']} "
        f"authorized={actions['authorized']} "
        f"deauthorized={actions['deauthorized']} "
        f"unknown={len(actions['unknown_members'])} "
        f"elapsed={elapsed_ms}ms"
    )

    return actions


def reconcile_all() -> dict:
    """Run reconciliation on all active portal networks.

    Returns a summary dict.
    """
    networks = PortalNetwork.query.filter(
        PortalNetwork.is_active.is_(True),
        PortalNetwork.deleted_at.is_(None),
    ).all()

    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] Unhandled error reconciling network "
                f"{network.name} ({network.id}): {exc}",
                exc_info=True,
            )
            results["errors"] += 1

    deleted_result = reconcile_deleted_memberships()
    results["deleted_memberships"] = deleted_result.get("deleted", 0)
    results["delete_errors"] = deleted_result.get("errors", 0)

    logger.info(
        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


def reconcile_deleted_memberships() -> dict:
    """Find soft-deleted memberships and hard-delete them after ZeroTier cleanup.

    Only processes memberships whose ZeroTier members are already de-authorized
    (the de-authorize step happened in revoke_request_soft). This function
    removes the member from ZeroTier entirely and then hard-deletes the DB record.
    """
    deleted = NetworkAccessRequest.query.filter(
        NetworkAccessRequest.deleted_at.isnot(None),
    ).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:
            device = Device.query.get(membership.device_id)
            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'} — soft-deleting record only."
                )
                membership.delete(soft=True)
                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(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 node {node_id} "
                    f"on {network_label}: {zt_exc} — proceeding with DB soft-delete."
                )

            membership.delete(soft=True)
            db.session.commit()
            results["deleted"] += 1
            logger.debug(
                f"[Reconciliation] Soft-deleted membership {membership.id} "
                f"(node={node_id}, network={network_label})."
            )

        except Exception as exc:
            logger.error(
                f"[Reconciliation] Failed to soft-delete membership {membership.id}: {exc}",
                exc_info=True,
            )
            results["errors"] += 1

    if results["deleted"] > 0:
        logger.info(f"[Reconciliation] Purged {results['deleted']} membership(s).")

    return results


def _sync_zt_membership(membership: NetworkAccessRequest, zt_member) -> None:
    """Update the ZeroTierMembership cache record from a ZT API response."""
    device = membership.device
    network = membership.portal_network

    zt_membership = ZeroTierMembership.query.filter(
        ZeroTierMembership.zerotier_network_id == network.zerotier_network_id,
        ZeroTierMembership.node_id == device.node_id,
        ZeroTierMembership.deleted_at.is_(None),
    ).first()

    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,
            network_access_request_id=membership.id,
            zerotier_network_id=network.zerotier_network_id,
            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)
    zt_membership.raw_controller_payload = zt_member.raw

    if zt_member.last_seen and zt_member.last_seen > 0:
        zt_membership.join_seen_at = datetime.fromtimestamp(
            zt_member.last_seen / 1000, tz=timezone.utc
        )

    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"Setting join_seen=True, active=False"
        )
        membership.join_seen = True
        membership.active = False
        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:
    """Expire an activation session and deauthorize the membership in ZT."""
    session.ended_at = datetime.now(timezone.utc)
    session.end_reason = ActivationEndReason.EXPIRED
    session.save()

    logger.info(
        f"[Reconciliation] Expiring activation session {session.id} "
        f"(user={session.user_id}, request={session.network_access_request_id}, "
        f"expired_at={session.expires_at.isoformat()})."
    )

    request = NetworkAccessRequest.query.get(session.network_access_request_id)
    if not request:
        logger.warning(
            f"[Reconciliation] Session {session.id}: request "
            f"{session.network_access_request_id} not found — skipping ZT deauth."
        )
    else:
        request.active = False
        request.save()

        device = Device.query.get(request.device_id)
        network = PortalNetwork.query.get(request.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,
                                      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(
                    ZeroTierMembership.zerotier_network_id == network.zerotier_network_id,
                    ZeroTierMembership.node_id == device.node_id,
                    ZeroTierMembership.deleted_at.is_(None),
                ).first()
                if zt_membership:
                    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 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 request "
                f"{request.id} — ZT deauth skipped."
            )

    from gatehouse_app.services.audit_service import AuditService
    AuditService.log_action(
        action="zt.activation.expired",
        user_id=session.user_id,
        organization_id=session.organization_id,
        resource_type="activation_session",
        resource_id=session.id,
        metadata={"request_id": session.network_access_request_id},
        description="Activation session expired",
        success=True,
    )