Expand enrollment logging and relax rate limits

Data/Agent/agent.py

@@ -243,6 +243,18 @@ def _log_agent(message: str, fname: str = 'agent.log'):
         pass
 
 
+def _mask_sensitive(value: str, *, prefix: int = 4, suffix: int = 4) -> str:
+    try:
+        if not value:
+            return ''
+        trimmed = value.strip()
+        if len(trimmed) <= prefix + suffix:
+            return '*' * len(trimmed)
+        return f"{trimmed[:prefix]}***{trimmed[-suffix:]}"
+    except Exception:
+        return '***'
+
+
 def _decode_base64_text(value):
     if not isinstance(value, str):
         return None
@@ -603,6 +615,14 @@ class AgentHttpClient:
                 "Set BOREALIS_INSTALLER_CODE, pass --installer-code, or update agent_settings.json."
             )
         self.refresh_base_url()
+        base_url = self.base_url or "https://localhost:5000"
+        code_masked = _mask_sensitive(code)
+        _log_agent(
+            "Enrollment handshake starting "
+            f"base_url={base_url} scope={SERVICE_MODE} "
+            f"fingerprint={SSL_KEY_FINGERPRINT[:16]} installer_code={code_masked}",
+            fname="agent.log",
+        )
         client_nonce = os.urandom(32)
         payload = {
             "hostname": socket.gethostname(),
@@ -611,10 +631,34 @@ class AgentHttpClient:
             "client_nonce": base64.b64encode(client_nonce).decode("ascii"),
         }
         request_url = f"{self.base_url}/api/agent/enroll/request"
-        _log_agent("Starting enrollment request...", fname="agent.log")
+        _log_agent(
+            "Starting enrollment request... "
+            f"url={request_url} hostname={payload['hostname']} pubkey_prefix={PUBLIC_KEY_B64[:24]}",
+            fname="agent.log",
+        )
         resp = self.session.post(request_url, json=payload, timeout=30)
-        resp.raise_for_status()
+        _log_agent(
+            f"Enrollment request HTTP status={resp.status_code} retry_after={resp.headers.get('Retry-After')}"
+            f" body_len={len(resp.content)}",
+            fname="agent.log",
+        )
+        try:
+            resp.raise_for_status()
+        except requests.HTTPError:
+            snippet = resp.text[:512] if hasattr(resp, "text") else ""
+            _log_agent(
+                f"Enrollment request failed status={resp.status_code} body_snippet={snippet}",
+                fname="agent.error.log",
+            )
+            raise
         data = resp.json()
+        _log_agent(
+            "Enrollment request accepted "
+            f"status={data.get('status')} approval_ref={data.get('approval_reference')} "
+            f"poll_after_ms={data.get('poll_after_ms')}"
+            f" server_cert={'yes' if data.get('server_certificate') else 'no'}",
+            fname="agent.log",
+        )
         if data.get("server_certificate"):
             self.key_store.save_server_certificate(data["server_certificate"])
             self._configure_verify()
@@ -632,6 +676,7 @@ class AgentHttpClient:
             raise RuntimeError("Enrollment response missing approval_reference or server_nonce")
         server_nonce = base64.b64decode(server_nonce_b64)
         poll_delay = max(int(data.get("poll_after_ms", 3000)) / 1000, 1)
+        attempt = 1
         while True:
             time.sleep(min(poll_delay, 15))
             signature = self.identity.sign(server_nonce + approval_reference.encode("utf-8") + client_nonce)
@@ -640,22 +685,61 @@ class AgentHttpClient:
                 "client_nonce": base64.b64encode(client_nonce).decode("ascii"),
                 "proof_sig": base64.b64encode(signature).decode("ascii"),
             }
+            _log_agent(
+                f"Enrollment poll attempt={attempt} ref={approval_reference} delay={poll_delay}s",
+                fname="agent.log",
+            )
             poll_resp = self.session.post(
                 f"{self.base_url}/api/agent/enroll/poll",
                 json=poll_payload,
                 timeout=30,
             )
-            poll_resp.raise_for_status()
+            _log_agent(
+                "Enrollment poll response "
+                f"status_code={poll_resp.status_code} retry_after={poll_resp.headers.get('Retry-After')}"
+                f" body_len={len(poll_resp.content)}",
+                fname="agent.log",
+            )
+            try:
+                poll_resp.raise_for_status()
+            except requests.HTTPError:
+                snippet = poll_resp.text[:512] if hasattr(poll_resp, "text") else ""
+                _log_agent(
+                    f"Enrollment poll failed attempt={attempt} status={poll_resp.status_code} "
+                    f"body_snippet={snippet}",
+                    fname="agent.error.log",
+                )
+                raise
             poll_data = poll_resp.json()
+            _log_agent(
+                f"Enrollment poll decoded attempt={attempt} status={poll_data.get('status')}"
+                f" next_delay={poll_data.get('poll_after_ms')}"
+                f" guid_hint={poll_data.get('guid')}",
+                fname="agent.log",
+            )
             status = poll_data.get("status")
             if status == "pending":
                 poll_delay = max(int(poll_data.get("poll_after_ms", 5000)) / 1000, 1)
