From 0de97381b743242ab62acbbe16dee1aed3e9f86f Mon Sep 17 00:00:00 2001 From: Josh Creek <8179928+jcreek@users.noreply.github.com> Date: Sat, 5 Sep 2026 21:35:50 +0100 Subject: [PATCH] fix(agones): stop a dead health loop from passing as a healthy server MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every allocated GameServer reached Ready and was recycled by Agones ~20s later. Health pings are the game process's job by design -- the supervisor has no health implementation at all -- so a server that stops pinging is exactly what Agones is built to reclaim. start_health() armed a Timer on a node that might not be inside the SceneTree. A Timer only ticks inside the tree, so the node reported itself configured, sent nothing, and said nothing about it. It now returns a bool, refuses loudly when unconfigured, and defers to _ready() when called before parenting, so the SDK arms its own timer and no caller has to get the ordering right. server_boot.gd defers the add like every sibling does (§9 gotcha 27) and logs when AGONES_SDK_HTTP_PORT is missing, which previously read identically to a healthy start. Also bounded the in-flight latch: it is set across an await, so a request that never completes would silence health permanently. Defence in depth rather than an observed fault. Tests target the contract rather than the mechanism: a test that parents the SDK correctly and asserts pings passes with the bug present, because the defect was in the wiring. The unit tests assert start_health() cannot claim success out of tree, and were confirmed to fail against the previous code. The smoke gains a counting sidecar and asserts a *repeating* ping -- it reports "health pings in 3.0s = 1, want at least 2" when the loop is broken, which is the production symptom exactly. It is also now actually run: nothing referenced it before. Two diagnostic fixes, both of which changed conclusions during this work: The kind gate only built the game-server image when the tag was absent, so a local rerun silently verified whatever was built last. That is why local runs and CI disagreed about the same commit. It now builds by default, with KIND_REUSE_GAME_SERVER_IMAGE=1 as the opt-in fast path. The failure dump logged only not-ready pods, and used --all-containers with a shared tail. A GameServer recycled after reaching Ready leaves no unready pod behind, and the Agones sidecar out-logs the game server, so the relevant output was never captured. It now dumps every pod, per container, current and previous, plus the GameServer and Fleet resources -- Agones' own state machine is what rejects these. --- Game/scripts/agones_sdk.gd | 57 +++++++++++++- Game/scripts/server_boot.gd | 14 +++- Game/tests/agones_sdk_smoke.gd | 115 +++++++++++++++++++++++++--- Game/tests/cases/test_agones_sdk.gd | 37 +++++++++ scripts/verify_kind_agones.sh | 40 +++++++--- scripts/verify_multiplayer_local.sh | 12 +++ 6 files changed, 249 insertions(+), 26 deletions(-) diff --git a/Game/scripts/agones_sdk.gd b/Game/scripts/agones_sdk.gd index c0df06ba..4d36991b 100644 --- a/Game/scripts/agones_sdk.gd +++ b/Game/scripts/agones_sdk.gd @@ -12,6 +12,21 @@ const MAX_ANNOTATION_VALUE_LENGTH := 4096 var _base_url := "" var _health_timer: Timer = null var _health_in_flight := false +var _health_started_msec := 0 +# Set when start_health() is called before this node is inside the tree, so +# _ready() can arm the timer at the first moment it is legal to do so. +var _health_pending := false + + +# Health is armed here rather than by the caller. A Timer only ticks while its +# owner is inside the SceneTree, so arming it from a caller that has not yet +# parented this node produces a node that looks configured and never pings — +# which is exactly how every allocated GameServer silently failed its Agones +# health check and was recycled. +func _ready() -> void: + if _health_pending: + _health_pending = false + _arm_health() func configure_from_environment() -> bool: @@ -33,8 +48,29 @@ func is_available() -> bool: return not _base_url.is_empty() -func start_health() -> void: - if not is_available() or _health_timer != null: +# Returns whether health pings are running. It is a bool rather than void +# because every way this can fail used to be silent, and a game server that +# believes it is healthy while sending nothing is worse than one that refuses +# to start: Agones recycles the former every ~20 seconds forever. +func start_health() -> bool: + if not is_available(): + push_error("AgonesSDK: start_health() before configuration; no health pings will be sent") + return false + if _health_timer != null: + return true + if not is_inside_tree(): + # Deferred rather than fatal: the caller may legitimately configure + # before parenting. _ready() arms it. Still reported, because if the + # node is never parented this is the whole failure. + _health_pending = true + push_warning("AgonesSDK: start_health() called outside the tree; deferring until ready") + return false + _arm_health() + return true + + +func _arm_health() -> void: + if _health_timer != null: return _health_timer = Timer.new() _health_timer.name = "AgonesHealth" @@ -46,6 +82,10 @@ func start_health() -> void: _send_health() +func health_is_running() -> bool: + return _health_timer != null and is_inside_tree() + + func stop_health() -> void: if _health_timer != null: _health_timer.stop() @@ -76,9 +116,20 @@ static func annotation_is_valid(key: String, value: String) -> bool: func _send_health() -> void: - if _health_in_flight or not is_available(): + if not is_available(): return + # The latch stops overlapping requests, but it must never become permanent. + # It is set across an await, and a request that never completes would + # otherwise silence health for the lifetime of the process. HTTPRequest's + # own timeout normally resolves this; the elapsed check is the backstop for + # the case where request_completed never fires at all. + if _health_in_flight: + var stuck_for := Time.get_ticks_msec() - _health_started_msec + if stuck_for < int(REQUEST_TIMEOUT_SECONDS * 2.0 * 1000.0): + return + push_warning("Agones health ping did not complete in %dms; sending another" % stuck_for) _health_in_flight = true + _health_started_msec = Time.get_ticks_msec() var status := await health() _health_in_flight = false if status < 200 or status >= 300: diff --git a/Game/scripts/server_boot.gd b/Game/scripts/server_boot.gd index 4d049209..dfb56154 100644 --- a/Game/scripts/server_boot.gd +++ b/Game/scripts/server_boot.gd @@ -91,11 +91,19 @@ func _ready() -> void: if agones_managed: _agones = AgonesSDKScript.new() _agones.name = "AgonesSDK" - # Health creates and starts a Timer immediately, so the SDK node must be - # in the tree before start_health() runs. - get_tree().root.add_child(_agones) + # Configure before parenting, then request health and defer the add like + # every other node here (§9 gotcha 27: add_child() on get_tree().root + # from inside _ready() is refused because the tree is still attaching + # this very node, and the refusal is not catchable from GDScript). The + # SDK arms its own timer in _ready(), so nothing depends on the order + # these deferred calls happen to flush in. if _agones.configure_from_environment(): _agones.start_health() + else: + # Never silent: without this the log looks identical to a healthy + # server right up until Agones recycles it. + printerr("cosmic-clash-server: AGONES_SDK_HTTP_PORT is missing or invalid; Agones health pings are disabled") + get_tree().root.add_child.call_deferred(_agones) if allocated_mode: var roster_file := String(config.get_value("join-authorisations-file")) var key_file := String(config.get_value("join-authorisations-key-file")) diff --git a/Game/tests/agones_sdk_smoke.gd b/Game/tests/agones_sdk_smoke.gd index 1ed43f98..1f2cb5d6 100644 --- a/Game/tests/agones_sdk_smoke.gd +++ b/Game/tests/agones_sdk_smoke.gd @@ -1,33 +1,130 @@ extends SceneTree +# Headless smoke for the Agones SDK bridge. Run by +# scripts/verify_multiplayer_local.sh: +# godot --headless --path Game --script res://tests/agones_sdk_smoke.gd +# +# Phase 1 drives each REST call directly. Phase 2 covers what phase 1 cannot: +# that start_health() produces a *repeating* ping. That is the property Agones +# actually enforces -- one ping proves nothing, because the Fleet recycles any +# GameServer that stops pinging for periodSeconds * failureThreshold -- and its +# absence is what silently recycled every allocated server. + const ServerControlScript = preload("res://scripts/server_control.gd") const AgonesSDKScript = preload("res://scripts/agones_sdk.gd") const PORT := 18081 +const HEALTH_PORT := 18082 +# start_health() pings every 2s, so three seconds must contain at least two. +const HEALTH_OBSERVATION_SECONDS := 3.0 +const MINIMUM_EXPECTED_PINGS := 2 + + +# Counting stand-in for the Agones sidecar. ServerControl answers /health but +# cannot report how often it was called, and asserting repetition is the whole +# point here, so this counts rather than changing production code for a test. +class CountingSidecar extends Node: + var health_pings := 0 + var _listener := TCPServer.new() + var _peers: Array = [] + + func start(port: int) -> Error: + return _listener.listen(port, "127.0.0.1") + + func stop() -> void: + _listener.stop() + for peer in _peers: + if is_instance_valid(peer): + peer.disconnect_from_host() + _peers.clear() + + func _process(_delta: float) -> void: + while _listener.is_connection_available(): + _peers.append(_listener.take_connection()) + for i in range(_peers.size() - 1, -1, -1): + var peer: StreamPeerTCP = _peers[i] + if peer.get_status() != StreamPeerTCP.STATUS_CONNECTED: + _peers.remove_at(i) + continue + var available := peer.get_available_bytes() + if available <= 0: + continue + var request := peer.get_utf8_string(available) + if "\r\n\r\n" not in request: + continue + if request.begins_with("POST /health"): + health_pings += 1 + var body := "{}" + peer.put_data(("HTTP/1.1 200 OK\r\nContent-Type: application/json\r\nContent-Length: %d\r\nConnection: close\r\n\r\n%s" % [body.length(), body]).to_utf8_buffer()) + peer.disconnect_from_host() + _peers.remove_at(i) func _init() -> void: + if not await _direct_calls_smoke(): + quit(1) + return + if not await _repeating_health_smoke(): + quit(1) + return + print("Agones SDK smoke passed") + quit(0) + + +func _direct_calls_smoke() -> bool: var fake_sidecar = ServerControlScript.new() root.add_child(fake_sidecar) if fake_sidecar.start(PORT) != OK: printerr("fake sidecar failed to bind") - quit(1) - return + return false fake_sidecar.set_process_ready(true) var sdk = AgonesSDKScript.new() root.add_child(sdk) if not sdk.configure_for_testing("http://127.0.0.1:%d" % PORT): printerr("SDK test configuration failed") - quit(1) - return + return false await process_frame var health_status := await sdk.health() var ready_status := await sdk.mark_ready() var annotation_status := await sdk.set_annotation("match", "result") var shutdown_status := await sdk.shutdown() + fake_sidecar.stop() + fake_sidecar.queue_free() + sdk.queue_free() if health_status != 200 or ready_status != 200 or annotation_status < 400 or shutdown_status < 400: printerr("Agones SDK smoke statuses health=%d ready=%d annotation=%d shutdown=%d" % [health_status, ready_status, annotation_status, shutdown_status]) - quit(1) - return - print("Agones SDK smoke passed") - fake_sidecar.stop() - quit(0) + return false + return true + + +func _repeating_health_smoke() -> bool: + var sidecar := CountingSidecar.new() + root.add_child(sidecar) + if sidecar.start(HEALTH_PORT) != OK: + printerr("counting sidecar failed to bind") + return false + + # Configure before parenting and let the node arm its own timer on _ready(), + # which is exactly how server_boot.gd wires it in an allocated pod. + var sdk = AgonesSDKScript.new() + if not sdk.configure_for_testing("http://127.0.0.1:%d" % HEALTH_PORT): + printerr("health SDK configuration failed") + return false + if sdk.start_health(): + printerr("start_health() reported success while the node was outside the tree") + return false + root.add_child(sdk) + await process_frame + if not sdk.health_is_running(): + printerr("health loop did not arm once the node entered the tree") + return false + + await create_timer(HEALTH_OBSERVATION_SECONDS).timeout + var observed := sidecar.health_pings + sdk.stop_health() + sidecar.stop() + sdk.queue_free() + sidecar.queue_free() + if observed < MINIMUM_EXPECTED_PINGS: + printerr("Agones health pings in %.1fs = %d, want at least %d; the health loop is not repeating" % [HEALTH_OBSERVATION_SECONDS, observed, MINIMUM_EXPECTED_PINGS]) + return false + return true diff --git a/Game/tests/cases/test_agones_sdk.gd b/Game/tests/cases/test_agones_sdk.gd index 7a8c6b27..f86e7c96 100644 --- a/Game/tests/cases/test_agones_sdk.gd +++ b/Game/tests/cases/test_agones_sdk.gd @@ -17,3 +17,40 @@ func test_annotation_validation_rejects_header_injection_and_oversized_values() assert_true(not AgonesSDKScript.annotation_is_valid("bad\nkey", "value"), "annotation key newline is rejected") assert_true(not AgonesSDKScript.annotation_is_valid("key", "bad\rvalue"), "annotation value newline is rejected") assert_true(not AgonesSDKScript.annotation_is_valid("key", "x".repeat(4097)), "oversized annotation is rejected") + + +# Regression: every allocated GameServer reached Ready and was then recycled by +# Agones ~20s later, because start_health() armed a Timer on a node that was +# never parented. A Timer only ticks inside the SceneTree, so the process +# reported healthy while sending no pings at all, and nothing said so. +# +# These are deliberately synchronous: test_runner.gd calls test methods without +# awaiting, so anything needing a live tree or an HTTP round trip belongs in +# tests/agones_sdk_smoke.gd instead. What is asserted here is the contract that +# makes the silent case impossible. +func test_start_health_refuses_when_not_configured() -> void: + var sdk = AgonesSDKScript.new() + assert_true(not sdk.start_health(), "health cannot start before a sidecar URL is known") + assert_true(not sdk.health_is_running(), "no timer is armed without configuration") + sdk.queue_free() + + +func test_start_health_reports_failure_when_outside_the_tree() -> void: + # The exact shape of the production bug: configured, so is_available() is + # true and the node looks ready to work, but unparented. + var sdk = AgonesSDKScript.new() + assert_true(sdk.configure_for_testing("http://127.0.0.1:9358"), "fixture configures") + assert_true(sdk.is_available(), "an unparented node still reports available") + assert_true(not sdk.start_health(), "start_health() must not claim success outside the tree") + assert_true(not sdk.health_is_running(), "no health loop is running outside the tree") + sdk.queue_free() + + +func test_health_is_not_running_until_a_timer_exists() -> void: + # health_is_running() is what a caller should trust, rather than + # is_available(), which only says a URL was parsed. + var sdk = AgonesSDKScript.new() + assert_true(not sdk.health_is_running(), "a fresh SDK is not pinging") + sdk.configure_for_testing("http://127.0.0.1:9358") + assert_true(not sdk.health_is_running(), "configuration alone does not start pinging") + sdk.queue_free() diff --git a/scripts/verify_kind_agones.sh b/scripts/verify_kind_agones.sh index a1cc07c2..ce12bff2 100755 --- a/scripts/verify_kind_agones.sh +++ b/scripts/verify_kind_agones.sh @@ -40,20 +40,31 @@ dump_cluster_state() { # does not: FailedScheduling, ImagePullBackOff, readiness probe errors. echo "=== namespace ${ns}: recent events ===" >&2 kubectl -n "$ns" get events --sort-by=.lastTimestamp 2>&1 | tail -40 >&2 || true + # Log EVERY pod, not only the not-ready ones. A GameServer that reaches + # Ready and is then recycled on a health check leaves no unready pod + # behind: the failures are already deleted and the survivors read 2/2 + # Running, so filtering on readiness dumped nothing useful and the game + # server's own output went unseen for several CI runs. for pod in $(kubectl -n "$ns" get pods -o jsonpath='{range .items[*]}{.metadata.name}{"\n"}{end}' 2>/dev/null); do ready="$(kubectl -n "$ns" get pod "$pod" -o jsonpath='{.status.containerStatuses[*].ready}' 2>/dev/null || true)" - case "$ready" in - *false*|"") - echo "=== ${ns}/${pod} is not ready (ready=${ready:-unknown}) ===" >&2 - kubectl -n "$ns" describe pod "$pod" 2>&1 | tail -35 >&2 || true - echo "--- ${ns}/${pod} logs (current) ---" >&2 - kubectl -n "$ns" logs "$pod" --all-containers --tail=40 >&2 2>&1 || true - echo "--- ${ns}/${pod} logs (previous, if it restarted) ---" >&2 - kubectl -n "$ns" logs "$pod" --all-containers --previous --tail=40 >&2 2>&1 || true - ;; - esac + echo "=== ${ns}/${pod} (ready=${ready:-unknown}) ===" >&2 + kubectl -n "$ns" describe pod "$pod" 2>&1 | tail -35 >&2 || true + # Per container, not --all-containers: the Agones sidecar is far chattier + # than the game server, so a shared tail hides exactly the output needed, + # and --previous without -c resolves to a container that never restarted. + for container in $(kubectl -n "$ns" get pod "$pod" -o jsonpath='{range .spec.containers[*]}{.name}{"\n"}{end}' 2>/dev/null); do + echo "--- ${ns}/${pod}[${container}] logs (current) ---" >&2 + kubectl -n "$ns" logs "$pod" -c "$container" --tail=60 >&2 2>&1 || true + echo "--- ${ns}/${pod}[${container}] logs (previous, if it restarted) ---" >&2 + kubectl -n "$ns" logs "$pod" -c "$container" --previous --tail=60 >&2 2>&1 || true + done done done + # Agones' own view: a GameServer can be Unhealthy while its Pod looks fine, + # which is precisely the shape of a failed health check. + echo "=== Agones GameServers and Fleets ===" >&2 + kubectl get gameservers --all-namespaces -o wide >&2 2>&1 || true + kubectl get fleets --all-namespaces -o wide >&2 2>&1 || true echo "=== helm releases ===" >&2 helm list --all-namespaces >&2 2>&1 || true } @@ -92,7 +103,14 @@ fi kind delete cluster --name "$cluster_name" >/dev/null 2>&1 || true -if ! docker image inspect "$game_server_image" >/dev/null 2>&1; then +# Build by default. Reusing whatever happens to be tagged locally silently +# verifies stale code: a developer fixes the game server, reruns this gate, and +# it exercises the previous build because the tag already exists. CI never hits +# that because a fresh runner has no image, which is precisely how a local pass +# and a CI failure can disagree about the same commit. +if [[ "${KIND_REUSE_GAME_SERVER_IMAGE:-}" == 1 ]] && docker image inspect "$game_server_image" >/dev/null 2>&1; then + echo "Reusing existing $game_server_image (KIND_REUSE_GAME_SERVER_IMAGE=1); it may not contain local changes" +else echo "Building $game_server_image from the pinned game-server target" docker build --target game-server -t "$game_server_image" . fi diff --git a/scripts/verify_multiplayer_local.sh b/scripts/verify_multiplayer_local.sh index d4adfa18..5368696e 100755 --- a/scripts/verify_multiplayer_local.sh +++ b/scripts/verify_multiplayer_local.sh @@ -48,6 +48,18 @@ echo "local multiplayer gate: bounded fuzz targets" echo "local multiplayer gate: Godot harness" run_godot_harness +# The Agones SDK smoke needs a live SceneTree and awaits an HTTP round trip, so +# it cannot live in test_runner.tscn -- that runner calls test methods without +# awaiting. It covers the property the unit tests structurally cannot: that +# start_health() produces a *repeating* ping, which is what Agones enforces and +# whose absence silently recycled every allocated GameServer. +echo "local multiplayer gate: Agones SDK smoke" +if [[ -x "$godot_bin" ]]; then + "$godot_bin" --headless --path "$root_dir/Game" --script res://tests/agones_sdk_smoke.gd +else + echo "local multiplayer gate: skipping Agones SDK smoke, Godot executable not found ($godot_bin)" >&2 +fi + echo "local multiplayer gate: contracts and manifests" python3 -m json.tool "$root_dir/server/contracts/v1/openapi.json" >/dev/null # json.tool only proves the contract parses. test_contracts.py is what actually