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}