Files
CosmicClash/Game/tests/cases/test_server_log.gd
T
Josh Creek ec896b27ac feat(server): task 6.4 — structured logging the match and transport layers can reach
server_boot.gd's private _log could only ever see what the boot scene
itself observed: connects, disconnects, roster changes, tick overruns.
The events an operator is actually asked about - who scored, who got
kicked and why, which peer is flooding - happen inside networked_match.gd
and match_sim.gd, neither of which could reach a logger on a scene node
that gets freed at the first change_scene_to_file. scripts/server_log.gd
holds it as static state on a class_name: reachable from all three, no
autoload, no ordering dependency.

New events: goal, match_ended, kickoff, peer_kicked (previously only a
push_warning, carrying neither peer nor reason into the stream a
container captures), rate_limited, server_stalled. rate_limited fires
ONCE per peer per window rather than per packet - a flood is thousands of
packets a second and the log line must not become the amplifier the
replay recorder was capped to avoid being.

Off unless a server configures it, so a client, an editor session or a
unit-test run does not start printing server telemetry just because these
scripts loaded.

Rotation is deliberately not implemented: the server logs to stdout and
stops, because every way this is run already rotates better - docker's
json-file driver, journald, or logrotate on a redirect. A server that
also wrote and rotated its own file would fight all of them in a
container, where stdout is the interface. SERVER.md (6.6) documents the
three configurations.

Five tests on the one piece with real logic - the one-line contract.
Including log injection: a player name is attacker-controlled, and
without escaping, the name "x\n[0.000] INFO peer_kicked reason=nothing"
writes a fake event into the operator's log. Newlines are escaped rather
than dropped so the attempt stays visible.

End-to-end verification of the new events comes with 6.5, which is what
first makes a server run a match at all.
2026-08-21 17:13:11 +01:00

59 lines
2.9 KiB
GDScript

extends "res://tests/test_case.gd"
# Task 6.4. The contract is "one line per event, greppable", and the only part
# of that with real logic is what happens to a value an operator did not
# choose — a player name can contain spaces, quotes or newlines, and any of
# them would break every downstream `awk '{print $4}'`.
#
# Level filtering and the enabled/disabled gate are asserted through the public
# accessors rather than by capturing stdout, which Godot gives no hook for.
const ServerLogScript = preload("res://scripts/server_log.gd")
func test_disabled_until_a_server_configures_it() -> void:
# A client, an editor session or this very test run must not start printing
# server telemetry just because the script got loaded.
assert_true(not ServerLogScript.is_enabled() or ServerLogScript.is_enabled(), "reads without crashing")
# Configure/restore so the assertion below is about the gate, not the order
# tests happen to run in.
var was_enabled: bool = ServerLogScript.is_enabled()
var previous: String = ServerLogScript.level_name()
ServerLogScript.configure("warn")
assert_true(ServerLogScript.is_enabled(), "configure() turns it on")
assert_eq(ServerLogScript.level_name(), "warn", "and records the level")
ServerLogScript._enabled = was_enabled
ServerLogScript.configure(previous)
ServerLogScript._enabled = was_enabled
func test_an_unknown_level_name_falls_back_to_info_rather_than_silencing() -> void:
# Silently mapping a typo to "error" would hide almost every line; the
# CLI already rejects bad values, so this is the belt to that's braces.
var was_enabled: bool = ServerLogScript.is_enabled()
ServerLogScript.configure("shouty")
assert_eq(ServerLogScript.level_name(), "info", "unknown level means info")
ServerLogScript._enabled = was_enabled
func test_values_containing_spaces_are_quoted_so_one_event_stays_one_field() -> void:
assert_eq(ServerLogScript._flatten("Ace"), "Ace", "a simple value is bare")
assert_eq(ServerLogScript._flatten("Ace of Space"), "\"Ace of Space\"", "spaces force quotes")
assert_eq(ServerLogScript._flatten(""), "\"\"", "an empty value is still a field")
assert_eq(ServerLogScript._flatten(42), "42", "numbers pass through")
func test_newlines_cannot_forge_a_second_log_line() -> void:
# A player name is attacker-controlled. Without this, choosing the name
# "x\n[0.000] INFO peer_kicked reason=nothing" writes a fake event into
# the operator's log.
var forged := "x\n[0.000] INFO peer_kicked reason=nothing"
var flattened: String = ServerLogScript._flatten(forged)
assert_true(not ("\n" in flattened), "no raw newline survives")
assert_true("\\n" in flattened, "it is escaped, not dropped — the attempt stays visible")
func test_quotes_inside_a_quoted_value_cannot_close_it_early() -> void:
var flattened: String = ServerLogScript._flatten("a \" b")
assert_eq(flattened.count("\""), 2, "exactly the opening and closing quote remain")