mirror of
https://github.com/jcreek/CosmicClash.git
synced 2026-09-10 16:04:04 +00:00
fix(multiplayer): server no longer rate-limits a backlog it caused itself
Closes task 5.10's three recording gaps, and the gap-closing found a real input-loss bug. Replay log: a failed write now ends the log permanently instead of desyncing every later record's framing; close() is called from _exit_tree with a summary, since the RefCounted destructor closes it implicitly but never says whether the log is complete; rejected packets are recorded with their reason in the kind byte (framing unchanged, FORMAT_VERSION 2 so "no rejects" differs from "this build never recorded them"). Recording is capped at 8 per peer per window - uncapped, the diagnostic is a remote disk-fill amplifier, since the attacker picks the packet rate. Uncapped totals live on MatchSim and survive the peer's disconnect. The bug: a 2s host stall has the client sending at 60Hz throughout, and ENet delivers that whole backlog in the first window after resume - 70 of an honest client's packets rejected as "rate limit exceeded". Redundancy does not cover it, because the dropped packets are contiguous: 0 of 70 rescued, and 82 of 923 sequences (8.88%, ~1.4s of input) never reached the server, against 0.00% with no stall. Every prediction gate passed. Fixed by granting each already-tracked peer a capped, two-window packet grace when the server detects its own wall-clock stall. Rate-limit rejects 70 -> 0, sequences missing 8.88% -> 0.00%, seq-guard rejects 9 -> 0. Controls on the unfixed build lost 4.34/7.52/7.86%. All three abuse roles still disconnect and no flood induced a stall, so the grace cannot be farmed. Also corrects an earlier wrong conclusion: the reviewer's free-flight p95 0.688 is real and reproduces on two processes with 0.0% snapshot loss. The plain --role=client drive fails the 0.5 free-flight bound in 3 of 8 runs because that drive is mostly a contact test - the harness comment already said so - leaving a cohort as small as 12 samples. Near-surface error is genuinely several times open-air error, so the calibrated bound now belongs to --exercise-free-flight alone and the plain role asserts the always-well-sampled all-cohort percentiles at 1.2/2.0, printing the free-flight numbers as reported-not-asserted. 6/6 plain runs pass where 3/7 failed; tightening to 0.3 still fails. tools/replay_dump.gd reads a log back: counts by kind, plus how much of the input sequence stream reached the server once redundancy is counted.
This commit is contained in:
+143
-7
@@ -21,6 +21,13 @@ const NetCodec = preload("res://scripts/net_codec.gd")
|
||||
|
||||
signal match_config_received(arena_path: String, peer_ids: PackedInt32Array, teams: PackedInt32Array, spawn_indices: PackedInt32Array)
|
||||
signal input_received(peer_id: int, decoded: Dictionary) # decoded: see NetCodec.unpack_input
|
||||
# Task 5.10. A packet this autoload dropped before it could ever reach a match,
|
||||
# with the verbatim bytes — the replay log's whole reason to exist is the field
|
||||
# report "my input did nothing", and an accepted-input-only log has thrown away
|
||||
# exactly the evidence that would explain it. `reason` is an InputRejectReason;
|
||||
# the transport layer deliberately does not know about the replay format's own
|
||||
# record kinds, so the mapping lives at the listener.
|
||||
signal input_rejected(peer_id: int, reason: int, bytes: PackedByteArray)
|
||||
signal snapshot_received(decoded: Dictionary) # decoded: see NetCodec.unpack_snapshot
|
||||
signal score_update_received(score: Dictionary)
|
||||
signal state_change_received(state: int, at_tick: int) # §6.1 MatchState.State
|
||||
@@ -57,6 +64,40 @@ const RATE_LIMIT_WINDOW_MS := 1000
|
||||
const RATE_LIMIT_EXCESS_PACKETS_TO_DISCONNECT := RATE_LIMIT_PACKETS_PER_SEC * 3
|
||||
const RATE_LIMIT_EXCESS_BYTES_TO_DISCONNECT := RATE_LIMIT_BYTES_PER_SEC * 3
|
||||
const MALFORMED_LIMIT_TO_DISCONNECT := 20
|
||||
# Task 5.10: how many rejected packets per peer per rate-limit window are
|
||||
# forwarded to `input_rejected`. Sized so an honest client — whose rejects are
|
||||
# occasional by definition, since a client rejected every tick is a bug the log
|
||||
# is meant to catch — is never sampled away, while a flood cannot turn the log
|
||||
# into unbounded attacker-controlled disk writes.
|
||||
const REJECTS_RECORDED_PER_WINDOW := 8
|
||||
|
||||
# Server-stall grace (found by task 5.10's own reject recording, which is the
|
||||
# only reason it was visible at all).
|
||||
#
|
||||
# When the server stalls — a 2s SIGSTOP stands in for a GC/IO/scheduler hitch —
|
||||
# the client keeps sending at 60Hz throughout, and ENet delivers that entire
|
||||
# backlog in the first window after resume. Measured: 70 of an HONEST client's
|
||||
# input packets rejected as "rate limit exceeded", against a limit the client
|
||||
# never came close to violating on its own. Redundancy does not cover it: the
|
||||
# dropped packets are CONTIGUOUS, so each one's redundancy window falls inside
|
||||
# the same dropped run — 0 of 70 were rescued, and 82 of 923 sequences (8.88%,
|
||||
# ~1.4s of that player's input) never reached the server at all, versus 0.00%
|
||||
# missing on an otherwise identical run with no stall. Every prediction gate
|
||||
# still passed, which is exactly why this needed the log to find.
|
||||
#
|
||||
# So: don't rate-limit a backlog the server itself caused. The grace is capped,
|
||||
# expires after two windows, and is granted only to peers already being
|
||||
# tracked, so it cannot be farmed by a peer that connects during the stall. An
|
||||
# attacker who can induce server stalls to earn budget already has a strictly
|
||||
# worse capability than sending extra input packets.
|
||||
const STALL_DETECT_MS := 250
|
||||
const MAX_STALL_GRACE_PACKETS := SimConstants.TICK_HZ * 4 # 4s of a 60Hz client's backlog
|
||||
const STALL_GRACE_WINDOWS := 2
|
||||
|
||||
enum InputRejectReason {
|
||||
MALFORMED = 0,
|
||||
RATE_LIMIT = 1,
|
||||
}
|
||||
|
||||
|
||||
class _PeerInputState:
|
||||
@@ -72,9 +113,29 @@ class _PeerInputState:
|
||||
var excess_packets := 0.0
|
||||
var excess_bytes := 0.0
|
||||
var malformed_count := 0
|
||||
# Reject-recording budget for the current window. Without it the diagnostic
|
||||
# is a remote disk-fill amplifier: the attacker chooses the flood rate, and
|
||||
# every dropped packet would otherwise become a disk write. Capped per
|
||||
# window, reset with the window itself, so an honest client's occasional
|
||||
# reject is always captured while a flood contributes a bounded sample.
|
||||
var rejects_recorded_this_window := 0
|
||||
# Extra packets this peer may send before the limiter treats it as abuse,
|
||||
# granted when the SERVER stalls and expiring shortly after.
|
||||
var grace_packets := 0
|
||||
var grace_windows_left := 0
|
||||
|
||||
|
||||
var _peer_input_state: Dictionary = {} # peer_id -> _PeerInputState, server only
|
||||
# Uncapped lifetime reject totals, so the sampled log can be read against the
|
||||
# true figure — "8 rate-limit rejects recorded" means nothing on its own when
|
||||
# the recorder itself stops at 8 per window. Deliberately NOT part of
|
||||
# _PeerInputState, which is erased the moment a peer disconnects: a departed
|
||||
# peer's reject history is exactly what the post-mortem wants, and the first
|
||||
# version of this lost it (every summary printed an empty dictionary, because
|
||||
# the client had always disconnected by the time the server tore the match
|
||||
# down). peer_id -> {"malformed": int, "rate_limit": int}.
|
||||
var _reject_totals: Dictionary = {}
|
||||
var _last_physics_ms := 0
|
||||
|
||||
# Bandwidth (task 3.7's debug overlay): only the two 60Hz hot-path channels
|
||||
# (input, snapshot) — match_config/score_update are low-frequency control
|
||||
@@ -114,6 +175,32 @@ func get_bytes_received_per_sec() -> float:
|
||||
|
||||
func _ready() -> void:
|
||||
NetworkManager.client_disconnected.connect(func(peer_id: int) -> void: _peer_input_state.erase(peer_id))
|
||||
# Seeded here, not left at 0, so the first physics frame measures a frame
|
||||
# gap rather than the whole process uptime.
|
||||
_last_physics_ms = Time.get_ticks_msec()
|
||||
|
||||
|
||||
# Server-side stall watchdog. A SIGSTOPped or hitching process doesn't run this
|
||||
# either, so the first physics frame after the stall is the one that sees the
|
||||
# whole wall-clock gap — which is precisely the size of the client backlog
|
||||
# about to arrive. Grace is handed only to peers ALREADY sending input, so a
|
||||
# peer that connects during the stall gets none of it.
|
||||
func _physics_process(_delta: float) -> void:
|
||||
var now := Time.get_ticks_msec()
|
||||
var gap := now - _last_physics_ms
|
||||
_last_physics_ms = now
|
||||
if not multiplayer.is_server() or _peer_input_state.is_empty():
|
||||
return
|
||||
if gap < STALL_DETECT_MS:
|
||||
return
|
||||
var credit: int = mini(int(float(gap) * SimConstants.TICK_HZ / 1000.0), MAX_STALL_GRACE_PACKETS)
|
||||
for peer_id in _peer_input_state:
|
||||
var state: _PeerInputState = _peer_input_state[peer_id]
|
||||
state.grace_packets = mini(state.grace_packets + credit, MAX_STALL_GRACE_PACKETS)
|
||||
state.grace_windows_left = STALL_GRACE_WINDOWS
|
||||
push_warning("MatchSim: server stalled %dms — granting %d packets of rate-limit grace to %d peer(s)" % [
|
||||
gap, credit, _peer_input_state.size()
|
||||
])
|
||||
|
||||
|
||||
func _track_sent(n: int) -> void:
|
||||
@@ -262,19 +349,35 @@ func _recv_input(bytes: PackedByteArray) -> void:
|
||||
# when nothing is arriving anyway.
|
||||
var now_ms := Time.get_ticks_msec()
|
||||
if now_ms - state.window_start_ms >= RATE_LIMIT_WINDOW_MS:
|
||||
state.excess_packets = maxf(0.0, state.excess_packets + float(state.packets_this_window) - float(RATE_LIMIT_PACKETS_PER_SEC))
|
||||
state.excess_bytes = maxf(0.0, state.excess_bytes + float(state.bytes_this_window) - float(RATE_LIMIT_BYTES_PER_SEC))
|
||||
# The leaky bucket drains against the SAME budget the window itself was
|
||||
# policed with, grace included — otherwise a server stall would still
|
||||
# accumulate excess toward a disconnect for traffic the server just
|
||||
# explicitly allowed.
|
||||
state.excess_packets = maxf(0.0, state.excess_packets + float(state.packets_this_window) - float(_packet_budget(state)))
|
||||
state.excess_bytes = maxf(0.0, state.excess_bytes + float(state.bytes_this_window) - float(_byte_budget(state)))
|
||||
state.window_start_ms = now_ms
|
||||
state.packets_this_window = 0
|
||||
state.bytes_this_window = 0
|
||||
state.rejects_recorded_this_window = 0
|
||||
if state.grace_windows_left > 0:
|
||||
state.grace_windows_left -= 1
|
||||
if state.grace_windows_left == 0:
|
||||
state.grace_packets = 0
|
||||
if state.excess_packets > RATE_LIMIT_EXCESS_PACKETS_TO_DISCONNECT or state.excess_bytes > RATE_LIMIT_EXCESS_BYTES_TO_DISCONNECT:
|
||||
# Record before disconnecting, same reasoning as _count_malformed:
|
||||
# the log should contain the packet that ended the connection, not
|
||||
# stop one short of it.
|
||||
_emit_reject(peer_id, state, InputRejectReason.RATE_LIMIT, bytes)
|
||||
_disconnect_abusive_peer(peer_id, "input rate limit exceeded (excess_packets=%.0f excess_bytes=%.0f)" % [state.excess_packets, state.excess_bytes])
|
||||
return
|
||||
|
||||
state.packets_this_window += 1
|
||||
state.bytes_this_window += bytes.size()
|
||||
if state.packets_this_window > RATE_LIMIT_PACKETS_PER_SEC or state.bytes_this_window > RATE_LIMIT_BYTES_PER_SEC:
|
||||
return # over budget for the current window — drop, counted above at the next window roll
|
||||
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.
|
||||
_emit_reject(peer_id, state, InputRejectReason.RATE_LIMIT, bytes)
|
||||
return
|
||||
|
||||
# Framing (§3.1 step 3), validated before decoding — unpack_input can't
|
||||
# be trusted to catch this itself: StreamPeerBuffer silently zero-fills
|
||||
@@ -283,11 +386,11 @@ func _recv_input(bytes: PackedByteArray) -> void:
|
||||
# payload would otherwise decode "successfully" into garbage actions
|
||||
# instead of being rejected.
|
||||
if bytes.size() < NetCodec.INPUT_HEADER_SIZE:
|
||||
_count_malformed(peer_id, state)
|
||||
_count_malformed(peer_id, state, bytes)
|
||||
return
|
||||
var count: int = bytes[5] # type_version(1) + seq(4) precede count — see pack_input's own layout
|
||||
if count == 0 or count > NetCodec.MAX_REDUNDANCY or bytes.size() != NetCodec.INPUT_HEADER_SIZE + count * NetCodec.INPUT_ENTRY_SIZE:
|
||||
_count_malformed(peer_id, state)
|
||||
_count_malformed(peer_id, state, bytes)
|
||||
return
|
||||
|
||||
var decoded := NetCodec.unpack_input(bytes)
|
||||
@@ -299,12 +402,45 @@ func _recv_input(bytes: PackedByteArray) -> void:
|
||||
input_received.emit(peer_id, decoded)
|
||||
|
||||
|
||||
func _count_malformed(peer_id: int, state: _PeerInputState) -> void:
|
||||
# The budget a peer is actually policed against right now: the standing limit
|
||||
# plus any outstanding server-stall grace. Bytes scale with packets by the same
|
||||
# worst-case-packet factor RATE_LIMIT_BYTES_PER_SEC itself is derived from, so
|
||||
# the two budgets can never drift apart by hand.
|
||||
func _packet_budget(state: _PeerInputState) -> int:
|
||||
return RATE_LIMIT_PACKETS_PER_SEC + state.grace_packets
|
||||
|
||||
|
||||
func _byte_budget(state: _PeerInputState) -> int:
|
||||
return _packet_budget(state) * (NetCodec.INPUT_HEADER_SIZE + NetCodec.MAX_REDUNDANCY * NetCodec.INPUT_ENTRY_SIZE)
|
||||
|
||||
|
||||
func _count_malformed(peer_id: int, state: _PeerInputState, bytes: PackedByteArray) -> void:
|
||||
state.malformed_count += 1
|
||||
# Emitted before the disconnect check so the packet that finally crossed
|
||||
# the limit is itself in the log, not just the 19 before it.
|
||||
_emit_reject(peer_id, state, InputRejectReason.MALFORMED, bytes)
|
||||
if state.malformed_count >= MALFORMED_LIMIT_TO_DISCONNECT:
|
||||
_disconnect_abusive_peer(peer_id, "too many malformed input packets (%d)" % state.malformed_count)
|
||||
|
||||
|
||||
func _emit_reject(peer_id: int, state: _PeerInputState, reason: int, bytes: PackedByteArray) -> void:
|
||||
var totals: Dictionary = _reject_totals.get(peer_id, {"malformed": 0, "rate_limit": 0})
|
||||
var key := "rate_limit" if reason == InputRejectReason.RATE_LIMIT else "malformed"
|
||||
totals[key] = int(totals[key]) + 1
|
||||
_reject_totals[peer_id] = totals
|
||||
if state.rejects_recorded_this_window >= REJECTS_RECORDED_PER_WINDOW:
|
||||
return
|
||||
state.rejects_recorded_this_window += 1
|
||||
input_rejected.emit(peer_id, reason, bytes)
|
||||
|
||||
|
||||
# Server-side, diagnostic. peer_id -> {"malformed": int, "rate_limit": int},
|
||||
# uncapped and surviving the peer's disconnect. Peers with no rejects at all
|
||||
# never appear, so an empty dictionary means a clean session.
|
||||
func get_reject_totals() -> Dictionary:
|
||||
return _reject_totals.duplicate(true)
|
||||
|
||||
|
||||
func _disconnect_abusive_peer(peer_id: int, reason: String) -> void:
|
||||
push_warning("MatchSim: disconnecting peer %d for abuse: %s" % [peer_id, reason])
|
||||
_peer_input_state.erase(peer_id)
|
||||
|
||||
@@ -392,7 +392,19 @@ func _owns_world_simulation() -> bool:
|
||||
|
||||
|
||||
func _exit_tree() -> void:
|
||||
pass
|
||||
# Task 5.10. Freeing the RefCounted would close the file anyway, but only
|
||||
# implicitly and only whenever the last reference happens to go — and it
|
||||
# would never print the summary, which is the one line that tells whoever
|
||||
# collected the log whether it is complete. Leaving the match scene is the
|
||||
# real end of the recording, so end it here explicitly.
|
||||
if _replay_log != null:
|
||||
_replay_log.close()
|
||||
print("NetworkedMatch: replay log closed — %d records, %d bytes, %d dropped%s; uncapped reject totals %s" % [
|
||||
_replay_log.records_written, _replay_log.bytes_written, _replay_log.records_dropped,
|
||||
" (WRITE FAILED — log is truncated)" if _replay_log.write_failed else "",
|
||||
MatchSim.get_reject_totals(),
|
||||
])
|
||||
_replay_log = null
|
||||
|
||||
|
||||
# ============================================================
|
||||
@@ -433,6 +445,8 @@ func _start_server() -> void:
|
||||
|
||||
MatchSim.send_match_config(arena_path, peer_ids, teams, spawn_indices)
|
||||
MatchSim.input_received.connect(_on_input_received)
|
||||
if _replay_log != null:
|
||||
MatchSim.input_rejected.connect(_on_input_rejected)
|
||||
NetworkManager.client_disconnected.connect(_on_client_disconnected)
|
||||
# Piggyback live state on the existing retry loop, so a peer that missed
|
||||
# the join-time bootstrap gets one every time it re-asks for config.
|
||||
@@ -522,6 +536,15 @@ func _on_input_received(peer_id: int, decoded: Dictionary) -> void:
|
||||
if seq > seq_bound:
|
||||
slot.consecutive_seq_rejects += 1
|
||||
if slot.consecutive_seq_rejects < SEQ_REJECT_RESYNC_LIMIT:
|
||||
# Recorded, not just counted: this is the drop that used to
|
||||
# be permanent input death, and a log that shows only what
|
||||
# the server accepted cannot distinguish "the client stopped
|
||||
# sending" from "the server refused everything it sent".
|
||||
if _replay_log != null:
|
||||
_replay_log.record_rejected_input(
|
||||
ReplayLog.RecordKind.REJECTED_SEQ_GUARD,
|
||||
Engine.get_physics_frames(), peer_id, decoded.get("raw", PackedByteArray())
|
||||
)
|
||||
return
|
||||
# Fall through and accept: this is the escape hatch, not a
|
||||
# missing `return`.
|
||||
@@ -538,6 +561,18 @@ func _on_input_received(peer_id: int, decoded: Dictionary) -> void:
|
||||
_unknown_sender_input_count += 1
|
||||
|
||||
|
||||
# Task 5.10, server only, connected only when a replay log is open. MatchSim
|
||||
# rejects at the protocol layer and knows nothing about the replay format, so
|
||||
# the reason-to-record-kind mapping lives here.
|
||||
func _on_input_rejected(peer_id: int, reason: int, bytes: PackedByteArray) -> void:
|
||||
if _replay_log == null:
|
||||
return
|
||||
var kind := ReplayLog.RecordKind.REJECTED_MALFORMED
|
||||
if reason == MatchSim.InputRejectReason.RATE_LIMIT:
|
||||
kind = ReplayLog.RecordKind.REJECTED_RATE_LIMIT
|
||||
_replay_log.record_rejected_input(kind, Engine.get_physics_frames(), peer_id, bytes)
|
||||
|
||||
|
||||
# --- §6.1 match state machine (task 5.1) -----------------------------------
|
||||
#
|
||||
# Deliberately does NOT gate physics, freezing or input this task. Tasks 5.3
|
||||
|
||||
@@ -29,20 +29,40 @@ extends RefCounted
|
||||
# `length` is a u16 because both hot-path packets are far under 64KB (a 1v1
|
||||
# snapshot is ~59 bytes) and MatchSim.MAX_INPUT_LENGTH already rejects
|
||||
# anything larger on the way in.
|
||||
#
|
||||
# Framing is kind-agnostic, so new RecordKind values are additive — a reader
|
||||
# that doesn't know a kind still walks past it correctly. The version bump to 2
|
||||
# exists anyway because absence is otherwise ambiguous: without it, a log with
|
||||
# no REJECTED_* records cannot be told apart from one written by a build that
|
||||
# never recorded rejections in the first place, which is exactly the question
|
||||
# "the server dropped my input" needs answered.
|
||||
|
||||
const MAGIC := 0x50524343
|
||||
const FORMAT_VERSION := 1
|
||||
const FORMAT_VERSION := 2
|
||||
const HEADER_SIZE := 8
|
||||
const RECORD_HEADER_SIZE := 11
|
||||
|
||||
enum RecordKind {
|
||||
INPUT = 0, # client -> server, as received
|
||||
INPUT = 0, # client -> server, accepted and handed to the jitter buffer
|
||||
SNAPSHOT = 1, # server -> client, as sent
|
||||
# Rejections. An accepted-input-only log answers "what did the server
|
||||
# simulate", but the field report that actually needs a replay is usually
|
||||
# "my input did nothing" — and the packets that would explain it are
|
||||
# precisely the ones the old log discarded. Each reason is its own kind
|
||||
# rather than a reason field, so the framing above is unchanged.
|
||||
REJECTED_MALFORMED = 2, # failed §3.1 step 3 framing validation
|
||||
REJECTED_RATE_LIMIT = 3, # over budget for the current 1s window
|
||||
REJECTED_SEQ_GUARD = 4, # seq beyond the slot's ingest bound (§3.1 step 4)
|
||||
}
|
||||
|
||||
var _file: FileAccess = null
|
||||
var records_written := 0
|
||||
var bytes_written := 0
|
||||
# Set once a write actually fails (disk full, removed volume). Everything after
|
||||
# it is dropped: a partial record would desync the framing of every record that
|
||||
# follows, turning a truncation into a corrupt file.
|
||||
var write_failed := false
|
||||
var records_dropped := 0
|
||||
|
||||
|
||||
# Returns OK, or an error code. A replay log is diagnostic: a caller that
|
||||
@@ -70,13 +90,20 @@ func record_snapshot(tick: int, payload: PackedByteArray) -> void:
|
||||
_write(RecordKind.SNAPSHOT, tick, 0, payload)
|
||||
|
||||
|
||||
# `kind` must be one of the REJECTED_* values; the caller knows why it dropped
|
||||
# the packet and nothing here can re-derive it.
|
||||
func record_rejected_input(kind: int, tick: int, peer_id: int, payload: PackedByteArray) -> void:
|
||||
_write(kind, tick, peer_id, payload)
|
||||
|
||||
|
||||
func _write(kind: int, tick: int, peer_id: int, payload: PackedByteArray) -> void:
|
||||
if _file == null:
|
||||
if _file == null or write_failed:
|
||||
return
|
||||
if payload.size() > 0xFFFF:
|
||||
# Cannot happen through the real ingress paths (see the header note),
|
||||
# but truncating silently would corrupt every later record's framing.
|
||||
push_warning("ReplayLog: dropping an oversized %d-byte payload" % payload.size())
|
||||
records_dropped += 1
|
||||
return
|
||||
_file.store_8(kind)
|
||||
_file.store_32(tick)
|
||||
@@ -84,6 +111,19 @@ func _write(kind: int, tick: int, peer_id: int, payload: PackedByteArray) -> voi
|
||||
_file.store_16(payload.size())
|
||||
if payload.size() > 0:
|
||||
_file.store_buffer(payload)
|
||||
# Checked via get_error() rather than the store_* return values because it
|
||||
# reports the same condition once for the whole record instead of six times,
|
||||
# and because a diagnostic log that has quietly stopped writing is worse
|
||||
# than no log at all — the reader would see a plausible short match rather
|
||||
# than a failure. One write error ends the log permanently.
|
||||
var err := _file.get_error()
|
||||
if err != OK:
|
||||
write_failed = true
|
||||
records_dropped += 1
|
||||
push_warning("ReplayLog: write failed (%s) after %d records — log closed early" % [error_string(err), records_written])
|
||||
_file.close()
|
||||
_file = null
|
||||
return
|
||||
records_written += 1
|
||||
bytes_written += RECORD_HEADER_SIZE + payload.size()
|
||||
|
||||
|
||||
@@ -108,6 +108,76 @@ func test_a_truncated_log_yields_its_intact_records() -> void:
|
||||
DirAccess.remove_absolute(ProjectSettings.globalize_path(path))
|
||||
|
||||
|
||||
func test_rejected_packets_are_recorded_and_distinguishable_by_reason() -> void:
|
||||
# The log exists to answer "my input did nothing", and the packets that
|
||||
# explain that are exactly the ones the server threw away. Recording them
|
||||
# is only useful if the reason survives too, so a reader can tell a
|
||||
# malformed packet from one the rate limiter dropped.
|
||||
var path := _temp_path("rejects")
|
||||
var log_writer = ReplayLogScript.new()
|
||||
log_writer.open_for_write(path)
|
||||
var malformed := PackedByteArray([0x01, 0x02])
|
||||
var flooded := PackedByteArray([0x09, 0x08, 0x07])
|
||||
var far_future := PackedByteArray([0x11, 0x22, 0x33, 0x44])
|
||||
log_writer.record_rejected_input(ReplayLogScript.RecordKind.REJECTED_MALFORMED, 10, 5, malformed)
|
||||
log_writer.record_rejected_input(ReplayLogScript.RecordKind.REJECTED_RATE_LIMIT, 11, 5, flooded)
|
||||
log_writer.record_rejected_input(ReplayLogScript.RecordKind.REJECTED_SEQ_GUARD, 12, 6, far_future)
|
||||
log_writer.record_input(13, 5, PackedByteArray([0xAA]))
|
||||
log_writer.close()
|
||||
|
||||
var records: Array = ReplayLogScript.read_all(path).get("records", [])
|
||||
assert_eq(records.size(), 4, "rejects and accepted input share one ordered stream")
|
||||
assert_eq(records[0]["kind"], ReplayLogScript.RecordKind.REJECTED_MALFORMED, "malformed reason survives")
|
||||
assert_eq(records[0]["payload"], malformed, "and so do the bytes that caused it")
|
||||
assert_eq(records[1]["kind"], ReplayLogScript.RecordKind.REJECTED_RATE_LIMIT, "rate-limit reason survives")
|
||||
assert_eq(records[1]["payload"], flooded, "with its own payload")
|
||||
assert_eq(records[2]["kind"], ReplayLogScript.RecordKind.REJECTED_SEQ_GUARD, "seq-guard reason survives")
|
||||
assert_eq(records[2]["peer_id"], 6, "attributed to the peer that sent it")
|
||||
assert_eq(records[3]["kind"], ReplayLogScript.RecordKind.INPUT, "an accepted packet is still its own kind")
|
||||
DirAccess.remove_absolute(ProjectSettings.globalize_path(path))
|
||||
|
||||
|
||||
func test_a_failed_write_stops_the_log_instead_of_corrupting_it() -> void:
|
||||
# A half-written record desyncs the framing of everything after it, turning
|
||||
# "the disk filled up" into "the file is garbage". Forcing a real ENOSPC is
|
||||
# out of scope for a unit test, so the failure is injected directly — this
|
||||
# covers the guard and the accounting, not the detection, which is a
|
||||
# get_error() check on the real FileAccess.
|
||||
var path := _temp_path("writefail")
|
||||
var log_writer = ReplayLogScript.new()
|
||||
log_writer.open_for_write(path)
|
||||
log_writer.record_input(1, 1, PackedByteArray([1, 2, 3, 4]))
|
||||
log_writer.write_failed = true
|
||||
log_writer.record_input(2, 1, PackedByteArray([5, 6, 7, 8]))
|
||||
log_writer.record_snapshot(3, PackedByteArray([9]))
|
||||
assert_eq(log_writer.records_written, 1, "nothing is written after a failure")
|
||||
log_writer.close()
|
||||
|
||||
var records: Array = ReplayLogScript.read_all(path).get("records", [])
|
||||
assert_eq(records.size(), 1, "what was written before the failure is still readable")
|
||||
assert_eq(records[0]["payload"], PackedByteArray([1, 2, 3, 4]), "and intact")
|
||||
DirAccess.remove_absolute(ProjectSettings.globalize_path(path))
|
||||
|
||||
|
||||
func test_an_oversized_payload_is_dropped_without_breaking_later_records() -> void:
|
||||
# `length` is a u16. Truncating an over-64KB payload to fit would leave the
|
||||
# reader parsing the payload's own tail as the next record header.
|
||||
var path := _temp_path("oversized")
|
||||
var log_writer = ReplayLogScript.new()
|
||||
log_writer.open_for_write(path)
|
||||
var oversized := PackedByteArray()
|
||||
oversized.resize(0x10000)
|
||||
log_writer.record_input(1, 1, oversized)
|
||||
assert_eq(log_writer.records_dropped, 1, "the oversized record is counted as dropped")
|
||||
log_writer.record_input(2, 1, PackedByteArray([7, 7]))
|
||||
log_writer.close()
|
||||
|
||||
var records: Array = ReplayLogScript.read_all(path).get("records", [])
|
||||
assert_eq(records.size(), 1, "only the well-sized record is present")
|
||||
assert_eq(records[0]["tick"], 2, "and it is the one that came after the drop, correctly framed")
|
||||
DirAccess.remove_absolute(ProjectSettings.globalize_path(path))
|
||||
|
||||
|
||||
func test_writing_to_an_unopened_log_is_a_no_op() -> void:
|
||||
# --replay-log is optional, so every record_* call happens behind a null
|
||||
# check in production — but the class must not corrupt or crash if that
|
||||
|
||||
@@ -353,6 +353,42 @@ func run_client_check(settle_seconds: float, drive_seconds: float, exercise_ball
|
||||
# predictions for an attack's filled gap sequences.
|
||||
const MAX_ACTION_MARKER_MISMATCH_RATE := 0.05
|
||||
var action_label_ok: bool = marker_samples_ok and not server_stalled and marker_rate < MAX_ACTION_MARKER_MISMATCH_RATE
|
||||
# The 0.5/2.0 free-flight bounds belong to --exercise-free-flight and ONLY
|
||||
# to it, because that mode is the only one that produces the profile they
|
||||
# were calibrated on. _run_free_flight_trace exists precisely because, in
|
||||
# its own words, "a straight forward trace reaches the goal/wall in seconds
|
||||
# and turns the supposed free-flight QA run into a contact test" — yet the
|
||||
# plain role went on asserting the open-volume bounds against whatever
|
||||
# free-flight samples that contact-heavy drive happened to leave behind.
|
||||
#
|
||||
# Measured over 8 plain-role runs on an idle machine: the free-flight
|
||||
# cohort ranged from 12 to 257 samples and its p95 from 0.275 to 0.726,
|
||||
# failing the 0.5 bound in 3 of 8 — a ~37% flake rate with no defect
|
||||
# present. That is the p95 0.688 an adversarial review reported and I first
|
||||
# mis-attributed to three-process CPU contention: it reproduces on two
|
||||
# processes, on an idle box, with 0.0% snapshot loss. The mechanism is not
|
||||
# noise — error near the arena's surface-pull field is genuinely several
|
||||
# times higher than in open air (--exercise-free-flight measures 0.084-0.111
|
||||
# on the same build) — but a gate that fires a third of the time is worse
|
||||
# than no gate, and calibrating one bound for both profiles cannot work.
|
||||
#
|
||||
# So the plain role asserts the ALL-COHORT percentiles instead. They are
|
||||
# always well-sampled (545-696 samples across those same runs, versus a
|
||||
# free-flight cohort that can collapse to 12) and much tighter in spread:
|
||||
# raw_p95 0.354-0.609, raw_p99 0.362-0.742. The bounds below sit ~2x above
|
||||
# the worst observed. A free-flight-cohort regression still cannot hide:
|
||||
# free_flight_hard_snaps is asserted in both modes, and anything past 2.0m
|
||||
# IS a hard snap by definition.
|
||||
#
|
||||
# The 100-sample floor is not the plain drive's number (545-696) but
|
||||
# --exercise-match-state's: its forced goal suspends prediction for the
|
||||
# whole GOAL_PAUSE, so an 8s run yields ~153. Still five times what the
|
||||
# old free-flight floor accepted.
|
||||
const NEAR_SURFACE_P95 := 1.2
|
||||
const NEAR_SURFACE_P99 := 2.0
|
||||
var overall_p95: float = float(prediction_stats.get("position_error_p95", INF))
|
||||
var overall_p99: float = float(prediction_stats.get("position_error_p99", INF))
|
||||
var overall_samples := int(prediction_stats.get("sample_count", 0))
|
||||
var prediction_quality_ok: bool = action_label_ok if exercise_input_transitions else \
|
||||
prediction_stats.get("hard_snap_count", 99) < 4 if exercise_ball_contact else \
|
||||
quality_samples >= 30 \
|
||||
@@ -362,7 +398,19 @@ func run_client_check(settle_seconds: float, drive_seconds: float, exercise_ball
|
||||
and raw_rotation_p99 < 15.0 \
|
||||
and quality_p95 < 0.5 \
|
||||
and quality_p99 < 2.0 \
|
||||
and free_flight_hard_snaps == 0 \
|
||||
if exercise_free_flight else \
|
||||
overall_samples >= 100 \
|
||||
and overall_p95 < NEAR_SURFACE_P95 \
|
||||
and overall_p99 < NEAR_SURFACE_P99 \
|
||||
and raw_rotation_p95 < 5.0 \
|
||||
and raw_rotation_p99 < 15.0 \
|
||||
and free_flight_hard_snaps == 0
|
||||
if not exercise_free_flight and not exercise_input_transitions and not exercise_ball_contact:
|
||||
print("SMOKE INFO: near-surface profile — asserting all-cohort p95=%.3f/p99=%.3f (bounds %.1f/%.1f, %d samples); free-flight cohort p95=%.3f/p99=%.3f over %d samples is REPORTED, NOT ASSERTED (see --exercise-free-flight for the calibrated gate)" % [
|
||||
overall_p95, overall_p99, NEAR_SURFACE_P95, NEAR_SURFACE_P99, overall_samples,
|
||||
raw_quality_p95, raw_quality_p99, quality_samples,
|
||||
])
|
||||
# ball_proxy_moved_before_authority counts ticks where the predicted proxy
|
||||
# had visibly moved BEFORE the next authoritative ball state arrived. That
|
||||
# is only a meaningful — or even achievable — claim when there is real RTT
|
||||
|
||||
@@ -0,0 +1,110 @@
|
||||
extends SceneTree
|
||||
|
||||
# Offline reader for a task 5.10 replay log (.ccrp). A log nobody can read is
|
||||
# only half a feature — this is the tool that turned "the server dropped some
|
||||
# input" into the exact numbers that found the stall/rate-limiter interaction
|
||||
# documented in MatchSim's own header.
|
||||
#
|
||||
# godot --headless --path Game --script res://tools/replay_dump.gd -- <path> [--records]
|
||||
#
|
||||
# Default output is one summary line: record counts by kind, plus how much of
|
||||
# the client's input SEQUENCE stream actually reached the server once each
|
||||
# packet's redundancy entries are counted. That last number is the one that
|
||||
# matters — a rejected-packet count is not an input-loss count, because a
|
||||
# packet carries several recent actions, so sporadic loss is usually covered
|
||||
# by its neighbours. Contiguous loss is not, which is exactly what a server
|
||||
# stall produces.
|
||||
#
|
||||
# --records additionally prints every record. Expect thousands.
|
||||
|
||||
const KIND_NAMES := ["INPUT", "SNAPSHOT", "REJECTED_MALFORMED", "REJECTED_RATE_LIMIT", "REJECTED_SEQ_GUARD"]
|
||||
|
||||
|
||||
func _init() -> void:
|
||||
var path := ""
|
||||
var verbose := false
|
||||
for arg in OS.get_cmdline_user_args():
|
||||
if arg == "--records":
|
||||
verbose = true
|
||||
else:
|
||||
path = arg
|
||||
if path.is_empty():
|
||||
print("usage: --script res://tools/replay_dump.gd -- <path.ccrp> [--records]")
|
||||
quit(1)
|
||||
return
|
||||
|
||||
var log_data := ReplayLog.read_all(path)
|
||||
if log_data.is_empty():
|
||||
print("not a replay log (or missing): %s" % path)
|
||||
quit(1)
|
||||
return
|
||||
|
||||
var counts := {}
|
||||
var covered := {} # seq -> true, including redundancy entries
|
||||
var heads := {} # seq -> true, arrived as a packet's own head
|
||||
var rejected_heads := {} # seq -> reject kind
|
||||
for record in log_data["records"]:
|
||||
var kind: int = record["kind"]
|
||||
counts[kind] = int(counts.get(kind, 0)) + 1
|
||||
var payload: PackedByteArray = record["payload"]
|
||||
if verbose:
|
||||
print(" tick=%d kind=%s peer=%d len=%d" % [
|
||||
record["tick"], _kind_name(kind), record["peer_id"], payload.size()
|
||||
])
|
||||
# Snapshots are server->client and carry no input sequence; rejected
|
||||
# packets are by definition not always well-formed, so only decode what
|
||||
# the framing check already passed.
|
||||
if kind == ReplayLog.RecordKind.SNAPSHOT or payload.size() < NetCodec.INPUT_HEADER_SIZE:
|
||||
continue
|
||||
var decoded := NetCodec.unpack_input(payload)
|
||||
var seq: int = decoded["seq"]
|
||||
if kind == ReplayLog.RecordKind.INPUT:
|
||||
heads[seq] = true
|
||||
for i in (decoded["actions"] as Array).size():
|
||||
covered[seq - i] = true
|
||||
else:
|
||||
rejected_heads[seq] = kind
|
||||
|
||||
var parts: Array[String] = []
|
||||
for kind in range(KIND_NAMES.size()):
|
||||
parts.append("%s=%d" % [KIND_NAMES[kind], int(counts.get(kind, 0))])
|
||||
var unknown := 0
|
||||
for kind in counts:
|
||||
if int(kind) >= KIND_NAMES.size():
|
||||
unknown += int(counts[kind])
|
||||
if unknown > 0:
|
||||
parts.append("unknown_kinds=%d" % unknown)
|
||||
|
||||
print("%s: version=%d tick_hz=%d records=%d %s" % [
|
||||
path, log_data["version"], log_data["tick_hz"], log_data["records"].size(), " ".join(parts)
|
||||
])
|
||||
|
||||
var seqs: Array = covered.keys()
|
||||
seqs.sort()
|
||||
if seqs.is_empty():
|
||||
print(" no accepted input — nothing to say about sequence coverage")
|
||||
quit(0)
|
||||
return
|
||||
var lo: int = seqs[0]
|
||||
var hi: int = seqs[-1]
|
||||
var missing := 0
|
||||
for seq in range(lo, hi + 1):
|
||||
if not covered.has(seq):
|
||||
missing += 1
|
||||
# Of the sequences whose own packet was rejected, how many still arrived
|
||||
# inside some other packet's redundancy window? Zero here means the loss
|
||||
# was contiguous, which is the signature of a stall rather than a lossy
|
||||
# link — redundancy only protects against sporadic loss.
|
||||
var rescued := 0
|
||||
for seq in rejected_heads:
|
||||
if covered.has(seq):
|
||||
rescued += 1
|
||||
print(" seq %d..%d (%d): heads=%d covered=%d missing=%d (%.2f%%); rejected_heads=%d rescued_by_redundancy=%d" % [
|
||||
lo, hi, hi - lo + 1, heads.size(), covered.size(), missing,
|
||||
100.0 * float(missing) / float(hi - lo + 1), rejected_heads.size(), rescued,
|
||||
])
|
||||
quit(0)
|
||||
|
||||
|
||||
func _kind_name(kind: int) -> String:
|
||||
return KIND_NAMES[kind] if kind >= 0 and kind < KIND_NAMES.size() else "UNKNOWN(%d)" % kind
|
||||
Reference in New Issue
Block a user