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.
This commit is contained in:
Josh Creek
2026-08-21 17:13:11 +01:00
parent 06881f05ca
commit ec896b27ac
7 changed files with 188 additions and 22 deletions
+17
View File
@@ -125,6 +125,7 @@ class _PeerInputState:
# granted when the SERVER stalls and expiring shortly after.
var grace_packets := 0
var grace_windows_left := 0
var logged_rate_limit_this_window := false
var _peer_input_state: Dictionary = {} # peer_id -> _PeerInputState, server only
@@ -203,6 +204,7 @@ func _physics_process(_delta: float) -> void:
push_warning("MatchSim: server stalled %dms — granting %d packets of rate-limit grace to %d peer(s)" % [
gap, credit, _peer_input_state.size()
])
ServerLog.warn("server_stalled", {"gap_ms": gap, "grace_packets": credit, "peers": _peer_input_state.size()})
func _track_sent(n: int) -> void:
@@ -376,6 +378,7 @@ func _recv_input(bytes: PackedByteArray) -> void:
state.packets_this_window = 0
state.bytes_this_window = 0
state.rejects_recorded_this_window = 0
state.logged_rate_limit_this_window = false
if state.grace_windows_left > 0:
state.grace_windows_left -= 1
if state.grace_windows_left == 0:
@@ -393,6 +396,15 @@ func _recv_input(bytes: PackedByteArray) -> void:
if state.packets_this_window > _packet_budget(state) or state.bytes_this_window > _byte_budget(state):
# Over budget for the current window — drop, counted above at the next
# window roll.
if not state.logged_rate_limit_this_window:
# ONCE per window, not 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.
state.logged_rate_limit_this_window = true
ServerLog.warn("rate_limited", {
"peer_id": peer_id, "packets": state.packets_this_window,
"budget": _packet_budget(state), "grace": state.grace_packets,
})
_emit_reject(peer_id, state, InputRejectReason.RATE_LIMIT, bytes)
return
@@ -460,6 +472,11 @@ func get_reject_totals() -> Dictionary:
func _disconnect_abusive_peer(peer_id: int, reason: String) -> void:
push_warning("MatchSim: disconnecting peer %d for abuse: %s" % [peer_id, reason])
# Task 6.4: the one server event an operator is most likely to be asked
# about ("why was I kicked?"), and it was previously only a push_warning —
# which does not carry the peer, the reason or a timestamp into the log
# stream a container actually captures.
ServerLog.warn("peer_kicked", {"peer_id": peer_id, "reason": reason})
_peer_input_state.erase(peer_id)
if multiplayer.multiplayer_peer is ENetMultiplayerPeer:
multiplayer.multiplayer_peer.disconnect_peer(peer_id)