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

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: <file>` before every program of a sequential sweep and `worker K starts: <files>` 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

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}
 

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

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) {

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

doc/reflections/das2rst.das

@@ -414,7 +414,7 @@ def document_module_debugapi(_root : string) {
     var mod = get_module("debugapi")
     var groups <- array<DocGroup>(
         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)$%%),

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]`.

include/daScript/simulate/aot_builtin_debugger.h

@@ -18,6 +18,7 @@ namespace das {
         const TBlock<void, StackWalker *> & 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 );

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<Context *>::to(args[0]);
         if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context");
         auto fn = cast<const char *>::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<recursive_mutex> 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<bool>::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<Context *>::to(args[0]);
         if ( !invCtx ) context.throw_error_at(call->debugInfo, "pinvoke with null context");
@@ -1644,6 +1663,28 @@ namespace debugger {
             addInterop<pinvoke_impl,void,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"invoke_in_context",
                 SideEffects::worstDefault,"pinvoke_impl")->unsafeOperation = true;
             // pinvoke2
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
+            addInterop<try_pinvoke_impl,bool,vec4f,const char *,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f,vec4f>(*this,lib,"try_invoke_in_context",
+                SideEffects::worstDefault,"try_pinvoke_impl")->unsafeOperation = true;
             addInterop<pinvoke_impl2,void,vec4f,Func>(*this,lib,"invoke_in_context",
                 SideEffects::worstDefault,"pinvoke_impl2")->unsafeOperation = true;
             addInterop<pinvoke_impl2,void,vec4f,Func,vec4f>(*this,lib,"invoke_in_context",

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 $<TARGET_FILE:daslang> ${_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 $<TARGET_FILE:daslang> ${_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()

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>) : 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: <file>` 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: <files>` 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}")
+    }
+}

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.

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)
         }
     }
 }