HarperFast / HarperFast/harper-pro

'indexing-finished' signal has no receiver: worker threads latch isIndexing=true permanently, 503 on every search of a completed index

Open
#681 0 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
JavaScript
Stars
3
Forks
0
Avg merge
1d 21h
Merged PRs (30d)
80

Description

> **Suggested priority: P2** — permanent per-thread 503s on a healthy index after any rolling
> restart, invisible to `describe_table` and load-balanced into "intermittent". A live workaround
> exists (set the flag via inspector), and the fix is small: the `'indexing-finished'` signal at
> `databases.js:2140` just needs a receiver.

## Summary

The `'indexing-finished'` schema event is **broadcast but never consumed**. Any worker thread that opens an index dbi while `indexingPID` is still present in the attribute descriptor latches `dbi.isIndexing = true` and has **no path back to `false`** for the life of the thread. Every `search()` on that attribute from that thread then throws `IndexRebuildingError` (503) forever, even though the backfill completed cleanly and the index on disk is complete.

Observed on **harper-pro 5.2.1**, Node v24.19.0, a 4-node cluster, on a newly-added `Int @indexed` attribute. 12 of 64 worker threads across 3 nodes were permanently stuck; the 4th node was entirely clean.

## The defect

`databases.js:2140` — on clean completion, the backfilling thread clears its own flags and signals siblings:

```js
attribute.dbi.isIndexing = false;
const activeDbi = Table.indices[attribute.name];
if (activeDbi) activeDbi.isIndexing = false;
...
await signalling.signalSchemaChange(
new SchemaEventMsg(process.pid, 'indexing-finished', Table.databaseName, Table.tableName));
```

`grep -rn "indexing-finished" dist/` returns **exactly one hit — that send.** Nothing subscribes to it. So the clearing is purely thread-local to whichever thread ran the backfill.

Meanwhile `databases.js:1871` latches the flag on any *other* thread that opens the dbi during the backfill window:

```js
// If a migration is in progress (indexingPID set), any newly opened dbi must also
// reflect isIndexing = true.
if (attributeDescriptor?.indexingPID) dbi.isIndexing = true;
```

That set is correct in isolation, but it is one-way: the only code that clears `isIndexing` is inside `runIndexing()`'s completion path, which runs in a single thread. A thread that opens the dbi inside the window and is not the backfilling thread keeps `true` permanently.

`search.js:284` then resolves exactly that object, and `search.js:407-413` rejects:

```js
const index = isPrimaryKey ? Table.primaryStore : Table.indices[attribute_name];
...
if (!index || index.isIndexing || needFullScan || ...) {
if (index?.isIndexing)
throw new IndexRebuildingError(`"${attribute_name}" is not indexed yet, can not search for this attribute`);
```

## Evidence that the index was complete and the flag was purely stale

Probed every worker thread (ports 9229–9245) on all 4 nodes via CDP.

**Persisted descriptor** (`Table.dbisDB.get("/")`) — identical on all nodes, i.e. Harper's own on-disk record says the backfill finished cleanly:

```json
{"indexingPID": null, "indexingFailed": null, "lastIndexedKey": null, "restartNumber": null}
```

**Raw index audit, read from the stuck threads themselves** — the index dbi is complete and exactly matches the primary store:

```
port 9238: {wi:8, isIndexing:true, idxEntries:8, rows:8, match:true, persistedPID:null, persistedFailed:null}
port 9233: {wi:3, isIndexing:true, idxEntries:8, rows:8, match:true, persistedPID:null, persistedFailed:null}
port 9242: {wi:12, isIndexing:true, idxEntries:8, rows:8, match:true, persistedPID:null, persistedFailed:null}
```

Indexed search vs full scan on a *healthy* thread of the same node returned identical results (8/8 rows, same values).

**Distribution** — same table, same data, same version; only the in-memory boolean differs:

| Node | Stuck worker threads |
|---|---|
| A | wi 3, 4, 5, 8, 12, 14 (6 of 16) |
| B | wi 0, 1, 7, 10 (4 of 16) |
| C | wi 12, 13 (2 of 16) |
| D | **none** |

Log attribution matched the probe 1:1 (`http/N` == `wi N-1`), and error volume tracked per-thread traffic (one thread produced 683 errors in 20 min).

## Secondary symptom: leaked read snapshots

Each rejected search leaks a read snapshot that is only reclaimed when the open-transaction limit trips, producing a matching warn per error:

```
[warn]: Read iterators held a committed transaction's snapshot past the open-transaction limit; releasing it, from table: /
```

Counts tracked the errors ~1:1 per thread over 20 min (683/663, 343/338, 260/262, 247/240, 192/185). Combined, the two streams produced ~520 MB of logs in 3 h on one node.

## Why it is not self-healing

- `indexingPID`/`indexingFailed` are absent from the persisted descriptor, so the crash-recovery / retry triggers in `databases.js` do **not** re-fire — Harper correctly believes indexing is done.
- Nothing consumes `'indexing-finished'`.
- The flag is per-thread in-memory state, so it survives until that worker generation is replaced.

A restart is not a reliable remedy: it re-runs the same race. In this incident the stuck state was *created* by a rolling restart, and the one node that restarted outside the window was the clean one.

## Impact

Any consumer searching that attribute gets a permanent 503 on a subset of threads — load-balanced, so it presents as intermittent. In our case the caller degraded fail-safe (feature held at its default), but a caller that treats 503 as fatal, or one whose correctness depends on the query, would see a partial outage that no metric attributes to an index problem. `describe_table` reports the attribute as normally `indexed` and gives no hint.

## Workaround

Setting the flag to match the already-correct persisted state clears it with no restart:

```js
databases...indices..isIndexing = false;
```

Applied to all 12 threads; both log streams went to zero immediately and indexed search returned correct results on every thread.

## Suggested fix

1. Add a receiver for `'indexing-finished'` that re-reads the descriptor and clears `isIndexing` on `attribute.dbi` and `Table.indices[name]` — the send at `databases.js:2140` currently has no counterpart.
2. Consider deriving `isIndexing` from the persisted descriptor at query time (or re-validating on miss) rather than caching a one-way per-thread boolean, so a missed signal cannot strand a thread permanently.
3. Optionally, rate-limit / dedupe the `IndexRebuildingError` log so a stuck thread cannot emit hundreds of MB of logs.

Contributor guide

Open the contributing guide

Research direction

Start in databases.js around lines 1871 and 2140, then trace the schema-event handling and the isIndexing checks in search.js around lines 284 and 407-413. Verify the indexing-finished event reaches every worker and that completed indexes no longer leave stale flags or produce 503 searches; the persisted descriptor should remain the source of completion state.

Written by the indexing model from the issue text.

Assessment

Tech stack
javascript, node.js
Domain
backend, databases
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Quiet
Clarity
Clearly specified
Newbie friendliness
68/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.