Organize scripts and add TWS plugins with HTTP timeouts
Vendor pinned T5 and T6 plugin sources under the new plugins layout. Add native HTTP deadlines, status and timing diagnostics, telemetry integration, and build/test tooling.
This commit is contained in:
@@ -0,0 +1,469 @@
|
||||
/* tws_t5_telemetry.gsc - Electric Cherry game reports via tws-t5-gsc-utils. */
|
||||
|
||||
#include maps\_utility;
|
||||
#include common_scripts\utility;
|
||||
|
||||
init()
|
||||
{
|
||||
if (GetDvar(#"zombiemode") != "1")
|
||||
return;
|
||||
|
||||
scripts\sp\tws_t5_common::ensure_config();
|
||||
|
||||
if (GetDvar("tws_telemetry_enabled") == "0")
|
||||
{
|
||||
print("[tws_t5_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://")
|
||||
{
|
||||
print("^1[tws_t5_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)
|
||||
{
|
||||
print("^1[tws_t5_telemetry] Telemetry disabled: embedded telemetry token must be at least 32 characters");
|
||||
return;
|
||||
}
|
||||
|
||||
level.telemetry_server = GetDvar("tws_server_id");
|
||||
if (level.telemetry_server == "")
|
||||
{
|
||||
print("^1[tws_t5_telemetry] Set tws_server_id to the registered Electric Cherry server name");
|
||||
return;
|
||||
}
|
||||
|
||||
level.telemetry_initialized = true;
|
||||
level.telemetry_started = false;
|
||||
level.telemetry_ended = false;
|
||||
level.telemetry_last_round = -1;
|
||||
level.telemetry_queue = [];
|
||||
level.telemetry_queue_read = 0;
|
||||
level.telemetry_queue_write = 0;
|
||||
level.telemetry_sequence = 0;
|
||||
level.telemetry_completed = 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; waiting for match start. log_level=" + telemetry_log_level());
|
||||
|
||||
// Use the shared dispatcher; a second connected listener breaks T5 SP.
|
||||
scripts\sp\tws_t5_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 with a round-0 intro.
|
||||
// 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_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. begin_spawning also
|
||||
// catches a start whose spawn predates our dispatcher, or has no players.
|
||||
telemetry_round_watcher()
|
||||
{
|
||||
level endon("telemetry_finished");
|
||||
|
||||
for (;;)
|
||||
{
|
||||
level.telemetry_round_tick = getTime();
|
||||
if (!level.telemetry_started && isDefined(level.flag) &&
|
||||
isDefined(level.flag["begin_spawning"]) && level.flag["begin_spawning"])
|
||||
{
|
||||
telemetry_log(1, "Starting from begin_spawning 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.
|
||||
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();
|
||||
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);
|
||||
}
|
||||
|
||||
telemetry_stat(player, name)
|
||||
{
|
||||
if (!isDefined(player.stats) || !isDefined(player.stats[name]))
|
||||
return 0;
|
||||
|
||||
return telemetry_nonnegative_int(player.stats[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;
|
||||
}
|
||||
|
||||
// getGuid returns a string. Never pass it through int or float.
|
||||
guid = player getGuid();
|
||||
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");
|
||||
// Current spendable points, not the lifetime points-earned stat.
|
||||
data["score"] = telemetry_nonnegative_int(player.score);
|
||||
}
|
||||
|
||||
if (body != "[")
|
||||
body += ",";
|
||||
body += jsonSerialize(data);
|
||||
}
|
||||
|
||||
// t5-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.
|
||||
body = "{\"event\":" + jsonSerialize(event_name);
|
||||
body += ",\"server\":" + jsonSerialize(level.telemetry_server);
|
||||
body += ",\"map\":" + jsonSerialize(GetDvar("mapname"));
|
||||
if (event_name != "game_start")
|
||||
body += ",\"round\":" + telemetry_nonnegative_int(level.round_number);
|
||||
body += ",\"players\":" + telemetry_players_json(event_name != "game_start") + "}";
|
||||
|
||||
entry = [];
|
||||
level.telemetry_sequence++;
|
||||
entry["id"] = level.telemetry_sequence;
|
||||
entry["event"] = event_name;
|
||||
entry["round"] = telemetry_nonnegative_int(level.round_number);
|
||||
entry["captured"] = getTime();
|
||||
entry["body"] = body;
|
||||
level.telemetry_queue[level.telemetry_queue_write] = entry;
|
||||
level.telemetry_queue_write++;
|
||||
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");
|
||||
}
|
||||
|
||||
// A single worker keeps one request in flight. It survives game-over notifies
|
||||
// to drain the final snapshot; no retries, discovery, or beta-specific calls.
|
||||
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; completed=" + level.telemetry_completed + " 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];
|
||||
level.telemetry_queue[level.telemetry_queue_read] = undefined;
|
||||
level.telemetry_queue_read++;
|
||||
telemetry_send(entry);
|
||||
}
|
||||
}
|
||||
|
||||
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 = http::request(level.telemetry_url, options);
|
||||
if (!isDefined(request))
|
||||
{
|
||||
telemetry_transport_failed(label + " request handle is undefined; skipping event");
|
||||
level.telemetry_inflight = undefined;
|
||||
level.telemetry_sender_state = "idle";
|
||||
return;
|
||||
}
|
||||
|
||||
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 HTTP status.
|
||||
// No automatic retry: the receiver may already have accepted the event.
|
||||
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++;
|
||||
if (level.telemetry_failure_streak > 0)
|
||||
telemetry_log(0, "Transport recovered after " + level.telemetry_failure_streak + " failures; " + label);
|
||||
level.telemetry_failure_streak = 0;
|
||||
if (isDefined(diagnostics) && isDefined(diagnostics["http_status"]))
|
||||
{
|
||||
if (diagnostics["http_status"] < 200 || diagnostics["http_status"] >= 300)
|
||||
{
|
||||
level.telemetry_http_rejected++;
|
||||
telemetry_log(0, "ERROR: HTTP rejected " + label + " elapsed_ms=" + elapsed + timing + " body=" + telemetry_preview(response));
|
||||
}
|
||||
else
|
||||
telemetry_log(1, "HTTP completed " + label + " elapsed_ms=" + elapsed + timing);
|
||||
}
|
||||
else
|
||||
telemetry_log(1, "Transport completed " + label + " elapsed_ms=" + elapsed + timing + " (API acceptance unverified)");
|
||||
if (!isDefined(response) || response == "")
|
||||
telemetry_log(0, "WARNING: empty API response for " + label);
|
||||
else
|
||||
telemetry_log(2, "Response " + label + " body=" + telemetry_preview(response));
|
||||
}
|
||||
|
||||
level.telemetry_inflight = undefined;
|
||||
level.telemetry_sender_state = "idle";
|
||||
}
|
||||
|
||||
// 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 "id=" + 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;
|
||||
|
||||
print("[tws_t5_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 "<undefined>";
|
||||
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 +
|
||||
" 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)
|
||||
{
|
||||
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);
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user