From 07a9cfeb65d59cdfb4f5e0dcbab8de0a9086aa31 Mon Sep 17 00:00:00 2001 From: Nicole Rappe Date: Sat, 18 Oct 2025 01:15:54 -0600 Subject: [PATCH] Expand enrollment logging and relax rate limits --- Data/Agent/agent.py | 96 +++++++++++++++++++++++- Data/Server/Modules/enrollment/routes.py | 75 +++++++++++++++++- 2 files changed, 166 insertions(+), 5 deletions(-) diff --git a/Data/Agent/agent.py b/Data/Agent/agent.py index 5cdeb85..4928f8c 100644 --- a/Data/Agent/agent.py +++ b/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() diff --git a/Data/Server/Modules/enrollment/routes.py b/Data/Server/Modules/enrollment/routes.py index 3d3570e..c408bcd 100644 --- a/Data/Server/Modules/enrollment/routes.py +++ b/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 ''} 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 "" + trimmed = str(code).strip() + if len(trimmed) <= 6: + return "***" + return f"{trimmed[:3]}***{trimmed[-3:]}"