From c8903416fed4045388cc18290a1502a33754cb3c Mon Sep 17 00:00:00 2001 From: Boris Batkin Date: Sat, 5 Sep 2026 16:44:27 -0700 Subject: [PATCH] dastest: a hung sweep names the program that hung - flushed, timestamped start lines, run_tests targets streamed through Ninja - and the first hang they named, the debug-agent threadlock test, fixed on a new try_invoke_in_context A mac Debug cell hung twice today in its interpreter sweep and the log ended in silence: `--failures-only` prints nothing for a passing file, and the sweep runs through `cmake --build --target run_tests_interpreter`, where Ninja holds a command's output until it finishes - a killed sweep loses everything it printed, including what would have named the hang. - `log::started` prints a timestamped line to stderr and flushes it at once, in every mode; stdout stays clean for `--bench-format json` and the isolated result protocol. The sequential sweep logs `run N/M: ` before each program; the isolated dispatcher logs `worker K starts: ` before each batch, and the batch's own child prints its `run` lines into the stderr the parent folds in on any abnormal exit. - Every `run_tests_*` custom target carries `USES_TERMINAL`, so Ninja runs it in the console pool and streams its output. - `tests/dastest/test_start_lines.das` runs dastest as a child in both modes and asserts the exit code and the start line. The lines named the hang on this branch's own JIT lane: tests/debug_agent/test_callback_threadlock.das. Its onTick spins until the main thread releases it, and the main thread waits for a second thread started by new_thread. The tick holds the agent registry for the whole callback, and a context clone walks that registry for onCreateContext, so when the tick reaches onTick before the second thread's clone the clone blocks, the release never comes, and the process deadlocks. A 16-core box always wins that race; a 3-core runner does not. The test wanted to assert "a pinvoke is blocked while the callback runs", and nothing in the language could observe that: `invoke_in_context` waits, so every shape of the test leaned on a second thread and a sleep window. New `try_invoke_in_context(ctx, "fn", args...) : bool` is the non-blocking form - `try_lock` on the context mutex, false with nothing run when another thread holds it - and the test proves the serialization from one thread: refused while onTick holds the lock, runs once the tick returned. No second thread, no window. The contract lands on DapiDebugAgent, in the daslib architecture doc, and as the one rule of tests/debug_agent/REVIEW.md: a hook never waits on a thread that has yet to create a context. Co-Authored-By: Claude Fable 5.1 --- CHANGELIST.md | 1 + daslib/ARCHITECTURE.md | 7 +++ daslib/debugger.das | 7 +++ dastest/dastest.das | 4 ++ dastest/log.das | 10 ++++ doc/reflections/das2rst.das | 2 +- ...y_invoke_in_context-0x3b138017b43557c8.rst | 1 + .../daScript/simulate/aot_builtin_debugger.h | 1 + src/builtin/module_builtin_debugger.cpp | 49 +++++++++++++++++-- tests/CMakeLists.txt | 7 +++ tests/dastest/test_start_lines.das | 48 ++++++++++++++++++ tests/debug_agent/REVIEW.md | 9 ++++ .../debug_agent/test_callback_threadlock.das | 17 ++----- 13 files changed, 146 insertions(+), 17 deletions(-) create mode 100644 doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst create mode 100644 tests/dastest/test_start_lines.das create mode 100644 tests/debug_agent/REVIEW.md diff --git a/CHANGELIST.md b/CHANGELIST.md index eb1c6740d2..332c958208 100644 --- a/CHANGELIST.md +++ b/CHANGELIST.md @@ -313,6 +313,7 @@ Z3 SMT solver bindings as a dynamic module, dasLLVM-style. - **The daspkg macos nightly fixed** (#3664, #3665) - Homebrew bison 3.x (stock 2.3 cannot parse the grammar), dasLLVM enabled so the `-exe` .app-bundle tests run - **Dagor config build support** (#3594) - **The release audit** (#3773, #3782) - `utils/internal/test-release`: the compile phase proves every shipped example and tutorial against the bundle's own binary (803 targets), and the utils phase exercises every shipped tool from the extracted bundle alone (exit code plus output only a working run prints). The RC1 sweep's structural yield: `examples/` and `tutorials/` install as whole directories, so 31 silently-dropped files ship again; three ship-defects fixed; package examples moved to their package repos +- **A hung sweep names the program that hung** (#3949) - dastest prints a timestamped `run N/M: ` before every program of a sequential sweep and `worker K starts: ` before every isolated batch, on stderr, flushed at once and printed under `--failures-only` too; the `run_tests_*` cmake targets carry `USES_TERMINAL`, so Ninja streams the sweep's output instead of holding it until the command ends - a lane cancelled mid-hang keeps its last line instead of losing everything the sweep printed. The first hang those lines named was `tests/debug_agent/test_callback_threadlock.das`: its hook waited on a thread that had yet to create its context, while the tick holds the agent registry every context creation needs - `DapiDebugAgent` carries the contract, and the test now proves the callback/pinvoke serialization from one thread with the new `try_invoke_in_context`, the non-blocking `invoke_in_context` that returns false, running nothing, while another thread holds the context lock - **Bounded apt on ubuntu runners** (#3785) - every workflow apt site goes through `ci/apt_install.sh`: the degrading Azure mirror swapped for the public archive (mirrorlist included), capped fetches, retried update - the worst case becomes a loud failure in minutes instead of a silent hours-long hang ### Examples and Tutorials diff --git a/daslib/ARCHITECTURE.md b/daslib/ARCHITECTURE.md index 46eef05630..97fe1f9703 100644 --- a/daslib/ARCHITECTURE.md +++ b/daslib/ARCHITECTURE.md @@ -136,6 +136,13 @@ Three companions carry a concern each; a section number is unique across all fou - **The debugger-ready query uses an explicit pinvoke** - generated `apply_in_context` verification would acquire the agent registry while holding the context mutex, opposite to the debugger tick's registry-to-context order. +- **A hook never waits on a thread that has yet to create a context** - the tick holds the + agent registry (`g_DebugAgentMutex`, `src/runtime/context.cpp`) for the whole callback, and + every `Context` construction walks that registry for `onCreateContext`, so a `new_thread` + started while a hook blocks cannot begin. `try_invoke_in_context` is the non-blocking attempt + on the context mutex - false while a hook runs - so the threadlock test proves the + callback/pinvoke serialization from one thread, with no timing window and no thread started + under a blocked hook. ### 24.2 Debugger worker startup {#debugger-worker-startup} diff --git a/daslib/debugger.das b/daslib/debugger.das index 2688d7a2d4..fc65829e0d 100644 --- a/daslib/debugger.das +++ b/daslib/debugger.das @@ -10,6 +10,13 @@ require debugapi public require daslib/rtti public +//! Every hook runs under the process-wide agent registry lock, and so does every context +//! creation (`onCreateContext` walks the registry). A hook therefore never waits on another +//! thread that has yet to create a context - `new_thread`, a fresh `Context` - or the process +//! deadlocks. A hook also runs under its own context's mutex, the same one `invoke_in_context` +//! takes, so a callback and a pinvoke into the agent context never overlap; +//! `try_invoke_in_context` is the non-blocking form - it returns false, running nothing, +//! while that mutex is held. class DapiDebugAgent { def abstract onInstall(agent : DebugAgent?) : void def abstract onUninstall(agent : DebugAgent?) : void diff --git a/dastest/dastest.das b/dastest/dastest.das index 35dde4674a..1be2cf0ff5 100644 --- a/dastest/dastest.das +++ b/dastest/dastest.das @@ -299,6 +299,7 @@ def private run_iso_batch(input : IsoInput#; t : int; perTestTimeout : float; ou // Batch timeout: per-test budget scaled by batch size (<=0 means none). let batchTimeout = perTestTimeout <= 0.0 ? perTestTimeout : perTestTimeout * float(nFiles) var br : BatchRun + log::started("worker {t + 1} starts: {join(input.uris, " ")}") run_iso_subprocess("{input.batchCmd}{widx}", batchTimeout, br) let k = min(length(br.results), nFiles) // Reported files (a prefix of the batch). The per-file JSON is authoritative, @@ -593,10 +594,13 @@ def main() : int { // nolint:STYLE037,STYLE038 - CLI dispatch, one arm per mode } elif (!empty(deser_file)) { res = deserialize_path(ctx, files, deser_file) } elif (!isolatedMode) { + var fileIndex = 0 for (file in files) { let uri = ctx.uriPaths ? file_name_to_uri(file) : file let fileTime = ref_time_ticks() currentTestFile = file + fileIndex ++ + log::started("run {fileIndex}/{length(files)}: {uri}") let status = suite::test_file(file, ctx) let fileDt = get_time_nsec(fileTime) / 1000 if (status.errors + status.failed == 0) { diff --git a/dastest/log.das b/dastest/log.das index b22cd44e84..6bfec3e696 100644 --- a/dastest/log.das +++ b/dastest/log.das @@ -6,6 +6,7 @@ module log shared require daslib/rtti require uriparser require strings +require daslib/fio require daslib/ansi_colors public @@ -27,6 +28,15 @@ def info(msg : string | #) { } } +//! a timestamped progress line that must survive the process dying right after it: printed in +//! every mode, --failures-only included, on stderr so a machine-read stdout (--bench-format +//! json, the isolated result protocol) stays clean, and flushed at once - a hung sweep's log +//! then ends with the program that hung and when it started, not with silence +def started(msg : string | #) { + fwrite(fstderr(), "{iso8601_now()} {msg}\n") + fflush(fstderr()) +} + //! prints a colored line with the newline outside the color wrap, so the closing reset //! escape can never land at the head of the next stdout line (it corrupts machine-read diff --git a/doc/reflections/das2rst.das b/doc/reflections/das2rst.das index 398b13a9b9..aeed88d1b8 100644 --- a/doc/reflections/das2rst.das +++ b/doc/reflections/das2rst.das @@ -414,7 +414,7 @@ def document_module_debugapi(_root : string) { var mod = get_module("debugapi") var groups <- array( group_by_regex("Agent lifecycle", mod, %regex~(fork_debug_agent_context|install_debug_agent|install_debug_agent_thread_local|install_new_debug_agent|install_new_thread_local_debug_agent|has_debug_agent_context|get_debug_agent_context|delete_debug_agent_context|is_in_debug_agent_creation|lock_debug_agent)$%%), - group_by_regex("Cross-context invocation", mod, %regex~(invoke_in_context|invoke_debug_agent_method|invoke_debug_agent_function)$%%), + group_by_regex("Cross-context invocation", mod, %regex~(invoke_in_context|try_invoke_in_context|invoke_debug_agent_method|invoke_debug_agent_function)$%%), group_by_regex("Agent construction", mod, %regex~(make_debug_agent|make_data_walker|make_stack_walker)$%%), group_by_regex("Agent tick and state collection", mod, %regex~(tick_debug_agent|collect_debug_agent_state|on_breakpoints_reset|report_context_state|debug_agent_command|debugger_stop_requested|debugger_thread_context_ready)$%%), group_by_regex("Instrumentation", mod, %regex~(instrument_node|instrument_function|instrument_all_functions|instrument_all_functions_thread_local|instrument_context_allocations|clear_instruments|set_single_step)$%%), diff --git a/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst b/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst new file mode 100644 index 0000000000..899bebddc8 --- /dev/null +++ b/doc/source/stdlib/handmade/function-debugapi-try_invoke_in_context-0x3b138017b43557c8.rst @@ -0,0 +1 @@ +The non-blocking `invoke_in_context`: tries the target context's lock instead of waiting on it. Returns `true` once the call ran, `false` - running nothing - when another thread holds that context, a debug-agent hook for instance. Same arguments as `invoke_in_context` by function name, up to 10 extra arguments; the target function must be marked `[export, pinvoke]`. diff --git a/include/daScript/simulate/aot_builtin_debugger.h b/include/daScript/simulate/aot_builtin_debugger.h index 5ef7aecf8e..eb8f4542dd 100644 --- a/include/daScript/simulate/aot_builtin_debugger.h +++ b/include/daScript/simulate/aot_builtin_debugger.h @@ -18,6 +18,7 @@ namespace das { const TBlock & blk, Context * context, LineInfoArg * at ); DAS_API vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ); + DAS_API vec4f try_pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f pinvoke_impl2 ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f pinvoke_impl3 ( Context & context, SimNode_CallBase * call, vec4f * args ); DAS_API vec4f invokeInDebugAgent ( Context & context, SimNode_CallBase * call, vec4f * args ); diff --git a/src/builtin/module_builtin_debugger.cpp b/src/builtin/module_builtin_debugger.cpp index fd4ca0a27a..15898a9599 100644 --- a/src/builtin/module_builtin_debugger.cpp +++ b/src/builtin/module_builtin_debugger.cpp @@ -1140,16 +1140,16 @@ namespace debugger { // pinvoke(context,"function",....) - vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + static bool pinvoke_named ( Context & context, SimNode_CallBase * call, vec4f * args, vec4f & res, bool tryLock ) { auto invCtx = cast::to(args[0]); if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context"); auto fn = cast::to(args[1]); if ( !fn ) context.throw_error_at(call->debugInfo, "can't pinvoke empty string"); if ( !invCtx->contextMutex ) context.throw_error_at(call->debugInfo,"threadlock_context is not set"); - vec4f res = v_zero(); + if ( tryLock && !invCtx->contextMutex->try_lock() ) return false; LineInfo exAt; string exText; - invCtx->threadlock_context([&](){ + auto body = [&](){ auto simFn = invCtx->findFunction(fn); if ( !simFn ) { exAt = call->debugInfo; @@ -1178,11 +1178,30 @@ namespace debugger { exAt = invCtx->exceptionAt; exText = invCtx->exception; } - }); + }; + if ( tryLock ) { + lock_guard guard(*invCtx->contextMutex, std::adopt_lock); + invCtx->lock(); + body(); + invCtx->unlock(); + } else { + invCtx->threadlock_context(body); + } if ( !exText.empty() ) context.throw_error_at(exAt, "%s", exText.c_str()); + return true; + } + + vec4f pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + vec4f res = v_zero(); + pinvoke_named(context, call, args, res, false); return res; } + vec4f try_pinvoke_impl ( Context & context, SimNode_CallBase * call, vec4f * args ) { + vec4f res = v_zero(); + return cast::from(pinvoke_named(context, call, args, res, true)); + } + vec4f pinvoke_impl2_core ( Context & context, SimNode_CallBase * call, vec4f * args, int32_t nUserArgs ) { auto invCtx = cast::to(args[0]); if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context"); @@ -1644,6 +1663,28 @@ namespace debugger { addInterop(*this,lib,"invoke_in_context", SideEffects::worstDefault,"pinvoke_impl")->unsafeOperation = true; // pinvoke2 + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; + addInterop(*this,lib,"try_invoke_in_context", + SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true; addInterop(*this,lib,"invoke_in_context", SideEffects::worstDefault,"pinvoke_impl2")->unsafeOperation = true; addInterop(*this,lib,"invoke_in_context", diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index f239fab83d..15ed8e2bdf 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -29,12 +29,14 @@ if(NOT DAS_TOOLS_DISABLED) DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (interpreter)" + USES_TERMINAL ) add_custom_target(run_tests_interpreter_isolated COMMAND $ ${_DAS_DASTEST} -- ${_DAS_TEST_COMMON} --isolated-mode --timeout ${DAS_TEST_TIMEOUT_ISOLATED} DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (interpreter, isolated retry)" + USES_TERMINAL ) if(NOT DAS_LLVM_DISABLED) @@ -61,12 +63,14 @@ if(NOT DAS_TOOLS_DISABLED) DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (JIT, isolated-parallel)" + USES_TERMINAL ) add_custom_target(run_tests_jit_isolated COMMAND $ ${_DAS_DASTEST} -jit -- ${_DAS_JIT_FLAGS} ${_DAS_TEST_COMMON} --isolated-mode --timeout 3600 DEPENDS daslang WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (JIT, isolated retry)" + USES_TERMINAL ) endif() endif() @@ -80,6 +84,7 @@ if(TARGET test_aot) DEPENDS test_aot WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (AOT)" + USES_TERMINAL ) endif() @@ -92,6 +97,7 @@ if(TARGET test_aot_subset) DEPENDS test_aot_subset WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (AOT, tests/language subset)" + USES_TERMINAL ) endif() @@ -106,5 +112,6 @@ if(TARGET test_llvm_aot) DEPENDS test_llvm_aot WORKING_DIRECTORY ${PROJECT_SOURCE_DIR} COMMENT "Running tests (LLVM-AOT)" + USES_TERMINAL ) endif() diff --git a/tests/dastest/test_start_lines.das b/tests/dastest/test_start_lines.das new file mode 100644 index 0000000000..ddbdd3305f --- /dev/null +++ b/tests/dastest/test_start_lines.das @@ -0,0 +1,48 @@ +options gen2 +options no_aot + +require dastest/testing_boost +require daslib/fio +require daslib/strings_boost + +// the start lines are what a hung sweep leaves behind, so they must be printed under +// --failures-only, in both modes, and not depend on the run finishing + +def run_dastest_capturing(t : T?; mode_args : array) : string { + let das_root = get_das_root() + var args <- [ + get_command_line_arguments()[0], + "-dasroot", das_root, + "{das_root}/dastest/dastest.das", + "--", + "--failures-only", + "--test", "{das_root}/tests/dastest/_fixture_pass.das" + ] + args |> push_from(mode_args) + var output : string + let exit_code = run_and_capture(args, output) + t |> equal(exit_code, 0, "the child dastest run must succeed; output:\n{output}") + return output +} + +[test] +def test_sequential_sweep_names_each_program(t : T?) { + let output = run_dastest_capturing(t, []) + let at = find(output, "run 1/1: ") + t |> success(at >= 0, "the sequential sweep prints `run N/M: ` before the program") + if (at >= 0) { + let line = (split(slice(output, at), "\n"))[0] + t |> success(find(line, "_fixture_pass.das") >= 0, "the start line names the program: {line}") + } +} + +[test] +def test_isolated_sweep_names_each_batch(t : T?) { + let output = run_dastest_capturing(t, ["--isolated-mode", "--isolated-mode-threads", "1"]) + let at = find(output, "worker 1 starts: ") + t |> success(at >= 0, "the isolated dispatcher prints `worker K starts: ` before the batch") + if (at >= 0) { + let line = (split(slice(output, at), "\n"))[0] + t |> success(find(line, "_fixture_pass.das") >= 0, "the batch line names its files: {line}") + } +} diff --git a/tests/debug_agent/REVIEW.md b/tests/debug_agent/REVIEW.md new file mode 100644 index 0000000000..ba0789c50d --- /dev/null +++ b/tests/debug_agent/REVIEW.md @@ -0,0 +1,9 @@ +# debug_agent tests Code Review Checklist + +**Read `REVIEW_COMMON.md` (repo root) first - its contract binds this checklist.** Architecture doc: +`daslib/ARCHITECTURE.md` (repo root). + +**A test in this folder that calls `tick_debug_agent` starts every thread its agent's +callbacks wait on before that call, and holds each such thread on an atomic flag until the +callback has entered.** A callback runs under the agent registry lock and `new_thread` cannot +create its context without that same lock, so the wait never ends. diff --git a/tests/debug_agent/test_callback_threadlock.das b/tests/debug_agent/test_callback_threadlock.das index 02ca8f3694..47c2172dfa 100644 --- a/tests/debug_agent/test_callback_threadlock.das +++ b/tests/debug_agent/test_callback_threadlock.das @@ -52,7 +52,6 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { var active = atomic32_create() var overlap = atomic32_create() var tick_done = atomic32_create() - var probe_started = atomic32_create() let agent_context = unsafe(addr(get_debug_agent_context("callback_threadlock_test"))) unsafe { invoke_in_context( @@ -68,23 +67,18 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { tick_debug_agent("callback_threadlock_test") tick_done |> set(1) } - new_thread() @() { - probe_started |> set(1) - unsafe { - invoke_in_context(*agent_context, "probe_callback_overlap") - } - } while ((entered |> get) == 0) { sleep(10u) } - while ((probe_started |> get) == 0) { - sleep(10u) - } - sleep(200u) + let refused = !unsafe(try_invoke_in_context(*agent_context, "probe_callback_overlap")) + t |> success(refused, "a pinvoke is refused while the callback holds the context lock") + t |> equal(overlap |> get, 0) release |> set(1) while ((tick_done |> get) == 0) { sleep(10u) } + let ran = unsafe(try_invoke_in_context(*agent_context, "probe_callback_overlap")) + t |> success(ran, "a pinvoke runs once the callback returned") } t |> equal(overlap |> get, 0) delete_debug_agent_context("callback_threadlock_test") @@ -94,7 +88,6 @@ def test_callback_and_pinvoke_are_serialized(t : T?) { atomic32_remove(active) atomic32_remove(overlap) atomic32_remove(tick_done) - atomic32_remove(probe_started) } } }