+                _log_agent(
+                    f"Enrollment still pending attempt={attempt} new_delay={poll_delay}s",
+                    fname="agent.log",
+                )
+                attempt += 1
                 continue
             if status == "denied":
+                _log_agent("Enrollment denied by operator", fname="agent.error.log")
                 raise RuntimeError("Enrollment denied by operator")
             if status in ("expired", "unknown"):
+                _log_agent(
+                    f"Enrollment failed status={status} attempt={attempt}",
+                    fname="agent.error.log",
+                )
                 raise RuntimeError(f"Enrollment failed with status={status}")
             if status in ("approved", "completed"):
+                _log_agent(
+                    f"Enrollment approved attempt={attempt} ref={approval_reference}",
+                    fname="agent.log",
+                )
                 self._finalize_enrollment(poll_data)
                 break
             raise RuntimeError(f"Unexpected enrollment poll response: {poll_data}")
@@ -677,6 +761,12 @@ class AgentHttpClient:
         expires_in = int(payload.get("expires_in") or 900)
         if not (guid and access_token and refresh_token):
             raise RuntimeError("Enrollment approval response missing tokens or guid")
+        _log_agent(
+            "Enrollment approval payload received "
+            f"guid={guid} access_token_len={len(access_token)} refresh_token_len={len(refresh_token)} "
+            f"expires_in={expires_in}",
+            fname="agent.log",
+        )
         self.guid = str(guid).strip()
         self.access_token = access_token.strip()
         self.refresh_token = refresh_token.strip()

Data/Server/Modules/enrollment/routes.py

