fix(agones): stop a dead health loop from passing as a healthy server

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.
This commit is contained in:
Josh Creek
2026-09-05 21:35:50 +01:00
parent ca70568fad
commit 0de97381b7
6 changed files with 249 additions and 26 deletions
+54 -3
View File
@@ -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:
+11 -3
View File
@@ -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"))
+106 -9
View File
@@ -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
+37
View File
@@ -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()
+29 -11
View File
@@ -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
+12
View File
@@ -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