Add safe bank failure diagnostics for T5 and T6

Address #14 with request correlation, bounded parser reasons, startup version reporting, and rate-limited storage and settlement logs. Preserve accounting and API identity contracts, extend portable tests, and update release versions and rollout guidance.
2026-10-13 10:02:36 -04:00
parent ab989395f7
commit 463b4bcc51
19 changed files with 804 additions and 78 deletions
@@ -14,16 +14,33 @@ init()
    level.bank_url = "https://ec.thewrightserver.net/api/bank";
    level.bank_server = GetDvar("tws_server_id");
    level.bank_token = GetDvar("tws_bank_token");
+    level.bank_logs = [];
+    level.bank_diagnostic_serial = 0;
+    credentials = "valid";
+    if (level.bank_token.size < 40 || getSubStr(level.bank_token, 0, 8) != "ec_bank_")
+        credentials = "invalid";
+    println("[tws_bank] startup script=2.0.2 plugin=" + bankVersion() +
+        " endpoint=" + level.bank_url + " server=" + bank_log_token(level.bank_server) +
+        " credentials=" + credentials);
    // A private per-server cfg supplies this; never embed bank credentials.
    if (level.bank_server == "" || level.bank_token.size < 40 ||
        getSubStr(level.bank_token, 0, 8) != "ec_bank_")
    {
-        println("^1[tws_bank] Disabled: configure tws_server_id and a private tws_bank_token");
+        println("^1[tws_bank] Disabled: configure tws_server_id and a private tws_bank_token; pending=not_loaded");
        return;
    }
    level.bank_queue = bankLoad(level.bank_server, level.bank_url);
    if (!isDefined(level.bank_queue))
+    {
+        println("[tws_bank] startup journal_load=failure pending=unknown bank=disabled");
        return;
+    }
+    println("[tws_bank] startup journal_load=success pending=" + level.bank_queue.size);
+    for (i = 0; i < level.bank_queue.size; i++)
+    {
+        level.bank_queue[i]["since"] = getTime();
+        level.bank_queue[i]["attempts"] = 0;
+    }
    level.bank_read = 0;
    level.bank_write = level.bank_queue.size;
    level.bank_busy = false;
@@ -222,8 +239,9 @@ bank_transfer(entry, args)
    data["capacity"] = capacity;
    data["decision"] = "cancel";
    body = jsonSerialize(data);
+    pending_since = getTime();
    // Persist cancellation BEFORE prepare can reach EC, including lost replies.
-    if (!bankStore(level.bank_server, level.bank_url, body))
+    if (!bank_store(body, id, "cancel"))
    {
        bank_say(entry, "^3Bank storage unavailable. Your points are unchanged.");
        return;
@@ -241,7 +259,7 @@ bank_transfer(entry, args)
            commit_body = jsonSerialize(data);
            // No yield between recording the decision and updating the balance.
            // Do not change score_total: bank funds are not earned match points.
-            if (bankStore(level.bank_server, level.bank_url, commit_body))
+            if (bank_store(commit_body, id, "commit"))
            {
                if (operation == "deposit")
                    player.score -= transfer;
@@ -268,6 +286,8 @@ bank_transfer(entry, args)
    pending["id"] = id;
    pending["body"] = body;
    pending["decision"] = data["decision"];
+    pending["since"] = pending_since;
+    pending["attempts"] = 0;
    level.bank_queue[level.bank_write] = pending;
    level.bank_write++;
 }
@@ -287,8 +307,118 @@ bank_error(code)
    return "^3Bank rejected the transfer. Your points are unchanged.";
 }

