Merge branch 'web-logs-reach-the-spec' into correctness-and-spec-skills

internal/driver/chrome/driver.go

@@ -70,7 +70,16 @@ func New() *Driver {
 		}
 		var parts []string
 		for _, arg := range e.Args {
-			if arg.Value != nil {
+			// An object argument, which is what console.error(err) passes,
+			// carries no value at all: CDP sends a description instead. Reading
+			// only the value logged those calls with an empty message, so the
+			// entry named a level and nothing a reader could act on.
+			if arg.Value == nil {
+				if arg.Description != "" {
+					parts = append(parts, arg.Description)
+				}
+				continue
+			}
 			var s string
 			if err := json.Unmarshal(arg.Value, &s); err == nil {
 				parts = append(parts, s)
@@ -78,15 +87,10 @@ func New() *Driver {
 				parts = append(parts, string(arg.Value))
 			}
 		}
-		}
-		level := strings.ToUpper(string(e.Type))
-		if level == "LOG" {
-			level = "I"
-		}
 		d.logsMu.Lock()
 		d.logs = append(d.logs, driver.LogEntry{
 			UnixMillis: int64(e.Timestamp.Time().UnixMilli()),
-			Level:      level,
+			Level:      consoleLevel(e.Type),
 			Tag:        "console",
 			Message:    strings.Join(parts, " "),
 		})
@@ -712,9 +716,33 @@ func (d *Driver) Metrics(ctx context.Context, _ string) (driver.Metrics, error)
 	}, nil
 }
 
