Logging follow-up: serialize setLogger callers (JVM crash), pin the logging contracts with tests

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

TODO.md

@@ -17,6 +17,26 @@ 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 — `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.
+
 ### Atmosphere coding agent (`llama-atmosphere-agent/`) — follow-ups
 
 The headless loop is verified, including the model-backed CI job (run 35600558852: tool call

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"));
+    }
 }