@@ -54,6 +54,10 @@ def register(
     def _rate_limited(key: str, limiter: SlidingWindowRateLimiter, limit: int, window_s: float):
         decision = limiter.check(key, limit, window_s)
         if not decision.allowed:
+            log(
+                "server",
+                f"enrollment rate limited key={key} limit={limit}/{window_s}s retry_after={decision.retry_after:.2f}",
+            )
             response = jsonify({"error": "rate_limited", "retry_after": decision.retry_after})
             response.status_code = 429
             response.headers["Retry-After"] = f"{int(decision.retry_after) or 1}"
@@ -243,7 +247,7 @@ def register(
     @blueprint.route("/api/agent/enroll/request", methods=["POST"])
     def enrollment_request():
         remote = _remote_addr()
-        rate_error = _rate_limited(f"ip:{remote}", ip_rate_limiter, 10, 60.0)
+        rate_error = _rate_limited(f"ip:{remote}", ip_rate_limiter, 40, 60.0)
         if rate_error:
             return rate_error
 
@@ -253,32 +257,47 @@ def register(
         agent_pubkey_b64 = payload.get("agent_pubkey")
         client_nonce_b64 = payload.get("client_nonce")
 
+        log(
+            "server",
+            "enrollment request received "
+            f"ip={remote} hostname={hostname or '<missing>'} code_mask={_mask_code(enrollment_code)} "
+            f"pubkey_len={len(agent_pubkey_b64 or '')} nonce_len={len(client_nonce_b64 or '')}",
+        )
+
         if not hostname:
+            log("server", f"enrollment rejected missing_hostname ip={remote}")
             return jsonify({"error": "hostname_required"}), 400
         if not enrollment_code:
+            log("server", f"enrollment rejected missing_code ip={remote} host={hostname}")
             return jsonify({"error": "enrollment_code_required"}), 400
         if not isinstance(agent_pubkey_b64, str):
+            log("server", f"enrollment rejected missing_pubkey ip={remote} host={hostname}")
             return jsonify({"error": "agent_pubkey_required"}), 400
         if not isinstance(client_nonce_b64, str):
+            log("server", f"enrollment rejected missing_nonce ip={remote} host={hostname}")
             return jsonify({"error": "client_nonce_required"}), 400
 
         try:
             agent_pubkey_der = crypto_keys.spki_der_from_base64(agent_pubkey_b64)
         except Exception:
+            log("server", f"enrollment rejected invalid_pubkey ip={remote} host={hostname}")
             return jsonify({"error": "invalid_agent_pubkey"}), 400
 
         if len(agent_pubkey_der) < 10:
+            log("server", f"enrollment rejected short_pubkey ip={remote} host={hostname}")
             return jsonify({"error": "invalid_agent_pubkey"}), 400
 
         try:
             client_nonce_bytes = base64.b64decode(client_nonce_b64, validate=True)
         except Exception:
+            log("server", f"enrollment rejected invalid_nonce ip={remote} host={hostname}")
             return jsonify({"error": "invalid_client_nonce"}), 400
         if len(client_nonce_bytes) < 16:
+            log("server", f"enrollment rejected short_nonce ip={remote} host={hostname}")
             return jsonify({"error": "invalid_client_nonce"}), 400
 
         fingerprint = crypto_keys.fingerprint_from_spki_der(agent_pubkey_der)
-        rate_error = _rate_limited(f"fp:{fingerprint}", fp_rate_limiter, 3, 60.0)
+        rate_error = _rate_limited(f"fp:{fingerprint}", fp_rate_limiter, 12, 60.0)
         if rate_error:
             return rate_error
 
@@ -378,21 +397,33 @@ def register(
         client_nonce_b64 = payload.get("client_nonce")
         proof_sig_b64 = payload.get("proof_sig")
 
+        log(
+            "server",
+            "enrollment poll received "
+            f"ref={approval_reference} client_nonce_len={len(client_nonce_b64 or '')}"
+            f" proof_sig_len={len(proof_sig_b64 or '')}",
+        )
+
         if not isinstance(approval_reference, str) or not approval_reference:
+            log("server", "enrollment poll rejected missing_reference")
             return jsonify({"error": "approval_reference_required"}), 400
         if not isinstance(client_nonce_b64, str):
+            log("server", f"enrollment poll rejected missing_nonce ref={approval_reference}")
             return jsonify({"error": "client_nonce_required"}), 400
         if not isinstance(proof_sig_b64, str):
+            log("server", f"enrollment poll rejected missing_sig ref={approval_reference}")
             return jsonify({"error": "proof_sig_required"}), 400
 
         try:
             client_nonce_bytes = base64.b64decode(client_nonce_b64, validate=True)
         except Exception:
+            log("server", f"enrollment poll invalid_client_nonce ref={approval_reference}")
             return jsonify({"error": "invalid_client_nonce"}), 400
 
         try:
             proof_sig = base64.b64decode(proof_sig_b64, validate=True)
         except Exception:
+            log("server", f"enrollment poll invalid_sig ref={approval_reference}")
             return jsonify({"error": "invalid_proof_sig"}), 400
 
         conn = db_conn_factory()
@@ -410,6 +441,7 @@ def register(
             )
             row = cur.fetchone()
             if not row:
+                log("server", f"enrollment poll unknown_reference ref={approval_reference}")
                 return jsonify({"status": "unknown"}), 404
 
             (
@@ -428,11 +460,13 @@ def register(
             ) = row
 
             if client_nonce_stored != client_nonce_b64:
+                log("server", f"enrollment poll nonce_mismatch ref={approval_reference}")
                 return jsonify({"error": "nonce_mismatch"}), 400
 
             try:
                 server_nonce_bytes = base64.b64decode(server_nonce_b64, validate=True)
             except Exception:
+                log("server", f"enrollment poll invalid_server_nonce ref={approval_reference}")
                 return jsonify({"error": "server_nonce_invalid"}), 400
 
             message = server_nonce_bytes + approval_reference.encode("utf-8") + client_nonce_bytes
@@ -440,30 +474,58 @@ def register(
             try:
                 public_key = serialization.load_der_public_key(agent_pubkey_der)
             except Exception:
+                log("server", f"enrollment poll pubkey_load_failed ref={approval_reference}")
                 public_key = None
 
             if public_key is None:
+                log("server", f"enrollment poll invalid_pubkey ref={approval_reference}")
                 return jsonify({"error": "agent_pubkey_invalid"}), 400
 
             try:
                 public_key.verify(proof_sig, message)
             except Exception:
+                log("server", f"enrollment poll invalid_proof ref={approval_reference}")
                 return jsonify({"error": "invalid_proof"}), 400
 
             if status == "pending":
+                log(
+                    "server",
+                    f"enrollment poll pending ref={approval_reference} host={hostname_claimed}"
+                    f" fingerprint={fingerprint[:12]}",
+                )
                 return jsonify({"status": "pending", "poll_after_ms": 5000})
             if status == "denied":
+                log(
+                    "server",
+                    f"enrollment poll denied ref={approval_reference} host={hostname_claimed}",
+                )
                 return jsonify({"status": "denied", "reason": "operator_denied"})
             if status == "expired":
+                log(
+                    "server",
+                    f"enrollment poll expired ref={approval_reference} host={hostname_claimed}",
+                )
                 return jsonify({"status": "expired"})
             if status == "completed":
+                log(
+                    "server",
+                    f"enrollment poll already_completed ref={approval_reference} host={hostname_claimed}",
+                )
                 return jsonify({"status": "approved", "detail": "finalized"})
 
             if status != "approved":
+                log(
+                    "server",
+                    f"enrollment poll unexpected_status={status} ref={approval_reference}",
+                )
                 return jsonify({"status": status or "unknown"}), 400
 
             nonce_key = f"{approval_reference}:{base64.b64encode(proof_sig).decode('ascii')}"
             if not nonce_cache.consume(nonce_key):
+                log(
+                    "server",
+                    f"enrollment poll replay_detected ref={approval_reference} fingerprint={fingerprint[:12]}",
+                )
                 return jsonify({"error": "proof_replayed"}), 409
 
             # Finalize enrollment
@@ -534,3 +596,12 @@ def _load_tls_bundle(path: str) -> str:
             return fh.read()
     except Exception:
         return ""
+
+
+def _mask_code(code: str) -> str:
+    if not code:
+        return "<missing>"
+    trimmed = str(code).strip()
+    if len(trimmed) <= 6:
+        return "***"
+    return f"{trimmed[:3]}***{trimmed[-3:]}"