+// consoleLevel places a console call on driver.LogEntry's logcat scale. The
+// verbs a spec acts on are all named here; the rest are info rather than "E"
+// because promoting them would convict an app of an error it never logged.
+func consoleLevel(apiType runtime.APIType) string {
+	switch apiType {
+	case runtime.APITypeError, runtime.APITypeAssert:
+		return "E"
+	case runtime.APITypeWarning:
+		return "W"
+	case runtime.APITypeDebug:
+		return "D"
+	default:
+		return "I"
+	}
+}
+
+// meetsLevel keeps an entry whose level the scale cannot rank. Ranking an
+// unknown level below every threshold drops it, and a dropped entry is
+// indistinguishable from a quiet app: the caller sees silence and reports it as
+// health.
 func meetsLevel(level, minLevel string) bool {
 	order := map[string]int{"V": 0, "D": 1, "I": 2, "W": 3, "E": 4, "F": 5}
-	return order[level] >= order[minLevel]
+	rank, ranked := order[level]
+	if !ranked {
+		return true
+	}
+	return rank >= order[minLevel]
 }
 
 func pngDimensions(png []byte) (int, int) {

internal/driver/chrome/logs_test.go

@@ -0,0 +1,60 @@
+package chrome
+
+import (
+	"testing"
+
+	"github.com/chromedp/cdproto/runtime"
+)
+
+// Every console verb has to land on the logcat scale driver.LogEntry declares:
+// the runner fetches at "E" and the default properties count entries whose
+// level equals "E", so a level spelled any other way is an error the spec never
+// sees. A verb with no mapping is info, which is honest about severity without
+// fabricating an error the page never logged.
+func TestConsoleLevel(t *testing.T) {
+	cases := map[runtime.APIType]string{
+		runtime.APITypeError:          "E",
+		runtime.APITypeAssert:         "E",
+		runtime.APITypeWarning:        "W",
+		runtime.APITypeDebug:          "D",
+		runtime.APITypeLog:            "I",
+		runtime.APITypeInfo:           "I",
+		runtime.APITypeTable:          "I",
+		runtime.APIType("countReset"): "I",
+	}
+	for apiType, want := range cases {
+		if got := consoleLevel(apiType); got != want {
+			t.Errorf("consoleLevel(%q) = %q, want %q", apiType, got, want)
+		}
+	}
+}
+
+// A level the scale does not name is unknown, not verbose. Ranking it below
+// every threshold is what silently emptied the web log channel: the entries
+// existed, the filter dropped them, and the run reported nothing. Evidence the
+// filter cannot rank has to reach the caller, who can at least see it.
+func TestMeetsLevel(t *testing.T) {
+	cases := []struct {
+		level    string
+		minLevel string
+		want     bool
+	}{
+		{"E", "E", true},
+		{"F", "E", true},
+		{"W", "E", false},
+		{"I", "E", false},
+		{"D", "E", false},
+		{"V", "E", false},
+		{"W", "W", true},
+		{"I", "W", false},
+		{"D", "V", true},
+		{"ERROR", "E", true},
+		{"WARNING", "E", true},
+		{"", "E", true},
+	}
+	for _, tc := range cases {
+		if got := meetsLevel(tc.level, tc.minLevel); got != tc.want {
+			t.Errorf("meetsLevel(%q, %q) = %v, want %v", tc.level, tc.minLevel, got, tc.want)
+		}
+	}
+}

internal/driver/driver.go

@@ -82,6 +82,12 @@ type FocusedWindowChecker interface {
 	FocusedWindowApp(ctx context.Context) (string, error)
 }
 
+// LogEntry is one line of device log. Level is logcat's single-letter scale on
+// every platform: "V", "D", "I", "W", "E", "F", ordered as written. The runner
+// fetches at "E" and the default properties count entries whose level equals
+// "E", so a driver that spells a level any other way empties the channel
+// without failing anything: the entries never arrive and every property reading
+// state.logs holds vacuously.
 type LogEntry struct {
 	UnixMillis int64
 	Level      string

internal/driver/ioscompanion/driver.go

@@ -1084,7 +1084,10 @@ func (d *Driver) WaitForIdle(ctx context.Context, _ time.Duration) error {
 }
 
 // RecentLogs returns no entries: the companion log RPC is a follow-up, so v1
-// reports an empty slice rather than failing.
+// reports an empty slice rather than failing. Every property reading state.logs
+// therefore holds vacuously on iOS and nothing says so; closing it means
+// tailing idb's streaming log RPC and mapping os_log levels onto the
+// single-letter scale driver.LogEntry declares.
 func (d *Driver) RecentLogs(_ context.Context, _ time.Time, _ string) ([]driver.LogEntry, error) {
 	return []driver.LogEntry{}, nil
 }

test/browser/console_levels_test.go

@@ -0,0 +1,188 @@
+//go:build browser
+
+package browser_test
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"path/filepath"
+	"slices"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/priyanshujain/sanderling/internal/driver"
+	"github.com/priyanshujain/sanderling/internal/driver/chrome"
+	"github.com/priyanshujain/sanderling/internal/hierarchy"
+	"github.com/priyanshujain/sanderling/internal/verifier"
+)
+
+// TestBrowserConsoleErrorReachesTheSpec drives a page that calls console.error
+// and follows the entry the whole way a run does: the driver's log fetch at the
+// runner's minimum level, then into the verifier state a property reads. The
+// default noLogcatErrors counts entries whose level is "E", so a driver that
+// spells the level any other way leaves the property permanently satisfied on
+// web with nothing reporting that it never saw anything.
+func TestBrowserConsoleErrorReachesTheSpec(t *testing.T) {
+	ctx, driverInstance, since := launchConsoleFixture(t)
+
+	entries, err := driverInstance.RecentLogs(ctx, since, "E")
+	if err != nil {
+		t.Fatalf("recent logs: %v", err)
+	}
+	if len(entries) != 2 {
+		t.Fatalf("the runner's error-level fetch returned %d entries, want the page's two console.error calls: %+v", len(entries), entries)
+	}
+	for _, entry := range entries {
+		if entry.Level != "E" {
+			t.Errorf("console.error %q arrived as level %q, want %q", entry.Message, entry.Level, "E")
+		}
+	}
+	// console.error(err) is the ordinary way a page reports a failure, and the
+	// argument is then an object rather than a string. An entry that arrives
+	// with the right level and no message names nothing a reader can act on.
+	if !messageSeen(entries, "boom from the page") {
+		t.Errorf("the page's console.error string never arrived: %+v", entries)
+	}
+	if !messageSeen(entries, "object arg detail") {
+		t.Errorf("console.error(new Error(...)) arrived with no message: %+v", entries)
+	}
+
+	dump, err := driverInstance.Hierarchy(ctx)
+	if err != nil {
+		t.Fatalf("hierarchy: %v", err)
+	}
+	tree, err := hierarchy.Parse(dump)
+	if err != nil {
+		t.Fatalf("parse hierarchy: %v", err)
+	}
+
+	gojaBundle, _ := bundleSpec(t, filepath.Join(testdataDir(t), "console-levels", "spec.ts"))
+	verifierInstance, err := verifier.New(
+		verifier.WithSeed(fixtureSeed),
+		verifier.WithPlatform("web"),
+	)
+	if err != nil {
+		t.Fatalf("verifier: %v", err)
+	}
+	if err := verifierInstance.Load(string(gojaBundle)); err != nil {
+		t.Fatalf("load spec: %v", err)
+	}
+	if err := verifierInstance.PushSnapshot(verifier.SnapshotInput{
+		Tree: tree,
+		Logs: asVerifierLogs(entries),
+	}); err != nil {
+		t.Fatalf("push snapshot: %v", err)
+	}
+	verifierInstance.EvaluateProperties()
+	if violated := verifierInstance.NewlyViolatedProperties(); !slices.Contains(violated, "noLogcatErrors") {
+		t.Fatalf("a console.error on the page left noLogcatErrors satisfied; violations=%v", violated)
+	}
+}
+
+// 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
+// by letter has to get the same answer on web as it does on Android, and a
+// console verb the driver has no mapping for still has to arrive rather than be
+// silently discarded.
+func TestBrowserConsoleLevelsMapToTheLogcatScale(t *testing.T) {
+	ctx, driverInstance, since := launchConsoleFixture(t)
+
+	entries, err := driverInstance.RecentLogs(ctx, since, "V")
+	if err != nil {
+		t.Fatalf("recent logs: %v", err)
+	}
+	if len(entries) != 7 {
+		t.Fatalf("the page made 7 console calls, the driver kept %d: %+v", len(entries), entries)
+	}
+
+	wantLevels := map[string]string{
+		"boom from the page": "E",
+		"a warning":          "W",
+		"a plain log":        "I",
+		"a debug line":       "D",
+		"an info line":       "I",
+	}
+	seen := map[string]bool{}
+	for _, entry := range entries {
+		if !slices.Contains([]string{"V", "D", "I", "W", "E", "F"}, entry.Level) {
+			t.Errorf("entry %q carries level %q, which is not on the logcat scale a spec compares against", entry.Message, entry.Level)
+		}
+		for message, level := range wantLevels {
+			if !strings.Contains(entry.Message, message) {
+				continue
+			}
+			seen[message] = true
+			if entry.Level != level {
+				t.Errorf("console message %q arrived as level %q, want %q", message, entry.Level, level)
+			}
+		}
+	}
+	for message := range wantLevels {
+		if !seen[message] {
+			t.Errorf("console message %q never reached the driver's log buffer", message)
+		}
+	}
+
+	errorsOnly, err := driverInstance.RecentLogs(ctx, since, "E")
+	if err != nil {
+		t.Fatalf("recent logs: %v", err)
+	}
+	if len(errorsOnly) != 2 {
+		t.Fatalf("the error-level fetch kept %d of the 7 entries, want only the console.error calls: %+v", len(errorsOnly), errorsOnly)
+	}
+	warningsUp, err := driverInstance.RecentLogs(ctx, since, "W")
+	if err != nil {
+		t.Fatalf("recent logs: %v", err)
+	}
+	if len(warningsUp) != 3 {
+		t.Fatalf("the warning-level fetch kept %d entries, want the console.error calls and the console.warn: %+v", len(warningsUp), warningsUp)
+	}
+}
+
+// launchConsoleFixture serves the console-levels page and drives headless Chrome
+// to it, returning the driver plus the instant before the page ran so a log
+// fetch can ask for everything the page emitted.
+func launchConsoleFixture(t *testing.T) (context.Context, *chrome.Driver, time.Time) {
+	t.Helper()
+
+	server := httptest.NewServer(http.FileServer(http.Dir(testdataDir(t))))
+	t.Cleanup(server.Close)
+
+	driverInstance := chrome.New()
+	t.Cleanup(func() {
+		ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+		defer cancel()
+		_ = driverInstance.Terminate(ctx)
+	})
+
+	ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)
+	t.Cleanup(cancel)
+
+	since := time.Now()
+	if err := driverInstance.Launch(ctx, server.URL+"/console-levels/", false, nil); err != nil {
+		t.Fatalf("launch: %v", err)
+	}
+	return ctx, driverInstance, since
+}
+
+func messageSeen(entries []driver.LogEntry, want string) bool {
+	return slices.ContainsFunc(entries, func(entry driver.LogEntry) bool {
+		return strings.Contains(entry.Message, want)
+	})
+}
+
+func asVerifierLogs(entries []driver.LogEntry) []verifier.LogEntry {
+	out := make([]verifier.LogEntry, 0, len(entries))
+	for _, entry := range entries {
+		out = append(out, verifier.LogEntry{
+			UnixMillis: entry.UnixMillis,
+			Level:      entry.Level,
+			Tag:        entry.Tag,
+			Message:    entry.Message,
+		})
+	}
+	return out
+}

test/browser/testdata/console-levels/index.html

@@ -0,0 +1,25 @@
+<!doctype html>
+<html>
+  <head>
+    <meta charset="utf-8" />
+    <title>console-levels</title>
+  </head>
+  <body>
+    <button id="press">press</button>
+    <div id="count">0</div>
+    <script>
+      console.error("boom from the page");
+      console.error(new Error("object arg detail"));
+      console.warn("a warning");
+      console.log("a plain log");
+      console.debug("a debug line");
+      console.info("an info line");
+      console.table({ unmapped: 1 });
+      let presses = 0;
+      document.getElementById("press").addEventListener("click", function () {
+        presses += 1;
+        document.getElementById("count").textContent = String(presses);
+      });
+    </script>
+  </body>
+</html>

test/browser/testdata/console-levels/spec.ts

@@ -0,0 +1,6 @@
+import { taps } from "@sanderling/spec";
+import { noLogcatErrors } from "@sanderling/spec/defaults/properties";
+
+export const properties = { noLogcatErrors };
+
+export const actionsRoot = taps;