+// Only locally generated identities/configured server names pass through here.
+// Never use this to print response fields: those use fixed vocabularies below.
+bank_log_token(value)
+{
+    if (!isDefined(value) || typeof(value) != "string" || value.size == 0 || value.size > 128)
+        return "unavailable";
+    allowed = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789_.:-";
+    for (i = 0; i < value.size; i++)
+    {
+        found = false;
+        for (j = 0; j < allowed.size; j++)
+            if (value[i] == allowed[j])
+                found = true;
+        if (!found)
+            return "invalid";
+    }
+    return value;
+}
+
+bank_response_code(code)
+{
+    // Unknown values may contain secrets or console controls, even if short.
+    codes = strTok("ok insufficient_balance empty bank_limit points_limit not_in_match pending invalid_request unauthorized forbidden not_found conflict disabled", " ");
+    for (i = 0; i < codes.size; i++)
+        if (isDefined(code) && code == codes[i])
+            return codes[i];
+    return "unknown";
+}
+
+bank_response_reason(reason)
+{
+    reasons = strTok("empty_body body_limit invalid_json schema field_limit state amount_range ok_state missing_id zero_transfer", " ");
+    for (i = 0; i < reasons.size; i++)
+        if (isDefined(reason) && reason == reasons[i])
+            return reasons[i];
+    return "unknown";
+}
+
+bank_diagnostic_number(diagnostics, key)
+{
+    if (!isDefined(diagnostics) || typeof(diagnostics) != "array" || !isDefined(diagnostics[key]))
+        return "unavailable";
+    value = diagnostics[key];
+    if ((typeof(value) != "int" && typeof(value) != "float") || value < 0 || value > 2147483647)
+        return "unavailable";
+    return "" + int(value);
+}
+
+bank_http_details(diagnostics)
+{
+    detail = "";
+    keys = strTok("http_status curl_code dns_ms connect_ms tls_ms total_ms", " ");
+    for (i = 0; i < keys.size; i++)
+        detail += " " + keys[i] + "=" + bank_diagnostic_number(diagnostics, keys[i]);
+    return detail;
+}
+
+// Fixed keys bound memory. Correlation IDs/timings never form the signature.
+// Report first failure, reason/status/code changes, 30s reminders and recovery.
+bank_log(key, signature, detail, failed)
+{
+    now = getTime();
+    previous = level.bank_logs[key];
+    suppressed = 0;
+    recovery = "";
+    if (isDefined(previous))
+    {
+        suppressed = previous["suppressed"];
+        if (failed && previous["signature"] == signature && now >= previous["time"] && now - previous["time"] < 30000)
+        {
+            previous["suppressed"]++;
+            level.bank_logs[key] = previous;
+            return;
+        }
+        if (previous["failed"] && !failed)
+            recovery = " recovery=true";
+    }
+    println("[tws_bank] " + detail + recovery + " suppressed=" + suppressed);
+    current = [];
+    current["signature"] = signature;
+    current["time"] = now;
+    current["failed"] = failed;
+    current["suppressed"] = 0;
+    level.bank_logs[key] = current;
+}
+
+bank_store(body, id, decision)
+{
+    saved = bankStore(level.bank_server, level.bank_url, body);
+    outcome = "success";
+    if (!saved)
+        outcome = "storage_failure";
+    bank_log("write_" + decision, outcome, "journal_write decision=" + decision +
+        " request_id=" + bank_log_token(id) + " outcome=" + outcome, !saved);
+    return saved;
+}
+
+bank_http_outcome(action, id, correlation, reason, code, diagnostics, failed)
+{
+    level.bank_http_signature = reason + ":" + code + ":" +
+        bank_diagnostic_number(diagnostics, "http_status") + ":" + bank_diagnostic_number(diagnostics, "curl_code");
+    level.bank_http_detail = "correlation=" + correlation + " action=" + action +
+        " request_id=" + bank_log_token(id) + " outcome=" + reason + " code=" + code + bank_http_details(diagnostics);
+    // Settlement adds progress and cleanup outcome before logging this attempt.
+    if (action != "commit" && action != "cancel")
+        bank_log(action, level.bank_http_signature, level.bank_http_detail, failed);
+}
+
 bank_http(action, body, id)
 {
+    level.bank_diagnostic_serial++;
+    correlation = "bank-" + getTime() + "-" + level.bank_diagnostic_serial;
    headers = [];
    headers["Content-Type"] = "application/json";
    headers["Authorization"] = "Bearer " + level.bank_token;
@@ -300,15 +430,46 @@ bank_http(action, body, id)
    options["timeout_ms"] = 15000;
    request = http::request(level.bank_url + "/" + action, options);
    if (!isDefined(request))
+    {
+        bank_http_outcome(action, id, correlation, "request_creation", "none", undefined, true);
        return undefined;
+    }
    request waittill("done", response, success, error, diagnostics);
-    if (!isDefined(success) || !success || !isDefined(response) ||
-        !isDefined(diagnostics) || !isDefined(diagnostics["http_status"]) ||
-        diagnostics["http_status"] != 200)
+    reason = "ok";
+    if (!isDefined(success) || !success)
+        reason = "transport_failure";
+    else if (bank_diagnostic_number(diagnostics, "http_status") == "unavailable")
+        reason = "missing_diagnostics";
+    else if (diagnostics["http_status"] != 200)
+        reason = "http_rejection";
+    else if (!isDefined(response))
+        reason = "missing_response";
+    if (reason != "ok")
+    {
+        bank_http_outcome(action, id, correlation, reason, "none", diagnostics, true);
        return undefined;
+    }
    reply = bankResponse(response);
-    if (!reply["valid"] || reply["request_id"] != id)
+    if (!isDefined(reply) || !isDefined(reply["valid"]) || !reply["valid"])
+    {
+        reason = "unknown";
+        if (isDefined(reply))
+            reason = bank_response_reason(reply["reason"]);
+        bank_http_outcome(action, id, correlation, "invalid_ack_" + reason, "none", diagnostics, true);
        return undefined;
+    }
+    if (reply["request_id"] != id)
+    {
+        bank_http_outcome(action, id, correlation, "request_id_mismatch", "none", diagnostics, true);
+        return undefined;
+    }
+    if (reply["state"] == "rejected")
+        reason = "application_rejection";
+    else if ((action == "balance" && reply["state"] != "balance") ||
+        ((action == "deposit" || action == "withdraw") && reply["state"] != "prepared") ||
+        ((action == "commit" || action == "cancel") && !bank_resolved(action, reply["state"])))
+        reason = "unexpected_state";
+    bank_http_outcome(action, id, correlation, reason, bank_response_code(reply["code"]), diagnostics, reason != "ok");
    return reply;
 }

