From e9f45e3baab211a4f5353ca16ef1665e86e01047 Mon Sep 17 00:00:00 2001 From: Patrick Stel Date: Fri, 2 Oct 2026 15:25:22 +0200 Subject: [PATCH] Take the import census ahead of the engine, and stop re-walking a finished ladder (issue 105) The build-283f3e9 report from the AU7200 has no engine imports line, and the trail says why: the launch ended within five seconds of the engine failing, on the first rung of a second walk the post-failure thread started behind the early walk's verdict, with the census queued behind it. The second launch of the build never reached the UI, so the only page the set serves is the no-provider page, which had no build line and nothing of the census. - NativeProbe: a walk whose verdict is already on the books says so and asks nothing; EngineFailedHere() and Standing() expose the ledger's state. - EngineImports: RunInBackground + WaitForCensus, claimed under the lock before the thread starts (the harness found the race). - BrowserApp (elm): on an install whose ledger records the engine's failure, the census runs after the walk and ahead of the engine, waited for up to 60 s, the way the walk is. - DiagServer: the no-provider page carries build, engine imports and the stub block. - Program (elm): a breadcrumb before Elementary.Initialize(), which is where the second launch's three lines stop in front of. - NuiMseWatch (issue 100): loadedmetadata carries the duration and the loadstart/playing lines say "live page" on a /live address, so the next freeze trail can say whether the element on screen held a live stream. Harnesses: probeladder (resume, peek, early, notearly updated), engineimports (background scenario), msewatch (duration line) all pass; all five packages and OverscanProbe build. Co-Authored-By: Claude Fable 5.1 --- CLAUDE.md | 16 +++-- docs/INTERNALS.md | 110 ++++++++++++++++++++++++++++----- src/common/DiagServer.cs | 14 +++++ src/common/EngineImports.cs | 105 ++++++++++++++++++++++++++++--- src/common/NativeProbe.cs | 77 ++++++++++++++++++++--- src/common/SmackWall.cs | 8 ++- src/elm/BrowserApp.cs | 27 ++++++++ src/elm/Program.cs | 7 +++ src/nui/NuiMseWatch.cs | 28 ++++++++- tools/engineimports/Program.cs | 17 ++++- tools/engineimports/run.sh | 3 + tools/msewatch/build-page.py | 7 +++ tools/probeladder/Program.cs | 56 +++++++++++++---- 13 files changed, 422 insertions(+), 53 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 04e3754..19d8e76 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -287,9 +287,11 @@ platform types it touches, and walks it over the shapes that set has actually produced: a rung that hangs, a rung a previous launch never came back from (once, which is asked again, and twice, which is a refusal), a ledger left by another build, a ledger that never opens, a page loaded before the walk, an install whose -ledger says the engine already failed there (the walk goes ahead of the engine), and -a clean run twice over. It needs a C compiler for the stand-in library and nothing -else. +ledger says the engine already failed there (the walk goes ahead of the engine), a +clean run twice over (the second walk finds the verdict on the books and asks +nothing — issue #105's set ended two launches on the first rung of a walk behind a +verdict), and a walk started behind the early one on the same launch. It needs a C +compiler for the stand-in library and nothing else. The ladder's only real property is that it converges — whatever one rung does, the rungs and locations behind it still get asked. Two builds have been spent finding out @@ -312,9 +314,11 @@ builds a library in this box's own architecture that needs `libm`, `libc` and a `libblocked.so` made unopenable by permission, and holds the census to naming exactly the blocked library's two symbols (a function and a data object), the refusal with the loader's words, nothing that another library provides, and no -weak import. The committed ARM `libovprobe.so` exercises the ELF32 path, a FIFO -holds it to a recorded miss rather than a hang, and a second call must change -nothing. Needs the .NET 6 SDK under `~/.dotnet-local` and a C compiler. +weak import — taken inline and again on a thread of its own with the caller +waiting, which is how `OnCreate` runs it ahead of the engine. The committed ARM +`libovprobe.so` exercises the ELF32 path, a FIFO holds it to a recorded miss rather +than a hang, and a second call must change nothing. Needs the .NET 6 SDK under +`~/.dotnet-local` and a C compiler. ### The trail harness diff --git a/docs/INTERNALS.md b/docs/INTERNALS.md index 7cebb7f..31c815f 100644 --- a/docs/INTERNALS.md +++ b/docs/INTERNALS.md @@ -1211,10 +1211,71 @@ reversal later: never arrives — the set parks the census like the Q80 parked its calls; the previous-run block says which step. -**State of #105 (2026-10-02):** the ladder's answer is in and is the good one; the -census shipped in `build-283f3e9`, and the reply asking the reporter to run it quotes -that tag. Nothing here changes the Q80's close: -that set refused the mapping the AU7200 allows. +### The census has to go ahead of the engine too + +The `build-283f3e9` report (2026-10-02, the same afternoon) has no `engine imports:` +line on it, and the trail says why. Its previous-run block is the build's first +launch: the early walk reached its verdict in 248 ms, the engine failed line for line +as before, and then the post-failure thread **started the walk again** — the ledger's +answers replayed, `probe: copy libovprobe.so to data/`, `probe: open res/` — and that +is the launch's last line. No `read header` behind it, no deadline miss five seconds +later, no `still on the failure screen — +10s` from the heartbeat. The launch was over +within five seconds of `ENGINE FAILURE`: the Q80's shape (*The ladder has to start*, +above), on a set that otherwise answers every call we make. The census was queued +behind that second walk and never reached. + +The `this run` block — the second launch, 23 s later — is three lines with no UI: +`Main entered`, the socket, the engine preload. The `build-3996334` page had the same +three lines at the same place, fetched minutes after launch both times, so this is not +a quick reporter: **on this set the second launch of a build stops before or inside +`Elementary.Initialize()`** and the only page it ever serves is the no-provider page. +That page had no `build :` line, though the reply had promised one, and nothing of the +census. + +Four things follow and are in the code: + +- **A walk behind a verdict asks nothing.** `NativeProbe.Walk` reads the verdict + after `Ledger.Open` and returns on it: `native probe: verdict already on the books + — …; not walking again`. The repeatable rungs (`open`, `header`, `read`, the copy + into `data/`) were re-made on every walk so the rungs behind them had a descriptor; + behind a verdict there are no rungs, and on this set the first of them was where + the launch ended with the census behind it. `tools/probeladder`'s `resume`, `peek`, + `early` and `notearly` hold it; `peek` used to assert the opposite. +- **The census goes ahead of the engine, on the walk's gate.** + `NativeProbe.EngineFailedHere()` is true whenever a ledger exists, which it only + does on an install whose engine has failed. `OnCreate` then runs + `EngineImports.RunInBackground` after the walk and waits up to 60 s for it + (`engine imports: the engine waits for the census (up to 60 s)` … `census finished + after N ms — on to the engine`), the way it waits for the walk; every dlopen in it + is under its own deadline, and what the bound cuts off still reaches the trail from + the census's thread. The lines go to the trail as they are established, because + the page that shows them is the *next* launch's. The post-failure call stays for + the first failure on an install and finds the census taken on every launch after. + `tools/engineimports`'s `background` scenario drives this shape, and found the + claim race in the first version of it. +- **The no-provider page carries `build :`, `engine imports:` and the stub block**, + because on this set every page is that page. +- **`Program.Main` drops `Elementary: initializing` before the call**, so the second + launch's three lines become four and name the call they stop in front of. + +How to read the next report, in addition to the four readings above: the +previous-run block should carry, between `OnCreate: UI built` and `EFL subsystems`, +the walk's verdict (early or already on the books), then `engine imports: the engine +failed on an earlier launch here — taking the census now, ahead of the engine`, +`reading /usr/share/chromium-efl/lib/libchromium-impl.so`, the `ELF32 … needed, … +imports (… weak)` counts line, one `refused` line per library the loader would not +open, and the `N unresolved` line with up to forty names. A `DID NOT RETURN` on the +read is the set parking the census; `still counting after 60 s` with lines behind it +is a slow set, and the lines are still the answer. The reply also asks what the +screen showed on the second open: a failure screen that never came is the second +finding above, and the no-provider page is then the only page this set will ever +serve, which the reporter's instructions have to say. + +**State of #105 (2026-10-02, evening):** the ladder's answer is in and is the good +one; `build-283f3e9` shipped the census and the AU7200 never reached it; the build +after it takes the census ahead of the engine and is the one the stub depends on. The +reply quotes that tag. Nothing here changes the Q80's close: that set refused the +mapping the AU7200 allows. ### `ELM_ACCEL` has to be set before the window exists @@ -3254,17 +3315,36 @@ the one its report has to come from. The state is: three seconds before, paused the whole time. The fix is `NuiMseHold` (see *One video at a time*): the next reel's source is held back until TikTok plays it, so no second pipeline opens under the one on screen. Menu row to - switch it off. Shipped in `build-644c119`. **Waiting on:** his report from - that build, after a few reels. The trail answers it in three lines per reel: `hold - v2 blob while v1 plays`, then on the swipe `release v2 after Ns (play)`, - then the probe's `v2 playing`. Reels that play to the end with that sequence - is the fix. A `release` with no `playing` after it, or the next reel sitting - on its spinner, is TikTok's player waiting for the preload to be ready - before it will swap — the hold would then have to let the attach through and - the fallback is the automatic pause/play on the frozen reel, which recovers - after a freeze he would still see. Reels still freezing with `held 0` on the - `one video :` line is TikTok attaching by a path the hold does not see, and - the probe's `loadstart` line (`blob not ours`, `srcObject`) says which. + switch it off. Shipped in `build-644c119`. **His report from it (2026-10-02): + "if next is normal videos never freeze"**, and the one freeze left comes + "sometimes, if the next video is a live stream". Two trails. The one without a + freeze has TikTok's swipe as an element swap — `hold v2 blob while v1 plays`, + `v1 playing` two seconds later, v1 then playing for three minutes — and never + a release, because v1 had been readied before the script was in the page. The + one with the freeze has the hold doing exactly what it was built to do (`hold + v1 blob while v2 plays` at 17:08:19, `release v1 after 122.6s (play)` at + 17:10:22, `v1 playing` three seconds after that) and, four seconds after the + hold, a path it does not cover: TikTok **emptied the on-screen element and + gave it a new source** — `v2 emptied`, `v2 loadstart blob not ours`, a new + MediaSource `ms4` at the same 768x576 — and v2 sat `rs0 starved stuck` for + thirteen seconds before it played, then paused and resumed every few seconds + for two minutes. Those pauses are the page's own: nothing of ours calls + `pause` or `play` but `NuiVideoCap`, and it ran zero times on both trails. + Whether the re-sourced v2 was the live stream, or a reel TikTok loaded cold into + the element on screen because the held one was not ready, the trail cannot say: + it had no duration and no address. The build after `build-644c119` adds both + to the probe's lines, read-only: `loadedmetadata 768x576, dur inf` (`inf` is + what a live stream reads, and also what an MSE clip reads until its page sets + a duration — `inf` with a playhead that never loops back is live) and + `, live page` on `loadstart` and `playing` while the address is `/@user/live`. + **Waiting on:** his report from that build with a freeze on it. `live page` or + `dur inf` on the re-sourced element is the live stream itself stalling, and a + live stream cannot buffer ahead: that is the proxy's throughput, the hold is + doing its job, and the answer is that live streams through that proxy will + stall. A finite `dur` on a `/video/` page with a `hold` a few seconds before is + TikTok loading into the on-screen element because the held one was not ready + — the hold would then have to release when the element on screen is emptied, + which is the next fix and a `tools/msehold` case before it is one. Five things about that set are settled and should not be re-derived: **key `5` is his, not ours** — the engine's overlay path is the only one that gives him a diff --git a/src/common/DiagServer.cs b/src/common/DiagServer.cs index 5fa81c7..fa513f9 100644 --- a/src/common/DiagServer.cs +++ b/src/common/DiagServer.cs @@ -99,10 +99,24 @@ private static string Report() // The probe's ledger outlives a launch, and the header line is the // one a reporter copies first — so it is here too, on the page they // get when the UI is not up yet. + // + // The build tag and the import census too (issue #105): on the AU7200 + // every page has been this one, because the first launch of a build + // dies within seconds of the engine failing and the second never + // reaches the UI. The `build-283f3e9` reply told the reporter the + // page would start with `build :`, and it did not — this page had no + // such line — which is a round trip spent on doubt about which + // build was installed. What this page cannot show is what the + // *current* launch has not yet established; the census it carries + // is this launch's if it has run, and the previous run's lines are + // in the trail below. return "Overscan — no report provider yet (UI has not started)\n\n" + + "build : " + BuildInfo.Tag + "\n" + "own native : " + NativeProbe.Summary + "\n" + + "engine imports: " + EngineImports.Summary + "\n" + "trail write: " + Breadcrumbs.Status + "\n\n" + "this run\n" + DiagLog.Dump() + + "\nwhat a stub must provide (the implementation's imports)\n" + EngineImports.Dump() + "\nprevious run (last line is where it died)\n" + Breadcrumbs.Previous + "\nengine stdout/stderr (previous run)\n" + diff --git a/src/common/EngineImports.cs b/src/common/EngineImports.cs index 29aedbc..b693f0e 100644 --- a/src/common/EngineImports.cs +++ b/src/common/EngineImports.cs @@ -4,6 +4,7 @@ using System.IO; using System.Runtime.InteropServices; using System.Text; +using System.Threading; namespace Overscan { @@ -35,12 +36,24 @@ namespace Overscan /// load. Whatever is still unresolved is what the stub has to provide, by name. /// /// Each step past managed code goes out under a , because - /// a call this firmware objects to is parked rather than refused, and it runs on - /// the post-failure probe thread after the engine has already failed: whatever - /// is most likely not to survive the firmware goes last. It is placed ahead of - /// the permission investigation on that thread because the investigation's last - /// step is the one the Q80 never came back from, and this census is the question - /// the next build is waiting on. + /// a call this firmware objects to is parked rather than refused. + /// + /// Where it runs was decided by the `build-283f3e9` report (2026-10-02). That build + /// put the census on the post-failure probe thread, behind the ladder's walk and + /// ahead of the permission investigation, and the census never ran: the launch + /// ended within five seconds of `ENGINE FAILURE` — no heartbeat tick, no deadline + /// miss — with the thread still on the walk's first repeatable rung. That is the + /// Q80's shape exactly (see NativeProbe.StartEarlyIfUnfinished): on these + /// sets a launch whose engine has failed is over before anything queued behind + /// the failure gets a turn, and the second launch of the same build never reached + /// the UI at all. So, like the walk, the census goes **ahead of the engine** on + /// an install whose ledger already says the engine fails here + /// (NativeProbe.EngineFailedHere), after the walk if one is due, and the + /// engine waits for it, bounded. On every set this app works on there is no + /// ledger and none of this runs. The post-failure call is still made, for the + /// first failure on an install, and finds the census already taken on the rest. + /// Its lines go to the trail as they are established, because the page that + /// shows them is served by the *next* launch, before its UI exists. /// /// How to read it: a short list of plain C function names is a no-op stub, /// buildable with the same toolchain recipe as `libovprobe.so`. C++ names (`_Z…`) @@ -76,6 +89,9 @@ internal static class EngineImports private static readonly List Lines = new List(); private static bool _ran; + /// Set whenever no census is running; reset while one is. + private static readonly ManualResetEvent Finished = new ManualResetEvent(true); + /// One line for the diagnostics header. public static string Summary { get; private set; } = "(not asked)"; @@ -115,17 +131,36 @@ private static void Trace(string line) /// Never throws: a diagnostic has nobody to throw to. /// public static void Census(string implementation, string blocked) + { + if (Claim()) + { + Take(implementation, blocked); + } + } + + /// + /// Takes the one census this process gets, for whichever caller is first; + /// false for every caller after. The wait event is reset here, under the + /// same lock, so a caller that starts the census on a thread and then waits + /// cannot see the event still set from before the thread got going. + /// + private static bool Claim() { lock (Gate) { if (_ran) { - return; + return false; } _ran = true; + Finished.Reset(); + return true; } + } + private static void Take(string implementation, string blocked) + { try { Run(implementation, blocked); @@ -135,6 +170,62 @@ public static void Census(string implementation, string blocked) Summary = "threw " + ex.GetType().Name + ": " + ex.Message; Trace(Summary); } + finally + { + try + { + Finished.Set(); + } + catch (Exception) + { + // Nobody to tell. + } + } + } + + /// + /// on a thread of its own, for the launch that runs it + /// ahead of the engine: the caller waits with , + /// bounded, and a census still going when the bound passes carries on while + /// the engine is asked — its lines reach the trail either way. Claimed here, + /// before the thread exists, so the post-failure call finds it taken. + /// + public static void RunInBackground(string implementation, string blocked) + { + if (!Claim()) + { + return; + } + + try + { + var thread = new Thread(delegate () { Take(implementation, blocked); }); + thread.IsBackground = true; + thread.Name = "engine-imports"; + thread.Start(); + } + catch (Exception ex) + { + // A set that will not give us a thread gets asked the dangerous way. + Trace("no thread (" + ex.GetType().Name + "), taking the census inline"); + Take(implementation, blocked); + } + } + + /// + /// Waits for a census started by to finish, for + /// at most . True if it did (or none is running). + /// + public static bool WaitForCensus(int timeoutMs) + { + try + { + return Finished.WaitOne(timeoutMs); + } + catch (Exception) + { + return false; + } } private static void Run(string implementation, string blocked) diff --git a/src/common/NativeProbe.cs b/src/common/NativeProbe.cs index 88302ea..f1ff697 100644 --- a/src/common/NativeProbe.cs +++ b/src/common/NativeProbe.cs @@ -625,6 +625,18 @@ private static string Watched(string step, Func call) /// returned. The page was loaded a second after launch, which is a /// reasonable thing to do and has now cost two rounds of somebody's evening. /// + /// The verdict on the books, from this launch or an earlier one, or null. + public static string Verdict + { + get + { + lock (Book) + { + return _verdict; + } + } + } + public static string Progress() { lock (Book) @@ -844,6 +856,10 @@ private static void Append(string path, string line) /// question is queued behind it. They are ledgered too, which is what makes /// them collectable at all: a hang on the first location used to eat every /// reading behind it, on every launch, forever. + /// + /// A walk whose verdict is already on the books — from an earlier launch, or + /// from the early walk on this one — says so and asks nothing; see the note + /// in . /// public static void Run() { @@ -932,13 +948,7 @@ public static bool WaitForWalk(int timeoutMs) /// public static bool StartEarlyIfUnfinished() { - string directory = DataDirectory(); - if (string.IsNullOrEmpty(directory)) - { - return false; - } - - string outcome = Ledger.Standing(Path.Combine(directory, LedgerFile)); + string outcome = Standing(); if (!outcome.StartsWith("unfinished", StringComparison.Ordinal)) { return false; @@ -950,6 +960,40 @@ public static bool StartEarlyIfUnfinished() return true; } + /// + /// Where the ladder stands on this install, read from the ledger and never + /// written: "no ledger" (every set this app works on), "finished", + /// "unfinished", "unfinished — another build's ledger", or the deadline's + /// miss. One small file read, under the deadline. + /// + public static string Standing() + { + string directory = DataDirectory(); + if (string.IsNullOrEmpty(directory)) + { + return "no ledger"; + } + + return Ledger.Standing(Path.Combine(directory, LedgerFile)); + } + + /// + /// Whether the engine has already failed on this install: the ledger only + /// ever comes into existence on a launch whose engine had failed, so its + /// presence is that record, whatever build wrote it and whether or not the + /// walk finished. This is the gate for every diagnostic allowed in front of + /// the engine — the walk when it is unfinished, and the import census + /// (issue #105) whenever the ledger is there at all — because on an install + /// where the books already say the engine fails, a launch spent + /// re-establishing that is a launch spent on nothing. + /// + public static bool EngineFailedHere() + { + string outcome = Standing(); + return string.Equals(outcome, "finished", StringComparison.Ordinal) || + outcome.StartsWith("unfinished", StringComparison.Ordinal); + } + /// /// on a background thread. The walk is claimed here, before /// the thread exists, so a that follows on another thread @@ -1014,6 +1058,25 @@ private static void Walk() Trace(" probe ledger: none — a fatal step will not be skipped next launch"); } + // A verdict on the books is the answer, and nothing behind this line + // can improve on it — so the walk stops here rather than re-asking + // the repeatable rungs. The AU7200 (issue #105) showed why that + // matters: on `build-3996334` and `build-283f3e9` alike the early walk + // reached its verdict in a quarter of a second, the engine failed, + // the post-failure thread started the walk *again*, and the launch + // ended at `probe: open res/` — the first repeatable rung — with the + // import census queued behind it and never reached. On that set + // every launch is over within five seconds of the engine failing + // (no heartbeat, no deadline miss), so whatever sits in front of a + // question on the failure path is what costs that question a build. + string settled = Ledger.Verdict; + if (settled != null) + { + Summary = settled; + Trace("native probe: verdict already on the books — " + settled + "; not walking again"); + return; + } + // Before the first question, and again after every location: both // reports on build-3368aea were pages loaded a second after launch, and // they read `own native : (not asked)` on a set whose trail plainly diff --git a/src/common/SmackWall.cs b/src/common/SmackWall.cs index 0326cc4..4629eb3 100644 --- a/src/common/SmackWall.cs +++ b/src/common/SmackWall.cs @@ -180,8 +180,12 @@ public static void InvestigateInBackground(string target) // Issue #105: what a stub would have to export, ahead of the // investigation because the investigation's last step is the - // one the Q80 never came back from, and this is the question - // the next build on a set that passed the ladder waits on. + // one the Q80 never came back from. On an install whose ledger + // already records the engine's failure the census was taken + // ahead of the engine, from OnCreate, and this call finds it + // done; this is the first failure's path. build-283f3e9 had it + // here only, and the AU7200's launch was over before the walk + // in front of it finished — see EngineImports. EngineImports.Census(ChromiumImpl.Implementation, target); Investigate(target); }); diff --git a/src/elm/BrowserApp.cs b/src/elm/BrowserApp.cs index 0a10951..53b68c9 100644 --- a/src/elm/BrowserApp.cs +++ b/src/elm/BrowserApp.cs @@ -175,6 +175,7 @@ protected override void OnCreate() // ladder is done. Bounded, because a set that stalls every rung would // otherwise hold a black screen for four minutes; the ledger carries the // rest to the next launch. See NativeProbe.WaitForWalk. + bool engineFailedHere = NativeProbe.EngineFailedHere(); if (NativeProbe.StartEarlyIfUnfinished()) { const int WalkBudgetMs = 90000; @@ -187,6 +188,32 @@ protected override void OnCreate() : "native probe: still walking after " + (WalkBudgetMs / 1000) + " s — on to the engine anyway"); } + // The second diagnostic allowed in front of the engine, on the same + // grounds and the same gate (issue #105). build-283f3e9 took the import + // census on the post-failure thread and the AU7200 never got there: the + // launch was over within five seconds of ENGINE FAILURE, as every Q80 + // launch was, and the second launch of the build never reached this + // method. On an install whose ledger already records the engine's + // failure, the census runs here, after the walk, and the engine waits + // for it — bounded, because each of the implementation's hundred-odd + // dependencies is a dlopen under its own deadline, and a set that parks + // them all would otherwise hold a black screen for minutes. What the + // bound cuts off still reaches the trail from the census's own thread. + // See EngineImports for what the lines mean. + if (engineFailedHere) + { + const int CensusBudgetMs = 60000; + Breadcrumbs.Drop("engine imports: the engine failed on an earlier launch here — taking the census now, ahead of the engine"); + EngineImports.RunInBackground(null, null); + Breadcrumbs.Drop("engine imports: the engine waits for the census (up to " + + (CensusBudgetMs / 1000) + " s)"); + var censusClock = System.Diagnostics.Stopwatch.StartNew(); + bool counted = EngineImports.WaitForCensus(CensusBudgetMs); + Breadcrumbs.Drop(counted + ? "engine imports: census finished after " + censusClock.ElapsedMilliseconds + " ms — on to the engine" + : "engine imports: still counting after " + (CensusBudgetMs / 1000) + " s — on to the engine anyway"); + } + // Bringing up chromium-efl is the one step we expect to be able to // fail: there are reports of an app-created Tizen.WebView crashing on // the TV emulator with nothing in the log, and the TV profile is not diff --git a/src/elm/Program.cs b/src/elm/Program.cs index 213a203..2fcfeec 100644 --- a/src/elm/Program.cs +++ b/src/elm/Program.cs @@ -59,6 +59,13 @@ private static void Main(string[] args) // Required before any ElmSharp widget is created (the Tizen.WebView // sample in TizenFX does the same). ElmSharp is deprecated from API // 10, so on a newer platform this is a place that can fail. + // + // Named before it is made, like every call that has ever stopped a + // launch. On the AU7200 (issue #105) the second launch of each build + // has shown three lines and no UI, on two builds; the last of them is + // the preload's, which puts this call next in line, by inference + // only. This line makes it the trail's statement rather than ours. + Breadcrumbs.Drop("Elementary: initializing"); Elementary.Initialize(); Elementary.ThemeOverlay(); Breadcrumbs.Drop("Elementary initialized"); diff --git a/src/nui/NuiMseWatch.cs b/src/nui/NuiMseWatch.cs index 6518632..291e2c0 100644 --- a/src/nui/NuiMseWatch.cs +++ b/src/nui/NuiMseWatch.cs @@ -421,6 +421,28 @@ function onScreen(v) { } catch (e) { return '?'; } } + /* How long the element says its media is: a number is a clip, `inf` is what a + live stream reads — and also what an MSE clip reads until its page sets + MediaSource.duration, so `inf` on its own is not live; `inf` with a playhead + that never loops back to 0 is. Issue #100's `build-644c119` reports: the one + freeze left is said to come with a live stream next in the feed, and nothing + on the trail could say which element had the live stream in it. */ + function dur(v) { + try { + var d = v.duration; + return 'dur ' + (isFinite(d) ? d.toFixed(1) + 's' : 'inf'); + } catch (e) { return 'dur ?'; } + } + + /* TikTok's feed moves the address to /@user/live while a live stream is the + item on screen, which is the one plain statement of it there is. Nothing + else about the page is read, and nothing when it is not that page. */ + function where() { + try { + return /\/live(\/|$)/.test(location.pathname) ? ', live page' : ''; + } catch (e) { return ''; } + } + ['loadstart', 'loadedmetadata', 'playing', 'waiting', 'pause', 'emptied'].forEach(function (type) { document.addEventListener(type, function (e) { try { @@ -429,10 +451,10 @@ function onScreen(v) { var g = tag(v); g.ev = type; g.at = Date.now(); - var what = type === 'loadstart' ? origin(v) + ', preload ' + v.preload + ', ' + onScreen(v) - : type === 'loadedmetadata' ? v.videoWidth + 'x' + v.videoHeight + ', ' + onScreen(v) + var what = type === 'loadstart' ? origin(v) + ', preload ' + v.preload + ', ' + onScreen(v) + where() + : type === 'loadedmetadata' ? v.videoWidth + 'x' + v.videoHeight + ', ' + dur(v) + ', ' + onScreen(v) : type === 'emptied' ? onScreen(v) - : 't ' + v.currentTime.toFixed(1) + ', ' + onScreen(v); + : 't ' + v.currentTime.toFixed(1) + ', ' + onScreen(v) + (type === 'playing' ? where() : ''); report(g.id + ' ' + type + ' ' + what); } catch (_) {} }, true); diff --git a/tools/engineimports/Program.cs b/tools/engineimports/Program.cs index 2d7f470..39753a3 100644 --- a/tools/engineimports/Program.cs +++ b/tools/engineimports/Program.cs @@ -31,7 +31,22 @@ private static int Main(string[] args) string blocked = args.Length > 2 ? args[2] : null; var started = DateTime.UtcNow; - EngineImports.Census(path, blocked); + if (scenario == "background") + { + // The shape OnCreate uses ahead of the engine (issue #105): the census + // on its own thread, the caller waiting, bounded. Same answers as + // the inline call, and a Census behind it must find it taken. + EngineImports.RunInBackground(path, blocked); + Expect(EngineImports.WaitForCensus(60000), "the census on its own thread finishes inside the wait"); + Expect(EngineImports.WaitForCensus(0), "a wait after it returns at once"); + scenario = "census"; + } + else + { + Expect(EngineImports.WaitForCensus(0), "before any census, a wait returns at once"); + EngineImports.Census(path, blocked); + } + double seconds = (DateTime.UtcNow - started).TotalSeconds; string summary = EngineImports.Summary; diff --git a/tools/engineimports/run.sh b/tools/engineimports/run.sh index 302b931..f19d4a1 100755 --- a/tools/engineimports/run.sh +++ b/tools/engineimports/run.sh @@ -67,6 +67,9 @@ run() { # set says "Operation not permitted", and the census only has to carry the words. chmod 000 "$work/lib/libblocked.so" run census "$work/lib/libneedy.so" libblocked.so +# The same, taken on a thread of its own with the caller waiting — how OnCreate +# runs it ahead of the engine. +run background "$work/lib/libneedy.so" libblocked.so chmod 644 "$work/lib/libblocked.so" # Nothing to import at all, on the committed ARM ELF32. diff --git a/tools/msewatch/build-page.py b/tools/msewatch/build-page.py index c9e9d44..8e1a2ee 100644 --- a/tools/msewatch/build-page.py +++ b/tools/msewatch/build-page.py @@ -138,9 +138,14 @@ def script(): Object.defineProperty(fake, 'currentTime', {get:function(){ return T; }, set:function(){ fake.__touched = 'seek'; }}); Object.defineProperty(fake, 'src', {get:function(){ return url; }}); Object.defineProperty(fake, 'currentSrc', {get:function(){ return url; }}); +Object.defineProperty(fake, 'duration', {get:function(){ return Infinity; }}); fake.getVideoPlaybackQuality = function(){ return {totalVideoFrames: 40, droppedVideoFrames: 0}; }; ['pause','play','load'].forEach(function(f){ fake[f] = function(){ fake.__touched = f; }; }); document.body.appendChild(fake); +/* Metadata the way a live stream reports it — no finite duration. The real MSE + element above never reaches metadata (its segments are shells), so this is the + one loadedmetadata the run has, and the probe has to read the duration off it. */ +setTimeout(function(){ fake.dispatchEvent(new Event('loadedmetadata')); }, 1500); setTimeout(function(){ setInterval(function(){ T += 0.25; }, 250); }, 5000); function has(re){ return mse.some(function(l){ return re.test(l); }); } @@ -165,6 +170,8 @@ def script(): if (!has(/^moving again v\\d after \\d+\\.\\ds \\(on its own\\), frames \\+0, appends \\+0$/)) { fail('end of stall not reported'); } if (has(/avc1 0x0/)) { fail('the ftyp brand list was read as a sample entry'); } if (!has(/^v\\d loadstart ms1, preload \\w+, (on|off) screen$/)) { fail('MSE element loadstart not reported with its source'); } + if (!has(/^v\\d loadedmetadata \\d+x\\d+, dur inf, (on|off) screen$/)) { fail('loadedmetadata not reported with the duration'); } + if (has(/live page/)) { fail('a page that is not /live was called one'); } if (!has(/^v\\d loadstart url example\\.invalid\\/video, preload auto, (on|off) screen$/)) { fail('plain-URL element loadstart not reported'); } if (!has(/^with v\\d paused rs\\d ns\\d url example\\.invalid\\/video, (on|off) screen|no box, last \\w+ \\d+\\.\\ds ago$/)) { fail('stall does not list the plain-URL element'); } if (!has(/^with v\\d paused rs\\d ns\\d ms1, /)) { fail('stall does not list the other MSE element'); } diff --git a/tools/probeladder/Program.cs b/tools/probeladder/Program.cs index 356e69b..a35b835 100644 --- a/tools/probeladder/Program.cs +++ b/tools/probeladder/Program.cs @@ -151,31 +151,44 @@ private static void Peek(string root) NativeProbe.Run(); - Expect(NativeProbe.Summary.Contains("maps executable and dlopen loaded it"), - "a walk behind it replaces the verdict with this box's own"); + // Until the AU7200's two reports a walk behind a verdict replaced it with + // this launch's own. It asks nothing now — see Resume — so the seeded + // verdict stands, on the header and on the file, and nothing is written + // after it. + Expect(NativeProbe.Summary == before, "a walk behind it keeps the verdict rather than asking again"); + Expect(Breadcrumbs.Trail.Contains("verdict already on the books — " + before), "and says why"); string ledger = Ledger(root); - Expect(ledger.IndexOf("verdict\t" + NativeProbe.Summary, StringComparison.Ordinal) > - ledger.IndexOf("verdict\tREFUSED in res/", StringComparison.Ordinal), - "and writes the new one down after the old — later lines win"); + Expect(Occurrences(ledger, "verdict\t") == 1, "and writes no second verdict down"); + Expect(!Breadcrumbs.Trail.Contains("probe: open res/"), "having opened nothing"); } /// - /// A second launch replays what the first established instead of asking again. - /// The rungs that must not be repeated are the ones that can end a launch. + /// A second walk behind a verdict asks nothing at all. It used to replay the + /// answered rungs and re-make the repeatable ones, and on the AU7200 (issue + /// #105) the post-failure walk behind the early walk's verdict stopped on the + /// first of those — `probe: open res/`, on two builds — with the import census + /// queued behind it. The verdict is the answer; a walk cannot improve on it. /// private static void Resume(string root) { NativeProbe.Run(); + string verdict = NativeProbe.Summary; + Expect(verdict.Contains("maps executable and dlopen loaded it"), "the first walk reaches a verdict"); + NativeProbe.Run(); string trail = Breadcrumbs.Trail; - Expect(trail.Contains("res/:exec: answered on an earlier launch"), - "the second launch replays the executable mapping"); + Expect(trail.Contains("native probe: verdict already on the books — " + verdict + "; not walking again"), + "the second walk says the verdict is on the books"); + Expect(Occurrences(trail, "native probe: starting") == 2, + "and said it started before it looked — the ledger's own open is still a call"); + Expect(Occurrences(trail, "probe: open res/") == 1, + "and does not open the file again — nothing behind the verdict is worth a call"); Expect(Occurrences(trail, "probe: mmap PROT_READ|PROT_EXEC res/") == 1, - "and does not ask for it a second time"); - Expect(Occurrences(trail, "probe: open res/") == 2, - "but does open the file again — the rungs behind it need the descriptor"); + "nor ask for the executable mapping again"); + Expect(NativeProbe.Summary == verdict, "and the header still holds the verdict"); + Expect(NativeProbe.EngineFailedHere(), "a ledger with a verdict says the engine has failed here"); } /// @@ -251,6 +264,7 @@ private static void Abandoned(string root) /// private static void Early(string root, Stopwatch clock) { + Expect(NativeProbe.EngineFailedHere(), "an unfinished ledger says the engine has failed here"); bool started = NativeProbe.StartEarlyIfUnfinished(); Expect(started, "an unfinished ledger starts the walk ahead of the engine"); Expect(Breadcrumbs.Trail.Contains("walking it now, ahead of the engine"), @@ -266,6 +280,14 @@ private static void Early(string root, Stopwatch clock) Expect(NativeProbe.WaitForWalk(0), "a wait after the walk returns at once"); Expect(Occurrences(Breadcrumbs.Trail, "native probe: starting") == 1, "having started exactly once"); + + // The post-failure thread's walk, behind the early one, on the same launch: + // the shape that stopped the AU7200 twice. + NativeProbe.Run(); + Expect(Breadcrumbs.Trail.Contains("verdict already on the books"), + "a walk behind the early walk's verdict on the same launch asks nothing"); + Expect(Occurrences(Breadcrumbs.Trail, "probe: open res/") == 1, + "and the file is opened once in the launch"); } /// @@ -274,12 +296,22 @@ private static void Early(string root, Stopwatch clock) /// private static void NotEarly(string root) { + Expect(NativeProbe.Standing() == "no ledger", "no ledger: the standing says so"); + Expect(!NativeProbe.EngineFailedHere(), "no ledger: the engine has not failed here, nothing runs ahead of it"); Expect(!NativeProbe.StartEarlyIfUnfinished(), "no ledger: the engine goes first, as always"); File.WriteAllText(Path.Combine(root, "data", "probe-ledger.txt"), "ledger 3\nlaunch\nres/:exec\tPROT_READ|PROT_EXEC: ok\nverdict\tseeded\n"); + Expect(NativeProbe.Standing() == "finished", "a ledger with a verdict stands finished"); + Expect(NativeProbe.EngineFailedHere(), "and says the engine has failed here — the census still goes ahead of it"); Expect(!NativeProbe.StartEarlyIfUnfinished(), "a ledger with a verdict: nothing left to ask early"); Expect(!Breadcrumbs.Trail.Contains("native probe: starting"), "and neither started a walk"); + + NativeProbe.Run(); + Expect(Breadcrumbs.Trail.Contains("verdict already on the books — seeded; not walking again"), + "and the ordinary walk behind the engine takes the seeded verdict as the answer"); + Expect(!Breadcrumbs.Trail.Contains("probe: open res/"), "without opening a file"); + Expect(NativeProbe.Summary == "seeded", "the header shows it"); } ///