diff --git a/arena_studio.html b/arena_studio.html index 3d495c18..9e1c1e2e 100644 --- a/arena_studio.html +++ b/arena_studio.html @@ -10764,7 +10764,10 @@

Import error

const key = [st.records, st.dropped, st.gaps, st.errors, st.notStored].join('/'); if (key === Studio.telemetry.lastReport) return; Studio.telemetry.lastReport = key; - Studio.rawLog('telemetry ring: ' + st.records + ' records · ' + st.blocks + ' blocks · ' + (st.bytes / 1024).toFixed(1) + ' KiB · dropped ' + st.dropped + ' · gaps ' + st.gaps + ' · errors ' + st.errors + (st.notStored ? ' · refused by bridge ' + st.notStored : '') + (st.heapCollision ? ' · RING DISABLED (heap collision)' : '') + (st.survivedReboot ? ' · ring survived a reboot (boot #' + st.bootCount + ')' : ''), 'dim'); + // `dropped` in the block header is the controller's LIFETIME eviction count (since + // its boot, mostly from before this page connected); only the growth since our + // first block is in-session loss. Say both, lead with the one that matters. + Studio.rawLog('telemetry ring: ' + st.records + ' records · ' + st.blocks + ' blocks · ' + (st.bytes / 1024).toFixed(1) + ' KiB · evicted this session ' + st.droppedSession + ' (controller lifetime ' + st.dropped + ') · gaps ' + st.gaps + ' · errors ' + st.errors + (st.notStored ? ' · refused by bridge ' + st.notStored : '') + (st.heapCollision ? ' · RING DISABLED (heap collision)' : '') + (st.survivedReboot ? ' · ring survived a reboot (boot #' + st.bootCount + ')' : ''), 'dim'); }, 60000); } else { Studio.telemetry.drainer.rearm(); // NO_ACK first: learn the ring incarnation before freeing anything @@ -10826,7 +10829,7 @@

Import error

