diff --git a/agent/README_UPDATE.txt b/agent/README_UPDATE.txt index 700e879..1286b97 100644 --- a/agent/README_UPDATE.txt +++ b/agent/README_UPDATE.txt @@ -1,18 +1,34 @@ -Hockey vMix Agent 1.5.2 +Hockey vMix Agent 1.5.3 Changes: -- More reliable Agent ↔ Hockey Server reconnect after WebSocket drops. -- After a working session the Agent retries the last healthy server first, then falls back to the other configured server. -- WebSocket TCP keep-alive is enabled and the connection handshake timeout is increased to 12 seconds. -- The Agent is marked ONLINE only after the server accepts the hello/credentials, not immediately after TCP/WebSocket upgrade. -- A failed command/ACK write now immediately tears down the broken WebSocket and starts reconnect instead of continuing to send into a dead connection. -- Reverse-proxy HTTP errors such as 502/503 now include a short diagnostic response in agent.log. -- Server heartbeat ACK is sent before the PostgreSQL status update, so a slow database cannot make a healthy Agent connection look dead. +- Connection diagnostics are now split into DNS/TCP, TLS and WebSocket Upgrade stages. +- TCP/TLS/Upgrade stages use short independent timeouts (5 seconds) instead of one opaque 12-second timeout. +- After WebSocket upgrade the Agent waits only 10 seconds for hello.ok and reports this stage explicitly. +- The Agent is considered to have a healthy server route only after hello.ok. +- A failed/slow server attempt can no longer become the preferred server merely because it lasted 5 seconds or more. +- After a real successful session the last healthy server is retried first after a disconnect. +- Reconnect backoff is 2s -> 4s -> 8s -> 15s (max), with manual settings changes resetting the backoff. +- Existing heartbeat, vMix monitoring, Mapping, match assignment and command handling are unchanged. + +Expected connection log now looks like: + Connecting to wss://... + TCP connected · 70 ms + TLS handshake OK · 120 ms + WebSocket upgrade OK · 155 ms + WebSocket established: ...; waiting for server hello (10s) + Server registration OK · https://... + Device registered on server + +If the public server is not reachable, the log will identify the stage, for example: + TCP connect failed after 5000 ms: ... + TLS handshake failed after 5000 ms: ... + WebSocket upgrade response failed after 5000 ms: ... + server did not send hello.ok within 10s Update: -1. Completely close the current Agent through tray → Exit. +1. Completely close the current Agent through tray -> Exit. 2. Replace only agent.exe. -3. Keep the existing agent_config.json next to agent.exe. +3. Keep the existing agent_config.json next to agent.exe. Do NOT replace it. 4. Start Agent again. Device ID, Device Secret and account pairing remain in agent_config.json and are not changed by this update. diff --git a/agent/agent.exe b/agent/agent.exe index e790227..320e937 100644 Binary files a/agent/agent.exe and b/agent/agent.exe differ diff --git a/agent/core.go b/agent/core.go index 02115b2..643352d 100644 --- a/agent/core.go +++ b/agent/core.go @@ -27,7 +27,7 @@ import ( ) const ( - agentVersion = "1.5.2" + agentVersion = "1.5.3" protocolVersion = 1 websocketGUID = "258EAFA5-E914-47DA-95CA-C5AB0DC85B11" heartbeatInterval = 8 * time.Second @@ -130,17 +130,18 @@ type AppState struct { } type Agent struct { - mu sync.RWMutex - cfg Config - cfgPath string - state AppState - logs []string - logFilePath string - fileLog chan string - currentWS *wsConn - inventory VmixInventory - stop chan struct{} - reconnect chan struct{} + mu sync.RWMutex + cfg Config + cfgPath string + state AppState + logs []string + logFilePath string + fileLog chan string + currentWS *wsConn + serverSessionHealthy bool + inventory VmixInventory + stop chan struct{} + reconnect chan struct{} } type wsConn struct { @@ -444,7 +445,11 @@ func suffixVersion(v string) string { } func (a *Agent) connectionLoop() { - backoff := time.Second + // 1.5.3: use a short staged connection timeout and prefer only a server + // that actually completed Agent authentication (hello.ok). A slow failed + // TCP/TLS attempt must never become the preferred server just because it + // consumed five seconds. + backoff := 2 * time.Second preferredServer := "" outer: for { @@ -460,9 +465,6 @@ outer: if len(candidates) == 0 { candidates = []string{"http://127.0.0.1:8000"} } - // Once a server has carried a real session, try that server first after - // a disconnect. This avoids wasting the 12-second local/remote dial - // timeout on a known-unavailable address every time the live socket drops. if preferredServer != "" { for index, candidate := range candidates { if candidate == preferredServer { @@ -473,23 +475,20 @@ outer: } } } + var lastErr error + healthyEnded := false for _, serverBase := range candidates { a.mu.Lock() a.state.ServerConnecting = true a.state.ServerError = "" + a.serverSessionHealthy = false a.mu.Unlock() - connectionStarted := time.Now() + err := a.runConnection(serverBase) - connectionDuration := time.Since(connectionStarted) - if connectionDuration >= 5*time.Second { - // A socket that survived at least a few seconds is a useful - // signal that this is currently the healthy route. Prefer it - // on the next reconnect, but still fall back if it is unavailable. - preferredServer = serverBase - backoff = time.Second - } + a.mu.Lock() + healthySession := a.serverSessionHealthy a.state.ServerConnected = false a.state.ServerConnecting = false a.state.ConnectedServer = "" @@ -498,6 +497,23 @@ outer: } a.currentWS = nil a.mu.Unlock() + + if healthySession { + healthyEnded = true + // This route successfully authenticated the Agent. Keep it as the + // preferred route after a transient disconnect, but do not mark it + // healthy merely because dialing took a long time. + preferredServer = serverBase + backoff = 2 * time.Second + lastErr = err + if err != nil { + a.logf("Server session ended (%s): %v", serverBase, err) + } + // Reconnect the route that was actually healthy before trying a + // different configured server. + break + } + if err == nil { lastErr = nil break @@ -508,12 +524,15 @@ outer: case <-a.stop: return case <-a.reconnect: - backoff = time.Second + backoff = 2 * time.Second continue outer default: } } - if lastErr != nil { + + if healthyEnded { + a.logf("Connection lost; retrying the last healthy Hockey server") + } else if lastErr != nil { a.logf("All configured Hockey servers are offline") } timer := time.NewTimer(backoff) @@ -523,7 +542,7 @@ outer: return case <-a.reconnect: timer.Stop() - backoff = time.Second + backoff = 2 * time.Second continue case <-timer.C: } @@ -545,13 +564,14 @@ func (a *Agent) runConnection(serverBase string) error { return err } a.logf("Connecting to %s", target) - ws, err := dialWebSocket(target, 12*time.Second) + ws, err := dialWebSocket(target, 5*time.Second, a.logf) if err != nil { return err } defer ws.Close() a.mu.Lock() a.currentWS = ws + a.serverSessionHealthy = false // TCP/TLS/WebSocket upgrade is not enough to call the Agent online: the // server still has to accept hello + device credentials. The UI therefore // becomes ONLINE only after hello.ok arrives in handleMessage. @@ -561,7 +581,7 @@ func (a *Agent) runConnection(serverBase string) error { a.state.LastServerAt = time.Now() a.state.ConnectedServer = serverBase a.mu.Unlock() - a.logf("WebSocket established: %s; waiting for server hello", serverBase) + a.logf("WebSocket established: %s; waiting for server hello (10s)", serverBase) vmix, inventory := scanVmix(cfg.VmixURL) a.mu.Lock() @@ -632,12 +652,20 @@ func (a *Agent) runConnection(serverBase string) error { } }() - // The server answers every heartbeat. If no complete server frame is - // received for 30 seconds, treat the TCP connection as stale and reconnect. - // A timeout always discards this socket; we never continue after partially - // consuming a frame. + // The server answers every heartbeat. During initial registration we use a + // shorter deadline so a TCP/WebSocket peer that accepts the socket but never + // answers hello is reported clearly instead of looking like a healthy Agent. + helloReceived := false + helloDeadline := time.Now().Add(10 * time.Second) for { - _ = ws.conn.SetReadDeadline(time.Now().Add(30 * time.Second)) + readDeadline := time.Now().Add(30 * time.Second) + if !helloReceived { + if time.Now().After(helloDeadline) { + return errors.New("server did not send hello.ok within 10s") + } + readDeadline = helloDeadline + } + _ = ws.conn.SetReadDeadline(readDeadline) payload, err := ws.ReadText() if err != nil { select { @@ -646,6 +674,9 @@ func (a *Agent) runConnection(serverBase string) error { default: } if ne, ok := err.(net.Error); ok && ne.Timeout() { + if !helloReceived { + return errors.New("server did not send hello.ok within 10s") + } return errors.New("server watchdog timeout: no data for 30s") } select { @@ -659,9 +690,18 @@ func (a *Agent) runConnection(serverBase string) error { if json.Unmarshal(payload, &msg) != nil { continue } + registrationLog := "" a.mu.Lock() a.state.LastServerAt = time.Now() + if stringValue(msg["type"]) == "hello.ok" { + helloReceived = true + a.serverSessionHealthy = true + registrationLog = a.state.ConnectedServer + } a.mu.Unlock() + if registrationLog != "" { + a.logf("Server registration OK · %s", registrationLog) + } if err := a.handleMessage(ws, msg); err != nil { a.logf("Message error: %v", err) // A message handler error is normally a failed ACK/response write. @@ -1143,7 +1183,7 @@ func websocketURL(server string) (string, error) { return u.String(), nil } -func dialWebSocket(target string, timeout time.Duration) (*wsConn, error) { +func dialWebSocket(target string, timeout time.Duration, logf func(string, ...any)) (*wsConn, error) { u, err := url.Parse(target) if err != nil { return nil, err @@ -1159,18 +1199,37 @@ func dialWebSocket(target string, timeout time.Duration) (*wsConn, error) { } address := net.JoinHostPort(host, port) d := net.Dialer{Timeout: timeout, KeepAlive: 15 * time.Second} - var conn net.Conn - if u.Scheme == "wss" { - conn, err = tls.DialWithDialer(&d, "tcp", address, &tls.Config{ServerName: host, MinVersion: tls.VersionTLS12}) - } else { - conn, err = d.Dial("tcp", address) - } + tcpStarted := time.Now() + conn, err := d.Dial("tcp", address) if err != nil { - return nil, err + var dnsErr *net.DNSError + if errors.As(err, &dnsErr) { + return nil, fmt.Errorf("DNS resolve failed: %w", err) + } + return nil, fmt.Errorf("TCP connect failed after %s: %w", durationText(time.Since(tcpStarted)), err) } - // Bound the entire HTTP Upgrade handshake. Without this, a peer that - // accepts TCP but never completes the response can stall a connection attempt. + if logf != nil { + logf("TCP connected · %s", durationText(time.Since(tcpStarted))) + } + + if u.Scheme == "wss" { + tlsStarted := time.Now() + tlsConn := tls.Client(conn, &tls.Config{ServerName: host, MinVersion: tls.VersionTLS12}) + _ = tlsConn.SetDeadline(time.Now().Add(timeout)) + if err := tlsConn.Handshake(); err != nil { + conn.Close() + return nil, fmt.Errorf("TLS handshake failed after %s: %w", durationText(time.Since(tlsStarted)), err) + } + conn = tlsConn + if logf != nil { + logf("TLS handshake OK · %s", durationText(time.Since(tlsStarted))) + } + } + + // Bound only the HTTP Upgrade stage here. TCP and TLS have their own + // deadlines above, so the log tells us exactly which stage is stuck. _ = conn.SetDeadline(time.Now().Add(timeout)) + upgradeStarted := time.Now() key := randomBase64(16) path := u.EscapedPath() if path == "" { @@ -1182,18 +1241,15 @@ func dialWebSocket(target string, timeout time.Duration) (*wsConn, error) { req := fmt.Sprintf("GET %s HTTP/1.1\r\nHost: %s\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Key: %s\r\nSec-WebSocket-Version: 13\r\nUser-Agent: Hockey-vMix-Agent/%s\r\n\r\n", path, u.Host, key, agentVersion) if _, err := io.WriteString(conn, req); err != nil { conn.Close() - return nil, err + return nil, fmt.Errorf("WebSocket upgrade write failed: %w", err) } reader := bufio.NewReader(conn) statusLine, err := reader.ReadString('\n') if err != nil { conn.Close() - return nil, err + return nil, fmt.Errorf("WebSocket upgrade response failed after %s: %w", durationText(time.Since(upgradeStarted)), err) } if !strings.Contains(statusLine, " 101 ") { - // Keep a small diagnostic preview from reverse proxies (502/503/504). - // This makes intermittent public-server failures distinguishable from - // a local TCP/DNS problem without dumping an HTML error page to the log. preview := "" if statusLine != "" { _ = conn.SetReadDeadline(time.Now().Add(500 * time.Millisecond)) @@ -1208,16 +1264,16 @@ func dialWebSocket(target string, timeout time.Duration) (*wsConn, error) { preview = preview[:300] + "…" } if preview != "" { - return nil, fmt.Errorf("websocket upgrade failed: %s · %s", strings.TrimSpace(statusLine), preview) + return nil, fmt.Errorf("WebSocket upgrade rejected after %s: %s · %s", durationText(time.Since(upgradeStarted)), strings.TrimSpace(statusLine), preview) } - return nil, fmt.Errorf("websocket upgrade failed: %s", strings.TrimSpace(statusLine)) + return nil, fmt.Errorf("WebSocket upgrade rejected after %s: %s", durationText(time.Since(upgradeStarted)), strings.TrimSpace(statusLine)) } headers := map[string]string{} for { line, err := reader.ReadString('\n') if err != nil { conn.Close() - return nil, err + return nil, fmt.Errorf("WebSocket upgrade headers failed after %s: %w", durationText(time.Since(upgradeStarted)), err) } line = strings.TrimRight(line, "\r\n") if line == "" { @@ -1234,8 +1290,20 @@ func dialWebSocket(target string, timeout time.Duration) (*wsConn, error) { return nil, errors.New("invalid Sec-WebSocket-Accept") } _ = conn.SetDeadline(time.Time{}) + if logf != nil { + logf("WebSocket upgrade OK · %s", durationText(time.Since(upgradeStarted))) + } return &wsConn{conn: conn, r: reader}, nil } + +func durationText(value time.Duration) string { + ms := value.Milliseconds() + if ms < 1 { + ms = 1 + } + return fmt.Sprintf("%d ms", ms) +} + func (w *wsConn) Close() error { return w.conn.Close() } func (w *wsConn) WriteJSON(value any) error { payload, err := json.Marshal(value) diff --git a/app.py b/app.py index 815cbf4..90535a4 100644 --- a/app.py +++ b/app.py @@ -30,7 +30,7 @@ from ui_builder import install_ui_builder from khl_site.khl_data_center import APP as khl_site_app BASE_DIR = Path(__file__).resolve().parent -BUILD_VERSION = "2026.09.24.3" +BUILD_VERSION = "2026.09.24.4" # compatibility: BUILD_VERSION = "2026.09.24.2" # compatibility: BUILD_VERSION = "2026.09.23.8" # compatibility: BUILD_VERSION = "2026.09.23.7" @@ -277,15 +277,15 @@ install_ui_builder( f"/hockey-assets/tournament-menu.js?v={BUILD_VERSION}", f"/hockey-assets/admin-directories.js?v={BUILD_VERSION}", "/hockey-assets/match-status-header.js", - "/hockey-assets/agent-devices.js", - "/hockey-assets/agent-diagnostics.js", + f"/hockey-assets/agent-devices.js?v={BUILD_VERSION}", + f"/hockey-assets/agent-diagnostics.js?v={BUILD_VERSION}", ], custom_style_urls=[ "/hockey-assets/tournament-menu.css", f"/hockey-assets/admin-directories.css?v={BUILD_VERSION}", "/hockey-assets/match-status-header.css", - "/hockey-assets/agent-devices.css", - "/hockey-assets/agent-diagnostics.css", + f"/hockey-assets/agent-devices.css?v={BUILD_VERSION}", + f"/hockey-assets/agent-diagnostics.css?v={BUILD_VERSION}", ], ) diff --git a/hockey_data/static/agent-devices.js b/hockey_data/static/agent-devices.js index 2025f9a..63917db 100644 --- a/hockey_data/static/agent-devices.js +++ b/hockey_data/static/agent-devices.js @@ -29,15 +29,29 @@ .replaceAll("'", "'"); async function api(path, options = {}) { - const response = await fetch(path, { - cache: "no-store", - credentials: "same-origin", - ...options, - headers: { + const controller = new AbortController(); + const timeoutMs = Number(options.timeoutMs || 5000); + const timer = setTimeout(() => controller.abort(), timeoutMs); + const fetchOptions = { ...options }; + delete fetchOptions.timeoutMs; + if (!fetchOptions.signal) fetchOptions.signal = controller.signal; + let response; + try { + response = await fetch(path, { + cache: "no-store", + credentials: "same-origin", + ...fetchOptions, + headers: { ...(options.body ? { "Content-Type": "application/json" } : {}), - ...(options.headers || {}), - }, - }); + ...(options.headers || {}), + }, + }); + } catch (error) { + if (error?.name === "AbortError") throw new Error(`Запрос ${path} превысил ${timeoutMs / 1000} с`); + throw error; + } finally { + clearTimeout(timer); + } let payload = {}; try { payload = await response.json(); } catch (_) {} if (!response.ok) { @@ -279,7 +293,7 @@ async function load(force = false) { if (state.loading && !force) return; try { - const payload = await api("/api/hockey/agents/devices"); + const payload = await api("/api/hockey/agents/devices", { timeoutMs: 3500 }); state.devices = Array.isArray(payload.devices) ? payload.devices : []; state.activeDeviceId = String(payload.active_device_id || ""); state.activeDeviceIds = Array.isArray(payload.active_device_ids) @@ -300,7 +314,10 @@ const editingTest = Boolean(state.root?.querySelector("[data-agent-test-form]")?.contains(document.activeElement)); if (!editingTest) render(); } catch (error) { - if (!String(error.message || "").includes("401")) console.warn("Could not load vMix agents", error); + if (!String(error.message || "").includes("401")) { + console.warn("Could not load vMix agents", error); + if (state.panelOpen) setMessage(error.message || "Не удалось получить список Agent", true); + } } } @@ -409,9 +426,12 @@ panel.innerHTML = `
VMIX BRIDGEУстройства
- +
+ + +
-
Web матч: ${esc(gameId || "не выбран")}
+
Web матч: ${esc(gameId || "не выбран")} · найдено: ${state.devices.length}
${state.message ? `
${esc(state.message)}
` : ""}
${cards}
@@ -420,6 +440,16 @@ state.panelOpen = false; render(); }); + panel.querySelector("[data-agent-refresh]")?.addEventListener("click", async () => { + const button = panel.querySelector("[data-agent-refresh]"); + if (button) button.disabled = true; + try { + await load(true); + setMessage("Список Agent обновлён"); + } finally { + if (button) button.disabled = false; + } + }); } window.HockeyAgentRuntime = {