From 0220002379f9be73dca98a35a5e3f60b88604947 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 21 Sep 2026 17:26:21 +0000 Subject: [PATCH 1/3] Serialize setLogger callers; document the drain-lock and -lv caveats Two concurrent setLogger calls raced on common_log's worker std::thread: the swap pauses (joins) and resumes (assigns a fresh thread) the worker, and without serialization one caller joined while the other assigned over the still-joinable object, which is std::terminate -- the JVM died with "terminate called without an active exception". The previous llama_log_set implementation held g_log_mutex for the whole swap; the sink swap cannot (the join needs that mutex on the worker), so a separate g_set_logger_mutex now serializes callers. LlamaLoggerTest#concurrentSetLoggerCallsDoNotRace OnTheLogWorker (4 threads x 200 swaps) reproduced the crash before the fix and passes after it. Javadoc: setLogger now names the second deadlock rule (do not hold a lock the previous callback needs while the drain runs it on the worker); setLogVerbosity no longer claims "the last model loaded wins" -- a load without -lv leaves the process-wide threshold untouched. The per-line attach/detach of the worker thread is documented as the simple, not the cheapest, choice, with the thread_local-guard optimisation filed in TODO.md. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH --- CLAUDE.md | 2 +- TODO.md | 18 +++++++++++ llama/src/main/cpp/jllama.cpp | 22 ++++++++++--- .../java/net/ladenthin/llama/LlamaModel.java | 8 +++-- .../llama/parameters/ModelParameters.java | 5 +-- .../net/ladenthin/llama/LlamaLoggerTest.java | 31 +++++++++++++++++++ 6 files changed, 76 insertions(+), 10 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 87a099d2..73af7626 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -756,7 +756,7 @@ Current patches: | `0010-server-cast-vocab-type-for-common-json.patch` | **Upstream regression from the b10585 `common_json` switch (#27511), one line.** `get_res_model_info()` (`tools/server/server-context.cpp`) builds the `GET /models` + `GET /v1/models` payload and emits `{"vocab_type", meta.model_vocab_type}` — an **unscoped enum**. `common_json_value`'s integral constructor template is `std::is_integral`-gated, which *excludes* enums, so the value binds to `common_json_value(bool)` and serialises as `true`/`false` instead of the numeric vocab type. It was correct while the alias was `nlohmann::ordered_json` (nlohmann serialises an enum as an integer), so upstream regressed it silently when they flipped the alias. The project ships this: `server-context.cpp` is compiled into `libjllama` and both routes are served by `NativeServer` — the default fat-jar `Main-Class` — in full **and** attach mode (`patches/0007`'s common route table registers them). The patch casts the value to `int` at the emit site, mirroring what `jllama.cpp` does for its own two `"vocab_type"` sites. Upstream-submittable; **not yet filed upstream**. Applies after `0002`/`0003` (same file) — numbered `0010` because `0009` is burned: it names the subprocess.h patch dropped at the b10280 bump (see the note below this table), and reusing the number would make that note read as if it were about this patch. **On every bump, check whether upstream cast the value themselves; if they did, DROP this patch rather than refreshing it** — the fail-loud applier only detects "does not apply", never "upstream already fixed this", and no test can catch a redundant carry here because `get_res_model_info` is `static` inside `server-context.cpp` and unreachable from `jllama_test`. See the `CommonJsonEnumTrap` tests in `test_json_helpers.cpp` for the mechanism the cast defends against. | | `0006-server-embed-native-server-jni.patch` | **Makes `server.cpp`'s `llama_server` embeddable in the JVM** so the `NativeServer` JNI bridge can run the full upstream HTTP server (WebUI included) inside `libjllama` — see "Two server modes" below. b9870 already exposes `int llama_server(int, char**)` (non-static; no `main` in the file), so the patch only adds embedded-mode support: (1) a `g_llama_server_embedded` flag + `llama_server_set_embedded()` / `llama_server_request_shutdown()` (declared in the committed `src/main/cpp/native_server_bridge.h`); (2) skips installing the process-wide SIGINT/SIGTERM handlers when embedded (they would hijack the JVM's); (3) in embedded mode parses the **forwarded** argv via `common_params_parse` instead of `common_params_parse_main` (whose `GetCommandLineW` recovery would pick up `java.exe`'s command line — the same Windows class of bug `0001` fixes). `llama_server_request_shutdown()` mirrors the SIGTERM path (invokes the installed `shutdown_handler` → `ctx_server.terminate()` unblocks `start_loop()`), giving JNI an out-of-band stop since `ctx_server` is loop-local. Applies **after `0001`** (which flips this call site to `common_params_parse_main`), so its context is the post-`0001` tree; regenerate against `0001`+source on a bump. Only touches `tools/server/server.cpp`. | | `0012-model-guard-zero-split-sum-and-name-the-device-index.patch` | **A GPU that reports zero free memory makes every model load fail with the unactionable `error loading model: vector`.** `llama_model_base::load_tensors` (`src/llama-model.cpp`) weights the per-device layer split by `ggml_backend_dev_memory()`'s `free`, then normalises: `splits[i] /= split_sum`. With a single device reporting `free == 0` that is `0/0` → **NaN** in every split point; NaN compares false against everything, so the `std::upper_bound` below returns the end iterator, `layer_gpu == n_devices()`, and `devices.at(layer_gpu)` throws `std::out_of_range` — whose libc++ `what()` is the bare string `"vector"`, which `llama.cpp`'s `catch (const std::exception &)` prints verbatim. Upstream's `free == 0 && total == 0` host-memory fallback does **not** fire, because `total` is `recommendedMaxWorkingSetSize` and is non-zero. **Reachable since b10618..b10797**: upstream `8c0b9cd04` ("metal : fix memory query under low-memory conditions", [#27701](https://github.com/ggml-org/llama.cpp/pull/27701)) changed `ggml-metal-device.m` to `*free = *total > cur ? *total - cur : 0`; before that clamp an over-committed device (`currentAllocatedSize > recommendedMaxWorkingSetSize`) *underflowed* to a huge `size_t`, which normalised fine, so the same precondition was harmless. That is why the `Java Tests macOS …` jobs went red at the b10792→b10797 step while every Linux/Windows job stayed green — **and why only a GPU build can fail this way at all**: `act_gpu_layers` is `devices.empty() ? 0 : …`, so with no GPU backend `devices` is empty, every layer returns early on `cpu_dev`, and the `.at()` line is unreachable. **Shape:** the two blocks are lifted out of `load_tensors` into free functions declared in `src/llama-model.h`, purely so they can be driven by a test — the failing state needs a real over-committed GPU and cannot be arranged through any public API. `llama_model_splits_normalize()` carries **the fix**: on `split_sum == 0` it `LLAMA_LOG_WARN`s and falls back to an even split (`splits[i] = float(i+1)/splits.size()`), the only neutral choice when no device can be preferred and exactly right for a single device. `llama_model_splits_select_device()` carries **the diagnostic**: it bounds-checks the index and throws a `std::runtime_error` naming the function, the offloaded layer, the device index, the split-point count **and the split points themselves** — with NaN splits that message prints `nan` and names the cause outright, which is precisely what was missing when this had to be diagnosed by reading source. **A second, backend-independent trigger reaches the same line**, found while writing this up and verified against the unfixed library: `--tensor-split` values are parsed with `std::stof` and never range-checked (`common/arg.cpp`), so `-ts 1,-1` cancels out, `split_sum` is 0 again, the split points become `[inf, -nan]`, and every layer maps one past the last device — on CUDA, Vulkan or ROCm just as much as on Metal, with no memory pressure involved. That is what makes this an ordinary upstream defect rather than a Metal edge case, and the warning names both causes rather than only the memory one. Also adds upstream `tests/test-model-split.cpp` (5 cases in upstream's `testing.h` style) + its `llama_build_and_test` registration. Touches `src/llama-model.{cpp,h}`, `tests/test-model-split.cpp` and `tests/CMakeLists.txt` — **none** of which any other patch touches, so it is independent of all of them. Upstream-submittable ("model: fall back to an even split when no device reports free memory"); **not yet filed upstream**. **Runnable guard: `src/test/cpp/test_model_split.cpp`** — a FetchContent subproject builds with `LLAMA_BUILD_TESTS=OFF`, so the upstream test above is applied-but-never-compiled here (same as `0001`'s test). That file drives the same two functions from `jllama_test`, which runs on **every** platform in `C++ Tests`, so a bump that drops this patch fails the build at link time everywhere instead of surfacing as one red macOS Java job. **Verification limit — read before assuming this can be dropped:** the *failing path* still cannot be reached without a GPU backend, so the guard pins the arithmetic (what actually broke), not the end-to-end load; the end-to-end proof is the macOS CI job. On a bump, re-check whether upstream added its own `split_sum == 0` guard (grep `split_sum` in `src/llama-model.cpp`) and **drop this patch rather than refreshing it** if they did — the fail-loud applier detects "does not apply", never "upstream already fixed this". | -| `0014-common-log-callback-sink.patch` | **Gives `common_log` a callback sink: `common_log_set_callback(log, cb, user_data)` (`common/log.{h,cpp}`).** This is what `LlamaModel.setLogger` hooks. Before it, the Java logger was a `llama_log_set()` callback, which has two holes, both found while chasing `slot print_timing` lines interleaving with the Atmosphere agent's streamed answer: **(a)** every model load runs `common_init()`, which re-points `llama_log_set()` at `common_log_default_callback` (`common.cpp:394`), so `setLogger(…)` *before* `new LlamaModel(…)` silently lost the callback; **(b)** the server's own `SRV_*`/`SLT_*` macros are `LOG_INF` and write straight into `common_log`, which `llama_log_set()` never carried, so the per-request `slot …`/`srv …` lines could not be routed to Java at all (the reason `LlamaModelTest#testLogText/JSON` sat `@Disabled` for years). `common_log` upstream offers file, colors, prefix, timestamps, verbosity and JSONL but no hook. The patch adds one: while a callback is set, the worker thread hands every entry to it **instead of** printing to stdout/stderr (a `--log-file` still receives them); the callback gets the bare formatted message (no prefix/timestamp/colors) with the `ggml_log_callback` signature; swapping the callback pauses the worker first, so queued entries reach the *previous* sink (which is what makes `setLogger(format, null)` a synchronous drain). With the sink, `common_init()`'s `llama_log_set()` reset is harmless — it points at the default callback that feeds `common_log`, i.e. exactly the path into the sink — so the ordering problem (a) disappears without any re-install logic, and the `srv`/`slot` lines (b) arrive because they are `common_log` entries. `jllama.cpp`'s `setLogger` therefore sets `common_log_set_callback(common_log_main(), trampoline)` **plus** `llama_log_set(common_log_default_callback)` (so llama/ggml lines feed `common_log` even before the first load). Two consequences to know: the callback runs on `common_log`'s **worker thread**, a plain `std::thread` llama.cpp re-creates on every pause/resume and never attaches to the JVM — the trampoline attaches per call and detaches again (`get_jni_env_attaching`; a thread that exits while attached leaks a `JavaThread`, and this thread is not ours to detach), and `setLogger` must call `common_log_set_callback` **outside** `g_log_mutex`, because the pause joins the worker, which needs that mutex to read the callback. And the verbosity threshold applies *before* the sink: at the default (`3`) the Java logger sees errors, warnings and the server's INFO lines, while llama/ggml INFO lines (`common_log_get_verbosity` maps them to TRACE = 4) arrive only from `setLogVerbosity(4)` on — the same filtering the console gets, and a behaviour change for consumers who captured the unfiltered `llama_log_set()` stream before. **Runnable guards:** `src/test/cpp/test_common_log_callback.cpp` (6 tests over a private `common_log_init()` instance: delivery, bare text under prefix+timestamps, clear, swap-drains-to-old-sink, file kept, levels pass through) links the function on every platform, so a bump that drops the patch reds `C++ Tests` at link time; `LlamaLoggerTest` (model-free, needs only `libjllama`: a logger set before a deliberately failing load on a non-GGUF file sees the `srv … loading model` INFO line and llama's ERROR line, in TEXT and JSON) and the re-enabled `LlamaModelTest#testLogText/testLogJSON` plus `#testLoggerSetBeforeLoadSurvivesTheLoad` (vocab-only load) cover the Java side. Upstream-submittable ("common : add a callback sink to common_log for embedding hosts"); **not yet filed upstream**. Touches only `common/log.{h,cpp}`, which no other patch touches. **On a bump, check whether upstream added a hook of its own (grep `callback` in `common/log.h`) and, if so, DROP this patch and port `setLogger` to theirs rather than refreshing it.** | +| `0014-common-log-callback-sink.patch` | **Gives `common_log` a callback sink: `common_log_set_callback(log, cb, user_data)` (`common/log.{h,cpp}`).** This is what `LlamaModel.setLogger` hooks. Before it, the Java logger was a `llama_log_set()` callback, which has two holes, both found while chasing `slot print_timing` lines interleaving with the Atmosphere agent's streamed answer: **(a)** every model load runs `common_init()`, which re-points `llama_log_set()` at `common_log_default_callback` (`common.cpp:394`), so `setLogger(…)` *before* `new LlamaModel(…)` silently lost the callback; **(b)** the server's own `SRV_*`/`SLT_*` macros are `LOG_INF` and write straight into `common_log`, which `llama_log_set()` never carried, so the per-request `slot …`/`srv …` lines could not be routed to Java at all (the reason `LlamaModelTest#testLogText/JSON` sat `@Disabled` for years). `common_log` upstream offers file, colors, prefix, timestamps, verbosity and JSONL but no hook. The patch adds one: while a callback is set, the worker thread hands every entry to it **instead of** printing to stdout/stderr (a `--log-file` still receives them); the callback gets the bare formatted message (no prefix/timestamp/colors) with the `ggml_log_callback` signature; swapping the callback pauses the worker first, so queued entries reach the *previous* sink (which is what makes `setLogger(format, null)` a synchronous drain). With the sink, `common_init()`'s `llama_log_set()` reset is harmless — it points at the default callback that feeds `common_log`, i.e. exactly the path into the sink — so the ordering problem (a) disappears without any re-install logic, and the `srv`/`slot` lines (b) arrive because they are `common_log` entries. `jllama.cpp`'s `setLogger` therefore sets `common_log_set_callback(common_log_main(), trampoline)` **plus** `llama_log_set(common_log_default_callback)` (so llama/ggml lines feed `common_log` even before the first load). Two consequences to know: the callback runs on `common_log`'s **worker thread**, a plain `std::thread` llama.cpp re-creates on every pause/resume and never attaches to the JVM — the trampoline attaches per call and detaches again (`get_jni_env_attaching`; a thread that exits while attached leaks a `JavaThread`, and this thread is not ours — the leak-free choice, not the cheapest: each attach creates a `java.lang.Thread` object, so a `thread_local` guard that detaches once at thread exit is the optimisation on file in `TODO.md`), `setLogger` must call `common_log_set_callback` **outside** `g_log_mutex`, because the pause joins the worker, which needs that mutex to read the callback, and `setLogger` callers are serialized by a **separate** `g_set_logger_mutex`: two unserialized swaps race on the worker's `std::thread` (one joins it while the other assigns a fresh thread over the still-joinable object = `std::terminate`, the whole JVM), which `LlamaLoggerTest#concurrentSetLoggerCallsDoNotRaceOnTheLogWorker` reproduced before the mutex existed. Two caveats the Javadoc carries: a caller must not hold a lock the *previous* callback needs (the drain runs it on the worker while the caller waits), and the verbosity threshold is process-wide, overwritten only by a load that passes `-lv`. And the verbosity threshold applies *before* the sink: at the default (`3`) the Java logger sees errors, warnings and the server's INFO lines, while llama/ggml INFO lines (`common_log_get_verbosity` maps them to TRACE = 4) arrive only from `setLogVerbosity(4)` on — the same filtering the console gets, and a behaviour change for consumers who captured the unfiltered `llama_log_set()` stream before. **Runnable guards:** `src/test/cpp/test_common_log_callback.cpp` (6 tests over a private `common_log_init()` instance: delivery, bare text under prefix+timestamps, clear, swap-drains-to-old-sink, file kept, levels pass through) links the function on every platform, so a bump that drops the patch reds `C++ Tests` at link time; `LlamaLoggerTest` (model-free, needs only `libjllama`: a logger set before a deliberately failing load on a non-GGUF file sees the `srv … loading model` INFO line and llama's ERROR line, in TEXT and JSON) and the re-enabled `LlamaModelTest#testLogText/testLogJSON` plus `#testLoggerSetBeforeLoadSurvivesTheLoad` (vocab-only load) cover the Java side. Upstream-submittable ("common : add a callback sink to common_log for embedding hosts"); **not yet filed upstream**. Touches only `common/log.{h,cpp}`, which no other patch touches. **On a bump, check whether upstream added a hook of its own (grep `callback` in `common/log.h`) and, if so, DROP this patch and port `setLogger` to theirs rather than refreshing it.** | **`0011` was dropped at the b11069 bump.** Upstream merged [ggml-org/llama.cpp#29161](https://github.com/ggml-org/llama.cpp/pull/29161) diff --git a/TODO.md b/TODO.md index 843507c5..bfff29cf 100644 --- a/TODO.md +++ b/TODO.md @@ -17,6 +17,24 @@ so everything below is genuinely still open. ## Open — jllama-specific +### Logging sink (`patches/0014`) — follow-ups + +- **Keep the log worker attached instead of attaching per line.** `LlamaModel.setLogger`'s trampoline + runs on `common_log`'s worker thread, which llama.cpp creates (and re-creates on every + pause/resume) and which is not ours; today `get_jni_env_attaching` does `AttachCurrentThread` + + `DetachCurrentThread` **per log line**. Leak-free and simple, but every attach creates a + `java.lang.Thread` object and fires JVMTI `ThreadStart`/`ThreadEnd`, which is noticeable at + `--verbose` volumes and makes profilers/debuggers crawl. The cheaper shape is a `thread_local` + guard object whose destructor detaches once at thread exit (C++ TLS destructors run on normal + thread exit on glibc/macOS/MSVC, including for a `dlopen`'d library, and `std::thread::join` in + `common_log::pause()` is a normal exit). Caveats to design in: attach as daemon + (`AttachCurrentThreadAsDaemon`, so `DestroyJavaVM` never waits for the leaked singleton's worker), + skip the detach when `g_vm` is already gone (`JNI_OnUnload` ran), and pin the behaviour with the + existing model-free `LlamaLoggerTest` plus a count of `java.lang.Thread` objects seen by the + callback (today it is one per line). Not a correctness issue; measure before doing it. +- **File the patch upstream.** `common_log_set_callback` is a small, self-contained addition to + `common/log.{h,cpp}` with no jllama specifics; upstream acceptance would retire the carry. + ### Atmosphere coding agent (`llama-atmosphere-agent/`) — follow-ups The headless loop is verified, including the model-backed CI job (run 35600558852: tool call diff --git a/llama/src/main/cpp/jllama.cpp b/llama/src/main/cpp/jllama.cpp index ca483944..e99043cf 100644 --- a/llama/src/main/cpp/jllama.cpp +++ b/llama/src/main/cpp/jllama.cpp @@ -611,11 +611,14 @@ JNIEnv *get_jni_env_or_null() noexcept { * A JNIEnv for the current thread, attaching the thread to the JVM if it is not attached yet. * * The log sink runs on common_log's worker thread, a plain std::thread that llama.cpp creates - * (and re-creates on every pause/resume) and that has never seen the JVM. A per-call attach is - * the only option that leaks nothing: the thread is not ours, so nobody could detach it before - * it exits, and a thread that exits while attached leaves a dangling JavaThread behind. Returns - * nullptr (nothing to log through) when the JVM is gone or refuses the attach. `attached` tells - * the caller whether it owes a DetachCurrentThread. + * (and re-creates on every pause/resume) and that has never seen the JVM. The thread is not ours, + * and a thread that exits while attached leaves a dangling JavaThread behind, so this attaches per + * call and the caller detaches again. That is the simple, leak-free choice, not the cheapest one: + * every attach creates a java.lang.Thread object (and fires JVMTI thread events), which is + * noticeable at --verbose volumes. A thread_local guard whose destructor detaches once at thread + * exit would keep the thread attached across lines; see TODO.md. Returns nullptr (nothing to log + * through) when the JVM is gone or refuses the attach. `attached` tells the caller whether it owes + * a DetachCurrentThread. */ JNIEnv *get_jni_env_attaching(bool &attached) noexcept { attached = false; @@ -645,6 +648,12 @@ static std::mutex g_log_mutex; // call into a just-deleted global ref (a use-after-free on the JNI ref). static int g_log_active = 0; static std::condition_variable g_log_cv; +// Serializes setLogger callers against each other. It is NOT g_log_mutex: the swap pauses and +// resumes common_log's worker (a join + a fresh std::thread), and two unserialized swaps race on +// that std::thread -- one caller joins it while the other assigns a new thread over the still +// joinable object, which is std::terminate. The trampoline never takes this mutex, so holding it +// across the join cannot deadlock. +static std::mutex g_set_logger_mutex; /** * Invoke the log callback if there is any. When JSON mode is enabled, @@ -1546,6 +1555,9 @@ JNIEXPORT void JNICALL Java_net_ladenthin_llama_LlamaModel_cancelCompletion(JNIE JNIEXPORT void JNICALL Java_net_ladenthin_llama_LlamaModel_setLogger(JNIEnv *env, jclass clazz, jobject log_format, jobject jcallback) { return jni_guard_impl(env, c_llama_error, [&]() -> void { + // One swap at a time (see g_set_logger_mutex); the trampoline never takes this lock. + std::lock_guard swap_lock(g_set_logger_mutex); + // The Java logger is a sink on common_log (patches/0014), not a llama_log_set() callback. // Every line reaches common_log -- the server's SRV_*/SLT_* macros write into it directly // and llama/ggml lines arrive through common_log_default_callback -- and common_init(), diff --git a/llama/src/main/java/net/ladenthin/llama/LlamaModel.java b/llama/src/main/java/net/ladenthin/llama/LlamaModel.java index 4c84e5be..61802c92 100644 --- a/llama/src/main/java/net/ladenthin/llama/LlamaModel.java +++ b/llama/src/main/java/net/ladenthin/llama/LlamaModel.java @@ -454,8 +454,12 @@ public String decode(int... tokens) { *

Messages are delivered asynchronously from llama.cpp's log worker thread, never from the * thread that logged. Replacing or removing the logger first flushes every queued message to the * previous callback and blocks until that is done, so {@code setLogger(format, null)} is a - * synchronous drain; do not call it from inside a log callback. To discard everything, pass an - * empty callback, i.e. (level, msg) {@literal ->} {}. + * synchronous drain. Two rules follow from that: do not call it from inside a log callback, and + * do not call it while holding a lock the previous callback may need (a + * {@code synchronized} logger, a bounded queue the calling thread drains): the queued messages + * are delivered on the log worker thread while the caller waits, so such a lock deadlocks. + * Concurrent calls from different threads are serialized natively. To discard everything, pass + * an empty callback, i.e. (level, msg) {@literal ->} {}. * * @param format the log format to use * @param callback a method to call for log messages, or {@code null} for the console diff --git a/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java b/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java index 51e9b96c..9daa7bab 100644 --- a/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java +++ b/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java @@ -1236,8 +1236,9 @@ public ModelParameters setVerbose() { *

llama.cpp's {@code -lv} scale: {@code 0} tool output only, {@code 1} errors, {@code 2} * warnings, {@code 3} info (the default: the server's per-request {@code slot …} lines), * {@code 4} trace (also the llama/ggml model-loading lines), {@code 5} debug. The threshold is - * process-wide and takes effect when the parameters are parsed, so the last model loaded wins. - * It applies before the {@link net.ladenthin.llama.LlamaModel#setLogger} callback is reached. + * process-wide and takes effect when the parameters are parsed: a load that passes it overwrites + * the previous value, a load without it leaves the current value untouched. It applies before + * the {@link net.ladenthin.llama.LlamaModel#setLogger} callback is reached. * * @param verbosity the verbosity threshold level * @return this builder diff --git a/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java index 1692942e..4470e2fa 100644 --- a/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java +++ b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java @@ -159,4 +159,35 @@ private static Map toMap(JsonNode node) { node.fields().forEachRemaining(e -> map.put(e.getKey(), e.getValue())); return map; } + + /** + * Concurrent {@code setLogger} calls must be serialized natively. The sink swap pauses and + * resumes llama.cpp's log worker, and two unserialized swaps race on that {@code std::thread}: + * one caller joins it while the other assigns a fresh thread over the still-joinable object, + * which is {@code std::terminate} — the whole JVM dies, not a test. Before the fix this hammered + * the race hard enough to reproduce it. + */ + @Test + void concurrentSetLoggerCallsDoNotRaceOnTheLogWorker() throws Exception { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + final int threads = 4; + final int rounds = 200; + java.util.concurrent.ExecutorService pool = java.util.concurrent.Executors.newFixedThreadPool(threads); + try { + java.util.List> futures = new ArrayList<>(); + for (int t = 0; t < threads; t++) { + futures.add(pool.submit(() -> { + for (int i = 0; i < rounds; i++) { + LlamaModel.setLogger(LogFormat.TEXT, (level, text) -> {}); + LlamaModel.setLogger(LogFormat.JSON, null); + } + })); + } + for (java.util.concurrent.Future f : futures) { + f.get(2, java.util.concurrent.TimeUnit.MINUTES); + } + } finally { + pool.shutdownNow(); + } + } } From 8fa1a98ebc0760a26fdb2fb3193d8cbd57a8b1cf Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 21 Sep 2026 17:31:27 +0000 Subject: [PATCH 2/3] Pin the logging contracts with model-free tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LlamaLoggerTest gains three tests, all against the real libjllama and a deliberately failing load, no GGUF needed: - verbosityThresholdIsProcessWideAndEveryLoadSetsIt: -lv 1 hides the server's INFO line and keeps llama's ERROR line; a load WITHOUT -lv puts the threshold back to 3. That last part corrects the previous commit's Javadoc, which followed a review remark claiming such a load leaves the threshold untouched -- measured, it does not: common_params_parse ends with common_log_set_verbosity_thold(params.verbosity), default 3. The Javadoc and CLAUDE.md now say what the test shows. - deliveryIsAsynchronousOnTheLogWorkerAndRemovingTheLoggerDrains: lines never arrive on the caller's thread, always on a native-attached one, and setLogger(format, null) returns only after the queue is drained -- the facts behind both deadlock rules. It prints the distinct Thread count (13 lines -> 13 Thread objects today), recorded in TODO.md for the thread_local-guard optimisation. - The srv-line matcher is exact now ("srv … loading model '"); the loose contains("loading model") also matched llama's "error loading model". LocalAgentTest pins .mvn/jvm.config with -Dstdout.encoding=UTF-8 and -Dstderr.encoding=UTF-8, so the Windows console fix cannot be dropped unnoticed. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH --- CLAUDE.md | 2 +- TODO.md | 4 +- .../llama/parameters/ModelParameters.java | 7 +- .../net/ladenthin/llama/LlamaLoggerTest.java | 95 +++++++++++++++++-- 4 files changed, 96 insertions(+), 12 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 73af7626..d8663b24 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -756,7 +756,7 @@ Current patches: | `0010-server-cast-vocab-type-for-common-json.patch` | **Upstream regression from the b10585 `common_json` switch (#27511), one line.** `get_res_model_info()` (`tools/server/server-context.cpp`) builds the `GET /models` + `GET /v1/models` payload and emits `{"vocab_type", meta.model_vocab_type}` — an **unscoped enum**. `common_json_value`'s integral constructor template is `std::is_integral`-gated, which *excludes* enums, so the value binds to `common_json_value(bool)` and serialises as `true`/`false` instead of the numeric vocab type. It was correct while the alias was `nlohmann::ordered_json` (nlohmann serialises an enum as an integer), so upstream regressed it silently when they flipped the alias. The project ships this: `server-context.cpp` is compiled into `libjllama` and both routes are served by `NativeServer` — the default fat-jar `Main-Class` — in full **and** attach mode (`patches/0007`'s common route table registers them). The patch casts the value to `int` at the emit site, mirroring what `jllama.cpp` does for its own two `"vocab_type"` sites. Upstream-submittable; **not yet filed upstream**. Applies after `0002`/`0003` (same file) — numbered `0010` because `0009` is burned: it names the subprocess.h patch dropped at the b10280 bump (see the note below this table), and reusing the number would make that note read as if it were about this patch. **On every bump, check whether upstream cast the value themselves; if they did, DROP this patch rather than refreshing it** — the fail-loud applier only detects "does not apply", never "upstream already fixed this", and no test can catch a redundant carry here because `get_res_model_info` is `static` inside `server-context.cpp` and unreachable from `jllama_test`. See the `CommonJsonEnumTrap` tests in `test_json_helpers.cpp` for the mechanism the cast defends against. | | `0006-server-embed-native-server-jni.patch` | **Makes `server.cpp`'s `llama_server` embeddable in the JVM** so the `NativeServer` JNI bridge can run the full upstream HTTP server (WebUI included) inside `libjllama` — see "Two server modes" below. b9870 already exposes `int llama_server(int, char**)` (non-static; no `main` in the file), so the patch only adds embedded-mode support: (1) a `g_llama_server_embedded` flag + `llama_server_set_embedded()` / `llama_server_request_shutdown()` (declared in the committed `src/main/cpp/native_server_bridge.h`); (2) skips installing the process-wide SIGINT/SIGTERM handlers when embedded (they would hijack the JVM's); (3) in embedded mode parses the **forwarded** argv via `common_params_parse` instead of `common_params_parse_main` (whose `GetCommandLineW` recovery would pick up `java.exe`'s command line — the same Windows class of bug `0001` fixes). `llama_server_request_shutdown()` mirrors the SIGTERM path (invokes the installed `shutdown_handler` → `ctx_server.terminate()` unblocks `start_loop()`), giving JNI an out-of-band stop since `ctx_server` is loop-local. Applies **after `0001`** (which flips this call site to `common_params_parse_main`), so its context is the post-`0001` tree; regenerate against `0001`+source on a bump. Only touches `tools/server/server.cpp`. | | `0012-model-guard-zero-split-sum-and-name-the-device-index.patch` | **A GPU that reports zero free memory makes every model load fail with the unactionable `error loading model: vector`.** `llama_model_base::load_tensors` (`src/llama-model.cpp`) weights the per-device layer split by `ggml_backend_dev_memory()`'s `free`, then normalises: `splits[i] /= split_sum`. With a single device reporting `free == 0` that is `0/0` → **NaN** in every split point; NaN compares false against everything, so the `std::upper_bound` below returns the end iterator, `layer_gpu == n_devices()`, and `devices.at(layer_gpu)` throws `std::out_of_range` — whose libc++ `what()` is the bare string `"vector"`, which `llama.cpp`'s `catch (const std::exception &)` prints verbatim. Upstream's `free == 0 && total == 0` host-memory fallback does **not** fire, because `total` is `recommendedMaxWorkingSetSize` and is non-zero. **Reachable since b10618..b10797**: upstream `8c0b9cd04` ("metal : fix memory query under low-memory conditions", [#27701](https://github.com/ggml-org/llama.cpp/pull/27701)) changed `ggml-metal-device.m` to `*free = *total > cur ? *total - cur : 0`; before that clamp an over-committed device (`currentAllocatedSize > recommendedMaxWorkingSetSize`) *underflowed* to a huge `size_t`, which normalised fine, so the same precondition was harmless. That is why the `Java Tests macOS …` jobs went red at the b10792→b10797 step while every Linux/Windows job stayed green — **and why only a GPU build can fail this way at all**: `act_gpu_layers` is `devices.empty() ? 0 : …`, so with no GPU backend `devices` is empty, every layer returns early on `cpu_dev`, and the `.at()` line is unreachable. **Shape:** the two blocks are lifted out of `load_tensors` into free functions declared in `src/llama-model.h`, purely so they can be driven by a test — the failing state needs a real over-committed GPU and cannot be arranged through any public API. `llama_model_splits_normalize()` carries **the fix**: on `split_sum == 0` it `LLAMA_LOG_WARN`s and falls back to an even split (`splits[i] = float(i+1)/splits.size()`), the only neutral choice when no device can be preferred and exactly right for a single device. `llama_model_splits_select_device()` carries **the diagnostic**: it bounds-checks the index and throws a `std::runtime_error` naming the function, the offloaded layer, the device index, the split-point count **and the split points themselves** — with NaN splits that message prints `nan` and names the cause outright, which is precisely what was missing when this had to be diagnosed by reading source. **A second, backend-independent trigger reaches the same line**, found while writing this up and verified against the unfixed library: `--tensor-split` values are parsed with `std::stof` and never range-checked (`common/arg.cpp`), so `-ts 1,-1` cancels out, `split_sum` is 0 again, the split points become `[inf, -nan]`, and every layer maps one past the last device — on CUDA, Vulkan or ROCm just as much as on Metal, with no memory pressure involved. That is what makes this an ordinary upstream defect rather than a Metal edge case, and the warning names both causes rather than only the memory one. Also adds upstream `tests/test-model-split.cpp` (5 cases in upstream's `testing.h` style) + its `llama_build_and_test` registration. Touches `src/llama-model.{cpp,h}`, `tests/test-model-split.cpp` and `tests/CMakeLists.txt` — **none** of which any other patch touches, so it is independent of all of them. Upstream-submittable ("model: fall back to an even split when no device reports free memory"); **not yet filed upstream**. **Runnable guard: `src/test/cpp/test_model_split.cpp`** — a FetchContent subproject builds with `LLAMA_BUILD_TESTS=OFF`, so the upstream test above is applied-but-never-compiled here (same as `0001`'s test). That file drives the same two functions from `jllama_test`, which runs on **every** platform in `C++ Tests`, so a bump that drops this patch fails the build at link time everywhere instead of surfacing as one red macOS Java job. **Verification limit — read before assuming this can be dropped:** the *failing path* still cannot be reached without a GPU backend, so the guard pins the arithmetic (what actually broke), not the end-to-end load; the end-to-end proof is the macOS CI job. On a bump, re-check whether upstream added its own `split_sum == 0` guard (grep `split_sum` in `src/llama-model.cpp`) and **drop this patch rather than refreshing it** if they did — the fail-loud applier detects "does not apply", never "upstream already fixed this". | -| `0014-common-log-callback-sink.patch` | **Gives `common_log` a callback sink: `common_log_set_callback(log, cb, user_data)` (`common/log.{h,cpp}`).** This is what `LlamaModel.setLogger` hooks. Before it, the Java logger was a `llama_log_set()` callback, which has two holes, both found while chasing `slot print_timing` lines interleaving with the Atmosphere agent's streamed answer: **(a)** every model load runs `common_init()`, which re-points `llama_log_set()` at `common_log_default_callback` (`common.cpp:394`), so `setLogger(…)` *before* `new LlamaModel(…)` silently lost the callback; **(b)** the server's own `SRV_*`/`SLT_*` macros are `LOG_INF` and write straight into `common_log`, which `llama_log_set()` never carried, so the per-request `slot …`/`srv …` lines could not be routed to Java at all (the reason `LlamaModelTest#testLogText/JSON` sat `@Disabled` for years). `common_log` upstream offers file, colors, prefix, timestamps, verbosity and JSONL but no hook. The patch adds one: while a callback is set, the worker thread hands every entry to it **instead of** printing to stdout/stderr (a `--log-file` still receives them); the callback gets the bare formatted message (no prefix/timestamp/colors) with the `ggml_log_callback` signature; swapping the callback pauses the worker first, so queued entries reach the *previous* sink (which is what makes `setLogger(format, null)` a synchronous drain). With the sink, `common_init()`'s `llama_log_set()` reset is harmless — it points at the default callback that feeds `common_log`, i.e. exactly the path into the sink — so the ordering problem (a) disappears without any re-install logic, and the `srv`/`slot` lines (b) arrive because they are `common_log` entries. `jllama.cpp`'s `setLogger` therefore sets `common_log_set_callback(common_log_main(), trampoline)` **plus** `llama_log_set(common_log_default_callback)` (so llama/ggml lines feed `common_log` even before the first load). Two consequences to know: the callback runs on `common_log`'s **worker thread**, a plain `std::thread` llama.cpp re-creates on every pause/resume and never attaches to the JVM — the trampoline attaches per call and detaches again (`get_jni_env_attaching`; a thread that exits while attached leaks a `JavaThread`, and this thread is not ours — the leak-free choice, not the cheapest: each attach creates a `java.lang.Thread` object, so a `thread_local` guard that detaches once at thread exit is the optimisation on file in `TODO.md`), `setLogger` must call `common_log_set_callback` **outside** `g_log_mutex`, because the pause joins the worker, which needs that mutex to read the callback, and `setLogger` callers are serialized by a **separate** `g_set_logger_mutex`: two unserialized swaps race on the worker's `std::thread` (one joins it while the other assigns a fresh thread over the still-joinable object = `std::terminate`, the whole JVM), which `LlamaLoggerTest#concurrentSetLoggerCallsDoNotRaceOnTheLogWorker` reproduced before the mutex existed. Two caveats the Javadoc carries: a caller must not hold a lock the *previous* callback needs (the drain runs it on the worker while the caller waits), and the verbosity threshold is process-wide, overwritten only by a load that passes `-lv`. And the verbosity threshold applies *before* the sink: at the default (`3`) the Java logger sees errors, warnings and the server's INFO lines, while llama/ggml INFO lines (`common_log_get_verbosity` maps them to TRACE = 4) arrive only from `setLogVerbosity(4)` on — the same filtering the console gets, and a behaviour change for consumers who captured the unfiltered `llama_log_set()` stream before. **Runnable guards:** `src/test/cpp/test_common_log_callback.cpp` (6 tests over a private `common_log_init()` instance: delivery, bare text under prefix+timestamps, clear, swap-drains-to-old-sink, file kept, levels pass through) links the function on every platform, so a bump that drops the patch reds `C++ Tests` at link time; `LlamaLoggerTest` (model-free, needs only `libjllama`: a logger set before a deliberately failing load on a non-GGUF file sees the `srv … loading model` INFO line and llama's ERROR line, in TEXT and JSON) and the re-enabled `LlamaModelTest#testLogText/testLogJSON` plus `#testLoggerSetBeforeLoadSurvivesTheLoad` (vocab-only load) cover the Java side. Upstream-submittable ("common : add a callback sink to common_log for embedding hosts"); **not yet filed upstream**. Touches only `common/log.{h,cpp}`, which no other patch touches. **On a bump, check whether upstream added a hook of its own (grep `callback` in `common/log.h`) and, if so, DROP this patch and port `setLogger` to theirs rather than refreshing it.** | +| `0014-common-log-callback-sink.patch` | **Gives `common_log` a callback sink: `common_log_set_callback(log, cb, user_data)` (`common/log.{h,cpp}`).** This is what `LlamaModel.setLogger` hooks. Before it, the Java logger was a `llama_log_set()` callback, which has two holes, both found while chasing `slot print_timing` lines interleaving with the Atmosphere agent's streamed answer: **(a)** every model load runs `common_init()`, which re-points `llama_log_set()` at `common_log_default_callback` (`common.cpp:394`), so `setLogger(…)` *before* `new LlamaModel(…)` silently lost the callback; **(b)** the server's own `SRV_*`/`SLT_*` macros are `LOG_INF` and write straight into `common_log`, which `llama_log_set()` never carried, so the per-request `slot …`/`srv …` lines could not be routed to Java at all (the reason `LlamaModelTest#testLogText/JSON` sat `@Disabled` for years). `common_log` upstream offers file, colors, prefix, timestamps, verbosity and JSONL but no hook. The patch adds one: while a callback is set, the worker thread hands every entry to it **instead of** printing to stdout/stderr (a `--log-file` still receives them); the callback gets the bare formatted message (no prefix/timestamp/colors) with the `ggml_log_callback` signature; swapping the callback pauses the worker first, so queued entries reach the *previous* sink (which is what makes `setLogger(format, null)` a synchronous drain). With the sink, `common_init()`'s `llama_log_set()` reset is harmless — it points at the default callback that feeds `common_log`, i.e. exactly the path into the sink — so the ordering problem (a) disappears without any re-install logic, and the `srv`/`slot` lines (b) arrive because they are `common_log` entries. `jllama.cpp`'s `setLogger` therefore sets `common_log_set_callback(common_log_main(), trampoline)` **plus** `llama_log_set(common_log_default_callback)` (so llama/ggml lines feed `common_log` even before the first load). Two consequences to know: the callback runs on `common_log`'s **worker thread**, a plain `std::thread` llama.cpp re-creates on every pause/resume and never attaches to the JVM — the trampoline attaches per call and detaches again (`get_jni_env_attaching`; a thread that exits while attached leaks a `JavaThread`, and this thread is not ours — the leak-free choice, not the cheapest: each attach creates a `java.lang.Thread` object, so a `thread_local` guard that detaches once at thread exit is the optimisation on file in `TODO.md`), `setLogger` must call `common_log_set_callback` **outside** `g_log_mutex`, because the pause joins the worker, which needs that mutex to read the callback, and `setLogger` callers are serialized by a **separate** `g_set_logger_mutex`: two unserialized swaps race on the worker's `std::thread` (one joins it while the other assigns a fresh thread over the still-joinable object = `std::terminate`, the whole JVM), which `LlamaLoggerTest#concurrentSetLoggerCallsDoNotRaceOnTheLogWorker` reproduced before the mutex existed. Two caveats the Javadoc carries: a caller must not hold a lock the *previous* callback needs (the drain runs it on the worker while the caller waits), and the verbosity threshold is process-wide and reset by **every** load (`common_params_parse` ends with `common_log_set_verbosity_thold(params.verbosity)`, default 3), so a load without `-lv` puts it back to 3 — a review assumed the opposite, and `LlamaLoggerTest#verbosityThresholdIsProcessWideAndEveryLoadSetsIt` now pins the measured behaviour. And the verbosity threshold applies *before* the sink: at the default (`3`) the Java logger sees errors, warnings and the server's INFO lines, while llama/ggml INFO lines (`common_log_get_verbosity` maps them to TRACE = 4) arrive only from `setLogVerbosity(4)` on — the same filtering the console gets, and a behaviour change for consumers who captured the unfiltered `llama_log_set()` stream before. **Runnable guards:** `src/test/cpp/test_common_log_callback.cpp` (6 tests over a private `common_log_init()` instance: delivery, bare text under prefix+timestamps, clear, swap-drains-to-old-sink, file kept, levels pass through) links the function on every platform, so a bump that drops the patch reds `C++ Tests` at link time; `LlamaLoggerTest` (model-free, needs only `libjllama`: a logger set before a deliberately failing load on a non-GGUF file sees the `srv … loading model` INFO line and llama's ERROR line, in TEXT and JSON) and the re-enabled `LlamaModelTest#testLogText/testLogJSON` plus `#testLoggerSetBeforeLoadSurvivesTheLoad` (vocab-only load) cover the Java side. Upstream-submittable ("common : add a callback sink to common_log for embedding hosts"); **not yet filed upstream**. Touches only `common/log.{h,cpp}`, which no other patch touches. **On a bump, check whether upstream added a hook of its own (grep `callback` in `common/log.h`) and, if so, DROP this patch and port `setLogger` to theirs rather than refreshing it.** | **`0011` was dropped at the b11069 bump.** Upstream merged [ggml-org/llama.cpp#29161](https://github.com/ggml-org/llama.cpp/pull/29161) diff --git a/TODO.md b/TODO.md index bfff29cf..dc46a9a8 100644 --- a/TODO.md +++ b/TODO.md @@ -31,7 +31,9 @@ so everything below is genuinely still open. (`AttachCurrentThreadAsDaemon`, so `DestroyJavaVM` never waits for the leaked singleton's worker), skip the detach when `g_vm` is already gone (`JNI_OnUnload` ran), and pin the behaviour with the existing model-free `LlamaLoggerTest` plus a count of `java.lang.Thread` objects seen by the - callback (today it is one per line). Not a correctness issue; measure before doing it. + callback — `deliveryIsAsynchronousOnTheLogWorkerAndRemovingTheLoggerDrains` already prints it + (measured: 13 lines of a failed load → 13 distinct `Thread` objects, i.e. one per line). Not a + correctness issue; measure the time cost before doing it. - **File the patch upstream.** `common_log_set_callback` is a small, self-contained addition to `common/log.{h,cpp}` with no jllama specifics; upstream acceptance would retire the carry. diff --git a/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java b/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java index 9daa7bab..929d2b96 100644 --- a/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java +++ b/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java @@ -1236,9 +1236,10 @@ public ModelParameters setVerbose() { *

llama.cpp's {@code -lv} scale: {@code 0} tool output only, {@code 1} errors, {@code 2} * warnings, {@code 3} info (the default: the server's per-request {@code slot …} lines), * {@code 4} trace (also the llama/ggml model-loading lines), {@code 5} debug. The threshold is - * process-wide and takes effect when the parameters are parsed: a load that passes it overwrites - * the previous value, a load without it leaves the current value untouched. It applies before - * the {@link net.ladenthin.llama.LlamaModel#setLogger} callback is reached. + * process-wide and set by every load when its parameters are parsed: to this value, or + * to llama.cpp's default ({@code 3}) when the method was not called, so the last model loaded + * wins either way. It applies before the {@link net.ladenthin.llama.LlamaModel#setLogger} + * callback is reached. * * @param verbosity the verbosity threshold level * @return this builder diff --git a/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java index 4470e2fa..fa2374f2 100644 --- a/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java +++ b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java @@ -6,6 +6,7 @@ import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.empty; +import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.hasItem; import static org.hamcrest.Matchers.hasKey; import static org.hamcrest.Matchers.is; @@ -22,8 +23,11 @@ import java.util.ArrayList; import java.util.Collections; import java.util.HashMap; +import java.util.HashSet; import java.util.List; import java.util.Map; +import java.util.Set; +import java.util.concurrent.atomic.AtomicInteger; import java.util.stream.Collectors; import net.ladenthin.llama.args.LogFormat; import net.ladenthin.llama.exception.LlamaException; @@ -89,19 +93,30 @@ private Path notAGguf() throws IOException { /** Logs through a failing load and drains the queue; the drain is what makes the assertions safe. */ private List linesOfAFailedLoad(LogFormat format) throws IOException { + return linesOfAFailedLoad(format, new ModelParameters()); + } + + private List linesOfAFailedLoad(LogFormat format, ModelParameters parameters) throws IOException { List lines = Collections.synchronizedList(new ArrayList<>()); LlamaModel.setLogger(format, (level, text) -> lines.add(new Line(level, text))); - Path file = notAGguf(); - assertThrows( - LlamaException.class, - () -> new LlamaModel( - new ModelParameters().setModel(file.toString()).setDevices("none")) - .close()); + failingLoad(parameters); // Removing the logger flushes every queued message to the previous callback before returning. LlamaModel.setLogger(LogFormat.TEXT, null); return lines; } + private void failingLoad(ModelParameters parameters) throws IOException { + Path file = notAGguf(); + assertThrows( + LlamaException.class, + () -> new LlamaModel(parameters.setModel(file.toString()).setDevices("none")).close()); + } + + /** The server's own {@code srv … loading model '…'} INFO line — not llama's {@code error loading model}. */ + private static boolean sawLoadingModel(List lines) { + return lines.stream().anyMatch(l -> l.text.startsWith("srv ") && l.text.contains("loading model '")); + } + @Test void loggerSetBeforeTheLoadReceivesTheLoadsOwnLines() throws IOException { assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); @@ -111,7 +126,7 @@ void loggerSetBeforeTheLoadReceivesTheLoadsOwnLines() throws IOException { assertThat("a failed load must log something: " + lines, lines, not(empty())); assertThat( "the server's own INFO line ('srv … loading model') must reach a logger set before the load: " + lines, - lines.stream().anyMatch(l -> l.text.contains("loading model")), + sawLoadingModel(lines), is(true)); assertThat( "llama's own error line must reach the logger too: " + lines, @@ -190,4 +205,70 @@ void concurrentSetLoggerCallsDoNotRaceOnTheLogWorker() throws Exception { pool.shutdownNow(); } } + + /** + * The verbosity threshold is process-wide and applies before the sink: {@code -lv 1} hides the + * server's INFO line but keeps llama's ERROR line. It is set by every load, not only by + * one that passes {@code -lv}: {@code common_params_parse} ends with + * {@code common_log_set_verbosity_thold(params.verbosity)}, whose default is 3, so a load without + * the flag resets the threshold to llama.cpp's default. The last model loaded wins, whichever + * way it was loaded. (Written down because the opposite was assumed once, in a review.) + */ + @Test + void verbosityThresholdIsProcessWideAndEveryLoadSetsIt() throws IOException { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + try { + List errorsOnly = linesOfAFailedLoad(LogFormat.TEXT, new ModelParameters().setLogVerbosity(1)); + assertThat("-lv 1 must drop the server's INFO line: " + errorsOnly, sawLoadingModel(errorsOnly), is(false)); + assertThat( + "-lv 1 must keep llama's ERROR line: " + errorsOnly, + errorsOnly.stream().map(l -> l.level).collect(Collectors.toList()), + hasItem(LogLevel.ERROR)); + + List reset = linesOfAFailedLoad(LogFormat.TEXT, new ModelParameters()); + assertThat( + "a load without -lv resets the threshold to llama.cpp's default (3), so the INFO line is back: " + + reset, + sawLoadingModel(reset), + is(true)); + } finally { + // Belt and braces for the other tests: leave the process at llama.cpp's default. + linesOfAFailedLoad(LogFormat.TEXT, new ModelParameters().setLogVerbosity(3)); + } + } + + /** + * Messages are delivered on llama.cpp's log worker thread, never on the thread that logged + * or the one that installed the logger; and removing the logger returns only after every queued + * message has been delivered. Both are the facts behind the two deadlock rules in the Javadoc + * (no {@code setLogger} from a callback; no lock held that the previous callback needs). The + * distinct-thread count is recorded, not pinned: today every line attaches the worker afresh + * (one {@code java.lang.Thread} per line), a {@code thread_local} guard would make it one. + */ + @Test + void deliveryIsAsynchronousOnTheLogWorkerAndRemovingTheLoggerDrains() throws Exception { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + Thread caller = Thread.currentThread(); + Set deliveringThreads = Collections.synchronizedSet(new HashSet<>()); + AtomicInteger delivered = new AtomicInteger(); + LlamaModel.setLogger(LogFormat.TEXT, (level, text) -> { + deliveringThreads.add(Thread.currentThread()); + delivered.incrementAndGet(); + }); + + failingLoad(new ModelParameters()); + LlamaModel.setLogger(LogFormat.TEXT, null); + int atReturn = delivered.get(); + Thread.sleep(200); + + assertThat("a failed load logs at least one line", atReturn, greaterThan(0)); + assertThat("nothing may arrive after setLogger(format, null) returned", delivered.get(), is(atReturn)); + assertThat("delivery never runs on the caller's thread", deliveringThreads.contains(caller), is(false)); + assertThat( + "every delivering thread is a native-attached one, not a Java-created one", + deliveringThreads.stream().allMatch(t -> t.getName().startsWith("Thread-")), + is(true)); + System.out.println("[LlamaLoggerTest] " + atReturn + " lines delivered on " + deliveringThreads.size() + + " distinct Thread object(s)"); + } } From 4360845f8828f0c9c7c885da5125f50a10981ae0 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 21 Sep 2026 17:31:55 +0000 Subject: [PATCH 3/3] llama-atmosphere-agent: add the .mvn/jvm.config test the previous commit described The LocalAgentTest addition announced in 8753693 had not been written to disk (the script that carried it aborted earlier); this is that test. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH --- .../ladenthin/llama/atmosphere/LocalAgentTest.java | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/LocalAgentTest.java b/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/LocalAgentTest.java index 8c132ef3..dd156630 100644 --- a/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/LocalAgentTest.java +++ b/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/LocalAgentTest.java @@ -172,4 +172,17 @@ void verboseReplacesTheThresholdWithLlamaCppsOwnVerboseFlag() { assertThat(args, hasItem("--verbose")); assertThat(args, not(hasItem("--log-verbosity"))); } + + @Test + void mavenJvmConfigPinsAUtf8ConsoleForExecJava() throws Exception { + // On Windows llama.cpp's common_init() switches the console to UTF-8 after the JVM fixed its + // stdout encoding from the old code page; exec:java runs in Maven's JVM, so the fix has to + // live in .mvn/jvm.config (Maven reads it from the project root the user runs mvn in). + Path jvmConfig = Path.of(".mvn", "jvm.config").toAbsolutePath(); + assertThat("expected " + jvmConfig, Files.exists(jvmConfig), is(true)); + String content = Files.readString(jvmConfig); + + assertThat(content, containsString("-Dstdout.encoding=UTF-8")); + assertThat(content, containsString("-Dstderr.encoding=UTF-8")); + } }