From 3c44f55f6b0aba77c7ad57d0a5ebe3e55b409473 Mon Sep 17 00:00:00 2001 From: Christophe Besson Date: Tue, 25 Aug 2026 18:18:48 +0200 Subject: fix(hub,node): Create Group wizard silently skipped apps, and lost track of scanning progress MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two real-world bugs found together while testing multi-root group creation: - CreateGroupWizard only sent the enabled-apps PUT when the operator had *unchecked* something, assuming "every box left checked" already matched the node's own default (Roster.DEFAULT_APPS = chat, files). It doesn't — so leaving every app checked, the common case, silently left Videos/Music/Photos disabled on the node. Now sent unconditionally. - The wizard's "add extra roots" step never polled index-status, so once step 3 (which only watches the first/upload root) finished, the progress bar froze while the node kept scanning the remaining roots for minutes, unwatched. Added waitForRootsIndexed (platform.js), mirroring waitForGroupHosted's own race handling. That fix exposed a deeper one: indexer.py's _scan_root() only flipped `progress.scanning` on *after* walking the directory and stat()-ing every file — both off-loop, but slow enough on a large root that a poller's grace period (waitForRootsIndexed's 5s) could expire before ever observing `scanning: true` (confirmed against production logs: a GEK-init step fired 5.058s after a root started scanning, matching the grace period almost exactly). The stat() pass was also a synchronous loop directly on the asyncio event loop — blocking the whole daemon (WebRTC, chat, admin UI) for as long as it took on a root with many files. Both fixed: `scanning` now flips on before the walk starts, and stat()-ing is now off-loop too (_size_files). Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_013XSohfUQQiaE77qyFLgSv3 --- packages/meshbay-hub/src/meshbay_hub/static/app.js | 37 ++++++---- .../meshbay-hub/src/meshbay_hub/static/platform.js | 40 ++++++++++ .../src/meshbay_node/indexer/indexer.py | 65 +++++++++++++---- packages/meshbay-node/tests/test_indexer.py | 85 ++++++++++++++++++++++ 4 files changed, 198 insertions(+), 29 deletions(-) (limited to 'packages') diff --git a/packages/meshbay-hub/src/meshbay_hub/static/app.js b/packages/meshbay-hub/src/meshbay_hub/static/app.js index 1530ff5..5ec1ac8 100644 --- a/packages/meshbay-hub/src/meshbay_hub/static/app.js +++ b/packages/meshbay-hub/src/meshbay_hub/static/app.js @@ -926,11 +926,15 @@ function CreateGroupWizard({ token, username, onCreated }) { { label: t('wizard.step_attach'), status: 'pending' }, ]; steps.push({ label: t('wizard.step_index'), status: 'pending' }); - // Only a step at all when it does something — the common case (every - // app left on, the default) has nothing to set and no reason to show a - // step for it. After indexing (see the execution order below for why). - if (enabledApps.length < APPS.length) - steps.push({ label: t('wizard.step_apps'), status: 'pending' }); + // Always a step: the node's own default for a brand-new group is + // `chat, files` only (Roster.DEFAULT_APPS) — narrower than "every app + // checked" here, which is this wizard's own default. Skipping this call + // whenever nothing was *unchecked* used to assume those two defaults + // agreed; they don't, so leaving every box checked — the common, + // recommended case — silently left Videos/Music/Photos disabled on the + // node (found live 2026-08-25: no `set_enabled_apps`/"Enabled apps for + // group" ever logged for a group created with every app left on). + steps.push({ label: t('wizard.step_apps'), status: 'pending' }); if (roots.length > 1) steps.push({ label: t('wizard.step_add_roots'), status: 'pending' }); steps.push({ label: t('wizard.step_gek'), status: 'pending' }); @@ -1009,7 +1013,10 @@ function CreateGroupWizard({ token, username, onCreated }) { update('done'); advance(); - // 4. Narrow the enabled apps down, if the operator unchecked any. + // 4. Set the enabled apps — unconditionally (see the step-list + // comment above on why "only if narrowed" was wrong: the node's own + // default is not "every app", so leaving every box checked must still + // be told to the node explicitly). // Used to run *before* the scan above, reasoning that a member // joining mid-scan should never briefly see an app meant to be off — // but nobody can join before the group is hosted either (same @@ -1019,13 +1026,11 @@ function CreateGroupWizard({ token, username, onCreated }) { // indefinite "Group not hosted on this node" (found live against a // real, several-thousand-file library: withRetry's five attempts // don't come close to covering a scan that takes minutes). - if (enabledApps.length < APPS.length) { - update('running'); - await withRetry(() => platform.node.call( - 'PUT', `/api/groups/${gid}/apps`, { apps: enabledApps })); - update('done'); - advance(); - } + update('running'); + await withRetry(() => platform.node.call( + 'PUT', `/api/groups/${gid}/apps`, { apps: enabledApps })); + update('done'); + advance(); // 5. Add extra roots (if >1) if (roots.length > 1) { @@ -1038,6 +1043,12 @@ function CreateGroupWizard({ token, username, onCreated }) { upload: i === uploadIdx, })); } + // Each add above only schedules its scan (platform.js's + // waitForRootsIndexed docstring) — wait for it to actually finish, + // reusing the same progress bar step 3 fed, or this step reports + // "done" while the node is still hashing gigabytes behind the + // scenes (found live 2026-08-25). + await platform.waitForRootsIndexed(gid, setIndexProgress); update('done'); advance(); } diff --git a/packages/meshbay-hub/src/meshbay_hub/static/platform.js b/packages/meshbay-hub/src/meshbay_hub/static/platform.js index a5312e1..78e27eb 100644 --- a/packages/meshbay-hub/src/meshbay_hub/static/platform.js +++ b/packages/meshbay-hub/src/meshbay_hub/static/platform.js @@ -327,6 +327,46 @@ export async function waitForGroupHosted(groupId, onProgress, } } +/** + * Create Group wizard only: after adding extra roots (step 5), wait for + * whatever scanning that triggers to actually finish, showing progress along + * the way. `POST /api/groups/{id}/roots` (ui/app.py) schedules its rescan as + * a detached background task and returns as soon as the config write is + * done — "every add-root call resolved" is not "the node is done indexing". + * Found live (2026-08-25): a multi-root group's later, larger roots kept + * scanning for minutes after the wizard had already moved on to GEK init and + * pairing, with no progress shown anywhere — the disk was working, the UI + * just never asked again. + * + * Same race as waitForGroupHosted above, one level down: the very first + * poll can land in the gap between "the last add-root call returned" and + * "its background reload actually started scanning", which reads as "not + * scanning" for the wrong reason (nothing left to do) rather than the right + * one (hasn't started yet). Waits up to `graceMs` for scanning to be + * observed at least once before trusting a "not scanning" answer — after + * that, the first "not scanning" really does mean finished, because the + * node scans one root at a time (indexer.py's single-worker executor) and + * nothing here adds more roots once this call starts. + */ +export async function waitForRootsIndexed(groupId, onProgress, + { intervalMs = 500, graceMs = 5000 } = {}) { + const graceDeadline = Date.now() + graceMs; + let sawScanning = false; + for (;;) { + let status; + try { + status = await node.call('GET', `/api/groups/${groupId}/index-status`); + } catch { + return; // the node went away mid-poll — same stance as watchIndexProgress + } + if (onProgress) onProgress(status); + if (status.scanning) sawScanning = true; + if (sawScanning && !status.scanning) return; + if (!sawScanning && Date.now() > graceDeadline) return; + await new Promise((r) => setTimeout(r, intervalMs)); + } +} + /** * LAN cast relay — re-serve decrypted video segments over HTTP so a * Chromecast or Smart TV on the same Wi-Fi can play the stream. diff --git a/packages/meshbay-node/src/meshbay_node/indexer/indexer.py b/packages/meshbay-node/src/meshbay_node/indexer/indexer.py index 10981c0..f78465b 100644 --- a/packages/meshbay-node/src/meshbay_node/indexer/indexer.py +++ b/packages/meshbay-node/src/meshbay_node/indexer/indexer.py @@ -139,6 +139,27 @@ def _walk_root(root: Root) -> list[Path]: return [p for p in root.path.rglob("*") if p.is_file()] +def _size_files(files: list[Path]) -> list[tuple[Path, int]]: + """ + Blocking: stat() every file from an already-completed walk — run via an + executor for the same reason `_walk_root` is (its own docstring above). + Previously a plain loop straight on the asyncio event loop thread: for a + root with many thousands of files (a real personal library, not a + hypothetical — docs/musicbay.md's own "several thousand files" example) + that blocked the entire daemon, every WebRTC session and the admin UI + included, for as long as the stat() calls took — and did so *before* + `_scan_root` had even set `progress.scanning`, so a consumer polling it + saw "not scanning" the whole time real, blocking work was happening. + """ + sized: list[tuple[Path, int]] = [] + for p in files: + try: + sized.append((p, p.stat().st_size)) + except OSError: + continue + return sized + + def _scan_file(root: Root, file_path: Path) -> IndexEntry | None: """Compute IndexEntry for a file. Blocking — run in executor. Uses streaming blake3 so arbitrarily large files (ISOs, VM images, etc.) @@ -304,26 +325,38 @@ class DirectoryIndexer: log.info("Scanning %s (root %r) ...", root.path, root.name) count = 0 loop = asyncio.get_event_loop() - try: - files = await loop.run_in_executor(self._executor, _walk_root, root) - except OSError as e: - log.warning("Cannot scan root %r: %s", root.name, e) - return 0 - - # Sizes up front, off the same listing that already walked the tree — - # the progress bar's denominator, not a second pass over the disk. - sized: list[tuple[Path, int]] = [] - for p in files: - try: - sized.append((p, p.stat().st_size)) - except OSError: - continue + # `scanning` flips on here, before the walk — not after it and the + # sizing pass, which for a large or slow (network/USB) root can + # themselves take a long time despite running off-loop. A consumer + # polling IndexProgress (index-status; the Create Group wizard's + # own progress bar) must see "scanning" the moment real work starts, + # not only once the file list and its total size are known. Found + # live (2026-08-25): the wizard's post-creation "add extra roots" + # step gave up waiting after a short grace period because the flag + # had not yet turned on, even though the node was already several + # seconds into walking and sizing a large root — total_bytes is + # unknown at this point, so it starts at 0 and is corrected below. self.progress.scanning = True self.progress.scanned_bytes = 0 - self.progress.total_bytes = sum(size for _, size in sized) - self.progress.current_dir = "" + self.progress.total_bytes = 0 + self.progress.current_dir = root.name try: + try: + files = await loop.run_in_executor(self._executor, _walk_root, root) + except OSError as e: + log.warning("Cannot scan root %r: %s", root.name, e) + return 0 + + # Sizes up front, off the same listing that already walked the + # tree — the progress bar's denominator, not a second pass over + # the disk. Off-loop for the same reason the walk itself is + # (_size_files's own docstring: this used to be a synchronous + # loop right here, blocking the whole daemon for a large root). + sized = await loop.run_in_executor(self._executor, _size_files, files) + + self.progress.total_bytes = sum(size for _, size in sized) + self.progress.current_dir = "" for file_path, size in sized: self.progress.current_dir = file_path.parent.name entry = await self._hash_or_cached(root, file_path) diff --git a/packages/meshbay-node/tests/test_indexer.py b/packages/meshbay-node/tests/test_indexer.py index 4bae620..9aa9fb9 100644 --- a/packages/meshbay-node/tests/test_indexer.py +++ b/packages/meshbay-node/tests/test_indexer.py @@ -2,6 +2,7 @@ import asyncio import os +import threading import time import pytest from pathlib import Path @@ -520,6 +521,90 @@ async def test_walk_root_does_not_stall_the_event_loop(tmp_path, sk_node, gek): "during a 0.2s walk") +@pytest.mark.asyncio +async def test_scanning_flag_is_true_while_the_walk_is_still_running(tmp_path, sk_node, gek): + """ + Regression for the actual bug this was found by (2026-08-25): `scanning` + used to flip on only *after* the walk finished, so a consumer polling + IndexProgress — index-status; the Create Group wizard's own progress + poll, which gives up after a short grace period if it never observes + `scanning: true` — read "not scanning" for however long a large/slow + root's discovery phase took, even though the node was already doing real + work. Confirmed against production logs: a wizard step waiting on this + flag gave up exactly at its grace-period deadline for a root whose walk + was still running. + """ + d = tmp_path / "shared" + d.mkdir() + (d / "f.bin").write_bytes(b"x") + + real_walk = indexer_mod._walk_root + walk_started = threading.Event() + release_walk = threading.Event() + + def slow_walk(root): + walk_started.set() + release_walk.wait(timeout=5) + return real_walk(root) + + indexer_mod._walk_root = slow_walk + indexer = DirectoryIndexer(roots=one_root(d), group_id="g", sk_node=sk_node, gek=gek) + try: + scan_task = asyncio.create_task(indexer.initial_scan()) + # Off-loop wait for the walk to actually start — busy-polling the + # event loop itself here would defeat the point of the test. + await asyncio.get_event_loop().run_in_executor(None, walk_started.wait, 5) + + assert indexer.progress.scanning is True, ( + "scanning must be True the moment the walk starts, not only " + "once it (and the sizing pass) finish") + finally: + release_walk.set() + indexer_mod._walk_root = real_walk + await scan_task + + assert indexer.progress.scanning is False + + +@pytest.mark.asyncio +async def test_scanning_flag_is_true_while_sizing_files_is_still_running( + tmp_path, sk_node, gek): + """ + Same regression, one phase later: sizing (stat()-ing every walked file) + used to be a synchronous loop straight on the asyncio event loop thread — + for a root with many thousands of files (a real personal library, not a + hypothetical) that blocked the entire daemon, and did so before + `scanning` was ever set. Now off-loop (_size_files) and `scanning` is + already true throughout, same principle as the walk phase above. + """ + d = tmp_path / "shared" + d.mkdir() + (d / "f.bin").write_bytes(b"x") + + real_size = indexer_mod._size_files + sizing_started = threading.Event() + release_sizing = threading.Event() + + def slow_size(files): + sizing_started.set() + release_sizing.wait(timeout=5) + return real_size(files) + + indexer_mod._size_files = slow_size + indexer = DirectoryIndexer(roots=one_root(d), group_id="g", sk_node=sk_node, gek=gek) + try: + scan_task = asyncio.create_task(indexer.initial_scan()) + await asyncio.get_event_loop().run_in_executor(None, sizing_started.wait, 5) + + assert indexer.progress.scanning is True + finally: + release_sizing.set() + indexer_mod._size_files = real_size + await scan_task + + assert indexer.progress.scanning is False + + @pytest.mark.asyncio async def test_reconcile_backoff_grows_with_no_changes_then_caps(shared_dir, sk_node, gek): indexer = DirectoryIndexer(roots=one_root(shared_dir), group_id="g", -- cgit v1.2.3