@@ -330,12 +491,20 @@ bank_sender()
            continue;
        }
        entry = level.bank_queue[level.bank_read];
+        entry["attempts"]++;
+        level.bank_queue[level.bank_read] = entry;
        reply = bank_http(entry["decision"], entry["body"], entry["id"]);
+        duration = int((getTime() - entry["since"]) / 1000);
+        progress = " decision=" + entry["decision"] + " attempt=" + entry["attempts"] +
+            " pending_seconds=" + duration;
+        outcome = "pending";
        if (isDefined(reply) && bank_resolved(entry["decision"], reply["state"]))
        {
            // Cleanup failures never reapply points; settlement is idempotent.
            if (bankRemove(level.bank_server, level.bank_url, entry["id"]))
            {
+                bank_log("settlement", "resolved", level.bank_http_detail + progress +
+                    " journal_remove=success settlement=resolved next_retry_seconds=0", false);
                level.bank_queue[level.bank_read] = undefined;
                level.bank_read++;
                if (level.bank_read == level.bank_write)
@@ -347,8 +516,10 @@ bank_sender()
                delay = 1;
                continue;
            }
+            outcome = "journal_remove_failure";
        }
-        println("^1[tws_bank] Transfer settlement pending; retaining durable decision and retrying");
+        bank_log("settlement", level.bank_http_signature + ":" + outcome, level.bank_http_detail + progress +
+            " settlement=" + outcome + " next_retry_seconds=" + delay, true);
        wait delay;
        delay *= 2;
        if (delay > 30)