diff --git a/Game/scripts/match_sim.gd b/Game/scripts/match_sim.gd index 3f3d19af..6f14786d 100644 --- a/Game/scripts/match_sim.gd +++ b/Game/scripts/match_sim.gd @@ -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) diff --git a/Game/scripts/networked_match.gd b/Game/scripts/networked_match.gd index 40667bd3..a20fda60 100644 --- a/Game/scripts/networked_match.gd +++ b/Game/scripts/networked_match.gd @@ -685,6 +685,7 @@ func _begin_kickoff() -> void: # §6.3: before the reset, so a promoted player's ship is placed by this very # kickoff rather than left wherever its previous owner abandoned it. _promote_late_joiners() + ServerLog.debug("kickoff", {"reset_gen": (_reset_gen + 1) % 256, "slots": _slots.size()}) reset_ball() reset_ships() # Bump before the broadcast so the kickoff and the reset_gen it announces @@ -992,6 +993,7 @@ func _enter_results(winning_team: int) -> void: _clock_running = false _set_bodies_frozen(true) match_ended.emit(winning_team, score.duplicate()) + ServerLog.info("match_ended", {"score_0": score.get(0, 0), "score_1": score.get(1, 0), "overtime": _in_overtime}) _set_match_state(MatchState.State.RESULTS) @@ -1066,6 +1068,10 @@ func _on_goal_registered(conceding_team: int) -> void: MatchSim.send_score_update(score.duplicate()) if not multiplayer.is_server() or not MatchState.is_live(match_state): return + ServerLog.info("goal", { + "team": scoring_team, "score_0": score.get(0, 0), "score_1": score.get(1, 0), + "tick": Engine.get_physics_frames(), + }) var goal_tick := Engine.get_physics_frames() var resume_tick := goal_tick + int(_goal_pause_seconds() * SimConstants.TICK_HZ) # No end_tick arithmetic here any more: entering GOAL_PAUSE banks the diff --git a/Game/scripts/server_boot.gd b/Game/scripts/server_boot.gd index 0d3155b8..d08cdc78 100644 --- a/Game/scripts/server_boot.gd +++ b/Game/scripts/server_boot.gd @@ -12,17 +12,12 @@ extends Node # Deliberately does not spawn a match yet — that's Phase 2's networked_match # scene. This is just the process shell: listen, log, idle cheaply. -const LOG_LEVELS := {"debug": 0, "info": 1, "warn": 2, "error": 3} - -var _boot_ms := 0 var _last_physics_frame := 0 -var _log_level := 1 # info var config: ServerConfig = null var _watchdog_armed := false # skip the first _process(): engine startup scheduling can batch several physics frames before the first idle frame runs, which isn't a real overrun func _ready() -> void: - _boot_ms = Time.get_ticks_msec() Engine.max_fps = 60 # a server never renders; this just caps the idle-frame poll rate so it doesn't spin # Task 6.3. This process owns the whole command line, so it parses STRICTLY: @@ -44,9 +39,9 @@ func _ready() -> void: printerr("try --help") get_tree().quit(1) return + ServerLog.configure(String(config.get_value("log-level"))) var port := int(config.get_value("port")) var max_clients := int(config.get_value("max-clients")) - _log_level = LOG_LEVELS[String(config.get_value("log-level"))] NetworkManager.client_connected.connect(_on_client_connected) NetworkManager.client_disconnected.connect(_on_client_disconnected) @@ -55,10 +50,15 @@ func _ready() -> void: var err := NetworkManager.host(port, max_clients) if err != OK: - _log("error", "server_boot_failed", {"port": port, "error": error_string(err)}) + ServerLog.error("server_boot_failed", {"port": port, "error": error_string(err)}) get_tree().quit(1) return - _log("info", "server_started", {"port": port, "max_clients": max_clients}) + ServerLog.info("server_started", { + "port": port, "max_clients": max_clients, "log_level": ServerLog.level_name(), + "min_players": int(config.get_value("min-players")), + "max_matches": int(config.get_value("max-matches")), + "arena_rotation": String(config.get_value("arena-rotation")), + }) _last_physics_frame = Engine.get_physics_frames() @@ -72,7 +72,7 @@ func _process(_delta: float) -> void: # that's expected quantisation, not backlog. A real overrun is the # accumulator failing to drain back down, i.e. 3+ ticks in one frame. if steps > 2 and _watchdog_armed: - _log("warn", "physics_overrun", {"steps": steps}) + ServerLog.warn("physics_overrun", {"steps": steps}) _watchdog_armed = true @@ -81,26 +81,17 @@ func _physics_process(_delta: float) -> void: func _on_client_connected(peer_id: int) -> void: - _log("debug", "peer_connected", {"peer_id": peer_id}) + ServerLog.debug("peer_connected", {"peer_id": peer_id}) func _on_client_disconnected(peer_id: int) -> void: - _log("debug", "peer_disconnected", {"peer_id": peer_id}) + ServerLog.debug("peer_disconnected", {"peer_id": peer_id}) func _on_player_joined(peer_id: int, player_name: String) -> void: - _log("info", "player_joined", {"peer_id": peer_id, "name": player_name}) + ServerLog.info("player_joined", {"peer_id": peer_id, "name": player_name, "roster": MatchNet.roster.size()}) func _on_player_left(peer_id: int) -> void: - _log("info", "player_left", {"peer_id": peer_id}) + ServerLog.info("player_left", {"peer_id": peer_id, "roster": MatchNet.roster.size()}) - -func _log(level: String, event: String, fields: Dictionary) -> void: - if LOG_LEVELS.get(level, 1) < _log_level: - return - var parts := PackedStringArray() - for key in fields: - parts.append("%s=%s" % [key, str(fields[key])]) - var elapsed_sec := (Time.get_ticks_msec() - _boot_ms) / 1000.0 - print("[%.3f] %s %s %s" % [elapsed_sec, level.to_upper(), event, " ".join(parts)]) diff --git a/Game/scripts/server_log.gd b/Game/scripts/server_log.gd new file mode 100644 index 00000000..c7701008 --- /dev/null +++ b/Game/scripts/server_log.gd @@ -0,0 +1,92 @@ +class_name ServerLog +extends RefCounted + +# Structured server logging (multiplayer-todo.md task 6.4). +# +# Extracted from server_boot.gd's private `_log`, which could only ever see +# what the boot scene itself observed: connects, disconnects, roster changes +# and tick overruns. The events an operator actually asks 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 +# living on a scene node that gets freed at the first change_scene_to_file. +# Static state on a class_name is reachable from all three with no autoload +# and no ordering dependency. +# +# Format: `[] LEVEL event key=value key=value`. One line +# per event, no wrapping, no multi-line payloads, keys before values — so +# `grep 'player_joined'` and `awk` both work on it without a parser. +# +# ROTATION IS DELIBERATELY NOT IMPLEMENTED HERE. The server logs to stdout and +# stops there, because every way this is actually run already owns log +# rotation and does it better: `docker logs` with its json-file driver's +# max-size/max-file, journald under the systemd unit, or a redirect into +# logrotate for a bare process. A server that also writes and rotates its own +# file would duplicate all of that and fight it in a container, where stdout is +# the interface. SERVER.md documents the three configurations; task 6.6 ships +# them. Godot's own `debug/file_logging` remains available for anyone who wants +# a file as well, and it rotates via `max_log_files`. + +const LEVELS := {"debug": 0, "info": 1, "warn": 2, "error": 3} + +static var _level := 1 # info +static var _boot_ms := -1 +static var _enabled := false # servers only; a client process logs nothing + + +# Called once by the process that owns the command line. Until then nothing is +# emitted at all — a client, an editor session or a unit-test run must not +# start printing server telemetry just because it loaded these scripts. +static func configure(level_name: String) -> void: + _level = int(LEVELS.get(level_name, 1)) + _boot_ms = Time.get_ticks_msec() + _enabled = true + + +static func is_enabled() -> bool: + return _enabled + + +static func level_name() -> String: + for key in LEVELS: + if int(LEVELS[key]) == _level: + return key + return "info" + + +static func debug(event: String, fields: Dictionary = {}) -> void: + _write("debug", event, fields) + + +static func info(event: String, fields: Dictionary = {}) -> void: + _write("info", event, fields) + + +static func warn(event: String, fields: Dictionary = {}) -> void: + _write("warn", event, fields) + + +static func error(event: String, fields: Dictionary = {}) -> void: + _write("error", event, fields) + + +static func _write(level: String, event: String, fields: Dictionary) -> void: + if not _enabled: + return + if int(LEVELS.get(level, 1)) < _level: + return + var parts := PackedStringArray() + for key in fields: + parts.append("%s=%s" % [key, _flatten(fields[key])]) + var elapsed_sec := float(Time.get_ticks_msec() - _boot_ms) / 1000.0 + print("[%.3f] %s %s %s" % [elapsed_sec, level.to_upper(), event, " ".join(parts)]) + + +# One line per event is the whole contract, so a value containing a space or a +# newline would break every downstream `awk '{print $4}'`. Quote rather than +# silently mangle: a player name is operator-supplied and can contain anything. +static func _flatten(value: Variant) -> String: + var text := str(value) + text = text.replace("\n", "\\n").replace("\r", "\\r") + if " " in text or text.is_empty(): + return "\"%s\"" % text.replace("\"", "'") + return text diff --git a/Game/scripts/server_log.gd.uid b/Game/scripts/server_log.gd.uid new file mode 100644 index 00000000..460b8c32 --- /dev/null +++ b/Game/scripts/server_log.gd.uid @@ -0,0 +1 @@ +uid://6oqo5tyiayu3 diff --git a/Game/tests/cases/test_server_config.gd.uid b/Game/tests/cases/test_server_config.gd.uid new file mode 100644 index 00000000..8281abdc --- /dev/null +++ b/Game/tests/cases/test_server_config.gd.uid @@ -0,0 +1 @@ +uid://b8uhme5odsvwe diff --git a/Game/tests/cases/test_server_log.gd b/Game/tests/cases/test_server_log.gd new file mode 100644 index 00000000..a99d6823 --- /dev/null +++ b/Game/tests/cases/test_server_log.gd @@ -0,0 +1,58 @@ +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")