From f59b7eab820cee9560bee08fc8f1526e5b0ad260 Mon Sep 17 00:00:00 2001 From: PJ Date: Wed, 19 Aug 2026 18:37:55 +0530 Subject: [PATCH] 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. --- internal/runner/log_step_test.go | 59 ++++++++++++++++++++++++++++ internal/runner/runner.go | 38 +++++++++++++++--- internal/runner/testdata/trace.jsonl | 8 ++-- 3 files changed, 95 insertions(+), 10 deletions(-) create mode 100644 internal/runner/log_step_test.go diff --git a/internal/runner/log_step_test.go b/internal/runner/log_step_test.go new file mode 100644 index 0000000..4251c71 --- /dev/null +++ b/internal/runner/log_step_test.go @@ -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) + } +} diff --git a/internal/runner/runner.go b/internal/runner/runner.go index dd9ed16..98dce79 100644 --- a/internal/runner/runner.go +++ b/internal/runner/runner.go @@ -236,10 +236,7 @@ func Run(ctx context.Context, options Options) (Summary, error) { } lastLogTime = stepStart - screen := "" - if tree != nil && len(tree.Elements) > 0 { - screen = tree.Elements[0].Screen - } + screen := tree.ScreenName() // A transitional tree is one nothing can vouch for: a NavHost mid // 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", "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. // #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 @@ -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 // be told about. + logStep(logger, stepIndex, screen, treeSize, nextAction, nextErr, actionSkipped, tree) + step := trace.Step{ Index: stepIndex, Timestamp: stepStart, @@ -1578,6 +1575,35 @@ func driverIsAndroid(ctx context.Context, options Options, logger *slog.Logger) 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 { traceAction := &trace.Action{ Kind: string(action.Kind), diff --git a/internal/runner/testdata/trace.jsonl b/internal/runner/testdata/trace.jsonl index 58bbfe1..ac7a869 100644 --- a/internal/runner/testdata/trace.jsonl +++ b/internal/runner/testdata/trace.jsonl @@ -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} -{"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"}},"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} +{"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"}},"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"}},"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"}},"screen":"HomeScreen","step":4,"timestamp":"0001-01-01T00:00:00Z","trace_version":1}