feat(runner): say what each step did in the step log

One line per step carried only an index and a node count. It now names the
screen, the action, its target and the typed value, the last through the
same redaction the trace and the prompt use. Emitted after the apply so the
line reports what actually happened, skip reason included.
This commit is contained in:
pj committed 2026-08-19 18:37:55 +05:30
1 parent be8a7e0194
commit f59b7eab82
3 files changed
+95 -10

No files matched your search

+59
View File
@@ -0,0 +1,59 @@
package runner
import (
"bytes"
"log/slog"
"strings"
"testing"
"github.com/priyanshujain/sanderling/internal/verifier"
)
func logStepLine(t *testing.T, action verifier.Action, treeJSON string) string {
t.Helper()
var buffer bytes.Buffer
logger := slog.New(slog.NewTextHandler(&buffer, nil))
logStep(logger, 7, "LoginScreen", 42, action, nil, "", mustParseTree(t, treeJSON))
return buffer.String()
}
func TestLogStepNamesTheActionItsTargetAndTheTypedValue(t *testing.T) {
line := logStepLine(t, typeInto("id:LoginEmail"), iosLoginTreeJSON)
for _, want := range []string{
"index=7", "screen=LoginScreen", "nodes=42",
"action=InputText", "target=id:LoginEmail", typedCredential,
} {
if !strings.Contains(line, want) {
t.Errorf("step log = %q, want it to carry %q", line, want)
}
}
}
func TestLogStepRedactsTheTypedValueOfASecureField(t *testing.T) {
line := logStepLine(t, typeInto("id:LoginPassword"), iosLoginTreeJSON)
if strings.Contains(line, typedCredential) {
t.Errorf("step log = %q, want the typed credential withheld", line)
}
if !strings.Contains(line, verifier.RedactedInputText) {
t.Errorf("step log = %q, want %q", line, verifier.RedactedInputText)
}
if !strings.Contains(line, "target=id:LoginPassword") {
t.Errorf("step log = %q, want it to still name the field typed into", line)
}
}
func TestLogStepReportsAStepThatActedOnNothing(t *testing.T) {
var buffer bytes.Buffer
logger := slog.New(slog.NewTextHandler(&buffer, nil))
logStep(logger, 3, "", 0, verifier.Action{}, verifier.ErrNoAction, actionSkippedNoActionProduced, nil)
line := buffer.String()
if !strings.Contains(line, "action=none") {
t.Errorf("step log = %q, want action=none", line)
}
if !strings.Contains(line, "skipped="+string(actionSkippedNoActionProduced)) {
t.Errorf("step log = %q, want the skip reason", line)
}
}
+32 -6
View File
@@ -236,10 +236,7 @@ func Run(ctx context.Context, options Options) (Summary, error) {
} }
lastLogTime = stepStart lastLogTime = stepStart
screen := "" screen := tree.ScreenName()
if tree != nil && len(tree.Elements) > 0 {
screen = tree.Elements[0].Screen
}
// A transitional tree is one nothing can vouch for: a NavHost mid // A transitional tree is one nothing can vouch for: a NavHost mid
// cross-fade, a screen that changed shape between two reads, or a // cross-fade, a screen that changed shape between two reads, or a
@@ -332,8 +329,6 @@ func Run(ctx context.Context, options Options) (Summary, error) {
logger.Warn("unsettled tree; skipping verifier", logger.Warn("unsettled tree; skipping verifier",
"step", stepIndex, "screen", screen, "nodes", treeSize) "step", stepIndex, "screen", screen, "nodes", treeSize)
} }
logger.Info("step", "index", stepIndex, "screen", screen, "nodes", treeSize)
// A frame the verifier would not look at is not one to act on either. // A frame the verifier would not look at is not one to act on either.
// #75 is the fuzzer tapping into a screen that is still filling in, and // #75 is the fuzzer tapping into a screen that is still filling in, and
// holding the action back is also what keeps the spec's view of the run // holding the action back is also what keeps the spec's view of the run
@@ -474,6 +469,8 @@ func Run(ctx context.Context, options Options) (Summary, error) {
// the action it points at is still the one the next verified step has to // the action it points at is still the one the next verified step has to
// be told about. // be told about.
logStep(logger, stepIndex, screen, treeSize, nextAction, nextErr, actionSkipped, tree)
step := trace.Step{ step := trace.Step{
Index: stepIndex, Index: stepIndex,
Timestamp: stepStart, Timestamp: stepStart,
@@ -1578,6 +1575,35 @@ func driverIsAndroid(ctx context.Context, options Options, logger *slog.Logger)
return health.Platform == "android" return health.Platform == "android"
} }
// logStep prints the one line a run emits per step: what screen it saw and what
// it did there. The typed value goes through the same redaction the trace and
// the prompt use, so the console cannot publish a credential the records
// withhold.
func logStep(
logger *slog.Logger,
stepIndex int,
screen string,
treeSize int,
action verifier.Action,
actionErr error,
skipped actionSkipReason,
tree *hierarchy.Tree,
) {
attrs := []any{"index", stepIndex, "screen", screen, "nodes", treeSize}
if actionErr != nil {
attrs = append(attrs, "action", "none")
} else {
attrs = append(attrs, "action", string(action.Kind), "target", actionTarget(action))
if action.Kind == verifier.ActionKindInputText {
attrs = append(attrs, "text", verifier.RecordedActionText(action, tree))
}
}
if skipped != "" {
attrs = append(attrs, "skipped", string(skipped))
}
logger.Info("step", attrs...)
}
func traceActionFor(action verifier.Action, tree *hierarchy.Tree) *trace.Action { func traceActionFor(action verifier.Action, tree *hierarchy.Tree) *trace.Action {
traceAction := &trace.Action{ traceAction := &trace.Action{
Kind: string(action.Kind), Kind: string(action.Kind),
+4 -4
View File
@@ -1,4 +1,4 @@
{"extractor_changes":{"extractor_0":{"prev":null,"curr":0}},"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"step":1,"timestamp":"0001-01-01T00:00:00Z","trace_version":1} {"extractor_changes":{"extractor_0":{"prev":null,"curr":0}},"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"screen":"HomeScreen","step":1,"timestamp":"0001-01-01T00:00:00Z","trace_version":1}
{"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"step":2,"timestamp":"0001-01-01T00:00:00Z","trace_version":1} {"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"screen":"HomeScreen","step":2,"timestamp":"0001-01-01T00:00:00Z","trace_version":1}
{"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"step":3,"timestamp":"0001-01-01T00:00:00Z","trace_version":1} {"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"screen":"HomeScreen","step":3,"timestamp":"0001-01-01T00:00:00Z","trace_version":1}
{"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"step":4,"timestamp":"0001-01-01T00:00:00Z","trace_version":1} {"hierarchy":{"elements":[{"resourceId":"HomeScreen","bounds":{"left":0,"top":0,"right":0,"bottom":0},"attrs":{"editable":"false","resource-id":"HomeScreen"}},{"resourceId":"next","clickable":true,"enabled":true,"bounds":{"left":40,"top":80,"right":240,"bottom":160},"attrs":{"bounds":"[40,80,240,160]","clickable":"true","editable":"false","enabled":"true","resource-id":"next"}}],"depths":[0,1]},"next_action":{"kind":"Tap","selector":"id:next","resolved_bounds":{"x":40,"y":80,"width":200,"height":80},"tap_point":{"x":140,"y":120},"source":"seeded"},"residuals":{"balanceNonNegative":{"op":"true"}},"screen":"HomeScreen","step":4,"timestamp":"0001-01-01T00:00:00Z","trace_version":1}