Name the entity behind the movement-warning burst
Browse filesThe server performance block reported a movement_warnings count with no way to attribute it. Measured: the counter went 0 -> 107 in under a minute and then stopped, so it is a burst from one event, not the server degrading. A count cannot say whether that is a player joining, a bot reconnecting, or the whole simulation falling behind, and the vanilla lines that carry the answer were not published anywhere -- the HF log stream served a frozen window and /voyager/status strips its log tail on purpose.
performance.movement_warning_samples now carries up to five of those lines, truncated to 200 characters each, so the entity is visible. They are deduplicated on the message rather than the raw line: every entry in a burst has its own timestamp, so comparing raw lines would fill the payload with five copies of one problem instead of showing five distinct ones. Verified directly: 40 warnings from one bot collapse to one sample, and adding a second bot's warning produces two.
This is diagnosis, not a fix. It says which entity to investigate; the cause still has to be established from the lines themselves.
Suite: 128 -> 131 passed, 0 failed. pyflakes clean.
- minecraft_stack.py +21 -2
- tests/test_server_performance.py +47 -0
|
@@ -350,12 +350,31 @@ def _server_performance(lines: list[str], now: datetime.datetime | None = None)
|
|
| 350 |
tick_lag = [line for line in recent if "Can't keep up!" in line]
|
| 351 |
delays = [int(match.group(1)) for line in tick_lag
|
| 352 |
if (match := re.search(r"Running (\d+)ms or \d+ ticks behind", line))]
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| 353 |
return {
|
| 354 |
"window_seconds": 300,
|
| 355 |
"tick_lag_events": len(tick_lag),
|
| 356 |
"max_reported_tick_delay_ms": max(delays, default=None),
|
| 357 |
-
"movement_warnings":
|
| 358 |
-
|
| 359 |
"last_tick_lag_at": tick_lag[-1][1:20] if tick_lag else None,
|
| 360 |
}
|
| 361 |
|
|
|
|
| 350 |
tick_lag = [line for line in recent if "Can't keep up!" in line]
|
| 351 |
delays = [int(match.group(1)) for line in tick_lag
|
| 352 |
if (match := re.search(r"Running (\d+)ms or \d+ ticks behind", line))]
|
| 353 |
+
movement = [line for line in recent
|
| 354 |
+
if "moved too quickly" in line or "moved wrongly" in line]
|
| 355 |
+
# The count alone cannot say whether this is one entity joining or the whole
|
| 356 |
+
# server degrading. Measured: the counter went 0 -> 107 in under a minute and
|
| 357 |
+
# then stopped, which is a burst, so the entity behind it has to be visible.
|
| 358 |
+
# Deduplicate on the message, not the raw line: a burst carries a distinct
|
| 359 |
+
# timestamp on every entry, so comparing raw lines would fill the payload with
|
| 360 |
+
# five copies of one problem instead of showing five distinct ones.
|
| 361 |
+
samples: list[str] = []
|
| 362 |
+
seen: set[str] = set()
|
| 363 |
+
for line in movement:
|
| 364 |
+
trimmed = line.strip()[:200]
|
| 365 |
+
key = re.sub(r"^\[[^\]]*\]\s*", "", trimmed)
|
| 366 |
+
if key in seen:
|
| 367 |
+
continue
|
| 368 |
+
seen.add(key)
|
| 369 |
+
samples.append(trimmed)
|
| 370 |
+
if len(samples) >= 5:
|
| 371 |
+
break
|
| 372 |
return {
|
| 373 |
"window_seconds": 300,
|
| 374 |
"tick_lag_events": len(tick_lag),
|
| 375 |
"max_reported_tick_delay_ms": max(delays, default=None),
|
| 376 |
+
"movement_warnings": len(movement),
|
| 377 |
+
"movement_warning_samples": samples,
|
| 378 |
"last_tick_lag_at": tick_lag[-1][1:20] if tick_lag else None,
|
| 379 |
}
|
| 380 |
|
|
@@ -17,11 +17,58 @@ def test_tick_lag_and_movement_are_distinct():
|
|
| 17 |
"tick_lag_events": 1,
|
| 18 |
"max_reported_tick_delay_ms": 321,
|
| 19 |
"movement_warnings": 2,
|
|
|
|
|
|
|
|
|
|
|
|
|
| 20 |
"last_tick_lag_at": "2026-09-27 16:29:00",
|
| 21 |
}
|
| 22 |
assert _server_performance(lines[:1], now)["max_reported_tick_delay_ms"] is None
|
| 23 |
|
| 24 |
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| 25 |
if __name__ == "__main__":
|
| 26 |
test_tick_lag_and_movement_are_distinct()
|
|
|
|
|
|
|
|
|
|
| 27 |
print("PASS bounded vanilla tick-lag and movement diagnostics")
|
|
|
|
| 17 |
"tick_lag_events": 1,
|
| 18 |
"max_reported_tick_delay_ms": 321,
|
| 19 |
"movement_warnings": 2,
|
| 20 |
+
"movement_warning_samples": [
|
| 21 |
+
"[2026-09-27 16:27:00] minecraft> [Server thread/WARN]: IffyBinkie6134 moved too quickly!",
|
| 22 |
+
"[2026-09-27 16:29:10] minecraft> [Server thread/WARN]: IffyBinkie6134 moved wrongly!",
|
| 23 |
+
],
|
| 24 |
"last_tick_lag_at": "2026-09-27 16:29:00",
|
| 25 |
}
|
| 26 |
assert _server_performance(lines[:1], now)["max_reported_tick_delay_ms"] is None
|
| 27 |
|
| 28 |
|
| 29 |
+
def test_movement_samples_name_the_entity_behind_the_burst():
|
| 30 |
+
# Measured: the counter went 0 -> 107 in under a minute and then stopped. A
|
| 31 |
+
# count cannot say whether one entity joining caused it or the whole server is
|
| 32 |
+
# degrading, so the entity has to be in the payload.
|
| 33 |
+
now = datetime.datetime(2026, 9, 29, 10, 30, 0)
|
| 34 |
+
lines = [
|
| 35 |
+
f"[2026-09-29 10:29:{second:02d}] minecraft> [Server thread/WARN]: Naldo_Bot moved too quickly! 12.5,0.0,-8.25"
|
| 36 |
+
for second in range(0, 40)
|
| 37 |
+
]
|
| 38 |
+
result = _server_performance(lines, now)
|
| 39 |
+
assert result["movement_warnings"] == 40
|
| 40 |
+
# The burst carries a distinct timestamp per entry, so the samples must
|
| 41 |
+
# collapse on the message: one entity, one problem, one sample.
|
| 42 |
+
assert result["movement_warning_samples"] == [
|
| 43 |
+
"[2026-09-29 10:29:00] minecraft> [Server thread/WARN]: Naldo_Bot moved too quickly! 12.5,0.0,-8.25"
|
| 44 |
+
], "a burst from one entity must not fill the payload with copies"
|
| 45 |
+
assert "Naldo_Bot" in result["movement_warning_samples"][0]
|
| 46 |
+
|
| 47 |
+
|
| 48 |
+
def test_movement_samples_are_bounded():
|
| 49 |
+
now = datetime.datetime(2026, 9, 29, 10, 30, 0)
|
| 50 |
+
lines = [
|
| 51 |
+
f"[2026-09-29 10:29:{second:02d}] minecraft> [Server thread/WARN]: Bot{second} moved wrongly!"
|
| 52 |
+
for second in range(0, 20)
|
| 53 |
+
]
|
| 54 |
+
result = _server_performance(lines, now)
|
| 55 |
+
assert result["movement_warnings"] == 20
|
| 56 |
+
assert len(result["movement_warning_samples"]) == 5, "the payload must stay small"
|
| 57 |
+
assert all(len(sample) <= 200 for sample in result["movement_warning_samples"])
|
| 58 |
+
|
| 59 |
+
|
| 60 |
+
def test_samples_are_empty_when_nothing_moved_wrongly():
|
| 61 |
+
now = datetime.datetime(2026, 9, 29, 10, 30, 0)
|
| 62 |
+
result = _server_performance(
|
| 63 |
+
["[2026-09-29 10:29:00] minecraft> [Server thread/INFO]: Done (1.2s)!"], now
|
| 64 |
+
)
|
| 65 |
+
assert result["movement_warnings"] == 0
|
| 66 |
+
assert result["movement_warning_samples"] == []
|
| 67 |
+
|
| 68 |
+
|
| 69 |
if __name__ == "__main__":
|
| 70 |
test_tick_lag_and_movement_are_distinct()
|
| 71 |
+
test_movement_samples_name_the_entity_behind_the_burst()
|
| 72 |
+
test_movement_samples_are_bounded()
|
| 73 |
+
test_samples_are_empty_when_nothing_moved_wrongly()
|
| 74 |
print("PASS bounded vanilla tick-lag and movement diagnostics")
|