Observe: record player-order pauses and their resume (#270 agent side)

README.md

@@ -1686,10 +1686,13 @@ The server needs `AiPlayerbot.DungeonSelfClear = 1` and `AiPlayerbot.RemoteComma
 
 **Controls.** `dungeon_stop` stops the run (`.bot run stop`, then the unbind). In an observed run `dungeon_pause`, `dungeon_resume` and `dungeon_skip` send the run leader's own
 `.bot run pause|resume|skip` on the watch's next look; the answer is in `report.remote.observe.controls`. The `commander` method takes `{"op":"run","verb":"status"}`
-for a hand-sent run command.
+for a hand-sent run command. A pause the module makes for a player's order (`PauseForPlayer`: the observer's own `cmd summon`, a `move`, ...) is listed in
+`report.remote.observe.player_orders`, one entry per pause (later orders during the same pause are not listed separately), with the step and the order (`step 2/5 (first): cmd summon Healy`); `controls` also records
+`player order: ...` and `resumed after the player order at step N` when the run goes on again, also when a person resumed on the server (a run that stops instead of going on ends the pause with no resume entry). The pause itself is the module's: after a `cmd`
+order the run waits for `dungeon_resume` / `.bot run resume`.
 
 **Report.** `report.remote.mode` is `observe`; `report.remote.observe` has `plan`, the newest `state`, `step`, `steps`, `leg`, `kind`, `phase`, `note` and a
-plain-words `text`, `started`, `lines`, `polls`, `pauses`, `controls`, `ended` and `changes[]` (the newest 300 status changes with their time). `report.wipes`
+plain-words `text`, `started`, `lines`, `polls`, `pauses`, `controls`, `player_orders`, `ended` and `changes[]` (the newest 300 status changes with their time). `report.wipes`
 counts the watched party's wipes: one rising edge of "every bot dead" in the feed is one wipe, the latch re-arms only once fewer than
 3 members are dead (a single member revived in place for a poll, dead again the next, does not count a second wipe). A wipe also counts
 when every member has died within 90 s of each other, each death newer than the last counted wipe, even if the lead bot revived in

internal/dungeon/observe.go

@@ -153,6 +153,8 @@ type ObserveReport struct {
 	Pauses int `json:"pauses"`
 	// Controls are the pause, resume, skip and stop requests sent, in order, each with its answer.
 	Controls []string `json:"controls,omitempty"`
+	// PlayerOrders are the pauses the module made for a player's order (the observer's `cmd summon`, a move), each with the step and the order.
+	PlayerOrders []string `json:"player_orders,omitempty"`
 	// Ended is how the watch ended: done, or the reason of a failure or stop.
 	Ended string `json:"ended,omitempty"`
 	// Changes are the status changes, oldest first (the newest MaxRunChanges).
@@ -165,6 +167,7 @@ func (r *ObserveReport) clone() *ObserveReport {
 	}
 	c := *r
 	c.Controls = append([]string(nil), r.Controls...)
+	c.PlayerOrders = append([]string(nil), r.PlayerOrders...)
 	c.Changes = append([]RunChange{}, r.Changes...)
 	return &c
 }
@@ -191,6 +194,8 @@ type observeState struct {
 	// The run leader's own rest (observe mode has no gate of the agent's): the phase rest of its status is the gate.
 	restSince time.Time // when the run leader's current rest phase began
 	restOpen  bool
+	// playerPaused: the run is paused for a player's order (the module's pause for a `cmd`), so the status says why it waits.
+	playerPaused bool
 
 	mu   sync.Mutex
 	reqs []string // pause, resume, skip requests from the RPC
@@ -715,6 +720,22 @@ func (d *RemoteDriver) takeLines(lines []string) {
 	}
 }
 
+// playerOrderOf reads the order out of the note of a pause the module made for a player's order: "player order (<order>): <why>". A later
+// status of the same pause appends to the note ("; X meanwhile: ..."), so the order ends at the first "): ". ok is false for any other note.
+func playerOrderOf(note string) (order string, ok bool) {
+	rest, ok := strings.CutPrefix(note, "player order (")
+	if !ok {
+		return "", false
+	}
+	if order, _, ok := strings.Cut(rest, "): "); ok {
+		return order, true
+	}
+	if i := strings.LastIndex(rest, ")"); i >= 0 {
+		return rest[:i], true
+	}
+	return "", false
+}
+
 // takeStatus folds one status into the observer, the report, the trace, the events and the current-step label.
 func (d *RemoteDriver) takeStatus(st tbm.RunStatus) {
 	o := d.obs
@@ -761,6 +782,31 @@ func (d *RemoteDriver) takeStatus(st tbm.RunStatus) {
 			ob.Changes = append([]RunChange{}, ob.Changes[n-MaxRunChanges:]...)
 		}
 	})
+	// A pause the module made for a player's order (the observer's own `cmd summon`, a move) is the observer's doing: the report names the
+	// order so a person sees why the run waited. Only the first status of that pause counts: the module appends to the note of a pause it
+	// already made. The run going on again is the resume after the order, whether the agent or a person sent it.
+	if order, ok := playerOrderOf(st.Note); st.State == tbm.RunPaused && ok && !o.playerPaused {
+		o.playerPaused = true
+		d.remote(func(r *RemoteReport) {
+			if ob := r.Observe; len(ob.PlayerOrders) < 50 {
+				ob.PlayerOrders = append(ob.PlayerOrders, fmt.Sprintf("step %d/%d (%s): %s", st.Step, st.Steps, st.Leg, order))
+			}
+		})
+		d.control("player order: " + order)
+		d.tr.Event("player_order", map[string]any{"order": order, "step": st.Step, "leg_name": st.Leg})
+		d.rep.note("observe mode: the run paused for a player order (" + order + ")")
+	}
+	if o.playerPaused {
+		switch st.State {
+		case tbm.RunRunning:
+			o.playerPaused = false
+			d.control(fmt.Sprintf("resumed after the player order at step %d", st.Step))
+			d.rep.note("observe mode: the run went on after the player order")
+		case tbm.RunDone:
+			// The run stopped instead of going on: the pause is over, but there was no resume to record (#270).
+			o.playerPaused = false
+		}
+	}
 	label := "run leader: " + st.Text()
 	if st.State != tbm.RunRunning {
 		label = "run leader " + st.State + ": " + st.Text()

internal/dungeon/observe_test.go

@@ -787,6 +787,156 @@ func TestObservePauseAndResumeGoThroughTheRPC(t *testing.T) {
 	}
 }
 
+func TestPlayerOrderOf(t *testing.T) {
+	for _, c := range []struct {
+		note  string
+		order string
+		ok    bool
+	}{
+		{"player order (cmd summon Healy): .bot run resume to go on", "cmd summon Healy", true},
+		{"player order (move 1 2 3): .bot run resume to go on; cave cleared meanwhile: .bot run resume goes on with step 4", "move 1 2 3", true},
+		{"player order (cmd revive)", "cmd revive", true},
+		{"player order (cmd summon Healy): .bot run resume to go on; note (2): a later aside", "cmd summon Healy", true},
+		{"3 dead: regroup (cmd revive), then .bot run resume", "", false},
+		{"", "", false},
+	} {
+		order, ok := playerOrderOf(c.note)
+		if ok != c.ok || order != c.order {
+			t.Fatalf("playerOrderOf(%q) = %q, %v", c.note, order, ok)
+		}
+	}
+}
+
+// A pause the module made for a player's order (the observer's own `cmd summon`, a move) is the observer's doing: the report names the order,
+// and the run going on again is recorded as the resume after it.
+func TestObserveRecordsAPlayerOrderPauseAndItsResume(t *testing.T) {
+	g := newFakeLeader(t,
+		leaderStep{0, rs("running", 1, 5, "first", "move", "walk", "walking")},
+		leaderStep{s(5), rs("paused", 2, 5, "first", "pull", "gather", "player order (cmd summon Healy): .bot run resume to go on")},
+		leaderStep{s(10), rs("running", 3, 5, "first", "pull", "pull", "pulling 299")},
+		leaderStep{s(20), rs("done", 5, 5, "second", "move", "walk", "plan done")})
+	var d *RemoteDriver
+	paused, asked := false, false
+	g.onStatus = func(l *fakeLeader, st tbm.RunStatus) {
+		// the module paused the run for the order: the leader holds it until a resume
+		if st.State == tbm.RunPaused {
+			paused = true
+			l.paused = true
+		}
+	}
+	tick := g.onTick
+	g.onTick = func(gr *fakeRemote) {
+		// the resume comes a look after the paused status: the watch serves requests before it reads the feed
+		if paused && !asked {
+			asked = true
+			if err := d.RunControl("resume"); err != nil {
+				t.Error(err)
+			}
+		}
+		tick(gr)
+	}
+	d = NewRemoteDriver(observePlan(), g, DefaultConfig(), observeOpts(ObserveSpec{}), g.clock())
+	err := d.Run(context.Background(), 0)
+	rep, _ := d.Status()
+	if err != nil || rep.State != "done" {
+		t.Fatalf("%v %s %s", err, rep.State, rep.Error)
+	}
+	ob := rep.Remote.Observe
+	if len(ob.PlayerOrders) != 1 || !strings.Contains(ob.PlayerOrders[0], "cmd summon Healy") || !strings.Contains(ob.PlayerOrders[0], "step 2/") {
+		t.Fatalf("player orders %v", ob.PlayerOrders)
+	}
+	var order, resumed, ack bool
+	for _, c := range ob.Controls {
+		order = order || c == "player order: cmd summon Healy"
+		resumed = resumed || strings.HasPrefix(c, "resumed after the player order")
+		ack = ack || strings.HasPrefix(c, "resume: ack")
+	}
+	if !order || !resumed || !ack {
+		t.Fatalf("controls %v", ob.Controls)
+	}
+}
+
+// #270: a pause for a player order that ends in a stop did not resume: the latch lets go with no "resumed after" entry.
+func TestObservePlayerOrderPauseEndingInAStopHasNoResume(t *testing.T) {
+	g := newFakeLeader(t,
+		leaderStep{0, rs("running", 1, 5, "first", "move", "walk", "walking")},
+		leaderStep{s(5), rs("paused", 2, 5, "first", "pull", "gather", "player order (cmd summon Healy): .bot run resume to go on")},
+		leaderStep{s(10), rs("done", 5, 5, "second", "move", "walk", "plan done")})
+	rep, err := runRemote(t, g, observePlan(), observeOpts(ObserveSpec{}), nil)
+	if err != nil || rep.State != "done" {
+		t.Fatalf("%v %s %s", err, rep.State, rep.Error)
+	}
+	ob := rep.Remote.Observe
+	if len(ob.PlayerOrders) != 1 {
+		t.Fatalf("player orders %v", ob.PlayerOrders)
+	}
+	for _, c := range ob.Controls {
+		if strings.HasPrefix(c, "resumed after the player order") {
+			t.Fatalf("a stop wrote a resume: %v", ob.Controls)
+		}
+	}
+}
+
+func TestObserveDoesNotCountAnOrdinaryPauseAsAPlayerOrder(t *testing.T) {
+	g := newFakeLeader(t,
+		leaderStep{0, rs("running", 1, 5, "first", "move", "walk", "walking")},
+		leaderStep{s(5), rs("paused", 2, 5, "first", "pull", "gather", "3 dead: regroup (cmd revive), then .bot run resume")},
+		leaderStep{s(10), rs("running", 3, 5, "first", "pull", "pull", "pulling 299")},
+		leaderStep{s(20), rs("done", 5, 5, "second", "move", "walk", "plan done")})
+	var d *RemoteDriver
+	paused, asked := false, false
+	g.onStatus = func(l *fakeLeader, st tbm.RunStatus) {
+		if st.State == tbm.RunPaused {
+			paused = true
+			l.paused = true
+		}
+	}
+	tick := g.onTick
+	g.onTick = func(gr *fakeRemote) {
+		if paused && !asked {
+			asked = true
+			if err := d.RunControl("resume"); err != nil {
+				t.Error(err)
+			}
+		}
+		tick(gr)
+	}
+	d = NewRemoteDriver(observePlan(), g, DefaultConfig(), observeOpts(ObserveSpec{}), g.clock())
+	err := d.Run(context.Background(), 0)
+	rep, _ := d.Status()
+	if err != nil || rep.State != "done" {
+		t.Fatalf("%v %s %s", err, rep.State, rep.Error)
+	}
+	if g.indexOf("run resume") < 0 {
+		t.Fatalf("the run was never resumed: %v", g.orders)
+	}
+	ob := rep.Remote.Observe
+	if len(ob.PlayerOrders) != 0 {
+		t.Fatalf("player orders %v", ob.PlayerOrders)
+	}
+	for _, c := range ob.Controls {
+		if strings.HasPrefix(c, "player order") || strings.HasPrefix(c, "resumed after") {
+			t.Fatalf("controls %v", ob.Controls)
+		}
+	}
+}
+
+// The module appends to the note of a pause it already made ("; boss meanwhile: ..."): that is the same player order, counted once.
+func TestObservePlayerOrderPauseRepeatedNoteCountsOnce(t *testing.T) {
+	g := newFakeLeader(t,
+		leaderStep{0, rs("running", 1, 5, "first", "move", "walk", "walking")},
+		leaderStep{s(5), rs("paused", 2, 5, "first", "pull", "gather", "player order (cmd summon Healy): .bot run resume to go on")},
+		leaderStep{s(10), rs("paused", 2, 5, "first", "pull", "gather", "player order (cmd summon Healy): .bot run resume to go on; boss meanwhile: .bot run resume goes on with step 3")},
+		leaderStep{s(20), rs("done", 5, 5, "second", "move", "walk", "plan done")})
+	rep, err := runRemote(t, g, observePlan(), observeOpts(ObserveSpec{}), nil)
+	if err != nil || rep.State != "done" {
+		t.Fatalf("%v %s %s", err, rep.State, rep.Error)
+	}
+	if ob := rep.Remote.Observe; len(ob.PlayerOrders) != 1 {
+		t.Fatalf("player orders %v", ob.PlayerOrders)
+	}
+}
+
 func TestObserveAPausedRunThatNobodyResumesIsStopped(t *testing.T) {
 	g := newFakeLeader(t,
 		leaderStep{0, rs("running", 1, 5, "first", "move", "walk", "walking")},