diff --git a/README.md b/README.md index 6aab75bf..7597911d 100644 --- a/README.md +++ b/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 diff --git a/internal/dungeon/observe.go b/internal/dungeon/observe.go index 3b1f6d1c..0b7456ea 100644 --- a/internal/dungeon/observe.go +++ b/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 (): ". 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() diff --git a/internal/dungeon/observe_test.go b/internal/dungeon/observe_test.go index 2a716d8c..87850ab6 100644 --- a/internal/dungeon/observe_test.go +++ b/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")},