Skip to content

fix(storage_engine): end the HNSW build deadlock that hung .index create and bound index builds by the request deadline - #382

Merged
jsam merged 3 commits into
mainfrom
fm/fix-index-hang
Oct 5, 2026
Merged

jsam merged 3 commits into
mainfrom
fm/fix-index-hang

Conversation

@jsam

@jsam jsam commented Oct 5, 2026 •

Copy link
Copy Markdown
Contributor

Intent

I want you to really hyper focus on making the symbolic engine, you know, crisp and really truly production ready. (Context: #377 : a rare hang where .index create (HNSW, cosine) never replies; also related flake #302 in the HNSW recall test.)

Issue #377, "Rare hang: .index create (HNSW, cosine) never replies under load": the scenario harness test harness::shop_pack_vector_serves_the_near_rule failed 1 of 9 full debug runs on 4 pinned cores because the engine never answered .index create emb_idx on embedding(vec) metric cosine within 60 s. It was not reproduced alone, in 16 parallel copies or in 120 overloaded runs, and is likely related to the process-wide rayon pool / HNSW build path (#302). A request that hangs forever is a production bug: find the cause, fix it, and make index creation bounded (deadline + cancellation) like queries. The scenario is quarantined to the nightly tier with that issue number until fixed.

Issue #302, "hnsw recall@10 test flakes on CI (0.58-0.65 vs ~0.98) - parallel_insert makes the graph nondeterministic": hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors (3000 rows of dimension 32, m=16, ef_construction=200, ef_search=64, cosine) sometimes fails on CI with recall far below its 0.95 bar (0.654 and 0.577 seen; usual recall about 0.98), and each run's recall varies even though the data seeds are fixed. Options named there: build the test index deterministically and keep the 0.95 bar, or find out why some parallel builds come out degenerate, since a 0.58 recall at ef_search=64 may point to a real build-quality problem rather than test noise.

What Changed

  • Vendors hnsw_rs 0.3.4 under vendor/hnsw_rs and loads it through [patch.crates-io], with three patches listed in PATCHES.md. Patch 1 fixes the parallel-insert deadlock behind the .index create hang (Rare hang: .index create (HNSW, cosine) never replies under load #377): reverse_update_neighborhood_simple held a read lock on one point's list while waiting for a write lock on another's. Patch 2 stores reverse links on the correct layer, which fixes the degenerate graphs behind the recall flake (test: hnsw recall@10 test flakes on CI (0.58-0.65 vs ~0.98) — parallel_insert makes the graph nondeterministic #302). Patch 3 sends a progress line to the log instead of stdout. The Dockerfile and the CI path filter now include vendor/.
  • .index create and .index rebuild now build the index without holding the knowledge-graph lock, in a dedicated index-build rayon pool sized to half the global pool, so queries and writes continue during the build. HnswIndex::build_unless inserts the first vector alone, then the rest in parallel, and checks a stop callback before each insert. The build stops at the request's deadline or on cancel. A stopped build registers nothing; otherwise the request takes the write lock, applies the writes made during the build, and only then enters its commit to install the index. The statement gate no longer puts these two commands into the commit up front, and the indexing guide documents the new behaviour.
  • Adds tests for the build-stop, catch-up and install paths (vector_index_tests.rs, hnsw_index_tests.rs) and for cancelling a WebSocket request during an index build (ws_cancel_tests.rs). Lifts the Rare hang: .index create (HNSW, cosine) never replies under load #377 quarantine from harness::shop_pack_vector_serves_the_near_rule and updates TESTING.md to match.

Risk Assessment

⚠️ Medium: The change forks a dependency with concurrency patches, which are minimal and verified against the registry copy, and restructures index create/rebuild into an unlocked build followed by a catch-up and a commit-time install. The tracing found no correctness defects, but the concurrency surface is broad and the #377 scenario stays quarantined.

Testing

I stood up the real server on its own port with a throwaway data directory and drove it over WebSocket. The scenario that failed in round 1 now passes. During a 19 s build of a 15k-row index, another connection ran 58 reads with a 1 s deadline: the slowest took 69 ms (7 ms with no build running) and none hit the deadline. In round 1 the same read timed out, and a read with no short deadline took 8.8 s. The build takes about twice as long now, because the build pool has half the threads. The other live checks also passed: the issue's exact .index create replied 50 of 50 times in a row and 8 of 8 when sent at once on separate connections; a 150 ms deadline and a cancel each stopped a build and left nothing registered; a rebuild stopped by its deadline kept the old index; a write and read during a build were answered at once and the written row ended up in the index. One driver check failed: hnsw_nearest for row 42 on a dataset where every vector appears six times. I compared this with a base-commit server built in a throwaway directory. The base misses 10 to 64 of 200 such queries; the change misses 25 to 48. On distinct random data the change finds every query's own row as top-1 (300 of 300). So this is a pre-existing weakness of HNSW on exact duplicates, not a regression. Targeted tests also pass: the hnsw, vector_index and residency unit tests (including the never-hang stress test), the #302 recall test 20 of 20 times, the ws deadline/cancel/during-build tests, and the un-quarantined shop_pack_vector scenario on the plain PR tier (a test-harness run, not a live one). I stopped the servers and removed the temp directories; the worktree is clean.

  • Live validation: ✅ go - 8 of 9 scenarios driven live against the product
Scenario Result Live Evidence
Another connection's read is answered promptly while an index builds ✅ pass live live-starvation-r2-transcript.txt: 58 reads during a 19 s build, max 69 ms, 0 deadline_exceeded
The issue's exact .index create emb_idx ... metric cosine always replies (50 in a row, 8 at once on separate connections) ✅ pass live live-ws-r2-transcript.txt S1/S1b
.index create with a short timeout_ms returns deadline_exceeded promptly and registers nothing ✅ pass live live-ws-r2-transcript.txt S2 (152 ms)
Cancelling an in-flight .index create stops it and registers nothing ✅ pass live live-ws-r2-transcript.txt S3 (cancelled 1 ms after the cancel; cancel_ack outcome=cancelled); ws_cancel_tests cancel_stops_an_index_build
A rebuild stopped by its deadline keeps the old index serving ✅ pass live live-ws-r2-transcript.txt S5 (deadline_exceeded; stats still shows 6000 vectors)
A write on another connection during a build is answered at once and ends up in the new index ✅ pass live live-ws-r2-transcript.txt S4 (write+read in 9 ms, index has 6001 vectors, late row found at distance 0)
HNSW recall stays high and stable (#302) ✅ pass live live-recall-probe-transcript.txt (300/300 self top-1); recall-302-r2.txt (20/20 passes)
No recall regression vs base on duplicate-heavy data ✅ pass live live-dup-probe-base-transcript.txt (10-64/200 misses) vs live-dup-probe-change-transcript.txt (25-48/200)
The un-quarantined #377 scenario runs and passes on the plain PR tier ⏸️ untested no The prior payload only established this through the cargo integration test harness (harness::shop_pack_vector_serves_the_near_rule, integration-tests-r2.txt), which is not a live-product run; it did n…
Evidence: Reads during an index build stay fast (round-1 failure, now passing)
22:12:24.816 result schema starve1791238344794
22:12:27.528 loaded 15000 rows of dim 16 into starve1791238344794
22:12:27.541 no build running: read result in 7 ms | read under timeout_ms=1000 result in 6 ms
22:12:28.056 t+515 ms, build running: write result in 14 ms
22:12:28.056 PASS write on another connection succeeds during build
22:12:28.068 t+515 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:28.378 t+828 ms, build running: read under timeout_ms=1000 -> result in 9 ms
22:12:28.702 t+1141 ms, build running: read under timeout_ms=1000 -> result in 20 ms
22:12:29.016 t+1463 ms, build running: read under timeout_ms=1000 -> result in 10 ms
22:12:29.348 t+1782 ms, build running: read under timeout_ms=1000 -> result in 25 ms
22:12:29.657 t+2108 ms, build running: read under timeout_ms=1000 -> result in 8 ms
22:12:29.970 t+2417 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:30.299 t+2736 ms, build running: read under timeout_ms=1000 -> result in 22 ms
22:12:30.620 t+3058 ms, build running: read under timeout_ms=1000 -> result in 21 ms
22:12:30.931 t+3379 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:31.279 t+3699 ms, build running: read under timeout_ms=1000 -> result in 39 ms
22:12:31.594 t+4038 ms, build running: read under timeout_ms=1000 -> result in 15 ms
22:12:31.926 t+4357 ms, build running: read under timeout_ms=1000 -> result in 28 ms
22:12:32.244 t+4685 ms, build running: read under timeout_ms=1000 -> result in 18 ms
22:12:32.565 t+5010 ms, build running: read under timeout_ms=1000 -> result in 14 ms
22:12:32.903 t+5325 ms, build running: read under timeout_ms=1000 -> result in 37 ms
22:12:33.216 t+5663 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:33.535 t+5975 ms, build running: read under timeout_ms=1000 -> result in 19 ms
22:12:33.856 t+6297 ms, build running: read under timeout_ms=1000 -> result in 17 ms
22:12:34.170 t+6618 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:34.527 t+6930 ms, build running: read under timeout_ms=1000 -> result in 56 ms
22:12:34.851 t+7286 ms, build running: read under timeout_ms=1000 -> result in 24 ms
22:12:35.164 t+7610 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:35.538 t+7928 ms, build running: read under timeout_ms=1000 -> result in 69 ms
22:12:35.846 t+8299 ms, build running: read under timeout_ms=1000 -> result in 6 ms
22:12:36.177 t+8607 ms, build running: read under timeout_ms=1000 -> result in 29 ms
22:12:36.491 t+8939 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:36.824 t+9251 ms, build running: read under timeout_ms=1000 -> result in 32 ms
22:12:37.154 t+9589 ms, build running: read under timeout_ms=1000 -> result in 24 ms
22:12:37.477 t+9915 ms, build running: read under timeout_ms=1000 -> result in 21 ms
22:12:37.788 t+10239 ms, build running: read under timeout_ms=1000 -> result in 8 ms
22:12:38.127 t+10553 ms, build running: read under timeout_ms=1000 -> result in 33 ms
22:12:38.442 t+10886 ms, build running: read under timeout_ms=1000 -> result in 15 ms
22:12:38.753 t+11201 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:39.094 t+11517 ms, build running: read under timeout_ms=1000 -> result in 36 ms
22:12:39.432 t+11859 ms, build running: read under timeout_ms=1000 -> result in 32 ms
22:12:39.746 t+12192 ms, build running: read under timeout_ms=1000 -> result in 13 ms
22:12:40.093 t+12509 ms, build running: read under timeout_ms=1000 -> result in 43 ms
22:12:40.408 t+12852 ms, build running: read under timeout_ms=1000 -> result in 15 ms
22:12:40.729 t+13169 ms, build running: read under timeout_ms=1000 -> result in 19 ms
22:12:41.042 t+13489 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:41.357 t+13801 ms, build running: read under timeout_ms=1000 -> result in 15 ms
22:12:41.669 t+14116 ms, build running: read under timeout_ms=1000 -> result in 12 ms
22:12:41.990 t+14431 ms, build running: read under timeout_ms=1000 -> result in 18 ms
22:12:42.301 t+14749 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:42.627 t+15063 ms, build running: read under timeout_ms=1000 -> result in 23 ms
22:12:42.948 t+15386 ms, build running: read under timeout_ms=1000 -> result in 21 ms
22:12:43.268 t+15707 ms, build running: read under timeout_ms=1000 -> result in 20 ms
22:12:43.578 t+16027 ms, build running: read under timeout_ms=1000 -> result in 10 ms
22:12:43.894 t+16337 ms, build running: read under timeout_ms=1000 -> result in 16 ms
22:12:44.204 t+16653 ms, build running: read under timeout_ms=1000 -> result in 10 ms
22:12:44.545 t+16975 ms, build running: read under timeout_ms=1000 -> result in 29 ms
22:12:44.883 t+17304 ms, build running: read under timeout_ms=1000 -> result in 38 ms
22:12:45.215 t+17649 ms, build running: read under timeout_ms=1000 -> result in 25 ms
22:12:45.525 t+17976 ms, build running: read under timeout_ms=1000 -> result in 8 ms
22:12:45.845 t+18284 ms, build running: read under timeout_ms=1000 -> result in 20 ms
22:12:46.159 t+18604 ms, build running: read under timeout_ms=1000 -> result in 14 ms
22:12:46.470 t+18918 ms, build running: read under timeout_ms=1000 -> result in 11 ms
22:12:46.662 BUILD DONE result [["Index 'starve1791238344794_idx' created on starve1791238344794.v (15001 vectors)."]] after 19121 ms
22:12:46.770 PASS build replies with result
22:12:46.770 PASS at least 3 reads completed while the build ran (got 58)
22:12:46.770 PASS no read during the build hit deadline_exceeded (bad=0)
22:12:46.770 PASS max read latency during build < 1000 ms (max=69 ms, baseline 7 ms)
22:12:46.776 stats [["Index 'starve1791238344794_idx': relation=starve1791238344794, column=v, type=hnsw, metric=cosine, vectors=15001, tombstones=0, dimension=16"]]
22:12:46.776 ALL PASS
Evidence: Live WS driver: create replies, deadline, cancel, rebuild, writes during build
22:13:01.505 result schema embedding
22:13:01.525 loaded 100 rows of dim 8 into embedding
22:13:02.153 PASS S1 .index create emb_idx ... metric cosine replied 50/50 times (got 50) in 628 ms
22:13:05.399 PASS S1b 8 concurrent .index create on 8 connections all replied: result,result,result,result,result,result,result,result
22:13:05.410 result schema big
22:13:05.896 loaded 6000 rows of dim 16 into big
22:13:06.048 deadline reply: error code=deadline_exceeded Request deadline exceeded before it began committing; nothing was applied after 152 ms
22:13:06.048 PASS S2 create with timeout_ms=150 -> deadline_exceeded in 152 ms
22:13:06.050 .index list -> result [["Index 'par_0' on embedding.v (type: hnsw, metric: cosine, vectors: 100)"],["Index 'par_1' on embedding.v (type: hnsw, metric: cosine, vectors: 100)"],["Index
22:13:06.050 PASS S2 no big_idx registered after deadline
22:13:06.867 full create reply: result [["Index 'big_idx' created on big.v (6000 vectors)."]] after 817 ms
22:13:06.867 PASS S2 same create without a short deadline builds all 6000 vectors
22:13:06.968 rebuild reply: error code=deadline_exceeded Request deadline exceeded before it began committing; nothing was applied
22:13:06.969 PASS S5 rebuild with timeout_ms=100 -> deadline_exceeded
22:13:06.970 stats: result [["Index 'big_idx': relation=big, column=v, type=hnsw, metric=cosine, vectors=6000, tombstones=0, dimension=16"]]
22:13:06.970 PASS S5 old big_idx still serves after stopped rebuild
22:13:06.974 nearest: [[2732,0.08319713968875364]]
22:13:06.974 FAIL S5 hnsw_nearest on old index finds row 42
22:13:07.286 cancel reply: error code=cancelled Request cancelled before it began committing; nothing was applied after 1 ms; ack: {"type":"cancel_ack","id":"cc","target":"cx","outcome":"cancelled"}
22:13:07.286 PASS S3 cancel stops the build promptly
22:13:07.288 PASS S3 nothing registered after cancel: result [["Index 'par_0' on embedding.v (type: hnsw, metric: cosine, vectors: 100)"],["Index 'par_1' on embedding.v (type: hnsw, metric: cosine, vectors: 100)"],["Index
22:13:07.597 other connection write result, read result rows=1 answered in 9 ms
22:13:08.107 build reply: result [["Index 'big_idx' created on big.v (6001 vectors)."]] finished 510 ms after the read was answered
22:13:08.107 PASS S4 write+read on another connection answered before the build finished
22:13:08.107 PASS S4 index includes the row written during the build (6001 vectors)
22:13:08.112 nearest late row: [[5001,0]]
22:13:08.112 PASS S4 hnsw_nearest finds a distance-0 match for the late row (its vector duplicates row 1001)
22:13:08.112 1 FAILURES
Evidence: Recall on distinct random vectors (live)
22:13:26.638 A duplicate-heavy big_idx (6001 rows, 1000 distinct vectors x6): top-1 not at distance 0 for 81/200 self-queries
22:13:28.128 build [["Index 'rec1791238406638_idx' created on rec1791238406638.v (3000 vectors)."]]
22:13:29.394 B distinct random 3000x32: self not top-1 for 0/300 queries
Evidence: Duplicate-heavy recall, base commit
22:15:57.069 result schema dup1791238557061
22:15:57.559 loaded 6000 rows of dim 16 into dup1791238557061
22:15:58.344 BASE fresh create [["Index 'dup1791238557061_idx' created on dup1791238557061.v (6000 vectors)."]]
22:15:59.017 BASE fresh index on duplicate-heavy data: top-1 not at distance 0 for 37/200
22:15:59.026 result schema dup1791238559017
22:15:59.540 loaded 6000 rows of dim 16 into dup1791238559017
22:16:00.355 BASE fresh create [["Index 'dup1791238559017_idx' created on dup1791238559017.v (6000 vectors)."]]
22:16:01.072 BASE fresh index on duplicate-heavy data: top-1 not at distance 0 for 10/200
22:16:01.082 result schema dup1791238561072
22:16:01.579 loaded 6000 rows of dim 16 into dup1791238561072
22:16:02.419 BASE fresh create [["Index 'dup1791238561072_idx' created on dup1791238561072.v (6000 vectors)."]]
22:16:03.081 BASE fresh index on duplicate-heavy data: top-1 not at distance 0 for 64/200
Evidence: Duplicate-heavy recall, this change
22:16:11.529 CHANGE fresh index on duplicate-heavy data: top-1 not at distance 0 for 35/200
22:16:13.615 CHANGE fresh index on duplicate-heavy data: top-1 not at distance 0 for 25/200
22:16:15.672 CHANGE fresh index on duplicate-heavy data: top-1 not at distance 0 for 40/200
Evidence: ws index tests + un-quarantined scenario
test cancel_stops_an_index_build ... ok
test writes_and_reads_are_served_while_an_index_builds ... ok
test an_index_build_stops_at_its_deadline_and_creates_nothing ... ok
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 8 filtered out; finished in 6.60s
test harness::shop_pack_vector_serves_the_near_rule ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 26 filtered out; finished in 0.62s
Evidence: #302 recall test looped 20x
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.55s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.52s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.48s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.79s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.74s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.71s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.68s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.70s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.78s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.76s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.88s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.98s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.76s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.85s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.86s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.92s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.81s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.85s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.90s
test hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 3214 filtered out; finished in 1.79s
Evidence: Server log for round-2 live runs
InputLayer Server
=================

WARNING: ws_max_messages_per_sec = 0 (unlimited). No WebSocket message rate limit is enforced. Set a finite value for production.
�[2m2026-10-05T22:11:23.019341Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m data_dir_lock_acquired �[3mdata_dir�[0m�[2m=�[0m/tmp/il-live2-pSCF/data �[3melapsed_us�[0m�[2m=�[0m146
�[2m2026-10-05T22:11:23.035403Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m persist_open_complete �[3mshards�[0m�[2m=�[0m0 �[3melapsed_ms�[0m�[2m=�[0m15
�[2m2026-10-05T22:11:23.035744Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_register_complete �[3mknowledge_graphs�[0m�[2m=�[0m0 �[3mshards�[0m�[2m=�[0m0 �[3melapsed_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:11:23.038745Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m save_metadata_complete �[3melapsed_ms�[0m�[2m=�[0m2
�[2m2026-10-05T22:11:23.038798Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_create_complete �[3mkg�[0m�[2m=�[0mdefault �[3melapsed_ms�[0m�[2m=�[0m2
�[2m2026-10-05T22:11:23.040033Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_memory_limits �[3mquery_memory_bytes�[0m�[2m=�[0m4294967296 �[3mtotal_query_memory_bytes�[0m�[2m=�[0m76020921138 �[3mcompute_permits�[0m�[2m=�[0m24
�[2m2026-10-05T22:11:23.042754Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m save_metadata_complete �[3melapsed_ms�[0m�[2m=�[0m2
�[2m2026-10-05T22:11:23.042838Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_create_complete �[3mkg�[0m�[2m=�[0m_internal �[3melapsed_ms�[0m�[2m=�[0m2
�[2m2026-10-05T22:11:23.448734Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m Auth bootstrap: reusing credentials from /tmp/il-live2-pSCF/data/credentials.toml
�[2m2026-10-05T22:11:23.454895Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine::program_commit�[0m�[2m:�[0m program_commit_persisted �[3mkg�[0m�[2m=�[0m_internal �[3mrelations�[0m�[2m=�[0m1 �[3mstatements�[0m�[2m=�[0m1 �[3mtime�[0m�[2m=�[0m1 �[3mpersist_ms�[0m�[2m=�[0m5
�[2m2026-10-05T22:11:23.455056Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m snapshot_publish_complete �[3mrelations�[0m�[2m=�[0m1 �[3mrules�[0m�[2m=�[0m0 �[3msnapshot_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:11:23.455085Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m Auth bootstrap: admin user created
�[2m2026-10-05T22:11:23.462497Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine::program_commit�[0m�[2m:�[0m program_commit_persisted �[3mkg�[0m�[2m=�[0m_internal �[3mrelations�[0m�[2m=�[0m3 �[3mstatements�[0m�[2m=�[0m1 �[3mtime�[0m�[2m=�[0m2 �[3mpersist_ms�[0m�[2m=�[0m7
�[2m2026-10-05T22:11:23.462636Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m snapshot_publish_complete �[3mrelations�[0m�[2m=�[0m4 �[3mrules�[0m�[2m=�[0m0 �[3msnapshot_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:11:23.462660Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m Auth bootstrap: API key 'bootstrap' created for admin
�[2m2026-10-05T22:11:23.464054Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m Auth bootstrap: credentials saved to /tmp/il-live2-pSCF/data/credentials.toml

=== INITIAL ADMIN CREDENTIALS CREATED ===
Admin API key: ****13a9
==========================================

Generated credentials saved to: /tmp/il-live2-pSCF/data/credentials.toml
Retrieve them with:  cat /tmp/il-live2-pSCF/data/credentials.toml
Delete this file to generate new credentials on next boot.

Storage engine initialized

HTTP Server
-----------
Address: 127.0.0.1:18977

HTTP server listening on: http://127.0.0.1:18977
WebSocket API docs at: http://127.0.0.1:18977/api/ws-docs
�[2m2026-10-05T22:11:54.599948Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_connection_start �[3mkg�[0m�[2m=�[0mlive
�[2m2026-10-05T22:11:55.402385Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m audit_auth_login_success �[3musername�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2 �[3mpeer�[0m�[2m=�[0m127.0.0.1
�[2m2026-10-05T22:11:55.402515Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_authenticated �[3mkg�[0m�[2m=�[0mlive �[3musername�[0m�[2m=�[0madmin �[3mrole�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2
�[2m2026-10-05T22:11:55.402555Z�[0m �[33m WARN�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_session_create_failed �[3mkg�[0m�[2m=�[0mlive �[3merror�[0m�[2m=�[0mKnowledge graph 'live' not found: Knowledge graph not found: live
�[2m2026-10-05T22:11:58.281194Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_connection_start �[3mkg�[0m�[2m=�[0mlive
�[2m2026-10-05T22:11:58.690016Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m audit_auth_login_success �[3musername�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2 �[3mpeer�[0m�[2m=�[0m127.0.0.1
�[2m2026-10-05T22:11:58.690139Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_authenticated �[3mkg�[0m�[2m=�[0mlive �[3musername�[0m�[2m=�[0madmin �[3mrole�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2
�[2m2026-10-05T22:11:58.690176Z�[0m �[33m WARN�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_session_create_failed �[3mkg�[0m�[2m=�[0mlive �[3merror�[0m�[2m=�[0mKnowledge graph 'live' not found: Knowledge graph not found: live
�[2m2026-10-05T22:12:18.535748Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_connection_start �[3mkg�[0m�[2m=�[0mdefault
�[2m2026-10-05T22:12:19.407932Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m audit_auth_login_success �[3musername�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2 �[3mpeer�[0m�[2m=�[0m127.0.0.1
�[2m2026-10-05T22:12:19.408062Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_authenticated �[3mkg�[0m�[2m=�[0mdefault �[3musername�[0m�[2m=�[0madmin �[3mrole�[0m�[2m=�[0madmin �[3mcredential�[0m�[2m=�[0mpassword:admin#2
�[2m2026-10-05T22:12:19.408115Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_ensure_exists �[3mkg�[0m�[2m=�[0mdefault �[3melapsed_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:12:19.408195Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_session_created �[3mkg�[0m�[2m=�[0mdefault �[3mactive_sessions�[0m�[2m=�[0m1
�[2m2026-10-05T22:12:19.410340Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::rest::handlers::ws::execute�[0m�[2m:�[0m ws_execute_start �[3mprogram_len�[0m�[2m=�[0m15 �[3mparam_count�[0m�[2m=�[0m0 �[3mprogram_preview�[0m�[2m=�[0m.kg create live �[2m�[3mrequest_id�[0m�[2m=�[0m1 �[3mmsg_bytes�[0m�[2m=�[0m55�[0m
�[2m2026-10-05T22:12:19.410636Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_job_start �[3mprogram_len�[0m�[2m=�[0m15
�[2m2026-10-05T22:12:19.410664Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_ensure_exists �[3mkg�[0m�[2m=�[0mdefault �[3melapsed_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:12:19.410688Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_parse_complete �[3mprogram_len�[0m�[2m=�[0m15 �[3mstatements�[0m�[2m=�[0m1 �[3mparse_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:12:19.410720Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m meta_kg_create_start �[3mkg�[0m�[2m=�[0mlive
�[2m2026-10-05T22:12:19.422864Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m save_metadata_complete �[3melapsed_ms�[0m�[2m=�[0m11
�[2m2026-10-05T22:12:19.422912Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_create_complete �[3mkg�[0m�[2m=�[0mlive �[3melapsed_ms�[0m�[2m=�[0m12
�[2m2026-10-05T22:12:19.422936Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m meta_kg_create_ok �[3mkg�[0m�[2m=�[0mlive
�[2m2026-10-05T22:12:19.423020Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_statement_exec_complete �[3mprogram_len�[0m�[2m=�[0m15 �[3mstmt_exec_ms�[0m�[2m=�[0m12 �[3msession_facts�[0m�[2m=�[0m0 �[3msession_rules�[0m�[2m=�[0m0
�[2m2026-10-

... [6610095 bytes truncated] ...

[0m kg_ensure_exists �[3mkg�[0m�[2m=�[0mlive �[3melapsed_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.666784Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_parse_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mstatements�[0m�[2m=�[0m1 �[3mparse_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.666876Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_execute_start �[3mrules�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.666968Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_parse_complete �[3msource_len�[0m�[2m=�[0m1 �[3mparse_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.667003Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_specialize_complete �[3msource_len�[0m�[2m=�[0m1 �[3mspec_us�[0m�[2m=�[0m23
�[2m2026-10-05T22:16:15.667042Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_sip_complete �[3msource_len�[0m�[2m=�[0m1 �[3msip_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.667070Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_magic_sets_complete �[3msource_len�[0m�[2m=�[0m1 �[3mmagic_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.667105Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_build_ir_complete �[3msource_len�[0m�[2m=�[0m1 �[3mbuild_ms�[0m�[2m=�[0m0 �[3mir_nodes�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.667168Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_optimize_complete �[3msource_len�[0m�[2m=�[0m1 �[3mopt_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.667209Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_shared_views_complete �[3msource_len�[0m�[2m=�[0m1 �[3mshared_ms�[0m�[2m=�[0m0 �[3mshared_views�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.668769Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_rule_complete �[3msource_len�[0m�[2m=�[0m1 �[3mrule_idx�[0m�[2m=�[0m0 �[3mrule_head�[0m�[2m=�[0m__query__ �[3mrule_ms�[0m�[2m=�[0m0 �[3mrecursive�[0m�[2m=�[0mfalse �[3mworkers�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.668796Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_execute_complete �[3msource_len�[0m�[2m=�[0m1 �[3mtotal_ms�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.668810Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine::snapshot�[0m�[2m:�[0m snapshot_execute �[3mrules�[0m�[2m=�[0m1 �[3msession_facts�[0m�[2m=�[0m0 �[3melapsed_ms�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.668856Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_engine_exec_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mkg�[0m�[2m=�[0mlive �[3mquery_exec_ms�[0m�[2m=�[0m2 �[3mhas_session_facts�[0m�[2m=�[0mfalse
�[2m2026-10-05T22:16:15.668889Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_job_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mtotal_ms�[0m�[2m=�[0m2 �[3mrow_count�[0m�[2m=�[0m1 �[3mtotal_count�[0m�[2m=�[0m1 �[3mtruncated�[0m�[2m=�[0mfalse
�[2m2026-10-05T22:16:15.669013Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mcompute_ms�[0m�[2m=�[0m2 �[3mok�[0m�[2m=�[0mtrue �[2m�[3mrequest_id�[0m�[2m=�[0m614 �[3mmsg_bytes�[0m�[2m=�[0m226�[0m
�[2m2026-10-05T22:16:15.669049Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::rest::handlers::ws::execute�[0m�[2m:�[0m ws_execute_end �[3mprogram_len�[0m�[2m=�[0m161 �[3melapsed_ms�[0m�[2m=�[0m2 �[3mok�[0m�[2m=�[0mtrue �[2m�[3mrequest_id�[0m�[2m=�[0m614 �[3mmsg_bytes�[0m�[2m=�[0m226�[0m
�[2m2026-10-05T22:16:15.669508Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::rest::handlers::ws::execute�[0m�[2m:�[0m ws_execute_start �[3mprogram_len�[0m�[2m=�[0m161 �[3mparam_count�[0m�[2m=�[0m0 �[3mprogram_preview�[0m�[2m=�[0m?hnsw_nearest("dup1791238573615_idx", [0.882, 0.611, 0.340, 0.069, 0.798, 0.527, �[2m�[3mrequest_id�[0m�[2m=�[0m615 �[3mmsg_bytes�[0m�[2m=�[0m226�[0m
�[2m2026-10-05T22:16:15.669701Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_job_start �[3mprogram_len�[0m�[2m=�[0m161
�[2m2026-10-05T22:16:15.669727Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine�[0m�[2m:�[0m kg_ensure_exists �[3mkg�[0m�[2m=�[0mlive �[3melapsed_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.669747Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_parse_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mstatements�[0m�[2m=�[0m1 �[3mparse_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.669806Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_execute_start �[3mrules�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.669923Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_parse_complete �[3msource_len�[0m�[2m=�[0m1 �[3mparse_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.669966Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_specialize_complete �[3msource_len�[0m�[2m=�[0m1 �[3mspec_us�[0m�[2m=�[0m25
�[2m2026-10-05T22:16:15.670006Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_sip_complete �[3msource_len�[0m�[2m=�[0m1 �[3msip_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.670028Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_magic_sets_complete �[3msource_len�[0m�[2m=�[0m1 �[3mmagic_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.670068Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_build_ir_complete �[3msource_len�[0m�[2m=�[0m1 �[3mbuild_ms�[0m�[2m=�[0m0 �[3mir_nodes�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.670130Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_optimize_complete �[3msource_len�[0m�[2m=�[0m1 �[3mopt_ms�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.670171Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_shared_views_complete �[3msource_len�[0m�[2m=�[0m1 �[3mshared_ms�[0m�[2m=�[0m0 �[3mshared_views�[0m�[2m=�[0m0
�[2m2026-10-05T22:16:15.671719Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_rule_complete �[3msource_len�[0m�[2m=�[0m1 �[3mrule_idx�[0m�[2m=�[0m0 �[3mrule_head�[0m�[2m=�[0m__query__ �[3mrule_ms�[0m�[2m=�[0m0 �[3mrecursive�[0m�[2m=�[0mfalse �[3mworkers�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.671746Z�[0m �[32m INFO�[0m �[2minputlayer�[0m�[2m:�[0m engine_execute_complete �[3msource_len�[0m�[2m=�[0m1 �[3mtotal_ms�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.671761Z�[0m �[32m INFO�[0m �[2minputlayer::storage_engine::snapshot�[0m�[2m:�[0m snapshot_execute �[3mrules�[0m�[2m=�[0m1 �[3msession_facts�[0m�[2m=�[0m0 �[3melapsed_ms�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:15.671774Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_engine_exec_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mkg�[0m�[2m=�[0mlive �[3mquery_exec_ms�[0m�[2m=�[0m1 �[3mhas_session_facts�[0m�[2m=�[0mfalse
�[2m2026-10-05T22:16:15.671794Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_job_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mtotal_ms�[0m�[2m=�[0m2 �[3mrow_count�[0m�[2m=�[0m1 �[3mtotal_count�[0m�[2m=�[0m1 �[3mtruncated�[0m�[2m=�[0mfalse
�[2m2026-10-05T22:16:15.671949Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::handler�[0m�[2m:�[0m query_complete �[3mprogram_len�[0m�[2m=�[0m161 �[3mcompute_ms�[0m�[2m=�[0m2 �[3mok�[0m�[2m=�[0mtrue �[2m�[3mrequest_id�[0m�[2m=�[0m615 �[3mmsg_bytes�[0m�[2m=�[0m226�[0m
�[2m2026-10-05T22:16:15.671990Z�[0m �[32m INFO�[0m �[1mws_request�[0m: �[2minputlayer::protocol::rest::handlers::ws::execute�[0m�[2m:�[0m ws_execute_end �[3mprogram_len�[0m�[2m=�[0m161 �[3melapsed_ms�[0m�[2m=�[0m2 �[3mok�[0m�[2m=�[0mtrue �[2m�[3mrequest_id�[0m�[2m=�[0m615 �[3mmsg_bytes�[0m�[2m=�[0m226�[0m
�[2m2026-10-05T22:16:15.678287Z�[0m �[33m WARN�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_protocol_error �[3merror�[0m�[2m=�[0mWebSocket protocol error: Connection reset without closing handshake
�[2m2026-10-05T22:16:15.678365Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest::handlers::ws�[0m�[2m:�[0m ws_session_disconnecting �[3mactive_sessions�[0m�[2m=�[0m1
�[2m2026-10-05T22:16:34.508938Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest�[0m�[2m:�[0m Received SIGTERM, shutting down...
�[2m2026-10-05T22:16:34.509382Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest�[0m�[2m:�[0m session_reaper_shutdown
�[2m2026-10-05T22:16:34.509383Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::rest�[0m�[2m:�[0m auto_compact_shutdown
�[2m2026-10-05T22:16:34.509478Z�[0m �[32m INFO�[0m �[2minputlayer::protocol::handler�[0m�[2m:�[0m Flushing WAL and saving metadata...
- Outcome: 🔧 3 issues found → auto-fixed ✅ across 2 runs (38m21s)

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

⚠️ **Review** - 2 infos
  • ⚠️ tests/scenarios/harness.rs:68 - The intent says the scenario 'is quarantined to the nightly tier with that issue number until fixed'. This change claims the durable fix for Rare hang: .index create (HNSW, cosine) never replies under load #377: vendor patch 1 removes the lock-order inversion in reverse_update_neighborhood_simple, and builds now run under the request's deadline and cancel. But harness::shop_pack_vector_serves_the_near_rule is still #[ignore = &#34;quarantined: rare engine hang in .index create (#377); nightly tier runs it&#34;], so the PR gate still does not run the regression scenario from the issue. Should the quarantine be lifted in this change (moving the test back to the PR tier) or left for a follow-up? That CI-tier decision is yours.
  • ℹ️ src/storage_engine/vector_index.rs:503 - catch_up runs inside with_kg_mut (install_created_index:611, install_rebuilt_index:674). It hashes every row of both the before and after relations, then applies the upserts written during the build one at a time with HnswIndex::apply. All of this holds the KG write lock and never checks the stop signal. If a bulk load lands while a large build runs, that catch-up work blocks the graph and is not bounded by the deadline. It is still far less than the old behaviour of building the whole index under the lock, so this is only a tradeoff to note.

🔧 Fix applied.
2 infos still open:

  • ℹ️ src/storage_engine/vector_index.rs:503 - catch_up runs inside with_kg_mut (install_created_index:611, install_rebuilt_index:674). It hashes every row of both the before and after relations, then applies the upserts written during the build one at a time with HnswIndex::apply. All of this holds the KG write lock and never checks the stop signal. If a bulk load lands while a large build runs, that catch-up work blocks the graph and is not bounded by the deadline. It is still far less than the old behaviour of building the whole index under the lock, so this is only a tradeoff to note.
  • ℹ️ src/storage_engine/vector_index.rs:95 - build_for_request checks for a stop with RequestControl::expire_if_due. Once the request has entered its commit (state COMMITTING), stop() returns Halt::TooLate, so neither the deadline nor a cancel stops the build. Concrete case: a program whose second statement is also an index build, such as .index create a ... then .index create b ..., or .index drop x then .index rebuild y. The first statement calls begin_commit in install_created_index (line 308) or as a durable meta command (supervise.rs:129). The second build then runs to completion whatever the deadline. This follows the existing rule that a committing request is not interrupted, and queries after a commit behave the same way. With vendor patch 1 the build is also finite, so this is a tradeoff to note, not a hang.
🔧 **Test** - 3 issues found → auto-fixed ✅
  • 🚨 src/storage_engine/residency_tests.rs:295 - The change added a third control parameter to StorageEngine::create_index_in, but residency_tests.rs:295 still called it with two arguments. cargo test --lib failed with E0061, so no lib unit test could run (CI would fail). Fixed in the worktree by passing None; the residency, vector_index and hnsw_index tests now compile and pass.
  • ⚠️ src/hnsw_index.rs:145 - A build no longer blocks writes, but it still blocks reads. HnswIndex::build_unless runs into_par_iter on the global rayon pool, which query evaluation also uses, so a read on another connection waits for the whole build. Measured live on the real server: 70 ms became 8.8 s during a 10 s build, and a read with a 1 s deadline failed with deadline_exceeded. The docs added in this change say queries go on while the build runs (docs/content/docs/guides/indexing.mdx), and the ws test writes_and_reads_are_served_while_an_index_builds passes only because it checks ordering. This is not a regression: at the base commit the build held the KG write lock, which was worse. But a build longer than query_timeout_ms will time out every read that runs alongside it. Options: run builds in a dedicated rayon pool with fewer threads, or correct the docs and tighten the test. Which do you want?
  • 🚨 live validation verdict: no-go (7 of 9 scenarios were driven live against the product); failed: Another connection's read is answered promptly while an index builds (the change's docs say queries go on while it runs)
  • Live validation: ❌ no-go - 7 of 9 scenarios driven live against the product
Scenario Result Live Evidence
The issue's .index create emb_idx on embedding(v) metric cosine always replies (50 create/drop rounds, plus 8 creates at once on 8 connections) ✅ pass live live-ws-transcript.txt (S1, S1b)
Un-quarantined scenario harness::shop_pack_vector_serves_the_near_rule passes repeatedly under load on 4 pinned cores ✅ pass live scenario-vector.txt, scenario-loop-summary.txt (240/240)
Adversarial #377: many parallel HNSW builds on an oversubscribed 4-core pool never deadlock (fails on stock hnsw_rs, passes when patched) ⏸️ untested no The prior payload did not establish a live result: this was a library-level stress test, not a run against the server. It reported 43,326 patched builds in 60 s with none hung, and stock hnsw_rs hung…
A create with timeout_ms=150 on 6000 rows fails with deadline_exceeded within the deadline and registers nothing; the same create without the short deadline builds all 6000 vectors ✅ pass live live-ws-transcript.txt (S2)
A cancel sent during a build stops it promptly with cancelled, and no index is registered ✅ pass live live-ws-transcript.txt (S3)
A rebuild with timeout_ms=100 stops with deadline_exceeded and the old index keeps serving hnsw_nearest ✅ pass live live-ws-transcript.txt (S5)
Rows written by another connection during the build, or after it, are in the installed index and found by hnsw_nearest ✅ pass live live-ws-transcript.txt (S4: 6001 vectors), live-late-rows-transcript.txt
Another connection's read is answered promptly while an index builds (the change's docs say queries go on while it runs) ❌ fail live live-starvation-transcript.txt, live-concurrency-transcript.txt
#302: hnsw recall@10 on 3000 random vectors stays at or above 0.95 on every run ⏸️ untested no The prior payload did not establish a live result: this was a unit-level recall test, not a run against the server. It reported 40 runs with min 0.997 and median 0.998 (recall-302-loop.txt, recall-302…
  • taskset -c 0-3 cargo test --test scenarios harness::shop_pack_vector_serves_the_near_rule (now un-ignored)
  • 240 runs of the scenario binary harness::shop_pack_vector_serves_the_near_rule --exact, 4 at a time on 4 pinned cores
  • taskset -c 0-3 cargo test --test ws_cancel_tests index (deadline, cancel, and writes/reads during a build)
  • Live: real target/debug/inputlayer-server with its own config, data dir and port 18977, driven over WebSocket by live-driver.mjs (50 create/drop rounds of the issue's cosine create; 8 creates at once on 8 connections; create and rebuild with timeout_ms; cancel during a build; write and read on another connection during a build)
  • Live: live-concurrency.mjs and live-starvation.mjs timing another connection's writes and reads, with and without a build running (15k rows, 10 s build)
  • Live: live-late-rows.mjs, hnsw_nearest finds rows written during and after the build
  • HNSW_STRESS_SECS=60 taskset -c 0-3 cargo test --release --lib test_hnsw_concurrent_builds_never_hang -- --ignored with the vendor patch
  • The same stress test with [patch.crates-io] commented out (stock hnsw_rs 0.3.4) to reproduce #377, then Cargo.toml and Cargo.lock restored
  • 40 runs of hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors on 4 pinned cores, recall recorded
  • cargo test --lib --no-run, which failed to compile; fixed src/storage_engine/residency_tests.rs:295, then ran storage_engine::residency::tests, vector_index_tests and hnsw_index

🔧 Fix applied.
✅ Re-checked - no issues remain.

  • Live validation: ✅ go - 8 of 9 scenarios driven live against the product
Scenario Result Live Evidence
Another connection's read is answered promptly while an index builds ✅ pass live live-starvation-r2-transcript.txt: 58 reads during a 19 s build, max 69 ms, 0 deadline_exceeded
The issue's exact .index create emb_idx ... metric cosine always replies (50 in a row, 8 at once on separate connections) ✅ pass live live-ws-r2-transcript.txt S1/S1b
.index create with a short timeout_ms returns deadline_exceeded promptly and registers nothing ✅ pass live live-ws-r2-transcript.txt S2 (152 ms)
Cancelling an in-flight .index create stops it and registers nothing ✅ pass live live-ws-r2-transcript.txt S3 (cancelled 1 ms after the cancel; cancel_ack outcome=cancelled); ws_cancel_tests cancel_stops_an_index_build
A rebuild stopped by its deadline keeps the old index serving ✅ pass live live-ws-r2-transcript.txt S5 (deadline_exceeded; stats still shows 6000 vectors)
A write on another connection during a build is answered at once and ends up in the new index ✅ pass live live-ws-r2-transcript.txt S4 (write+read in 9 ms, index has 6001 vectors, late row found at distance 0)
HNSW recall stays high and stable (#302) ✅ pass live live-recall-probe-transcript.txt (300/300 self top-1); recall-302-r2.txt (20/20 passes)
No recall regression vs base on duplicate-heavy data ✅ pass live live-dup-probe-base-transcript.txt (10-64/200 misses) vs live-dup-probe-change-transcript.txt (25-48/200)
The un-quarantined #377 scenario runs and passes on the plain PR tier ⏸️ untested no The prior payload only established this through the cargo integration test harness (harness::shop_pack_vector_serves_the_near_rule, integration-tests-r2.txt), which is not a live-product run; it did n…
  • Live: release-free debug inputlayer-server on 127.0.0.1:18977 with a throwaway data dir, driven over WebSocket by node live-starvation-r2.mjs (15k-row index build while another connection reads under timeout_ms=1000)
  • Live: node live-driver-r2.mjs (S1 50 sequential + 8 concurrent .index create emb_idx ... metric cosine; S2 timeout_ms=150 deadline; S3 cancel; S5 rebuild with timeout_ms=100 keeps the old index; S4 write and read during a build, late row indexed)
  • Live: node live-recall-probe.mjs (3000x32 distinct random vectors, self top-1 via hnsw_nearest)
  • Live: node live-dup-probe.mjs, live-dup-probe-change.mjs vs live-dup-probe-base.mjs against a base-commit (9aa22753) server built in a throwaway dir on port 18978: duplicate-heavy data recall, compared with base
  • cargo test --lib -- hnsw_index vector_index residency (plus --ignored: test_hnsw_concurrent_builds_never_hang)
  • cargo test --lib -- hnsw_index::tests::test_hnsw_recall_at_10_on_3000_random_vectors looped 20x (#302)
  • cargo test --test ws_cancel_tests -- index (deadline, cancel, reads/writes during build)
  • cargo test --test scenarios -- shop_pack_vector (un-quarantined #377 scenario, no --ignored)
✅ **Document** - passed

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

jsam added 3 commits October 5, 2026 21:32
…and build indexes under the request deadline without blocking the graph (#377)

A rare `.index create` never replied. Thread dumps of a looped build show
the cause in hnsw_rs 0.3.4: its reverse-link update held a read lock on the
new point's neighbour list while it write-locked each neighbour's list, so
two parallel inserts whose new points listed each other waited for each
other forever. Every parallel build could hang this way: `.index create`,
`.index rebuild`, tombstone compaction inside a delete, and the rebuild of
indexes when a knowledge graph loads. A standalone loop of the scenario's
build (100 vectors, dimension 8, cosine) on 4 pinned cores hung 2 runs in 3
within a minute; with the fix, about 270,000 builds never hung.

hnsw_rs is now vendored under vendor/hnsw_rs with [patch.crates-io] and
three marked patches (vendor/hnsw_rs/PATCHES.md):
1. copy the neighbour list and release its lock before locking any
   neighbour, so an insert never holds one point's lock while waiting for
   another's (upstream master still has the deadlock);
2. store a reverse link at the layer it links on instead of the new point's
   top layer (upstream's unreleased fix). Layer 0 lacked the reverse links of
   every point above it and could split apart: this is the cause of the
   recall flake #302 (recall@10 fell to 0.59 in about 1 build in 200; over
   200 builds the median goes from 0.984 to 0.996 and the minimum from 0.59
   to 0.994);
3. log the every-50,000-points line instead of printing it to stdout.
Serial insertion would also avoid the deadlock, but it is 3.5x slower on 4
threads and 14x on 16 (50k x 128: 145 s against 11 s).

`.index create` and `.index rebuild` are now bounded by the request's
deadline and cancellable, like queries. They used to enter the commit before
building and hold the knowledge graph's write lock through the build, so a
build could not be stopped and froze every read and write of the graph
while it ran. Now the rows are taken under a short read lock, the index is
built without any lock, checking the request's stop before each vector, and
only then does the request enter its commit: under the write lock it
applies the rows written during the build, checks that no other create or
redefinition won meanwhile, and installs the index. A stopped build
installs nothing and answers deadline_exceeded or cancelled. The first
vector is inserted alone so that parallel inserts never meet an empty graph,
where hnsw_rs leaves them unlinked.

The Dockerfile copies vendor/ and CI's Rust filter includes it. The
indexing guide says builds no longer block the graph and run under the
deadline (query_timeout_ms, 30 s by default, to be raised for big builds).

Fixes #302
@jsam
jsam force-pushed the fm/fix-index-hang branch from b77f4bd to 69e8244 Compare October 5, 2026 22:18
@jsam jsam changed the title fix(vector-index): end the hnsw_rs deadlock that hung .index create, and build indexes under the request deadline without blocking the graph fix(storage_engine): end the HNSW build deadlock that hung .index create and bound index builds by the request deadline Oct 5, 2026
@jsam
jsam marked this pull request as ready for review October 5, 2026 22:20
@jsam
jsam merged commit 94ae97c into main Oct 5, 2026
25 checks passed
@jsam
jsam deleted the fm/fix-index-hang branch October 5, 2026 22:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant