From 971f29b0590e381d5ac23ae7cb62ace39bd5192d Mon Sep 17 00:00:00 2001 From: JOJO <1498581755@qq.com> Date: Tue, 5 May 2026 13:54:51 +0800 Subject: [PATCH] chore(debug): add connection heartbeat diagnostics --- server/status.py | 51 ++++++++++- server/utils_common.py | 8 ++ static/src/app/methods/ui.ts | 159 ++++++++++++++++++++++++++++++++++- static/src/app/state.ts | 5 ++ 4 files changed, 219 insertions(+), 4 deletions(-) diff --git a/server/status.py b/server/status.py index 05a213a..644efbe 100644 --- a/server/status.py +++ b/server/status.py @@ -1,6 +1,7 @@ from __future__ import annotations import time import re +import os from pathlib import Path from flask import Blueprint, jsonify, request, send_file, session @@ -20,9 +21,12 @@ from modules.host_workspace_manager import ( resolve_host_workspace, ) from utils.host_workspace_debug import write_host_workspace_debug +from .utils_common import log_conn_diag from . import state status_bp = Blueprint('status', __name__) +STATUS_DIAG_VERBOSE = os.environ.get("STATUS_DIAG_VERBOSE", "0") not in {"0", "false", "False"} +STATUS_DIAG_SLOW_MS = int(os.environ.get("STATUS_DIAG_SLOW_MS", "1200") or 1200) def _parse_android_version_from_gradle(project_root: Path) -> tuple[int, str]: @@ -70,9 +74,33 @@ def _is_host_mode_request() -> bool: @with_terminal def get_status(terminal, workspace, username): """获取系统状态（包含对话、容器、版本等信息）""" - status = terminal.get_status() + started_at = time.perf_counter() + heartbeat_id = request.headers.get("X-Connection-Heartbeat", "").strip() + diag_requested = STATUS_DIAG_VERBOSE or request.args.get("diag") == "1" + timings = { + "terminal_ms": 0.0, + "terminals_ms": 0.0, + "conversation_meta_ms": 0.0, + "container_ms": 0.0, + "policy_ms": 0.0, + } + phase_started_at = time.perf_counter() + try: + status = terminal.get_status() + except Exception as exc: + timings["terminal_ms"] = (time.perf_counter() - phase_started_at) * 1000 + total_ms = (time.perf_counter() - started_at) * 1000 + log_conn_diag( + f"status hb={heartbeat_id or '-'} user={username} phase=terminal.get_status " + f"total_ms={total_ms:.1f} terminal_ms={timings['terminal_ms']:.1f} error={exc}" + ) + raise + timings["terminal_ms"] = (time.perf_counter() - phase_started_at) * 1000 + phase_started_at = time.perf_counter() if terminal.terminal_manager: status['terminals'] = terminal.terminal_manager.list_terminals() + timings["terminals_ms"] = (time.perf_counter() - phase_started_at) * 1000 + phase_started_at = time.perf_counter() try: current_conv = terminal.context_manager.current_conversation_id status.setdefault('conversation', {})['current_id'] = current_conv @@ -92,13 +120,18 @@ def get_status(terminal, workspace, username): "job_id": meta.get("compression_job_id"), } except Exception as exc: - print(f"[Status] 获取当前对话信息失败: {exc}") + log_conn_diag(f"status conversation-meta-failed user={username} error={exc}") + timings["conversation_meta_ms"] = (time.perf_counter() - phase_started_at) * 1000 status['project_path'] = str(workspace.project_path) + phase_started_at = time.perf_counter() try: status['container'] = container_manager.get_container_status(username) except Exception as exc: status['container'] = {"success": False, "error": str(exc)} + log_conn_diag(f"status container-status-failed user={username} error={exc}") + timings["container_ms"] = (time.perf_counter() - phase_started_at) * 1000 status['version'] = AGENT_VERSION + phase_started_at = time.perf_counter() try: policy = resolve_admin_policy(user_manager.get_user(username)) status['admin_policy'] = { @@ -109,6 +142,20 @@ def get_status(terminal, workspace, username): } except Exception: pass + timings["policy_ms"] = (time.perf_counter() - phase_started_at) * 1000 + total_ms = (time.perf_counter() - started_at) * 1000 + is_slow = total_ms >= STATUS_DIAG_SLOW_MS + if diag_requested or is_slow: + conversation = status.get("conversation") or {} + log_conn_diag( + f"status hb={heartbeat_id or '-'} user={username} host_mode={bool(session.get('host_mode'))} " + f"workspace_id={session.get('workspace_id') or '-'} " + f"conversation_id={conversation.get('current_id') or '-'} " + f"total_ms={total_ms:.1f} slow={is_slow} " + f"terminal_ms={timings['terminal_ms']:.1f} terminals_ms={timings['terminals_ms']:.1f} " + f"conversation_meta_ms={timings['conversation_meta_ms']:.1f} " + f"container_ms={timings['container_ms']:.1f} policy_ms={timings['policy_ms']:.1f}" + ) return jsonify(status) diff --git a/server/utils_common.py b/server/utils_common.py index 0a6f141..bf66a4c 100644 --- a/server/utils_common.py +++ b/server/utils_common.py @@ -144,6 +144,7 @@ DEBUG_LOG_FILE = Path(LOGS_DIR).expanduser().resolve() / "debug_stream.log" CHUNK_BACKEND_LOG_FILE = Path(LOGS_DIR).expanduser().resolve() / "chunk_backend.log" CHUNK_FRONTEND_LOG_FILE = Path(LOGS_DIR).expanduser().resolve() / "chunk_frontend.log" STREAMING_DEBUG_LOG_FILE = Path(LOGS_DIR).expanduser().resolve() / "streaming_debug.log" +CONN_DIAG_LOG_FILE = Path(LOGS_DIR).expanduser().resolve() / "conn_diag.log" def _write_log(file_path: Path, message: str) -> None: @@ -158,6 +159,11 @@ def debug_log(message): _write_log(DEBUG_LOG_FILE, message) +def log_conn_diag(message: str): + """连接诊断日志：统一关键词并直接落盘到独立文件。""" + _write_log(CONN_DIAG_LOG_FILE, f"[CONN_DIAG] {message}") + + def log_backend_chunk(conversation_id: str, iteration: int, chunk_index: int, elapsed: float, char_len: int, content_preview: str): preview = content_preview.replace('\n', '\\n') _write_log( @@ -192,4 +198,6 @@ __all__ = [ "CHUNK_BACKEND_LOG_FILE", "CHUNK_FRONTEND_LOG_FILE", "STREAMING_DEBUG_LOG_FILE", + "CONN_DIAG_LOG_FILE", + "log_conn_diag", ] diff --git a/static/src/app/methods/ui.ts b/static/src/app/methods/ui.ts index 0fcb8ca..60908ce 100644 --- a/static/src/app/methods/ui.ts +++ b/static/src/app/methods/ui.ts @@ -60,6 +60,61 @@ function uiBounceTrace( console.log('[SCROLL_BOUNCE_TRACE_UI]', event, payload); } +function isConnectionDiagEnabled() { + if (typeof window === 'undefined') return true; + try { + const explicit = (window as any).__CONN_DIAG__; + if (explicit === false || explicit === '0') return false; + if (explicit === true || explicit === '1') return true; + const localFlag = window.localStorage?.getItem('connDiag'); + if (localFlag === '0' || localFlag === 'false') return false; + if (localFlag === '1' || localFlag === 'true') return true; + // 默认常开：无需手动启动 + return true; + } catch { + return true; + } +} + +function pushConnectionDiagRecord(record: Record) { + if (typeof window === 'undefined') return; + try { + const w = window as any; + if (!Array.isArray(w.__CONN_DIAG_LOGS__)) { + w.__CONN_DIAG_LOGS__ = []; + } + w.__CONN_DIAG_LOGS__.push(record); + const max = 400; + if (w.__CONN_DIAG_LOGS__.length > max) { + w.__CONN_DIAG_LOGS__.splice(0, w.__CONN_DIAG_LOGS__.length - max); + } + } catch { + // ignore + } +} + +function connectionDiag( + level: 'log' | 'warn' | 'error', + event: string, + payload: Record = {}, + options: { force?: boolean } = {} +) { + const force = !!options.force; + const enabled = isConnectionDiagEnabled(); + if (!enabled && !force) { + return; + } + const record = { + ts: new Date().toISOString(), + event, + ...payload + }; + pushConnectionDiagRecord(record); + const logger = + level === 'error' ? console.error : level === 'warn' ? console.warn : console.log; + logger('[CONN_DIAG]', event, record); +} + function parseSubAgentDoneLabel(rawContent: any): string | null { const content = (rawContent || '').toString().trim(); if (!content) { @@ -1970,23 +2025,105 @@ export const uiMethods = { }, async checkConnectionHealth() { + const seq = Number(this.connectionHeartbeatSeq || 0) + 1; + this.connectionHeartbeatSeq = seq; + const requestId = `${Date.now()}-${seq}`; + const startedAt = Date.now(); + const diagEnabled = isConnectionDiagEnabled(); + const statusUrl = diagEnabled ? '/api/status?diag=1' : '/api/status'; + const wasConnected = !!this.isConnected; + let responseStatus: number | null = null; const controller = typeof AbortController !== 'undefined' ? new AbortController() : null; const timeoutId = controller ? window.setTimeout(() => controller.abort(), 5000) : null; try { - const response = await fetch('/api/status', { + const response = await fetch(statusUrl, { method: 'GET', cache: 'no-store', + headers: { + 'X-Connection-Heartbeat': requestId + }, signal: controller?.signal }); + responseStatus = response.status; if (!response.ok) { throw new Error(`HTTP ${response.status}`); } + const failCountBeforeRecover = this.connectionHeartbeatFailCount || 0; this.isConnected = true; this.connectionHeartbeatFailCount = 0; + this.connectionHeartbeatLastLatencyMs = Date.now() - startedAt; + this.connectionHeartbeatLastStatusCode = responseStatus; + this.connectionHeartbeatLastError = ''; + if (!wasConnected) { + this.connectionHeartbeatLastChangeAt = Date.now(); + connectionDiag( + 'warn', + 'health-recovered', + { + requestId, + seq, + elapsedMs: this.connectionHeartbeatLastLatencyMs, + failCountBeforeRecover, + status: responseStatus, + diagEnabled, + conversationId: this.currentConversationId || null, + taskInProgress: !!this.taskInProgress, + streamingMessage: !!this.streamingMessage, + visibility: document?.visibilityState || 'unknown', + online: typeof navigator !== 'undefined' ? navigator.onLine : null + }, + { force: true } + ); + } else if ( + isConnectionDiagEnabled() && + (this.connectionHeartbeatLastLatencyMs >= 700 || seq <= 3 || seq % 60 === 0) + ) { + connectionDiag('log', 'health-ok', { + requestId, + seq, + elapsedMs: this.connectionHeartbeatLastLatencyMs, + status: responseStatus, + visibility: document?.visibilityState || 'unknown' + }); + } } catch (error) { - this.connectionHeartbeatFailCount = (this.connectionHeartbeatFailCount || 0) + 1; + const nextFailCount = (this.connectionHeartbeatFailCount || 0) + 1; + this.connectionHeartbeatFailCount = nextFailCount; + this.connectionHeartbeatLastLatencyMs = Date.now() - startedAt; + this.connectionHeartbeatLastStatusCode = responseStatus; + const errName = error?.name || 'Error'; + const errMessage = error?.message || String(error); + this.connectionHeartbeatLastError = `${errName}: ${errMessage}`; // 一次失败就先置灰，避免“服务已断但常亮绿色”的误导 this.isConnected = false; + if (wasConnected) { + this.connectionHeartbeatLastChangeAt = Date.now(); + } + const shouldLogFail = wasConnected || nextFailCount <= 3 || nextFailCount % 10 === 0; + connectionDiag( + shouldLogFail ? 'warn' : 'log', + 'health-failed', + { + requestId, + seq, + elapsedMs: this.connectionHeartbeatLastLatencyMs, + failCount: nextFailCount, + status: responseStatus, + diagEnabled, + wasConnected, + nowConnected: !!this.isConnected, + errorName: errName, + errorMessage: errMessage, + timeout: errName === 'AbortError', + visibility: document?.visibilityState || 'unknown', + online: typeof navigator !== 'undefined' ? navigator.onLine : null, + conversationId: this.currentConversationId || null, + taskInProgress: !!this.taskInProgress, + streamingMessage: !!this.streamingMessage, + hasPendingTools: typeof this.hasPendingToolActions === 'function' ? this.hasPendingToolActions() : null + }, + { force: shouldLogFail } + ); } finally { if (timeoutId) { clearTimeout(timeoutId); @@ -2000,6 +2137,15 @@ export const uiMethods = { } this.connectionHeartbeatActive = true; this.connectionHeartbeatFailCount = 0; + connectionDiag( + 'log', + 'heartbeat-start', + { + connectedIntervalMs: this.connectionHeartbeatIntervalMs, + disconnectedIntervalMs: this.connectionHeartbeatDisconnectedIntervalMs + }, + { force: true } + ); const runHeartbeat = async () => { if (!this.connectionHeartbeatActive) { return; @@ -2018,6 +2164,14 @@ export const uiMethods = { ? this.connectionHeartbeatDisconnectedIntervalMs : 1000; const nextInterval = this.isConnected ? connectedInterval : disconnectedInterval; + if (isConnectionDiagEnabled() && (!this.isConnected || (this.connectionHeartbeatSeq || 0) <= 3)) { + connectionDiag('log', 'heartbeat-next', { + seq: this.connectionHeartbeatSeq, + isConnected: !!this.isConnected, + failCount: this.connectionHeartbeatFailCount, + nextInterval + }); + } this.connectionHeartbeatTimer = window.setTimeout(() => { runHeartbeat(); }, nextInterval); @@ -2033,6 +2187,7 @@ export const uiMethods = { clearTimeout(this.connectionHeartbeatTimer); this.connectionHeartbeatTimer = null; } + connectionDiag('log', 'heartbeat-stop', {}, { force: true }); }, openRealtimeTerminal() { diff --git a/static/src/app/state.ts b/static/src/app/state.ts index 0b70be8..76b298f 100644 --- a/static/src/app/state.ts +++ b/static/src/app/state.ts @@ -139,6 +139,11 @@ export function dataState() { connectionHeartbeatTimer: null, connectionHeartbeatActive: false, connectionHeartbeatFailCount: 0, + connectionHeartbeatSeq: 0, + connectionHeartbeatLastLatencyMs: 0, + connectionHeartbeatLastError: '', + connectionHeartbeatLastStatusCode: null, + connectionHeartbeatLastChangeAt: 0, connectionHeartbeatIntervalMs: 8000, connectionHeartbeatDisconnectedIntervalMs: 1000,