diff --git a/internal/driver/chrome/driver.go b/internal/driver/chrome/driver.go index db51c01..06914bd 100644 --- a/internal/driver/chrome/driver.go +++ b/internal/driver/chrome/driver.go @@ -887,6 +887,30 @@ func (d *Driver) SetLastAction(ctx context.Context, encoded json.RawMessage) err return nil } +// SetLogs installs the entries this step's log fetch returned as state.logs +// inside the page runtime. The page cannot derive them: console output reaches +// the driver over CDP and nothing in the page reads it back. Without this call +// every web state.logs is empty, and since the page's reading of an extractor +// replaces the host's, the default noLogcatErrors then reports green on a run +// whose console was full of errors. +// +// Unguarded for the same reason as SetLastAction: on a page with no setter, +// "the page cannot accept logs" has to fail the run rather than be reported as +// a successful install. +func (d *Driver) SetLogs(ctx context.Context, encoded json.RawMessage) error { + payload := strings.TrimSpace(string(encoded)) + if payload == "" { + payload = "[]" + } + script := fmt.Sprintf(`window.__sanderlingSetLogs__(%s)`, payload) + runCtx, cancel := d.runCtx(ctx) + defer cancel() + if err := chromedp.Run(runCtx, chromedp.Evaluate(script, nil)); err != nil { + return fmt.Errorf("set logs: %w", err) + } + return nil +} + // extractorScript resolves the extractor table once the page is not mid route // transition, giving up on that wait after %d ms. // diff --git a/internal/driver/chrome/driver_test.go b/internal/driver/chrome/driver_test.go index 36ef3fb..a0708a4 100644 --- a/internal/driver/chrome/driver_test.go +++ b/internal/driver/chrome/driver_test.go @@ -860,6 +860,54 @@ func TestSetLastAction_ReportsAPageThatCannotTakeIt(t *testing.T) { } } +// TestSetLogs_ReportsAPageThatCannotTakeThem is the same install on the channel +// the log properties hang off. The driver holding a console error changes +// nothing on web: the page's reading of every extractor replaces the host's, so +// unless the entries are put back into the page, noLogcatErrors counts an empty +// array and stays green through a run full of errors. +func TestSetLogs_ReportsAPageThatCannotTakeThem(t *testing.T) { + const withSetter = `` + const withoutSetter = `
no sanderling runtime here
` + pages := map[string]string{"/with": withSetter, "/without": withoutSetter} + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "text/html") + _, _ = w.Write([]byte(pages[r.URL.Path])) + })) + defer server.Close() + + d := New() + defer d.Terminate(context.Background()) + ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) + defer cancel() + + if err := d.Launch(ctx, server.URL+"/with", false, nil); err != nil { + t.Fatalf("Launch: %v", err) + } + logs := json.RawMessage(`[{"unixMillis":1,"level":"E","tag":"console","message":"boom"}]`) + if err := d.SetLogs(ctx, logs); err != nil { + t.Fatalf("SetLogs on a page that defines the setter: %v", err) + } + var seen []map[string]any + if err := chromedp.Run(d.tabCtx, + chromedp.Evaluate(`window.__logsSeen`, &seen)); err != nil { + t.Fatalf("read installed logs: %v", err) + } + if len(seen) != 1 || seen[0]["level"] != "E" || seen[0]["message"] != "boom" { + t.Errorf("the page received %v, want the error-level entry the driver captured", seen) + } + + if err := d.Launch(ctx, server.URL+"/without", false, nil); err != nil { + t.Fatalf("Launch: %v", err) + } + if err := d.SetLogs(ctx, logs); err == nil { + t.Error("SetLogs reported success on a page with no setter; " + + "a runtime that cannot take the step's logs is indistinguishable from one that did") + } +} + // TestEvaluateExtractors_ReportsAMissingTable is the same failure on the other // sampler. An empty override map is what a spec with no extractors returns, so // treating a missing table as {} makes "this page has no sanderling runtime" diff --git a/internal/runner/runner.go b/internal/runner/runner.go index 478907c..d89b8cf 100644 --- a/internal/runner/runner.go +++ b/internal/runner/runner.go @@ -163,7 +163,7 @@ func Run(ctx context.Context, options Options) (Summary, error) { }) logSince := lastLogTime g.Go(func() error { - logs = collectLogs(gctx, options.Driver, logSince) + logs = collectLogs(gctx, options.Driver, logger, si, logSince) return nil }) // All goroutines write to local variables and return nil, so the Wait @@ -222,9 +222,10 @@ func Run(ctx context.Context, options Options) (Summary, error) { // behind the hierarchy fetch; the fetch is what decides whether this // step counts at all, so it has to go first. // - // lastAction is the same value PushSnapshot hands the goja state - // below: the two engines evaluate this step against one action. - v8Overrides, overridesErr := extractorSource.ExtractorOverrides(ctx, lastAction) + // lastAction and logs are the same values PushSnapshot hands the + // goja state below: the two engines evaluate this step against one + // action and one set of log entries. + v8Overrides, overridesErr := extractorSource.ExtractorOverrides(ctx, lastAction, logs) if overridesErr != nil { // Not a warning. Without the page's values this step's // extractors keep goja's dump-derived readings while the @@ -823,11 +824,23 @@ func applyAction(ctx context.Context, drv driver.DeviceDriver, action verifier.A } // collectLogs pulls recent error-level log entries from the driver since the -// previous fetch. A failure is warned-on but not fatal: log capture is a -// best-effort observability channel, not a correctness dependency. -func collectLogs(ctx context.Context, drv driver.DeviceDriver, since time.Time) []verifier.LogEntry { +// previous fetch. A failure is warned-on but not fatal: one unreadable fetch on +// a flaky device should not end a run. It is not free either. This fetch is the +// whole evidence base for state.logs, so a step that could not make it leaves +// every log property (the default noLogcatErrors included) holding on an empty +// slice, and that has to be visible in the run's output rather than read as the +// app having logged nothing. +func collectLogs( + ctx context.Context, + drv driver.DeviceDriver, + logger *slog.Logger, + step int, + since time.Time, +) []verifier.LogEntry { entries, err := drv.RecentLogs(ctx, since, "E") if err != nil { + logger.Warn("log fetch failed; log properties hold vacuously this step", + "step", step, "err", err) return nil } result := make([]verifier.LogEntry, 0, len(entries)) diff --git a/internal/runner/source.go b/internal/runner/source.go index 513a8ab..f8f4c66 100644 --- a/internal/runner/source.go +++ b/internal/runner/source.go @@ -24,14 +24,15 @@ type ActionSource interface { // PushSnapshot. The mobile path has none (returns nil); the web path returns the // values its extractors computed in V8 against the real DOM. // -// lastAction is the action the previous step actually applied, the same value -// PushSnapshot hands the goja state. The web path has to install it in the page -// before its extractors run: a spec extractor reading state.lastAction runs in -// V8 there, and V8 has no way to know what the runner dispatched. +// lastAction and logs are what PushSnapshot hands the goja state. The web path +// has to install both in the page before its extractors run: a spec extractor +// reading state.lastAction or state.logs runs in V8 there, and V8 knows neither +// what the runner dispatched nor what the driver's log fetch returned. type ExtractorSource interface { ExtractorOverrides( ctx context.Context, lastAction *verifier.Action, + logs []verifier.LogEntry, ) (map[int]json.RawMessage, error) } @@ -42,6 +43,13 @@ type lastActionInstaller interface { SetLastAction(ctx context.Context, encoded json.RawMessage) error } +// logInstaller is the same channel for the entries this step's log fetch +// returned. Console output reaches the driver over CDP, so the page can only +// learn about it from the runner. +type logInstaller interface { + SetLogs(ctx context.Context, encoded json.RawMessage) error +} + // gojaSource drives both action selection and (trivially) extractor overrides // for the mobile path, where the goja-bundled picker runs in-process and no V8 // extractor values exist. @@ -56,6 +64,7 @@ func (s gojaSource) NextAction(context.Context) (verifier.Action, error) { func (gojaSource) ExtractorOverrides( context.Context, *verifier.Action, + []verifier.LogEntry, ) (map[int]json.RawMessage, error) { return nil, nil } @@ -77,24 +86,35 @@ func (s webSource) NextAction(ctx context.Context) (verifier.Action, error) { return verifier.DecodeAction(raw) } -// ExtractorOverrides installs the previous step's action in the page, then -// reads back what the spec's extractors computed against the live DOM. The -// install is not best-effort: a web driver that cannot take it leaves -// state.lastAction null in V8, which silently turns every action-gated -// property vacuously true, so it is reported as an error instead. +// ExtractorOverrides installs the previous step's action and this step's log +// entries in the page, then reads back what the spec's extractors computed +// against the live DOM. Neither install is best-effort: a web driver that +// cannot take them leaves state.lastAction null and state.logs empty in V8, +// which silently turns every action-gated property and every log property +// vacuously true, so both are reported as errors instead. func (s webSource) ExtractorOverrides( ctx context.Context, lastAction *verifier.Action, + logs []verifier.LogEntry, ) (map[int]json.RawMessage, error) { - installer, ok := s.web.(lastActionInstaller) + actions, ok := s.web.(lastActionInstaller) if !ok { return nil, fmt.Errorf( "web driver %T cannot install state.lastAction; every property gated "+ "on the last action would be vacuously true", s.web) } - if err := installer.SetLastAction(ctx, verifier.EncodeLastAction(lastAction)); err != nil { + if err := actions.SetLastAction(ctx, verifier.EncodeLastAction(lastAction)); err != nil { return nil, fmt.Errorf("install last action: %w", err) } + entries, ok := s.web.(logInstaller) + if !ok { + return nil, fmt.Errorf( + "web driver %T cannot install state.logs; every property reading the "+ + "log stream would be vacuously true", s.web) + } + if err := entries.SetLogs(ctx, verifier.EncodeLogs(logs)); err != nil { + return nil, fmt.Errorf("install logs: %w", err) + } return s.web.EvaluateExtractors(ctx) } diff --git a/internal/runner/web_carrier_test.go b/internal/runner/web_carrier_test.go index c5cb169..e47a8fb 100644 --- a/internal/runner/web_carrier_test.go +++ b/internal/runner/web_carrier_test.go @@ -75,6 +75,8 @@ func (d *carrierWebDriver) NextActionFromV8(context.Context) (json.RawMessage, e func (d *carrierWebDriver) SetLastAction(context.Context, json.RawMessage) error { return nil } +func (d *carrierWebDriver) SetLogs(context.Context, json.RawMessage) error { return nil } + // TestRunner_TransitionalStepNeverAdvancesThePageCarrier pins the ordering the // web path depends on. The page-side extractors must run only on steps the // verifier accepts: their getters advance spec state every time they evaluate, @@ -172,6 +174,8 @@ func (d *installFailsWebDriver) SetLastAction(context.Context, json.RawMessage) return errors.New("__sanderlingSetLastAction__ is not a function") } +func (d *installFailsWebDriver) SetLogs(context.Context, json.RawMessage) error { return nil } + // TestRunner_LastActionInstallFailureFailsTheRun covers the other half of the // same trust boundary. A run that cannot install lastAction in the page cannot // apply the page's extractor values either, so the step keeps goja's @@ -200,3 +204,49 @@ func TestRunner_LastActionInstallFailureFailsTheRun(t *testing.T) { t.Errorf("Run error = %v, want it to name the failed lastAction install", err) } } + +// logInstallFailsWebDriver takes lastAction and refuses the logs, the shape a +// page carrying an older published @sanderling/spec runtime has: it knows the +// action setter and not the log one. +type logInstallFailsWebDriver struct { + *installFailsWebDriver +} + +func (d *logInstallFailsWebDriver) SetLastAction(context.Context, json.RawMessage) error { + return nil +} + +func (d *logInstallFailsWebDriver) SetLogs(context.Context, json.RawMessage) error { + return errors.New("__sanderlingSetLogs__ is not a function") +} + +// TestRunner_LogInstallFailureFailsTheRun holds the log channel to the same +// standard as the action one. The driver having the console errors decides +// nothing on web: the page's reading of every extractor replaces the host's, so +// a run that cannot put the entries back into the page evaluates noLogcatErrors +// against an empty array and reports green on a console full of errors. +// Continuing past this is the vacuity the whole install exists to prevent. +func TestRunner_LogInstallFailureFailsTheRun(t *testing.T) { + state := newHarnessWithSpec(t, carrierSpec) + web := &logInstallFailsWebDriver{ + installFailsWebDriver: &installFailsWebDriver{Driver: state.mock}, + } + + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + _, err := Run(ctx, Options{ + Duration: 2 * time.Second, + IdleTimeout: 20 * time.Millisecond, + MaxSteps: 3, + Driver: web, + Verifier: state.verifier, + TraceWriter: state.writer, + }) + if err == nil { + t.Fatal("Run succeeded with a page that cannot take the step's logs; " + + "every property reading the log stream ran against an empty array") + } + if !bytes.Contains([]byte(err.Error()), []byte("install logs")) { + t.Errorf("Run error = %v, want it to name the failed log install", err) + } +} diff --git a/internal/runner/web_extractor_trace_test.go b/internal/runner/web_extractor_trace_test.go index b31733e..d2c54e4 100644 --- a/internal/runner/web_extractor_trace_test.go +++ b/internal/runner/web_extractor_trace_test.go @@ -47,6 +47,8 @@ func (d *webMockDriver) NextActionFromV8(context.Context) (json.RawMessage, erro func (d *webMockDriver) SetLastAction(context.Context, json.RawMessage) error { return nil } +func (d *webMockDriver) SetLogs(context.Context, json.RawMessage) error { return nil } + // TestRunner_TraceRecordsTheValueTheVerdictUsed fails if the trace and the // verdict disagree about an extractor. A witness is only an explanation of a // violation if it holds the state the violated property was evaluated against. diff --git a/internal/runner/web_last_action_test.go b/internal/runner/web_last_action_test.go index 10ce20e..6f66304 100644 --- a/internal/runner/web_last_action_test.go +++ b/internal/runner/web_last_action_test.go @@ -1,12 +1,16 @@ package runner import ( + "bytes" "context" "encoding/json" "errors" + "log/slog" + "strings" "testing" "time" + "github.com/priyanshujain/sanderling/internal/driver" mockdriver "github.com/priyanshujain/sanderling/internal/driver/mock" ) @@ -26,7 +30,8 @@ globalThis.properties = {}; // control, so the runner has a real applied action to report on the next step. type tappingWebDriver struct { *mockdriver.Driver - installed []string + installed []string + installedLogs []string } func (d *tappingWebDriver) InstallBundle(context.Context, []byte) error { return nil } @@ -44,6 +49,11 @@ func (d *tappingWebDriver) SetLastAction(_ context.Context, encoded json.RawMess return nil } +func (d *tappingWebDriver) SetLogs(_ context.Context, encoded json.RawMessage) error { + d.installedLogs = append(d.installedLogs, string(encoded)) + return nil +} + func TestRunner_WebInstallsLastActionInThePage(t *testing.T) { state := newHarnessWithSpec(t, lastActionSpec) web := &tappingWebDriver{Driver: state.mock} @@ -78,6 +88,73 @@ func TestRunner_WebInstallsLastActionInThePage(t *testing.T) { } } +// The same hole on the other channel: state.logs was hardcoded [] in +// pkg/spec/src/web-runtime.ts, and because the page's reading of an extractor +// replaces the host's on web, the driver's error-level entries never reached a +// property. The default noLogcatErrors counted an empty array on every run. +func TestRunner_WebInstallsTheStepsLogsInThePage(t *testing.T) { + state := newHarnessWithSpec(t, lastActionSpec) + state.mock.LogEntries = []driver.LogEntry{ + {UnixMillis: 1700000000123, Level: "E", Tag: "console", Message: "boom from the page"}, + } + web := &tappingWebDriver{Driver: state.mock} + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + if _, err := Run(ctx, Options{ + Duration: time.Hour, + IdleTimeout: 20 * time.Millisecond, + MaxSteps: 2, + Driver: web, + Verifier: state.verifier, + TraceWriter: state.writer, + }); err != nil { + t.Fatalf("Run: %v", err) + } + + if len(web.installedLogs) == 0 { + t.Fatal("the page was never handed the step's logs; every property reading " + + "state.logs evaluated against the empty array the page starts with") + } + // The shape is the goja host's (internal/verifier/marshal.go logFields), + // pinned against it by TestLogs_WebJSONMatchesTheGojaObject. + const want = `[{"unixMillis":1700000000123,"level":"E","tag":"console","message":"boom from the page"}]` + if web.installedLogs[0] != want { + t.Errorf("step 1 installed %s, want %s", web.installedLogs[0], want) + } +} + +// A log fetch that fails decides the verdict of every log property: they all +// evaluate against an empty slice and hold. That is not a fact about the app, +// so the step it happened on has to be visible in the run's output. It used to +// be dropped in silence, under a comment claiming it was warned about. +func TestRunner_ReportsALogFetchItCouldNotMake(t *testing.T) { + state := newHarnessWithSpec(t, lastActionSpec) + state.mock.Failures[mockdriver.ActionRecentLogs] = errors.New("adb: device offline") + + var buffer bytes.Buffer + logger := slog.New(slog.NewTextHandler(&buffer, &slog.HandlerOptions{Level: slog.LevelWarn})) + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + if _, err := Run(ctx, Options{ + Duration: time.Hour, + IdleTimeout: 20 * time.Millisecond, + MaxSteps: 2, + Driver: state.mock, + Verifier: state.verifier, + TraceWriter: state.writer, + Logger: logger, + }); err != nil { + t.Fatalf("Run: %v", err) + } + + if !strings.Contains(buffer.String(), "adb: device offline") { + t.Errorf("the run never reported the failed log fetch, so noLogcatErrors "+ + "held on evidence nobody collected; log was %q", buffer.String()) + } +} + // failingTapWebDriver dispatches the tap and then fails the call, the shape an // RPC deadline takes: the page has the click, the runner has an error. type failingTapWebDriver struct { diff --git a/internal/verifier/marshal.go b/internal/verifier/marshal.go index 18b2ac6..31c9e99 100644 --- a/internal/verifier/marshal.go +++ b/internal/verifier/marshal.go @@ -468,19 +468,44 @@ func runtimeMillis(stepTime, runStart time.Time) int64 { return stepTime.Sub(runStart).Milliseconds() } +// logFields is the ONE description of a state.logs entry, for the same reason +// lastActionFields is: the goja host turns it into a JS object (logsArray) and +// the web host receives the same fields as JSON (EncodeLogs), so a property +// counting error-level lines cannot read one shape on native and another on web. +func logFields(entry LogEntry) []actionField { + return []actionField{ + {key: "unixMillis", value: entry.UnixMillis}, + {key: "level", value: entry.Level}, + {key: "tag", value: entry.Tag}, + {key: "message", value: entry.Message}, + } +} + func logsArray(runtime *goja.Runtime, logs []LogEntry) *goja.Object { array := runtime.NewArray() for index, entry := range logs { - item := runtime.NewObject() - _ = item.Set("unixMillis", entry.UnixMillis) - _ = item.Set("level", entry.Level) - _ = item.Set("tag", entry.Tag) - _ = item.Set("message", entry.Message) - _ = array.Set(fmt.Sprintf("%d", index), item) + _ = array.Set(fmt.Sprintf("%d", index), objectFromFields(runtime, logFields(entry))) } return array } +// EncodeLogs renders this step's log entries for the web host, which has no +// Go-side state object to read: the runner pushes this JSON into the page +// before each extractor evaluation. No entries encodes as an empty array, the +// same value the goja host reports for a step whose log fetch found nothing. +func EncodeLogs(logs []LogEntry) json.RawMessage { + var buffer bytes.Buffer + buffer.WriteByte('[') + for index, entry := range logs { + if index > 0 { + buffer.WriteByte(',') + } + buffer.Write(encodeFields(logFields(entry))) + } + buffer.WriteByte(']') + return buffer.Bytes() +} + func exceptionsArray(runtime *goja.Runtime, exceptions []Exception) *goja.Object { array := runtime.NewArray() for index, exception := range exceptions { diff --git a/internal/verifier/marshal_test.go b/internal/verifier/marshal_test.go index b3a1a56..942aec0 100644 --- a/internal/verifier/marshal_test.go +++ b/internal/verifier/marshal_test.go @@ -282,3 +282,50 @@ func TestLastAction_ReportsARelaunchSeparatelyFromTheDispatch(t *testing.T) { }) } } + +// TestLogs_WebJSONMatchesTheGojaObject pins state.logs to ONE shape across the +// two hosts, for the same reason lastAction is pinned. On web the page's +// reading of every extractor replaces the host's, so state.logs is whatever +// EncodeLogs put in the page: a field this side renames or cases differently +// leaves the default noLogcatErrors counting nothing on web while it counts on +// native, with nothing reporting that it never saw an entry. +func TestLogs_WebJSONMatchesTheGojaObject(t *testing.T) { + verifier := newVerifier(t) + mustLoad(t, verifier, ` + globalThis.lines = __sanderling__.extract(state => JSON.stringify(state.logs)); + `) + + for _, testCase := range []struct { + name string + logs []LogEntry + }{ + {"none", nil}, + {"empty", []LogEntry{}}, + { + "one error", + []LogEntry{{UnixMillis: 1700000000123, Level: "E", Tag: "console", Message: "boom from the page"}}, + }, + { + "mixed levels", + []LogEntry{ + {UnixMillis: 1, Level: "E", Tag: "console", Message: `say "hi" & co`}, + {UnixMillis: 2, Level: "W", Tag: "AndroidRuntime", Message: "a warning"}, + }, + }, + } { + t.Run(testCase.name, func(t *testing.T) { + if err := verifier.PushSnapshot(SnapshotInput{ + Snapshots: Snapshots{}, + Logs: testCase.logs, + }); err != nil { + t.Fatal(err) + } + handle := verifier.runtime.GlobalObject().Get("lines").ToObject(verifier.runtime) + goja := handle.Get("current").String() + web := string(EncodeLogs(testCase.logs)) + if goja != web { + t.Errorf("the two hosts disagree on state.logs\n goja: %s\n web: %s", goja, web) + } + }) + } +} diff --git a/pkg/spec/src/web-runtime.ts b/pkg/spec/src/web-runtime.ts index a607758..c28f4aa 100644 --- a/pkg/spec/src/web-runtime.ts +++ b/pkg/spec/src/web-runtime.ts @@ -445,6 +445,15 @@ if (typeof globalThis.addEventListener === "function") { // that reads state.lastAction vacuously true on web. let lastAction: unknown = null; +// logs is what the driver captured between the previous step and this one, +// pushed in by the Go runner (via __sanderlingSetLogs__) before each extractor +// evaluation, in the shape internal/verifier/marshal.go builds for goja. The +// page cannot derive it: console output reaches the runner over CDP and nothing +// in the page reads it back. Hardcoding [] here, as this file used to, makes +// every spec property that reads state.logs vacuously true on web, the default +// noLogcatErrors included, because the page's reading is the one that wins. +let logs: unknown[] = []; + function buildState(): unknown { return { snapshots: {}, @@ -453,7 +462,7 @@ function buildState(): unknown { window, lastAction, time: 0, - logs: [], + logs, exceptions: capturedExceptions.slice(), }; } @@ -502,6 +511,11 @@ defineLockedGlobal("__sanderlingSetLastAction__", (value: unknown) => { lastAction = value ?? null; }); +// The host calls this once per step too, alongside __sanderlingSetLastAction__. +defineLockedGlobal("__sanderlingSetLogs__", (value: unknown) => { + logs = Array.isArray(value) ? value : []; +}); + // writable:false stops a page script from shadowing the runtime via plain // assignment (the realistic in-page threat). configurable:true is required so // unit tests sharing one process can reinstall a fake via defineProperty; a diff --git a/pkg/spec/test/web-runtime.test.ts b/pkg/spec/test/web-runtime.test.ts index 0d96434..95a9432 100644 --- a/pkg/spec/test/web-runtime.test.ts +++ b/pkg/spec/test/web-runtime.test.ts @@ -365,6 +365,35 @@ test("state.lastAction is null when the host pushed nothing", () => { assert.equal(lastActionSeenByASpec(null), null); }); +// state.logs is the same kind of hole. Console output reaches the runner over +// CDP, so the page cannot read it back, and while the web runtime hardcoded [] +// there the default noLogcatErrors counted an empty array on every web run: a +// page whose console was full of errors went green having checked nothing. +function logsSeenByASpec(pushed: unknown): unknown { + const setLogs = (globalThis as Record).__sanderlingSetLogs__ as ( + value: unknown, + ) => void; + __testing__.extractors.length = 0; + __testing__.runtime.extract((state) => (state as { logs: unknown }).logs); + let out: Record = {}; + withState(() => { + setLogs(pushed); + out = __testing__.evaluateExtractors(); + }); + return readingOf(out, 0); +} + +test("state.logs carries the entries the host pushed", () => { + const entries = [ + { unixMillis: 1700000000123, level: "E", tag: "console", message: "boom from the page" }, + ]; + assert.deepEqual(logsSeenByASpec(entries), entries); +}); + +test("state.logs is empty when the host pushed no entries", () => { + assert.deepEqual(logsSeenByASpec([]), []); +}); + // sanitize runs over every extractor's return value before it leaves the // runtime. A user extractor that returns a page object reachable from // document/window can be self-referential, carry functions, or nest deeply; diff --git a/test/browser/console_levels_test.go b/test/browser/console_levels_test.go index a1b81de..f977dc9 100644 --- a/test/browser/console_levels_test.go +++ b/test/browser/console_levels_test.go @@ -81,6 +81,33 @@ func TestBrowserConsoleErrorReachesTheSpec(t *testing.T) { } } +// TestBrowserConsoleErrorFiresTheLogProperty drives the same page through the +// whole bundle -> run -> verify pipeline instead of hand-assembling a snapshot. +// The driver holding the entry is not enough on web: every extractor reading is +// replaced by the one the page computed, so state.logs is whatever the page +// says it is, and a page that answers "no logs" leaves noLogcatErrors green on +// a run whose console was full of errors. +func TestBrowserConsoleErrorFiresTheLogProperty(t *testing.T) { + violations := runFixture(t, "console-levels") + if !slices.Contains(violations, "noLogcatErrors") { + t.Fatalf("a page calling console.error ran a whole run without noLogcatErrors firing; violations=%v", violations) + } +} + +// TestBrowserQuietPageKeepsTheLogPropertySatisfied is the other half: a page +// whose console never reaches the error level must leave noLogcatErrors alone, +// so the property is reporting what the page logged rather than being on +// whenever the run is web. +func TestBrowserQuietPageKeepsTheLogPropertySatisfied(t *testing.T) { + violations := runFixture(t, "console-quiet") + if slices.Contains(violations, "noLogcatErrors") { + t.Errorf("noLogcatErrors fired on a page that logged nothing at error level; violations=%v", violations) + } + if !slices.Contains(violations, "counterNeverMoves") { + t.Fatalf("nothing was ever pressed, so the run proves nothing about a property that can fire; violations=%v", violations) + } +} + // TestBrowserConsoleLevelsMapToTheLogcatScale pins what each console verb // becomes once it crosses the driver. driver.LogEntry.Level is the single-letter // logcat scale on every platform, so a spec asking for warnings or debug lines diff --git a/test/browser/testdata/console-quiet/index.html b/test/browser/testdata/console-quiet/index.html new file mode 100644 index 0000000..2020cf6 --- /dev/null +++ b/test/browser/testdata/console-quiet/index.html @@ -0,0 +1,23 @@ + + + + + console-quiet + + + +
0
+ + + diff --git a/test/browser/testdata/console-quiet/spec.ts b/test/browser/testdata/console-quiet/spec.ts new file mode 100644 index 0000000..842a8f4 --- /dev/null +++ b/test/browser/testdata/console-quiet/spec.ts @@ -0,0 +1,15 @@ +import { always, extract, taps } from "@sanderling/spec"; +import { noLogcatErrors } from "@sanderling/spec/defaults/properties"; + +const presses = extract((s) => { + const el = s.ax.find({ id: "count" }); + return el ? parseInt(el.text, 10) || 0 : 0; +}).named("presses"); + +// The run has to actually be driving the page, or noLogcatErrors staying +// satisfied says nothing about whether it can fire at all. +const counterNeverMoves = always(() => presses.current === 0); + +export const properties = { noLogcatErrors, counterNeverMoves }; + +export const actionsRoot = taps;