/* tws_t6_telemetry.gsc - Zombies game reports via tws-t6-gsc-utils. */ #include maps\mp\_utility; #include common_scripts\utility; // Plutonium probes both entry points; runtime setup belongs in init. main() { println("[tws_t6_telemetry] main reached (HTTP API target: tws-t6-gsc-utils with deadlines/diagnostics)"); } init() { println("[tws_t6_telemetry] init reached"); scripts\zm\tws_t6_common::ensure_config(); if (GetDvar("tws_telemetry_enabled") == "0") { println("[tws_t6_telemetry] Disabled by tws_telemetry_enabled=0"); return; } if (isDefined(level.telemetry_initialized)) return; level.telemetry_url = GetDvar("tws_telemetry_url"); if (level.telemetry_url == "") level.telemetry_url = "https://ec.thewrightserver.net/api/telemetry"; if (getSubStr(toLower(level.telemetry_url), 0, 8) != "https://") { println("^1[tws_t6_telemetry] Telemetry disabled: tws_telemetry_url must use HTTPS"); return; } // Shared reporter secret; update both scripts when rotating it. // This must match Electric Cherry's EC_TELEMETRY_TOKEN environment variable. level.telemetry_token = "e03a03f7d22418f0c062b0b2a7317fd91b1194c4400e84b469866de501180dc2"; if (level.telemetry_token.size < 32) { println("^1[tws_t6_telemetry] Telemetry disabled: embedded telemetry token must be at least 32 characters"); return; } level.telemetry_server = GetDvar("tws_server_id"); if (level.telemetry_server == "" || level.telemetry_server.size > 255) { println("^1[tws_t6_telemetry] Set tws_server_id to the exact registered server name (1-255 characters)"); return; } // Recover before registering producers, so old boundaries precede this match. recovered = telemetryLoad(level.telemetry_server, level.telemetry_url); if (!isDefined(recovered)) { telemetry_log(0, "ERROR: cannot recover durable outbox; reporting disabled until storage is repaired and the map restarted"); return; } level.telemetry_initialized = true; level.telemetry_started = false; level.telemetry_ended = false; level.telemetry_last_round = -1; level.telemetry_queue = recovered; level.telemetry_queue_read = 0; level.telemetry_queue_write = recovered.size; for (i = 0; i < recovered.size; i++) level.telemetry_queue[i]["captured"] = getTime(); level.telemetry_sequence = 0; level.telemetry_completed = 0; level.telemetry_accepted = 0; level.telemetry_failed = 0; level.telemetry_http_rejected = 0; level.telemetry_missing_diagnostics_warned = false; level.telemetry_failure_streak = 0; level.telemetry_last_completed = -1; level.telemetry_last_capture = getTime(); level.telemetry_round_tick = getTime(); level.telemetry_capture_event = "none"; level.telemetry_sender_state = "starting"; level.telemetry_inflight = undefined; telemetry_log(1, "Initialized; recovered=" + recovered.size + " waiting for match start. log_level=" + telemetry_log_level()); // Route through the shared dispatcher; a duplicate connected listener // would fight the T6 common spawn dispatcher. scripts\zm\tws_t6_common::register_spawn_handler(::telemetry_game_start); level thread telemetry_game_end_watcher(); level thread telemetry_sender(); level thread telemetry_round_watcher(); level thread telemetry_watchdog(); } // First playable spawn starts the match, including maps that pre-seed round 1. // Later spawns and joins must not reopen the match or repeat game_start. telemetry_game_start() { if (level.telemetry_started || level.telemetry_ended) return; level.telemetry_match = telemetryNewMatch(); if (!isDefined(level.telemetry_match)) { telemetry_log(0, "ERROR: cannot allocate match identity"); return; } level.telemetry_started = true; level.telemetry_last_capture = getTime(); telemetry_log(1, "Match start detected"); telemetry_enqueue("game_start"); level thread telemetry_heartbeat_watcher(); } // Start the interval with the match, independently of round changes or joins. telemetry_heartbeat_watcher() { level endon("telemetry_finished"); for (;;) { wait (30); telemetry_report_round(); telemetry_enqueue("heartbeat"); } } // Independent of HUD installation and player count. Poll for a positive round // with any player present as a fallback in case the dispatcher spawn hook missed // the first spawn (late-attach or stock ordering quirk). telemetry_round_watcher() { level endon("telemetry_finished"); for (;;) { level.telemetry_round_tick = getTime(); if (!level.telemetry_started && isDefined(level.round_number) && level.round_number >= 1 && getPlayers().size > 0) { telemetry_log(1, "Starting from round_watcher fallback"); telemetry_game_start(); } telemetry_report_round(); wait (0.5); } } telemetry_report_round() { if (!level.telemetry_started || level.telemetry_ended || !isDefined(level.round_number) || level.round_number < 0) return; round = telemetry_nonnegative_int(level.round_number); if (round == level.telemetry_last_round) return; level.telemetry_last_round = round; telemetry_enqueue("round_change"); } telemetry_game_end_watcher() { // One waiter consumes the first end signal, even if a map fires all three. // Stock end_game yields before player_intermission replaces score with // score_total. Serialize here without waiting so score stays spendable. level waittill_any("end_game", "game_ended", "intermission"); telemetry_log(1, "Game-end signal received; stopping producers and draining queue"); // Preserve order even if the match ends before the next polling tick. telemetry_game_start(); if (!level.telemetry_started) return; telemetry_report_round(); level.telemetry_ended = true; level notify("telemetry_finished"); telemetry_enqueue("game_end"); } telemetry_nonnegative_int(value) { if (!isDefined(value) || value < 0) return 0; return int(value); } // T6 stock initializes and updates match counters in player.pers[] through // _globallogic_score::initpersstat / incpersstat; getpersstat reads this array. telemetry_stat(player, name) { if (!isDefined(player.pers) || !isDefined(player.pers[name])) return 0; return telemetry_nonnegative_int(player.pers[name]); } telemetry_players_json(include_stats) { players = getPlayers(); body = "["; for (i = 0; i < players.size; i++) { player = players[i]; if (!isDefined(player)) { telemetry_log(0, "WARNING: skipping undefined player at roster index " + i); continue; } data = []; if (isDefined(player.name)) data["name"] = "" + player.name; else if (isDefined(player.playername)) data["name"] = "" + player.playername; else { telemetry_log(0, "WARNING: skipping player without a name at roster index " + i); continue; } // T6 exposes the persistent per-player identity as the .guid property // (Plutonium engine field; not a method call and not from the plugin). // With a linked Plutonium account it is the account ID; guest/local // sessions fall back to the client slot number, which is expected. // Force to string so the receiver never sees a numeric guid. guid = player.guid; if (!isDefined(guid) || guid == "" || data["name"] == "") { telemetry_log(0, "WARNING: skipping player with incomplete identity at roster index " + i); continue; } data["guid"] = "" + guid; if (include_stats) { data["kills"] = telemetry_stat(player, "kills"); data["headshots"] = telemetry_stat(player, "headshots"); data["downs"] = telemetry_stat(player, "downs"); data["revives"] = telemetry_stat(player, "revives"); // Stock match total is independent of the spendable balance. data["score"] = telemetry_nonnegative_int(player.score); data["score_total"] = telemetry_nonnegative_int(player.score_total); } if (body != "[") body += ","; body += jsonSerialize(data); } // t6-gsc-utils serializes an empty GSC array as null. Build only the // array delimiters ourselves; the serializer still escapes all strings. return body + "]"; } telemetry_enqueue(event_name) { level.telemetry_capture_event = event_name; telemetry_log(2, "Capturing event=" + event_name); // Snapshot and serialize before yielding, including during game over. level.telemetry_sequence++; body = "{\"event\":" + jsonSerialize(event_name); body += ",\"server\":" + jsonSerialize(level.telemetry_server); body += ",\"map\":" + jsonSerialize(GetDvar("mapname")); body += ",\"match\":" + jsonSerialize(level.telemetry_match); body += ",\"seq\":" + level.telemetry_sequence; if (event_name != "game_start") body += ",\"round\":" + telemetry_nonnegative_int(level.round_number); body += ",\"players\":" + telemetry_players_json(event_name != "game_start") + "}"; entry = []; entry["match"] = level.telemetry_match; entry["id"] = level.telemetry_sequence; entry["event"] = event_name; entry["round"] = telemetry_nonnegative_int(level.round_number); entry["captured"] = getTime(); entry["body"] = body; // Persist boundaries before yielding or handing any request to the plugin. // A failed save stays in memory and blocks sending until storage recovers. entry["stored"] = false; telemetry_queue_push(entry); if (telemetry_critical(entry)) telemetry_persist_pending(); level.telemetry_last_capture = getTime(); level.telemetry_capture_event = "none"; telemetry_log(2, "Queued " + telemetry_event_label(entry) + " pending=" + telemetry_pending()); level notify("telemetry_queued"); } // If storage was unavailable at an earlier capture, save it first. Otherwise a // newly captured end could be committed ahead of its unsaved start on restart. telemetry_persist_pending() { for (i = level.telemetry_queue_read; i < level.telemetry_queue_write; i++) { entry = level.telemetry_queue[i]; if (!telemetry_critical(entry) || entry["stored"]) continue; entry["stored"] = telemetryStore(level.telemetry_server, level.telemetry_url, entry["body"]); if (!entry["stored"]) return; } } telemetry_critical(entry) { return entry["event"] == "game_start" || entry["event"] == "game_end"; } // Remove obsolete waiting heartbeats, keeping round reports and the in-flight // head in order. The new heartbeat keeps its capture-time sequence and snapshot. telemetry_queue_push(entry) { queue = []; count = 0; for (i = level.telemetry_queue_read; i < level.telemetry_queue_write; i++) { previous = level.telemetry_queue[i]; inflight = i == level.telemetry_queue_read && isDefined(level.telemetry_inflight); if (entry["event"] == "heartbeat" && previous["event"] == "heartbeat" && !inflight) continue; queue[count] = previous; count++; } queue[count] = entry; level.telemetry_queue = queue; level.telemetry_queue_read = 0; level.telemetry_queue_write = count + 1; } // One worker retains the head through retries. No later report can overtake an // unacknowledged boundary. Retry delays grow 1, 2, 4, 8, 16, then at most 30s. telemetry_sender() { for (;;) { if (level.telemetry_queue_read == level.telemetry_queue_write) { level.telemetry_queue = []; level.telemetry_queue_read = 0; level.telemetry_queue_write = 0; if (level.telemetry_ended) { level.telemetry_sender_state = "drained"; telemetry_log(1, "Queue drained after game end; accepted=" + level.telemetry_accepted + " failed=" + level.telemetry_failed); level notify("telemetry_drained"); return; } level.telemetry_sender_state = "idle"; level waittill("telemetry_queued"); continue; } entry = level.telemetry_queue[level.telemetry_queue_read]; if (!telemetry_process(entry)) { delay = telemetry_retry_delay(entry); level.telemetry_sender_state = "retry_backoff"; telemetry_log(0, "Retry pending " + telemetry_event_label(entry) + " delay_s=" + delay); wait (delay); continue; } level.telemetry_queue[level.telemetry_queue_read] = undefined; level.telemetry_queue_read++; } } telemetry_retry_delay(entry) { if (!isDefined(entry["retry_delay"])) entry["retry_delay"] = 1; else entry["retry_delay"] *= 2; if (entry["retry_delay"] > 30) entry["retry_delay"] = 30; return entry["retry_delay"]; } telemetry_process(entry) { critical = telemetry_critical(entry); if (critical && !entry["stored"]) { entry["stored"] = telemetryStore(level.telemetry_server, level.telemetry_url, entry["body"]); if (!entry["stored"]) return false; } // If removing an acknowledged/terminal entry fails, retry the disk update // without POSTing again. A restart before removal safely replays its key/seq. if (!isDefined(entry["resolved"])) { outcome = telemetry_send(entry); if (critical && outcome == "retry") return false; entry["resolved"] = true; } if (critical) return telemetryRemove(level.telemetry_server, level.telemetry_url, entry["match"], entry["id"]); return true; } telemetry_send(entry) { level.telemetry_inflight = entry; level.telemetry_request_started = getTime(); level.telemetry_sender_state = "creating_request"; label = telemetry_event_label(entry); telemetry_log(1, "Sending " + label + " queue_ms=" + (getTime() - entry["captured"]) + " pending=" + telemetry_pending()); headers = []; headers["Content-Type"] = "application/json"; headers["Authorization"] = "Bearer " + level.telemetry_token; options = []; options["method"] = "POST"; options["headers"] = headers; options["body"] = entry["body"]; options["connect_timeout_ms"] = 5000; options["timeout_ms"] = 15000; request = httpPost(level.telemetry_url, options); if (!isDefined(request)) { telemetry_transport_failed(label + " request handle is undefined"); level.telemetry_inflight = undefined; level.telemetry_sender_state = "idle"; return "retry"; } level.telemetry_sender_state = "waiting_http"; request waittill("done", response, success, error, diagnostics); elapsed = getTime() - level.telemetry_request_started; level.telemetry_last_completed = getTime(); timing = telemetry_http_diagnostics(diagnostics); if (!isDefined(diagnostics) && !level.telemetry_missing_diagnostics_warned) { level.telemetry_missing_diagnostics_warned = true; telemetry_log(0, "WARNING: plugin returned no HTTP diagnostics; native timeouts are unverified. Install the TWS plugin build and restart the server process"); } // The plugin's success flag reports transport completion, not API acceptance. outcome = "retry"; if (!isDefined(success) || !success) { if (!isDefined(error)) error = "unknown transport error"; telemetry_transport_failed(label + " elapsed_ms=" + elapsed + timing + " error=" + telemetry_preview(error)); } else { level.telemetry_completed++; outcome = telemetry_response_outcome(response, diagnostics); if (outcome == "accepted") { ack = telemetryResponse(response); level.telemetry_accepted++; if (level.telemetry_failure_streak > 0) telemetry_log(0, "API recovered after " + level.telemetry_failure_streak + " failures; " + label); level.telemetry_failure_streak = 0; telemetry_log(1, "API accepted " + label + " ec_match_id=" + ack["match_id"] + " elapsed_ms=" + elapsed + timing); } else { level.telemetry_failure_streak++; level.telemetry_http_rejected++; telemetry_log(0, "ERROR: API unacknowledged " + label + " outcome=" + outcome + " elapsed_ms=" + elapsed + timing + " body=" + telemetry_preview(response)); } telemetry_log(2, "Response " + label + " body=" + telemetry_preview(response)); } if (outcome != "accepted" && (!telemetry_critical(entry) || outcome == "drop")) telemetry_log(0, "Dropping unaccepted " + label + " outcome=" + outcome); level.telemetry_inflight = undefined; level.telemetry_sender_state = "idle"; return outcome; } telemetry_response_outcome(response, diagnostics) { if (!isDefined(diagnostics) || !isDefined(diagnostics["http_status"])) return "retry"; status = diagnostics["http_status"]; if (status == 0 || status == 429 || (status >= 500 && status < 600)) return "retry"; if (status < 200 || status >= 300) return "drop"; if (!isDefined(response)) return "retry"; // Native nonthrowing JSON parsing requires an actual boolean true, rejects // truncated/proxy bodies, and preserves large Electric Cherry IDs as strings. ack = telemetryResponse(response); if (ack["accepted"]) return "accepted"; return "retry"; } // The native plugin appends diagnostics while preserving the old done arguments. // Curl timings are cumulative milestones, measured in real milliseconds. telemetry_http_diagnostics(diagnostics) { if (!isDefined(diagnostics)) return " diagnostics=unavailable"; keys = strTok("http_status,curl_code,dns_ms,connect_ms,tls_ms,first_byte_ms,total_ms,worker_queue_ms,notify_ms,connect_timeout_ms,timeout_ms", ","); detail = ""; for (i = 0; i < keys.size; i++) { key = keys[i]; if (isDefined(diagnostics[key])) detail += " " + key + "=" + int(diagnostics[key]); } return detail; } telemetry_transport_failed(detail) { level.telemetry_failed++; level.telemetry_failure_streak++; telemetry_log(0, "ERROR: transport failed " + detail + " consecutive_failures=" + level.telemetry_failure_streak); } telemetry_pending() { return level.telemetry_queue_write - level.telemetry_queue_read; } telemetry_event_label(entry) { return "match=" + entry["match"] + " seq=" + entry["id"] + " event=" + entry["event"] + " round=" + entry["round"]; } // Read live so diagnostics can be increased without restarting the map. telemetry_log_level() { raw = GetDvar("tws_telemetry_log_level"); if (raw == "0") return 0; if (raw == "2") return 2; return 1; } telemetry_log(verbosity, message) { if (verbosity > telemetry_log_level()) return; println("[tws_t6_telemetry] server=" + level.telemetry_server + " map=" + GetDvar("mapname") + " time_ms=" + getTime() + " " + message); } // Escape newlines/control characters and bound response/error output. Do not // jsonParse arbitrary replies: a proxy may return HTML or malformed JSON. telemetry_preview(value) { if (!isDefined(value)) return ""; value = "" + value; if (value.size > 256) value = getSubStr(value, 0, 256) + "... [truncated]"; return jsonSerialize(value); } // Independent of producers and the HTTP wait; survives game over until drain. // Native requests have deadlines. Warn without opening overlapping POSTs // that could arrive out of order or exhaust its native worker pool. telemetry_watchdog() { level endon("telemetry_drained"); for (;;) { wait (30); now = getTime(); pending = telemetry_pending(); completion_age = -1; if (level.telemetry_last_completed >= 0) completion_age = now - level.telemetry_last_completed; telemetry_log(1, "Health started=" + level.telemetry_started + " ended=" + level.telemetry_ended + " sender=" + level.telemetry_sender_state + " capturing=" + level.telemetry_capture_event + " pending=" + pending + " queued_total=" + level.telemetry_sequence + " accepted=" + level.telemetry_accepted + " completed=" + level.telemetry_completed + " failed=" + level.telemetry_failed + " http_rejected=" + level.telemetry_http_rejected + " last_done_ms_ago=" + completion_age); if (isDefined(level.telemetry_inflight)) { age = now - level.telemetry_request_started; if (age >= 30000) telemetry_log(0, "WARNING: HTTP stalled " + telemetry_event_label(level.telemetry_inflight) + " elapsed_ms=" + age + " pending=" + pending + " stage=" + level.telemetry_sender_state + "; native deadline exceeded; check plugin version, worker queue and completion delivery"); } else if (pending > 0 && level.telemetry_sender_state != "retry_backoff") { oldest = level.telemetry_queue[level.telemetry_queue_read]; if (now - oldest["captured"] >= 30000) telemetry_log(0, "WARNING: sender is not consuming queued reports; " + telemetry_event_label(oldest)); } if (!level.telemetry_ended) { if (now - level.telemetry_round_tick > 5000) telemetry_log(0, "WARNING: round watcher has stopped advancing"); if (level.telemetry_started && now - level.telemetry_last_capture >= 65000) telemetry_log(0, "WARNING: no snapshot captured for " + (now - level.telemetry_last_capture) + "ms; capture_event=" + level.telemetry_capture_event); } } }