test: surface path timing contracts in live harness

This commit is contained in:
BruceChen 2026-04-14 10:51:13 +00:00
parent 4b193e639c
commit be6be4da36
9 changed files with 305 additions and 38 deletions

View file

@ -0,0 +1,39 @@
using MinecraftClient.Mapping;
using MinecraftClient.Pathing.Core;
using MinecraftClient.Pathing.Execution;
using MinecraftClient.Pathing.Execution.Telemetry;
using Xunit;
namespace MinecraftClient.Tests.Pathing.Execution;
public sealed class PathExecutionLogObserverTests
{
[Fact]
public void Observer_EmitsMachineReadablePathMetricLines()
{
List<string> lines = [];
PathExecutionLogObserver observer = new(lines.Add);
PathSegment segment = new()
{
Start = new Location(10, 64, 10),
End = new Location(11, 64, 10),
MoveType = MoveType.Traverse,
ExitTransition = PathTransitionType.ContinueStraight,
};
observer.OnNavigationStarted([segment]);
observer.OnSegmentStarted(0, 1, segment);
observer.OnSegmentCompleted(0, 1, segment, 7, new Location(11.5, 64, 10.5));
observer.OnReplanStarted(1, new Location(11.5, 64, 10.5));
observer.OnReplanSucceeded(1, [segment]);
observer.OnNavigationCompleted(7);
Assert.Collection(lines,
line => Assert.Equal("[PathMetric] routeStart segments=1", line),
line => Assert.Equal("[PathMetric] segmentStart index=0 total=1 move=Traverse transition=ContinueStraight", line),
line => Assert.Equal("[PathMetric] segmentComplete index=0 total=1 move=Traverse ticks=7 x=11.50 y=64.00 z=10.50", line),
line => Assert.Equal("[PathMetric] replanStart count=1 x=11.50 y=64.00 z=10.50", line),
line => Assert.Equal("[PathMetric] replanSuccess count=1 segments=1", line),
line => Assert.Equal("[PathMetric] routeComplete totalTicks=7", line));
}
}

View file

@ -1763,7 +1763,8 @@ namespace MinecraftClient
pathSegmentManager = new Pathing.Execution.PathSegmentManager(
debugLog: msg => Log.Debug(msg),
infoLog: msg => Log.Info(msg));
infoLog: msg => Log.Info(msg),
observer: new Pathing.Execution.Telemetry.PathExecutionLogObserver(msg => Log.Debug(msg)));
pathSegmentManager.StartNavigation(goal, result);
string statusStr = result.Status == Pathing.Core.PathStatus.Partial ? " (partial)" : "";

View file

@ -0,0 +1,84 @@
using System;
using System.Collections.Generic;
using System.Globalization;
using MinecraftClient.Mapping;
namespace MinecraftClient.Pathing.Execution.Telemetry
{
public sealed class PathExecutionLogObserver : IPathExecutionObserver
{
private readonly Action<string>? _debug;
public PathExecutionLogObserver(Action<string>? debug) => _debug = debug;
public void OnNavigationStarted(IReadOnlyList<PathSegment> segments) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_route_start,
segments.Count));
public void OnSegmentStarted(int segmentIndex, int totalSegments, PathSegment segment) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_segment_start,
segmentIndex,
totalSegments,
segment.MoveType,
segment.ExitTransition));
public void OnSegmentCompleted(int segmentIndex, int totalSegments, PathSegment segment, int elapsedTicks, Location position) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_segment_complete,
segmentIndex,
totalSegments,
segment.MoveType,
elapsedTicks,
position.X,
position.Y,
position.Z));
public void OnSegmentFailed(int segmentIndex, int totalSegments, PathSegment segment, int elapsedTicks, Location position) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_segment_failed,
segmentIndex,
totalSegments,
segment.MoveType,
elapsedTicks,
position.X,
position.Y,
position.Z));
public void OnNavigationCompleted(int totalTicks) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_route_complete,
totalTicks));
public void OnReplanStarted(int replanCount, Location position) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_replan_start,
replanCount,
position.X,
position.Y,
position.Z));
public void OnReplanSucceeded(int replanCount, IReadOnlyList<PathSegment> segments) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_replan_success,
replanCount,
segments.Count));
public void OnReplanFailed(int replanCount, Location position) =>
_debug?.Invoke(string.Format(
CultureInfo.InvariantCulture,
Translations.pathing_metric_replan_failed,
replanCount,
position.X,
position.Y,
position.Z));
}
}

View file