r.kind === 'cmd' ? 'CMD 0x' + r.cmd.toString(16) + ' st' + r.status + ' @' + r.tUs : r.kind === 'frame' ? 'FRAME idx' + r.idx + ' sd' + r.sdLoadUs + 'us spi' + r.spiUs + 'us' + (r.reqAgeUs != null ? ' age' + r.reqAgeUs + 'us sup' + r.superseded + (r.contiguous ? ' contig' : '') : '') + ' @' + r.tUs : r.kind === 'state' ? 'STATE ' + r.stateName + ' ' + (r.codeName || r.code) + ' ' + r.arg + ' @' + r.tUs : '?'); - const summary = { tag: tag || 'drain', records: recs.length, blocks: blocks.length, survivedReboot: d.stats.survivedReboot, bootCount: d.stats.bootCount, dropped: d.stats.dropped, gaps: d.stats.gaps, heapCollision: !!d.stats.heapCollision, tail }; + const summary = { tag: tag || 'drain', records: recs.length, blocks: blocks.length, survivedReboot: d.stats.survivedReboot, bootCount: d.stats.bootCount, dropped: d.stats.dropped, droppedSession: d.stats.droppedSession, gaps: d.stats.gaps, heapCollision: !!d.stats.heapCollision, tail }; Studio.rawLog('telemetry dump (' + summary.tag + '): ' + recs.length + ' records' + (d.stats.survivedReboot ? ' — ring survived the reboot' : '') + (tail.length ? '\n ' + tail.join('\n ') : ''), recs.length ? 'warn' : 'dim'); const b = Studio.session.bridge; if (b && b.logging) b.log({ event: 'telemetry_dump', summary, raw_blocks: rawBlocks }); diff --git a/docs/development/telemetry-logging-reference.md b/docs/development/telemetry-logging-reference.md index b3acd26a..5ed48c0b 100644 --- a/docs/development/telemetry-logging-reference.md +++ b/docs/development/telemetry-logging-reference.md @@ -193,10 +193,10 @@ Studio v0.79 (`arena_studio.html`) or the named module; the bridge only adds the | `arena_command` | `js/arena-session.js:391` | > 8-byte requests (TRIAL_PARAMS) | v1 object, see §2.2 | | `trial_quality` | `arena_studio.html:8264` ← `js/trial-quality.js:246` `summary()` | **once, at run end, before export** (v0.78) | `threshold_us`, `target_us`, `trials[]`, `counts {pass, fail, unknown, open}`, `worst_gap_us`, `flagged_trials[]`, `unknown_trials[]`, `duplicates_dropped`, `records`. Per trial: `trial`, `pattern`, `status` (`pass`\|`fail`\|`unknown`), `duration_s`, `cmds70`, `index_changes`, `reads`, `frames`, `slow_reads`, `stalls`, `max_read_ms`, `age_gaps`, `max_age_ms`, `over_target`, `superseded`, `coverage[]` | | `display_gap` | `js/trial-quality.js:101` `gapEvent` → `arena_studio.html:8479` | one per gap > threshold, as it happens | `trial`, `pattern`, `seq`, `t_us`, `ms`, `kind` ∈ `sd_slow` (+ `phase`, `read_error`) · `frame_read` (+ `idx`; a slow read seen only in the FRAME record) · `frame_age` (+ `idx`; `req_age_us` > threshold). Absent from a clean run | -| `soak` | `arena_studio.html:8317` `logSoak` | soak driver phases | `phase` ∈ `start` · `iteration-start` · `iteration-end` · `paused` · `end`; `iteration-end` carries `iteration`, `outcome`, `fault`, `stop_acked`, `postmortem`, `applied_0x70`, `duration_s`, `telemetry` (drainer stats: `ackSeq`, `lastSeq`, `records`, `blocks`, `bytes`, `gaps`, `dropped`, `errors`, `notStored`, …). **`dropped` is the controller's lifetime evicted-record counter from the block header** (1157 with `gaps: 0` in the sample = eviction before the drainer started, not in-run loss) | +| `soak` | `arena_studio.html:8317` `logSoak` | soak driver phases | `phase` ∈ `start` · `iteration-start` · `iteration-end` · `paused` · `end`; `iteration-end` carries `iteration`, `outcome`, `fault`, `stop_acked`, `postmortem`, `applied_0x70`, `duration_s`, `telemetry` (drainer stats: `ackSeq`, `lastSeq`, `records`, `blocks`, `bytes`, `gaps`, `dropped`, `droppedSession`, `errors`, `notStored`, …). **`dropped` is the controller's lifetime evicted-record counter from the block header** (1157 with `gaps: 0` in the sample = eviction before the drainer started, not in-run loss); `droppedSession` (2026-10-29) is its growth since the drainer's first block of the ring incarnation, the in-session loss, and what the Studio's once-a-minute stats line leads with ("evicted this session N (controller lifetime M)") | | `sd_diag` | `arena_studio.html:8543` | `Studio.setSdDiag()` and the v0.79 connect banner | `flags`, `in_force` (GET_SD_INFO byte 29), `label` | | `probe` | `js/studio-postmortem.js:112` | post-mortem after a controller fault | `name`, `phase`, `cmd`, `req`, `sd`, then `dt`, `resp`, `status`, `ok`, `decoded` — or `error`, or `skipped: "capability X absent"`. The health read appears here as `name:"health"` with `decoded` | -| `telemetry_dump` | `arena_studio.html:8580` | post-mortem | `summary {tag, records, blocks, survivedReboot, bootCount, dropped, gaps, heapCollision, tail[]}`, `raw_blocks[]` (hex) | +| `telemetry_dump` | `arena_studio.html:8580` | post-mortem | `summary {tag, records, blocks, survivedReboot, bootCount, dropped, droppedSession, gaps, heapCollision, tail[]}`, `raw_blocks[]` (hex) | | `crash_report` | `arena_studio.html:8554` | post-mortem, fw flag bit 3 | `present`, `fault`, `ret_addr`, `cfsr`, `hfsr`, `bfar`, `mmfar`, `raw_hex` (junk after a HalfKay reflash — known) | | `health` | `arena_studio.html:5587` | **Console `chealth` only** | `source:"console"`, `health` (decoded 0xCA) | | `analog_loopback_sweep` | `arena_studio.html:5303` | Console Analog In panel | `channel`, `rows`, `fit`, `verdict` | diff --git a/js/arena-telemetry.js b/js/arena-telemetry.js index 052d495f..33a57df5 100644 --- a/js/arena-telemetry.js +++ b/js/arena-telemetry.js @@ -294,7 +294,9 @@ blocks: 0, bytes: 0, gaps: 0, // seq discontinuities seen (should equal controller-reported drops) - dropped: 0, // controller's cumulative drop counter (last value) + dropped: 0, // controller's LIFETIME eviction counter (header value, since its boot) + droppedBase: null, // that counter at our first block of this ring incarnation + droppedSession: 0, // evictions since then = loss this drainer could have prevented errors: 0, notStored: 0, // rows the sink refused (ack withheld, will be re-read) duplicates: 0, // records re-delivered after a rearm (already stored, dropped) @@ -339,6 +341,7 @@ break; } const rx = now(); + let freshRing = false; // Ring incarnation check (review finding: an old ack after a power // cycle would free unseen records). A different boot_count with the // ring NOT marked survived ⇒ fresh ring: forget the cursor. Same @@ -346,7 +349,10 @@ if (peekNext) { peekNext = false; if (st.bootCount != null && block.bootCount !== st.bootCount) { - if (!block.survivedReboot) st.lastSeq = null; + if (!block.survivedReboot) { + st.lastSeq = null; + freshRing = true; + } st.incarnations++; } if (st.lastSeq != null) { @@ -361,6 +367,15 @@ st.bytes += block.bytes; st.lastTNowUs = block.tNowUs; st.dropped = block.dropped; + // The header counter is the controller's lifetime eviction count: it + // includes everything the ring evicted before this drainer ever asked + // (a Studio connected hours after boot sees thousands with gaps 0). + // Only the growth since our first block of this incarnation is loss + // the host could have prevented, so that is what the UI reports. + if (st.droppedBase == null || freshRing || block.dropped < st.droppedBase) { + st.droppedBase = block.dropped; + } + st.droppedSession = (block.dropped - st.droppedBase) >>> 0; st.bootCount = block.bootCount; st.survivedReboot = block.survivedReboot; st.heapCollision = block.disabledHeapCollision; @@ -417,6 +432,8 @@ function reset() { st.ackSeq = NO_ACK; st.lastSeq = null; + st.droppedBase = null; + st.droppedSession = 0; peekNext = false; } diff --git a/js/studio-github.js b/js/studio-github.js index deb76c5e..8a2928f2 100644 --- a/js/studio-github.js +++ b/js/studio-github.js @@ -361,10 +361,22 @@ // Thin executor: run one descriptor with an injected fetch. Returns // {ok, status, data}. Never logs the token. Kept tiny so the builders stay // the tested surface. + // + // `cache: 'no-store'` (2026-10-29, found on ww18 under LAB-227): the JSON and + // the raw form of ONE contents URL differ only in the Accept header and + // GitHub gives both the same ETag. After a raw read (runBytes: ?p= open, + // promote, previews) Chrome revalidated the stored raw entry for the later + // JSON request, got a 304 and handed back the raw YAML; res.json() then + // threw, `data` was null and every "does this file exist?" check + // (resolveRepoSaveTarget, the silent-fork guard) answered "no" — a changed + // protocol silently overwrote the repo copy with no "Overwrite?" prompt. + // Bypassing the HTTP cache for the JSON executor closes it in both orders: + // nothing JSON is ever stored, so runBytes can keep caching the bytes. async function run(fetchImpl, req) { const res = await fetchImpl(req.url, { method: req.method, headers: req.headers, + cache: 'no-store', body: req.body != null ? JSON.stringify(req.body) : undefined }); let data = null; diff --git a/tests/test-arena-telemetry.js b/tests/test-arena-telemetry.js index 759d30c3..3440413b 100644 --- a/tests/test-arena-telemetry.js +++ b/tests/test-arena-telemetry.js @@ -341,6 +341,7 @@ function block(h, records) { const per = 3; const asked = []; let failNext = false; + let hdrDropped = 0; // the controller's lifetime eviction counter in the header const session = { async send(bytes) { const ack = @@ -365,7 +366,16 @@ function block(h, records) { const firstSeq = out.length ? (out[0][2] | (out[0][3] << 8) | (out[0][4] << 16) | (out[0][5] << 24)) >>> 0 : 0; - return block({ tNowUs: 999, firstSeq, more: ring.length > per, flags: 1 }, out); + return block( + { + tNowUs: 999, + firstSeq, + dropped: hdrDropped, + more: ring.length > per, + flags: 1 + }, + out + ); } }; const got = []; @@ -444,6 +454,27 @@ function block(h, records) { check('only the 2 new records counted', d.stats.records - recBefore, 2); d.reset(); check('reset forgets the cursor', [d.stats.ackSeq, d.stats.lastSeq], [0xffffffff, null]); + + // The header `dropped` is the controller's LIFETIME eviction count. A drainer that + // starts hours after boot sees thousands with no gaps: that is not in-session loss + // (ww18, 2026-10-29: "dropped 1929" read as a problem). Only growth since our first + // block counts as droppedSession. + const d3 = T.createDrainer({ session, wire: Wire, now: () => 42, onRecords: () => true }); + hdrDropped = 1929; + push(1); + await d3.drainOnce(); + check('lifetime counter kept verbatim', d3.stats.dropped, 1929); + check('nothing evicted since our first block', d3.stats.droppedSession, 0); + hdrDropped = 1931; + push(1); + await d3.drainOnce(); + check('growth since the first block is the session loss', d3.stats.droppedSession, 2); + d3.reset(); + check( + 'reset forgets the eviction baseline', + [d3.stats.droppedBase, d3.stats.droppedSession], + [null, 0] + ); } console.log('\n=== poller: single-flight, gated ==='); diff --git a/tests/test-studio-github.js b/tests/test-studio-github.js index 1bf145d4..248aef2f 100644 --- a/tests/test-studio-github.js +++ b/tests/test-studio-github.js @@ -474,9 +474,11 @@ console.log('=== run (injected fetch) ==='); (async () => { let seenUrl = null; let seenAuth = null; + let seenCache = null; const fakeFetch = async (url, init) => { seenUrl = url; seenAuth = init.headers.Authorization; + seenCache = init.cache; return { ok: true, status: 200, json: async () => ({ default_branch: 'main' }) }; }; const res = await G.run(fakeFetch, G.reqGetRepo(O, R, TOKEN)); @@ -484,6 +486,22 @@ console.log('=== run (injected fetch) ==='); check('run ok+status', [res.ok, res.status], [true, 200]); checkBool('run passed auth header', seenAuth === 'Bearer ' + TOKEN, seenAuth); checkBool('run hit repo url', seenUrl.endsWith('/repos/reiserlab/webDisplayTools'), seenUrl); + // The JSON executor bypasses the HTTP cache: the raw and JSON forms of a + // contents URL share an ETag, and a cached raw body served for a JSON + // request made the overwrite guard miss an existing file (ww18, 2026-10-29). + check('run bypasses the HTTP cache (no-store)', seenCache, 'no-store'); + + // A JSON reply that is not JSON (the cached-raw symptom) must not throw: + // callers see data null and decide; the status still comes through. + const notJson = async () => ({ + ok: true, + status: 200, + json: async () => { + throw new SyntaxError('raw'); + } + }); + const nj = await G.run(notJson, G.reqGetRepo(O, R, TOKEN)); + check('run tolerates a non-JSON body', [nj.ok, nj.status, nj.data], [true, 200, null]); console.log('=== runBytes (raw executor) ==='); const rawFetch = async () => ({