@ -3527,6 +3527,78 @@ namespace MinecraftClient {
return ResourceManager.GetString("cmd.goto.failed", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] routeStart segments={0}.
/// </summary>
internal static string pathing_metric_route_start {
get {
return ResourceManager.GetString("pathing.metric.route_start", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] segmentStart index={0} total={1} move={2} transition={3}.
/// </summary>
internal static string pathing_metric_segment_start {
get {
return ResourceManager.GetString("pathing.metric.segment_start", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] segmentComplete index={0} total={1} move={2} ticks={3} x={4:F2} y={5:F2} z={6:F2}.
/// </summary>
internal static string pathing_metric_segment_complete {
get {
return ResourceManager.GetString("pathing.metric.segment_complete", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] segmentFailed index={0} total={1} move={2} ticks={3} x={4:F2} y={5:F2} z={6:F2}.
/// </summary>
internal static string pathing_metric_segment_failed {
get {
return ResourceManager.GetString("pathing.metric.segment_failed", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] routeComplete totalTicks={0}.
/// </summary>
internal static string pathing_metric_route_complete {
get {
return ResourceManager.GetString("pathing.metric.route_complete", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] replanStart count={0} x={1:F2} y={2:F2} z={3:F2}.
/// </summary>
internal static string pathing_metric_replan_start {
get {
return ResourceManager.GetString("pathing.metric.replan_start", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] replanSuccess count={0} segments={1}.
/// </summary>
internal static string pathing_metric_replan_success {
get {
return ResourceManager.GetString("pathing.metric.replan_success", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to [PathMetric] replanFailed count={0} x={1:F2} y={2:F2} z={3:F2}.
/// </summary>
internal static string pathing_metric_replan_failed {
get {
return ResourceManager.GetString("pathing.metric.replan_failed", resourceCulture);
}
}
/// <summary>
/// Looks up a localized string similar to Already following {0}!.

View file

@ -1252,6 +1252,30 @@ Change EnableEmoji=false in the settings if the display is confusing.</value>
<data name="cmd.goto.failed" xml:space="preserve">
<value>No path found ({0} nodes explored in {1}ms)</value>
</data>
<data name="pathing.metric.route_start" xml:space="preserve">
<value>[PathMetric] routeStart segments={0}</value>
</data>
<data name="pathing.metric.segment_start" xml:space="preserve">
<value>[PathMetric] segmentStart index={0} total={1} move={2} transition={3}</value>
</data>
<data name="pathing.metric.segment_complete" xml:space="preserve">
<value>[PathMetric] segmentComplete index={0} total={1} move={2} ticks={3} x={4:F2} y={5:F2} z={6:F2}</value>
</data>
<data name="pathing.metric.segment_failed" xml:space="preserve">
<value>[PathMetric] segmentFailed index={0} total={1} move={2} ticks={3} x={4:F2} y={5:F2} z={6:F2}</value>
</data>
<data name="pathing.metric.route_complete" xml:space="preserve">
<value>[PathMetric] routeComplete totalTicks={0}</value>
</data>
<data name="pathing.metric.replan_start" xml:space="preserve">
<value>[PathMetric] replanStart count={0} x={1:F2} y={2:F2} z={3:F2}</value>
</data>
<data name="pathing.metric.replan_success" xml:space="preserve">
<value>[PathMetric] replanSuccess count={0} segments={1}</value>
</data>
<data name="pathing.metric.replan_failed" xml:space="preserve">
<value>[PathMetric] replanFailed count={0} x={1:F2} y={2:F2} z={3:F2}</value>
</data>
<data name="cmd.follow.already_following" xml:space="preserve">
<value>Already following {0}!</value>
</data>

View file

@ -111,19 +111,22 @@ def validate_report(
if report.total_ticks > timing_budget["maxTotalTicks"]:
raise SystemExit(
f"Route exceeded budget for {scenario_id}: actual={report.total_ticks} "
f"max={timing_budget['maxTotalTicks']}"
f"max={timing_budget['maxTotalTicks']}\n"
f"{render_report(scenario_id, report, timing_budget)}"
)
for expected, actual in zip(expected_timing_segments, report.segments, strict=True):
if actual.move != expected["moveType"]:
raise SystemExit(
f"Timing move mismatch for {scenario_id} segment {actual.index}: "
f"expected {expected['moveType']}, saw {actual.move}"
f"expected {expected['moveType']}, saw {actual.move}\n"
f"{render_report(scenario_id, report, timing_budget)}"
)
if actual.ticks > expected["maxTicks"]:
raise SystemExit(
f"Segment {actual.index} slow for {scenario_id}: move={actual.move} "
f"actual={actual.ticks} max={expected['maxTicks']}"
f"actual={actual.ticks} max={expected['maxTicks']}\n"
f"{render_report(scenario_id, report, timing_budget)}"
)

View file

@ -11,6 +11,8 @@ USERNAME="CursorBot"
SESSION_ROOT="$(_mcc_session_root "$SESSION")"
LOG="$(_mcc_session_log_file "$SESSION")"
PLANNER_CONTRACTS="$REPO_ROOT/MinecraftClient.Tests/TestData/Pathing/pathing-planner-contracts.json"
TIMING_BUDGETS="$REPO_ROOT/MinecraftClient.Tests/TestData/Pathing/pathing-timing-budgets.json"
PASSED_CASES=()
FAILED_CASES=()
@ -251,14 +253,15 @@ set_stone() {
}
run_accepted_route() {
local label="$1"
local start_x="$2"
local start_y="$3"
local start_z="$4"
local goal_x="$5"
local goal_y="$6"
local goal_z="$7"
local timeout="${8:-45}"
local scenario_id="$1"
local label="$2"
local start_x="$3"
local start_y="$4"
local start_z="$5"
local goal_x="$6"
local goal_y="$7"
local goal_z="$8"
local timeout="${9:-45}"
prepare_independent_route "$label" "$start_x" "$start_y" "$start_z"
capture_debug_state_before_route "$label"
@ -269,6 +272,12 @@ run_accepted_route() {
wait_for_navigation "$start_line" "$timeout"
assert_no_partial_since "$start_line"
assert_no_replans_since "$start_line"
python3 "$REPO_ROOT/tools/pathing_contract_report.py" \
--scenario-id "$scenario_id" \
--log-file "$LOG" \
--from-line "$start_line" \
--planner-contracts "$PLANNER_CONTRACTS" \
--timing-budgets "$TIMING_BUDGETS"
capture_debug_state_after_route "$label"
local x y z
@ -318,7 +327,7 @@ scenario_repeated_cardinal_parkour() {
set_stone 584 79 580
set_stone 586 79 580
set_stone 588 79 580
run_accepted_route "Repeated jump - cardinal parkour chain" "580.5" "80" "580.5" "588" "80.00" "580"
run_accepted_route "repeated-cardinal-parkour-chain" "Repeated jump - cardinal parkour chain" "580.5" "80" "580.5" "588" "80.00" "580"
}
scenario_repeated_diagonal_parkour() {
@ -328,7 +337,7 @@ scenario_repeated_diagonal_parkour() {
set_stone 602 79 602
set_stone 604 79 604
set_stone 606 79 606
run_accepted_route "Repeated jump - diagonal parkour chain" "600.5" "80" "600.5" "606" "80.00" "606"
run_accepted_route "repeated-diagonal-parkour-chain" "Repeated jump - diagonal parkour chain" "600.5" "80" "600.5" "606" "80.00" "606"
}
scenario_obstructed_parkour_turn_mix() {
@ -344,7 +353,7 @@ scenario_obstructed_parkour_turn_mix() {
set_stone 620 81 621
set_stone 622 80 622
set_stone 622 81 622
run_accepted_route "Obstructed jump mix - repeated parkour L-turns" "620.5" "80" "620.5" "626" "80.00" "622"
run_accepted_route "obstructed-parkour-l-turns" "Obstructed jump mix - repeated parkour L-turns" "620.5" "80" "620.5" "626" "80.00" "622"
}
scenario_parkour_ascend_descend_chain() {
@ -355,7 +364,7 @@ scenario_parkour_ascend_descend_chain() {
set_stone 644 79 620
set_stone 646 80 620
set_stone 648 79 620
run_accepted_route "Vertical jump mix - parkour ascend descend chain" "640.5" "80" "620.5" "648" "80.00" "620"
run_accepted_route "vertical-jump-mix" "Vertical jump mix - parkour ascend descend chain" "640.5" "80" "620.5" "648" "80.00" "620"
}
scenario_diagonal_ascend_descend_chain() {
@ -366,7 +375,7 @@ scenario_diagonal_ascend_descend_chain() {
set_stone 682 79 622
set_stone 683 80 623
set_stone 684 79 624
run_accepted_route "Diagonal vertical mix - ascend descend chain" "680.5" "80" "620.5" "684" "80.00" "624"
run_accepted_route "diagonal-vertical-mix" "Diagonal vertical mix - ascend descend chain" "680.5" "80" "620.5" "684" "80.00" "624"
}
start_mcc

View file

@ -11,6 +11,8 @@ USERNAME="CursorBot"
SESSION_ROOT="$(_mcc_session_root "$SESSION")"
LOG="$(_mcc_session_log_file "$SESSION")"
PLANNER_CONTRACTS="$REPO_ROOT/MinecraftClient.Tests/TestData/Pathing/pathing-planner-contracts.json"
TIMING_BUDGETS="$REPO_ROOT/MinecraftClient.Tests/TestData/Pathing/pathing-timing-budgets.json"
cleanup() {
mcc-kill --session "$SESSION" >/dev/null 2>&1 || true
@ -248,14 +250,15 @@ set_stone() {
}
run_accepted_route() {
local label="$1"
local start_x="$2"
local start_y="$3"
local start_z="$4"
local goal_x="$5"
local goal_y="$6"
local goal_z="$7"
local timeout="${8:-45}"
local scenario_id="$1"
local label="$2"
local start_x="$3"
local start_y="$4"
local start_z="$5"
local goal_x="$6"
local goal_y="$7"
local goal_z="$8"
local timeout="${9:-45}"
prepare_independent_route "$label" "$start_x" "$start_y" "$start_z"
capture_debug_state_before_route "$label"
@ -266,6 +269,12 @@ run_accepted_route() {
wait_for_navigation "$start_line" "$timeout"
assert_no_partial_since "$start_line"
assert_no_replans_since "$start_line"
python3 "$REPO_ROOT/tools/pathing_contract_report.py" \
--scenario-id "$scenario_id" \
--log-file "$LOG" \
--from-line "$start_line" \
--planner-contracts "$PLANNER_CONTRACTS" \
--timing-budgets "$TIMING_BUDGETS"
capture_debug_state_after_route "$label"
local x y z
@ -290,7 +299,7 @@ run_same_move_routes() {
fill_box 298 79 298 314 79 302 air
fill_box 298 80 298 314 90 302 air
fill_box 300 79 300 312 79 300 stone
run_accepted_route "Same move - straight traverse chain" "300.5" "80" "300.5" "312" "80.00" "300"
run_accepted_route "same-move-straight-traverse-chain" "Same move - straight traverse chain" "300.5" "80" "300.5" "312" "80.00" "300"
fill_box 318 79 318 330 79 330 air
fill_box 318 80 318 330 90 330 air
@ -302,7 +311,7 @@ run_same_move_routes() {
set_stone 325 79 325
set_stone 326 79 326
set_stone 327 79 327
run_accepted_route "Same move - diagonal chain" "320.5" "80" "320.5" "327" "80.00" "327"
run_accepted_route "same-move-diagonal-chain" "Same move - diagonal chain" "320.5" "80" "320.5" "327" "80.00" "327"
fill_box 338 79 338 347 85 342 air
fill_box 338 80 338 347 90 342 air
@ -312,7 +321,7 @@ run_same_move_routes() {
fill_box 343 82 339 343 82 341 stone
fill_box 344 83 339 344 83 341 stone
fill_box 345 84 339 345 84 341 stone
run_accepted_route "Same move - ascend staircase" "340.5" "80" "340.5" "345" "85.00" "340"
run_accepted_route "same-move-ascend-staircase" "Same move - ascend staircase" "340.5" "80" "340.5" "345" "85.00" "340"
fill_box 360 79 358 369 85 362 air
fill_box 360 80 358 369 90 362 air
@ -322,7 +331,7 @@ run_same_move_routes() {
fill_box 365 81 359 365 81 361 stone
fill_box 366 80 359 366 80 361 stone
fill_box 367 79 359 367 79 361 stone
run_accepted_route "Same move - descend staircase" "362.5" "85" "360.5" "367" "80.00" "360"
run_accepted_route "same-move-descend-staircase" "Same move - descend staircase" "362.5" "85" "360.5" "367" "80.00" "360"
fill_box 378 79 378 390 79 382 air
fill_box 378 80 378 390 90 382 air
@ -331,7 +340,7 @@ run_same_move_routes() {
set_stone 384 79 380
set_stone 386 79 380
set_stone 388 79 380
run_accepted_route "Same move - aligned parkour chain" "380.5" "80" "380.5" "388" "80.00" "380"
run_accepted_route "same-move-aligned-parkour-chain" "Same move - aligned parkour chain" "380.5" "80" "380.5" "388" "80.00" "380"
}
run_mixed_move_routes() {
@ -351,7 +360,7 @@ run_mixed_move_routes() {
set_stone 406 79 404
set_stone 407 79 404
set_stone 408 79 404
run_accepted_route "Mixed - traverse turn parkour turn traverse" "400.5" "80" "400.5" "408" "80.00" "404"
run_accepted_route "mixed-traverse-turn-parkour-turn-traverse" "Mixed - traverse turn parkour turn traverse" "400.5" "80" "400.5" "408" "80.00" "404"
fill_box 418 79 418 430 82 424 air
fill_box 418 80 418 430 92 424 air
@ -364,7 +373,7 @@ run_mixed_move_routes() {
set_stone 426 81 422
set_stone 427 80 422
set_stone 428 79 422
run_accepted_route "Mixed - diagonal ascend traverse descend" "420.5" "80" "420.5" "428" "80.00" "422"
run_accepted_route "mixed-diagonal-ascend-traverse-descend" "Mixed - diagonal ascend traverse descend" "420.5" "80" "420.5" "428" "80.00" "422"
fill_box 438 79 438 450 82 442 air
fill_box 438 80 438 450 92 442 air
@ -376,7 +385,7 @@ run_mixed_move_routes() {
set_stone 446 81 440
set_stone 447 80 440
set_stone 448 79 440
run_accepted_route "Mixed - traverse ascend parkour descend" "440.5" "80" "440.5" "448" "80.00" "440"
run_accepted_route "mixed-traverse-ascend-parkour-descend" "Mixed - traverse ascend parkour descend" "440.5" "80" "440.5" "448" "80.00" "440"
}
run_turn_density_routes() {
@ -394,7 +403,7 @@ run_turn_density_routes() {
set_stone 465 79 464
set_stone 465 79 465
set_stone 466 79 466
run_accepted_route "Turn density - alternating traverse diagonal chain" "460.5" "80" "460.5" "466" "80.00" "466"
run_accepted_route "turn-density-alternating-traverse-diagonal-chain" "Turn density - alternating traverse diagonal chain" "460.5" "80" "460.5" "466" "80.00" "466"
}
run_speed_carry_routes() {
@ -411,7 +420,7 @@ run_speed_carry_routes() {
set_stone 486 82 480
set_stone 487 82 480
set_stone 488 83 480
run_accepted_route "Speed carry - repeated traverse ascend" "480.5" "80" "480.5" "488" "84.00" "480"
run_accepted_route "speed-carry-repeated-traverse-ascend" "Speed carry - repeated traverse ascend" "480.5" "80" "480.5" "488" "84.00" "480"
fill_box 498 79 498 510 82 502 air
fill_box 498 80 498 510 94 502 air
@ -423,7 +432,7 @@ run_speed_carry_routes() {
set_stone 505 80 500
set_stone 506 79 500
set_stone 507 79 500
run_accepted_route "Speed carry - repeated traverse descend" "500.5" "83" "500.5" "507" "80.00" "500"
run_accepted_route "speed-carry-repeated-traverse-descend" "Speed carry - repeated traverse descend" "500.5" "83" "500.5" "507" "80.00" "500"
fill_box 518 79 518 532 79 522 air
fill_box 518 80 518 532 90 522 air
@ -434,7 +443,7 @@ run_speed_carry_routes() {
set_stone 526 79 520
set_stone 527 79 520
set_stone 529 79 520
run_accepted_route "Speed carry - repeated traverse parkour" "520.5" "80" "520.5" "529" "80.00" "520"
run_accepted_route "speed-carry-repeated-traverse-parkour" "Speed carry - repeated traverse parkour" "520.5" "80" "520.5" "529" "80.00" "520"
}
start_mcc

View file

@ -1,6 +1,8 @@
from pathlib import Path
from tools.pathing_contract_report import parse_metrics
import pytest
from tools.pathing_contract_report import MetricsReport, SegmentMetric, parse_metrics, validate_report
def test_parse_metrics_reads_route_and_segment_ticks(tmp_path: Path) -> None:
@ -12,3 +14,27 @@ def test_parse_metrics_reads_route_and_segment_ticks(tmp_path: Path) -> None:
assert report.total_ticks == 70
assert [segment.ticks for segment in report.segments] == [17, 16]
def test_validate_report_includes_route_and_segment_table_on_budget_failure() -> None:
report = MetricsReport(
segments=[SegmentMetric(index=0, move="Parkour", ticks=17)],
total_ticks=70,
replans=0,
planned=[],
)
planner_contract = {"segments": []}
timing_budget = {
"expectedTotalTicks": 60,
"maxTotalTicks": 65,
"segments": [
{"moveType": "Parkour", "expectedTicks": 15, "maxTicks": 16},
],
}
with pytest.raises(SystemExit) as exc:
validate_report("sample-scenario", report, planner_contract, timing_budget)
message = str(exc.value)
assert "Route sample-scenario: actual=70 expected=60 max=65" in message
assert "seg[0] move=Parkour actual=17 expected=15 max=16 delta=+2" in message