diff --git a/CHANGELOG.md b/CHANGELOG.md index 5289a3de..863aaf60 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,7 +9,33 @@ from version 5.0.0 onward. Pre-fork releases (`1.x`–`4.2.0`) were authored by ## [Unreleased] +### Fixed +- **`LlamaModel.setLogger` was silently overridden by every model load, and never saw the server's own + log lines.** llama.cpp's `common_init()` — run on each load — re-points `llama_log_set()` at its own + default callback, so a logger set *before* `new LlamaModel(…)` (the natural order) stopped receiving + anything; and the `srv …` / `slot …` lines (per-request timings, slot state) are written by the server + macros straight into `common_log`, which `llama_log_set()` never carried, so they went to stderr no + matter what Java configured. The logger is now a sink on `common_log` itself + (`patches/0014-common-log-callback-sink.patch`, `common_log_set_callback`): it survives loads, it + receives every line — the server's and llama/ggml's — and it replaces the console output instead of + duplicating it (a `setLogFile` file keeps being written). Messages are delivered from llama.cpp's log + worker thread; replacing or removing the logger flushes what is queued to the previous callback first, + so `setLogger(format, null)` is a synchronous drain. Behaviour change to know: the verbosity threshold + now applies before the callback (as on the console), so llama/ggml INFO lines reach the logger only + from `setLogVerbosity(4)` on. `LlamaModelTest#testLogText/testLogJSON` are re-enabled (they were + `@Disabled` because of exactly this), `#testLoggerSetBeforeLoadSurvivesTheLoad` pins the ordering, and + the model-free `LlamaLoggerTest` plus six C++ tests guard the sink on every platform. +- The `setLogger` Javadoc and the README "Logging" section claimed JSON to stdout as the default; the + default is llama.cpp's text format on stderr. `enableLogPrefix()` / `enableLogTimestamps()` are + documented as the no-ops they are (`common_init()` forces both on), `setLogFile` as additive. + ### Added +- **`llama-atmosphere-agent`: `--log-verbosity ` (default `2`) and `--verbose`** for the in-process + `--model` mode. llama.cpp's per-request INFO lines go to stderr, the console the streamed answer is + printed to, and interleaved with it; the agent now loads the model with warnings-and-errors only. A + `.mvn/jvm.config` pins `-Dstdout.encoding=UTF-8 -Dstderr.encoding=UTF-8` for the `mvn exec:java` + JVM, because on Windows `common_init()` switches the console to UTF-8 after the JVM fixed its stdout + encoding from the old code page (umlauts/emoji in answers rendered as `�`/`?`). - **`llama-atmosphere-agent/` — a local, offline JVM coding agent** (Claude Code / OpenCode reduced to the essentials) that drives [Atmosphere](https://github.com/Atmosphere/atmosphere)'s built-in OpenAI-compatible agent runtime **headless** (no Spring Boot, no servlet container) against this diff --git a/CLAUDE.md b/CLAUDE.md index 62148c82..87a099d2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -756,6 +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.** | **`0011` was dropped at the b11069 bump.** Upstream merged [ggml-org/llama.cpp#29161](https://github.com/ggml-org/llama.cpp/pull/29161) @@ -1614,6 +1615,7 @@ ctest --test-dir build --output-on-failure -R "ResultsToJson" | `src/test/cpp/test_server.cpp` | 206 | Upstream result types: `server_slot_stats` (the `timings` JSON payload; replaced `result_timings` in b10408), `task_params::to_json()` (incl. `dry_sequence_breakers`, `preserved_tokens`, `timings_per_token`), `completion_token_output`, `server_task_result_cmpl_partial` (non-oaicompat + `to_json_oaicompat` + logprobs + `to_json_oaicompat_chat` + `to_json_anthropic` + dispatcher), `server_task_result_cmpl_final` (non-oaicompat + `to_json_oaicompat` + `to_json_oaicompat_chat` + `to_json_oaicompat_chat_stream` + `to_json_anthropic` + `to_json_anthropic_stream` + tool_calls + dispatcher), `server_task_result_embd`, `server_task_result_rerank`, `server_task_result_metrics` (`to_metrics()` = the `/metrics` Prometheus exposition text; its `to_json()` has been unused since b10519 and returns `json{}` = JSON null), `server_task_result_slots` (`to_json()` = the `/slots` array, fed by the b10519 `SERVER_TASK_TYPE_SLOT_GET` task), `server_task_result_slot_save_load`, `server_task_result_slot_erase`, `server_task_result_apply_lora`, `server_task_result_get_lora`, `server_task_result_error`, `format_error_response`, `server_task::need_sampling()`, `server_task::n_tokens()`, `server_schema::eval_llama_cmpl_schema()` (parsing pipeline + grammar routing + error paths + per-request `dry_*` and `sse_ping_interval` field round-trips incl. hard-limit + server-default inheritance), `response_fields` projection | | `src/test/cpp/test_json_helpers.cpp` | 63 | All functions in `json_helpers.hpp`: `get_result_error_message`, `results_to_json`, `rerank_results_to_json` (incl. missing/out-of-range `index` rejection), `parse_encoding_format`, `extract_embedding_prompt`, `is_infill_request`, `parse_slot_prompt_similarity`, `parse_positive_int_config`, `wrap_stream_chunk`, `server_metrics_to_json` | | `src/test/cpp/test_log_helpers.cpp` | 13 | All functions in `log_helpers.hpp`: `log_level_name`, `format_log_as_json` | +| `src/test/cpp/test_common_log_callback.cpp` | 6 | **The runnable guard for `patches/0014`**: `common_log_set_callback()` on a private `common_log_init()` instance (never `common_log_main()`, so the process-wide logger the other tests print through is untouched) — delivery of level + bare text, no prefix/timestamp even when both are on (what `common_init()` does), clearing stops delivery, a swap drains queued entries to the *previous* sink (the property behind `LlamaModel.setLogger(format, null)` being a synchronous flush), a `--log-file` keeps being written alongside the sink, and every `ggml_log_level` passes through unchanged. The Java half (`LlamaLoggerTest`, model-free) proves the JNI trampoline on top of it. | | `src/test/cpp/test_jni_helpers.cpp` | 70 | All functions in `jni_helpers.hpp` using a zero-filled `JNINativeInterface_` mock (incl. the `utf8_to_jstring_impl` byte-array string path: emoji byte-preservation, truncated-UTF-8 replace-not-throw). Seven of them pin `jni_guard_impl` — the JNI exception boundary every `Java_*` entry point runs inside — including the `catch (...)` arm that is the only backstop for a non-`std::exception` type, and its two refusals (never `ThrowNew` over a pending Java exception, never with a null class). | | `src/test/cpp/test_tts_wav.cpp` | 2 | The in-memory WAV writer `pcm_to_wav16_bytes` in `tts_wav.hpp` (WAV header/payload + little-endian clamping) — our own code, not upstream. The Qwen3-TTS pipeline it pairs with (`mtmd_helper::gen_audio`) is entirely upstream-owned (no project-side DSP to unit-test here). The load path is additionally covered by `test_tts_params.cpp` (3 tests over `tts_params.hpp`'s `build_tts_params`, plus 2 pinning the upstream `-1` default it depends on), which pins the CPU-thread resolution whose absence used to crash the JVM on every platform — see the `TODO.md` entry for the mechanism. End-to-end coverage is `TtsIntegrationTest`, which is model-gated. | | `src/test/cpp/test_tts_params.cpp` | 13 | The **three** builders every hand-assembled `common_params` goes through: `build_tts_params` (`tts_params.hpp`), `build_train_params` (`train_params.hpp`) and the shared `jllama::resolve_cpu_params` (`cpu_params.hpp`). Each builder is guarded separately on purpose — testing the resolver alone does **not** cover its call sites, because `train_engine.cpp` is compiled into `jllama` only, never into `jllama_test`, and `LlamaTrainerIntegrationTest` is gated on `net.ladenthin.llama.train.model`, which no CI job sets. Without these the JVM-abort bug could regress in the trainer on every platform, unseen. | @@ -1621,7 +1623,7 @@ ctest --test-dir build --output-on-failure -R "ResultsToJson" | `src/test/cpp/test_model_flags.cpp` | 4 | **The contract between the Java CLI-flag registries and llama.cpp's server argument parser.** CMake reads `ModelFlag.java` + `ModelOption.java` (`cmake/extract-java-wire-names.cmake` → a generated header of `{name, contract}` pairs), and this file asserts every `SERVER_PARSER` name is in `common_params_parser_init(params, LLAMA_EXAMPLE_SERVER).options`. It exists because **no Java test can catch this class**: `ModelFlagTest`/`ModelParametersExtendedTest` pin the *string mapping* (`hasKey("--mlock")`), never that llama.cpp still accepts the string, so they stay green forever while the flag is dead — and `common_params_parse` treats an unregistered option as a hard error, so the affected builder method makes the model **unloadable**, not merely ineffective. **A grep over `arg.cpp` is not a substitute**: `--grp-attn-n`/`-w` are present there at every pinned tag but `set_examples()`-scoped to `LLAMA_EXAMPLE_COMPLETION`/`PASSKEY`, so the server parser rejects them exactly like a deleted flag — only the real option table sees that. `--vocab-only` is the one exemption, and it declares itself `CliContract.PROJECT_PSEUDO` on its own constant rather than appearing in a list inside this file; the test asserts such a name is **still unknown** to the parser (an exemption upstream later registers would be hiding a real check) and that the exempt set is non-empty. | | `src/test/cpp/test_wire_contracts.cpp` | 6 | **The same contract for the two quieter surfaces.** `RequestField` against `server_schema::make_llama_cmpl_schema(...)` (5 tests) and `TrainingField` against `jllama_train::config_keys()` (1 test). Both receivers *silently ignore* an unknown key — the schema skips it, `train_engine.cpp` reads with `j.value(key, default)` and falls back — so a dead field produces no error anywhere and every string-mapping test keeps passing. `OAI_LAYER`-declared keys (consumed by `oaicompat_*_params_parse` before the schema) are exempt from the schema check, and are checked **both** ways: still unknown to the schema (the inverted check), and read by at least one upstream reader-shaped site (the configure-time sweep — this is what caught `chat_template`, a key a public builder wrote and nothing read). See [`docs/history/parameter-wire-surface.md`](docs/history/parameter-wire-surface.md). | -**Current total: 552 tests (all passing).** +**Current total: 558 tests (all passing).** #### Upstream source location (in CMake build tree) @@ -2192,7 +2194,12 @@ lines: `AiConfig.configure` → `BuiltInAgentRuntime` → `AgentExecutionContext `WorkspaceAgentFileSystem` via `injectables()`), `ShellTool` (opt-in `run_command`, `sh -c` / `cmd /c` in the workspace, timeout kills the process tree, output tail-truncated), `LocalAgent` (`--base-url` = external server, `--model` = in-process `LlamaModel` + loopback `OpenAiCompatServer` -with `enableJinja()`, one-shot `--prompt` or a `you>` REPL with `/clear` `/exit`). Spotless (palantir) +with `enableJinja()` and `setLogVerbosity(2)` by default — llama.cpp logs to **stderr**, the console the +streamed answer shares, so the per-request `slot …` INFO lines would interleave with it; `--log-verbosity ` +/ `--verbose` override — one-shot `--prompt` or a `you>` REPL with `/clear` `/exit`). `.mvn/jvm.config` +pins `-Dstdout.encoding=UTF-8 -Dstderr.encoding=UTF-8` for the `mvn exec:java` JVM: on Windows, +`common_init()` switches the console to UTF-8 (`SetConsoleOutputCP(CP_UTF8)`) after the JVM fixed its +stdout encoding from the old code page, which turned umlauts/emoji in answers into `�`/`?`. Spotless (palantir) is configured in its own pom; the model-free CI job runs `spotless:check`. **Version bump note.** The pom's `llama.version` property is the **release** version, not the diff --git a/README.md b/README.md index aafa47cd..59b2b2ec 100644 --- a/README.md +++ b/README.md @@ -1146,21 +1146,28 @@ app already uses. The pattern is verified end-to-end by ### Logging -Per default, logs are written to stdout. -This can be intercepted via the static method `LlamaModel.setLogger(LogFormat, BiConsumer)`. -There is text- and JSON-based logging. The default is JSON. -Note, that text-based logging will include additional output of the GGML backend, while JSON-based logging -only provides request logs (while still writing GGML messages to stdout). -To only change the log format while still writing to stdout, `null` can be passed for the callback. -Logging can be disabled by passing an empty callback. +Per default, llama.cpp writes its log as text to **stderr** (`0.00.035.060 I slot …` once a model is +loaded): the server's own `srv …` / `slot …` lines and, from verbosity 4 on, the llama/ggml lines. +All of it can be intercepted via the static method +`LlamaModel.setLogger(LogFormat, BiConsumer)`: with a callback set, every line goes +to the callback instead of the console (a `setLogFile` file keeps receiving them). The callback +survives model loads, so set it before `new LlamaModel(…)` to capture the loading lines too. +`LogFormat.TEXT` hands over the bare message, `LogFormat.JSON` one JSON object per line. Passing +`null` as the callback restores the console output (always llama.cpp's own text format; the format +argument only matters with a callback). Logging can be disabled by passing an empty callback. +Messages arrive asynchronously from llama.cpp's log worker thread; replacing or removing the logger +flushes what is queued to the previous callback first. The verbosity threshold +(`ModelParameters.setLogVerbosity(int)`, llama.cpp's `-lv`: 1 errors, 2 warnings, 3 info, 4 trace, +5 debug) applies before the callback: `2` keeps warnings and errors and silences the per-request +INFO lines, which is what a console application sharing the terminal with its own output wants. ```java // Re-direct log messages however you like (e.g. to a logging library) LlamaModel.setLogger(LogFormat.TEXT, (level, message) -> System.out.println(level.name() + ": " + message)); -// Log to stdout, but change the format +// Back to llama.cpp's own console output (stderr) LlamaModel.setLogger(LogFormat.TEXT, null); // Disable logging by passing a no-op -LlamaModel.setLogger(null, (level, message) -> {}); +LlamaModel.setLogger(LogFormat.TEXT, (level, message) -> {}); ``` The `LogLevel` enum values passed to the callback correspond to the native llama.cpp log levels: diff --git a/TODO.md b/TODO.md index 5adbef0f..843507c5 100644 --- a/TODO.md +++ b/TODO.md @@ -171,10 +171,10 @@ These are JNI plumbing items for upstream API additions. Policy: add only after - **`--log-jsonl` / `--no-log-jsonl`** (a positive/negative flag pair, so it would fit `ModelFlag` directly). The only one of the three with real consumer value, but it is **not a free addition**: it flips `common_log_set_jsonl(common_log_main(), …)`, i.e. the process-wide llama.cpp logger, - whose output for this library goes through the JNI log callback. The project already has its own - JSON logging at the Java level — the `args.LogFormat` enum plus `log_helpers.hpp`'s - `format_log_as_json` — so the two would overlap and could contradict each other on the same - stream. Deciding which layer owns the format is a **feature decision**, not a correctness fix, + whose console output (and, since `patches/0014`, the sink `LlamaModel.setLogger` hooks) it would + reformat. The project already has its own JSON logging at the Java level — the `args.LogFormat` + enum plus `log_helpers.hpp`'s `format_log_as_json` — so the two would overlap and could contradict + each other on the same stream. Deciding which layer owns the format is a **feature decision**, not a correctness fix, and needs its own change with its own tests. - **`--spec-synth-len` and `--spec-synth-rates`** — a documented non-goal, not deferred work. The reasoning lives in its own entry below (**"deliberately NOT exposed, and this should stay that diff --git a/llama-atmosphere-agent/.mvn/jvm.config b/llama-atmosphere-agent/.mvn/jvm.config new file mode 100644 index 00000000..3540ddba --- /dev/null +++ b/llama-atmosphere-agent/.mvn/jvm.config @@ -0,0 +1,2 @@ +-Dstdout.encoding=UTF-8 +-Dstderr.encoding=UTF-8 diff --git a/llama-atmosphere-agent/README.md b/llama-atmosphere-agent/README.md index 126fb257..f2f23be2 100644 --- a/llama-atmosphere-agent/README.md +++ b/llama-atmosphere-agent/README.md @@ -78,6 +78,7 @@ irrelevant: inference stays in the running server, the agent's JVM loads no mode | `--base-url ` | OpenAI-compatible base URL of a running server | — | | `--model ` | load this GGUF in-process instead | — | | `--ngl ` / `--ctx-size ` | GPU layers / context size for `--model` | `0` / `8192` | +| `--log-verbosity ` / `--verbose` | llama.cpp log threshold for `--model` (1 errors, 2 warnings, 3 info, 4 trace, 5 debug) / log everything | `2` / off | | `--workspace ` | directory the file tools (and `run_command`) are confined to | cwd | | `--allow-shell` | register `run_command` | off | | `--system ` | replace the default system prompt | built-in | @@ -89,6 +90,19 @@ irrelevant: inference stays in the running server, the agent's JVM loads no mode Exactly one of `--base-url` / `--model` is required. Exit code 0 = turn completed, 1 = the turn errored, 2 = usage error. Set `-Dorg.slf4j.simpleLogger.defaultLogLevel=debug` to see every request. +**Console output with `--model`.** llama.cpp writes its own log (`slot …`, `srv …`, model loading) +to **stderr**, the same console the streamed answer goes to on stdout, so at llama.cpp's default +threshold (INFO) the per-request timing lines land in the middle of the answer. The agent therefore +loads the in-process model with `--log-verbosity 2` (warnings and errors only); `--log-verbosity 3` +brings the INFO lines back and `--verbose` logs everything. With `--base-url` the server is a separate +process and keeps its own log settings (`-lv` on `llama-server` / `NativeServer`). Two things stay +true whatever the threshold: the agent's own status lines (`Loading …`, `Endpoint …`) also go to +stderr, and `2> llama.log` therefore hides both. On Windows, loading a model switches the console to +UTF-8 (llama.cpp calls `SetConsoleOutputCP(CP_UTF8)`), while the JVM keeps encoding stdout in the +code page it saw at startup, so umlauts and emoji in the answer would turn into `�` / `?`; the +project's `.mvn/jvm.config` pins `-Dstdout.encoding=UTF-8 -Dstderr.encoding=UTF-8` for the `mvn` +JVM so both sides agree. + Pick a **tool-capable instruct model** (Qwen2.5/Qwen3-Instruct, Llama-3.x-Instruct, Mistral, Hermes, …). Quality of the loop is the model's: a 1.5B model calls one tool and reads its result, a 7B–32B model does multi-step edit/build/test work. diff --git a/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/AgentOptions.java b/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/AgentOptions.java index fad23854..95647980 100644 --- a/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/AgentOptions.java +++ b/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/AgentOptions.java @@ -37,10 +37,21 @@ public final class AgentOptions { /** Context size for the in-process model ({@code --model}). */ public static final int DEFAULT_CTX_SIZE = 8192; + /** + * Log verbosity threshold of the in-process model ({@code --model}): llama.cpp's {@code -lv} + * scale, {@code 0} output only, {@code 1} errors, {@code 2} warnings, {@code 3} info, {@code 4} + * trace, {@code 5} debug. The default keeps warnings and errors but drops the per-request + * {@code slot …} / {@code srv …} INFO lines, which otherwise interleave with the streamed answer + * on the console (llama.cpp writes them to stderr). + */ + public static final int DEFAULT_LOG_VERBOSITY = 2; + private final @Nullable String baseUrl; private final @Nullable String modelPath; private final int gpuLayers; private final int ctxSize; + private final int logVerbosity; + private final boolean verbose; private final String apiKey; private final String modelId; private final Path workspace; @@ -57,6 +68,8 @@ private AgentOptions(Builder b) { this.modelPath = b.modelPath; this.gpuLayers = b.gpuLayers; this.ctxSize = b.ctxSize; + this.logVerbosity = b.logVerbosity; + this.verbose = b.verbose; this.apiKey = b.apiKey; this.modelId = b.modelId; this.workspace = b.workspace; @@ -88,6 +101,8 @@ public static AgentOptions parse(String[] args) { case "--model" -> b.modelPath = value(args, ++i, a); case "--ngl", "--gpu-layers" -> b.gpuLayers = intValue(args, ++i, a); case "--ctx-size" -> b.ctxSize = intValue(args, ++i, a); + case "--log-verbosity" -> b.logVerbosity = intValue(args, ++i, a); + case "--verbose", "-v" -> b.verbose = true; case "--api-key" -> b.apiKey = value(args, ++i, a); case "--model-id" -> b.modelId = value(args, ++i, a); case "--workspace" -> @@ -146,6 +161,9 @@ public static String usage() { " --model load this GGUF in-process and serve it to the agent", " --ngl GPU layers for --model (default 0 = CPU only)", " --ctx-size context size for --model (default " + DEFAULT_CTX_SIZE + ")", + " --log-verbosity llama.cpp log threshold for --model: 1 errors, 2 warnings,", + " 3 info, 4 trace, 5 debug (default " + DEFAULT_LOG_VERBOSITY + ")", + " --verbose, -v log everything for --model (same as llama-server -v)", "", "Agent:", " --workspace directory the file tools are confined to (default: cwd)", @@ -196,6 +214,24 @@ public int getCtxSize() { return ctxSize; } + /** + * Log verbosity threshold for the in-process model. + * + * @return the {@code -lv} threshold; ignored when {@link #isVerbose()} is set + */ + public int getLogVerbosity() { + return logVerbosity; + } + + /** + * Whether {@code --verbose} was given. + * + * @return {@code true} to log every message of the in-process model + */ + public boolean isVerbose() { + return verbose; + } + /** * Bearer token. * @@ -289,7 +325,8 @@ public boolean isHelp() { @Override public String toString() { return "AgentOptions{baseUrl=" + baseUrl + ", modelPath=" + modelPath + ", gpuLayers=" + gpuLayers - + ", ctxSize=" + ctxSize + ", modelId=" + modelId + ", workspace=" + workspace + + ", ctxSize=" + ctxSize + ", logVerbosity=" + (verbose ? "verbose" : logVerbosity) + + ", modelId=" + modelId + ", workspace=" + workspace + ", allowShell=" + allowShell + ", temperature=" + temperature + ", maxTokens=" + maxTokens + ", maxToolRounds=" + maxToolRounds + ", prompt=" + (prompt == null ? "" : "") + "}"; @@ -304,6 +341,8 @@ private static final class Builder { int gpuLayers = 0; int ctxSize = DEFAULT_CTX_SIZE; + int logVerbosity = DEFAULT_LOG_VERBOSITY; + boolean verbose; String apiKey = DEFAULT_API_KEY; String modelId = DEFAULT_MODEL_ID; Path workspace = Paths.get("").toAbsolutePath().normalize(); diff --git a/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/LocalAgent.java b/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/LocalAgent.java index c23de408..53cb2c14 100644 --- a/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/LocalAgent.java +++ b/llama-atmosphere-agent/src/main/java/net/ladenthin/llama/atmosphere/LocalAgent.java @@ -179,7 +179,16 @@ private static boolean turn( return finished && session.failure() == null; } - private static ModelParameters modelParameters(AgentOptions options) { + /** + * The native parameters for {@code --model}. + * + *

Visible for tests: the log threshold is the one knob whose effect is only observable on a + * console, so the test pins the flags that leave here instead. + * + * @param options the parsed options + * @return the parameters the in-process {@link LlamaModel} is loaded with + */ + static ModelParameters modelParameters(AgentOptions options) { ModelParameters parameters = new ModelParameters() .setModel(options.getModelPath()) .setCtxSize(options.getCtxSize()) @@ -187,6 +196,13 @@ private static ModelParameters modelParameters(AgentOptions options) { .setFit(false) // Jinja rendering is what lets the native parser apply the model's tool-call template. .enableJinja(); + // llama.cpp logs to stderr, which shares the console with the streamed answer on stdout; the + // default threshold keeps warnings and errors and drops the per-request INFO lines. + if (options.isVerbose()) { + parameters.setVerbose(); + } else { + parameters.setLogVerbosity(options.getLogVerbosity()); + } if (options.getGpuLayers() == 0) { parameters.setDevices("none"); } diff --git a/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/AgentOptionsTest.java b/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/AgentOptionsTest.java index d933020c..6be50bf3 100644 --- a/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/AgentOptionsTest.java +++ b/llama-atmosphere-agent/src/test/java/net/ladenthin/llama/atmosphere/AgentOptionsTest.java @@ -28,10 +28,37 @@ void baseUrlModeWithDefaults() { assertThat(options.getTemperature(), is(AgentOptions.DEFAULT_TEMPERATURE)); assertThat(options.getMaxTokens(), is(AgentOptions.DEFAULT_MAX_TOKENS)); assertThat(options.getMaxToolRounds(), is(AgentOptions.DEFAULT_MAX_TOOL_ROUNDS)); + assertThat(options.getLogVerbosity(), is(AgentOptions.DEFAULT_LOG_VERBOSITY)); + assertThat(options.isVerbose(), is(false)); assertThat(options.getPrompt(), is(nullValue())); assertThat(options.isHelp(), is(false)); } + @Test + void logVerbosityIsAnIntegerThreshold() { + AgentOptions options = AgentOptions.parse(new String[] {"--model", "m.gguf", "--log-verbosity", "4"}); + + assertThat(options.getLogVerbosity(), is(4)); + assertThat(options.isVerbose(), is(false)); + assertThat( + assertThrows( + IllegalArgumentException.class, + () -> AgentOptions.parse(new String[] {"--model", "m.gguf", "--log-verbosity", "loud"})) + .getMessage(), + containsString("--log-verbosity")); + } + + @Test + void verboseIsAFlagWithAShortForm() { + assertThat( + AgentOptions.parse(new String[] {"--model", "m.gguf", "--verbose"}) + .isVerbose(), + is(true)); + assertThat(AgentOptions.parse(new String[] {"--model", "m.gguf", "-v"}).isVerbose(), is(true)); + assertThat(AgentOptions.usage(), containsString("--log-verbosity")); + assertThat(AgentOptions.usage(), containsString("--verbose")); + } + @Test void inProcessModeParsesEveryOption() { AgentOptions options = AgentOptions.parse(new String[] { 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 12d8c470..8c132ef3 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 @@ -6,8 +6,11 @@ import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.containsString; +import static org.hamcrest.Matchers.hasItem; import static org.hamcrest.Matchers.hasSize; import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.lessThan; +import static org.hamcrest.Matchers.not; import com.fasterxml.jackson.databind.JsonNode; import java.io.ByteArrayOutputStream; @@ -145,4 +148,28 @@ void failedTurnExitsNonZero() throws Exception { assertThat(exit, is(1)); } } + + @Test + void inProcessModelIsLoadedWithAQuietLogThresholdByDefault() { + // llama.cpp prints its per-request INFO lines to stderr, the very console the streamed answer + // goes to; the default threshold has to stay below INFO (3) or the two interleave again. + List args = List.of(LocalAgent.modelParameters(AgentOptions.parse(new String[] {"--model", "m.gguf"})) + .toArray()); + + assertThat(args, hasItem("--log-verbosity")); + assertThat( + args.get(args.indexOf("--log-verbosity") + 1), is(String.valueOf(AgentOptions.DEFAULT_LOG_VERBOSITY))); + assertThat(AgentOptions.DEFAULT_LOG_VERBOSITY, lessThan(3)); + assertThat(args, not(hasItem("--verbose"))); + } + + @Test + void verboseReplacesTheThresholdWithLlamaCppsOwnVerboseFlag() { + List args = List.of(LocalAgent.modelParameters( + AgentOptions.parse(new String[] {"--model", "m.gguf", "--log-verbosity", "1", "--verbose"})) + .toArray()); + + assertThat(args, hasItem("--verbose")); + assertThat(args, not(hasItem("--log-verbosity"))); + } } diff --git a/llama/CMakeLists.txt b/llama/CMakeLists.txt index edc703d4..240daa92 100644 --- a/llama/CMakeLists.txt +++ b/llama/CMakeLists.txt @@ -606,6 +606,7 @@ if(BUILD_TESTING) src/test/cpp/test_jni_helpers.cpp src/test/cpp/test_json_helpers.cpp src/test/cpp/test_log_helpers.cpp + src/test/cpp/test_common_log_callback.cpp src/test/cpp/test_tts_wav.cpp src/test/cpp/test_tts_params.cpp src/test/cpp/test_model_split.cpp diff --git a/llama/patches/0014-common-log-callback-sink.patch b/llama/patches/0014-common-log-callback-sink.patch new file mode 100644 index 00000000..f3d77140 --- /dev/null +++ b/llama/patches/0014-common-log-callback-sink.patch @@ -0,0 +1,108 @@ +common: add a callback sink to common_log (common_log_set_callback) + +An embedding host (here: the java-llama.cpp JNI binding) has no way to receive the +lines that common_log prints: llama_log_set() covers only llama/ggml, while the +server's SRV_*/SLT_* macros write straight into common_log and end up on stderr no +matter what the host configured. common_log offers file, colors, prefix, timestamps, +verbosity and JSONL, but no hook. + +This adds common_log_set_callback(log, cb, user_data): while set, the worker thread +hands every entry to the callback instead of printing it (a file set via +common_log_set_file still receives it). The callback gets the formatted message +without prefix/timestamp/colors and has the ggml_log_callback signature, so one +function can serve both llama_log_set() and this sink. Swapping the callback pauses +the worker first, so entries already queued reach the previous sink. + +Upstream-submittable ("common : add a callback sink to common_log for embedding +hosts"); not yet filed. Guarded by src/test/cpp/test_common_log_callback.cpp. + +diff --git a/common/log.cpp b/common/log.cpp +index 0a9a4eb..8c8ed23 100644 +--- a/common/log.cpp ++++ b/common/log.cpp +@@ -176,6 +176,9 @@ struct common_log { + running = false; + t_start = t_us(); + ++ callback = nullptr; ++ callback_user_data = nullptr; ++ + queue.resize(capacity, common_log_entry(256)); + head = 0; + tail = 0; +@@ -198,6 +201,9 @@ private: + + FILE * file; + ++ common_log_callback callback; ++ void * callback_user_data; ++ + bool prefix; + bool timestamps; + bool running; +@@ -212,7 +218,12 @@ private: + bool print_entry(const common_log_entry & e) const { + if (e.is_end) return true; + +- e.print(); ++ if (callback) { ++ // the sink replaces the console, not the file ++ callback(e.level, e.msg.data(), callback_user_data); ++ } else { ++ e.print(); ++ } + if (file) { + e.print(file); + } +@@ -407,6 +418,17 @@ public: + resume(); + } + ++ void set_callback(common_log_callback cb, void * user_data) { ++ // pause() drains the queue through the current sink before the worker stops, so an entry ++ // logged before the swap never reaches the new callback ++ pause(); ++ ++ callback = cb; ++ callback_user_data = user_data; ++ ++ resume(); ++ } ++ + void set_colors(bool colors) { + pause(); + +@@ -498,6 +520,10 @@ void common_log_set_file(struct common_log * log, const char * file) { + log->set_file(file); + } + ++void common_log_set_callback(struct common_log * log, common_log_callback callback, void * user_data) { ++ log->set_callback(callback, user_data); ++} ++ + void common_log_set_colors(struct common_log * log, log_colors colors) { + if (colors == LOG_COLORS_AUTO) { + log->set_colors(tty_can_use_colors()); +diff --git a/common/log.h b/common/log.h +index e36b094..65a0261 100644 +--- a/common/log.h ++++ b/common/log.h +@@ -97,6 +97,18 @@ void common_log_set_prefix (struct common_log * log, bool prefix); // w + void common_log_set_timestamps(struct common_log * log, bool timestamps); // whether to output timestamps in the prefix + void common_log_flush (struct common_log * log); // flush all pending log messages + ++// a sink for log entries, for hosts that embed llama.cpp (a JNI/FFI binding, a GUI, a service ++// with its own logger): while a callback is set, the worker thread hands every entry to it ++// instead of printing to stdout/stderr; a file set via common_log_set_file() still receives them. ++// ++// `text` is the formatted message only (no prefix, no timestamp, no colors) -- the callback ++// decides how to present it. The signature matches ggml_log_callback, so one function can serve ++// both llama_log_set() and this sink. Entries already queued when the callback changes are ++// delivered to the previous sink first. Pass NULL to restore the default console output. ++typedef void (*common_log_callback)(enum ggml_log_level level, const char * text, void * user_data); ++ ++void common_log_set_callback(struct common_log * log, common_log_callback callback, void * user_data); // not thread-safe ++ + // helper macros for logging + // use these to avoid computing log arguments if the verbosity of the log is higher than the threshold + // diff --git a/llama/src/main/cpp/jllama.cpp b/llama/src/main/cpp/jllama.cpp index 05d873be..ca483944 100644 --- a/llama/src/main/cpp/jllama.cpp +++ b/llama/src/main/cpp/jllama.cpp @@ -607,6 +607,33 @@ JNIEnv *get_jni_env_or_null() noexcept { return env; } +/** + * 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. + */ +JNIEnv *get_jni_env_attaching(bool &attached) noexcept { + attached = false; + JNIEnv *env = nullptr; + if (g_vm == nullptr) { + return nullptr; + } + const jint res = g_vm->GetEnv(reinterpret_cast(&env), JNI_VERSION_1_6); + if (res == JNI_OK) { + return env; + } + if (res == JNI_EDETACHED && g_vm->AttachCurrentThread(reinterpret_cast(&env), nullptr) == JNI_OK) { + attached = true; + return env; + } + return nullptr; +} + bool log_json; std::function log_callback; // Guards the logger globals so concurrent setLogger calls (and the trampoline @@ -849,6 +876,8 @@ JNIEXPORT void JNICALL JNI_OnUnload(JavaVM *vm, void *reserved) try { env->DeleteGlobalRef(*p); } + // Detach the sink first (this drains the queue through it), then drop the ref it calls into. + common_log_set_callback(common_log_main(), nullptr, nullptr); if (o_log_callback != nullptr) { env->DeleteGlobalRef(o_log_callback); } @@ -1517,50 +1546,72 @@ 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 { - // Serialize the whole swap under the logger mutex: first clear the live callback so no NEW - // trampoline invocation can copy a lambda that still references the global ref we are about - // to delete, then DRAIN trampolines already executing a copied callback (g_log_active), then - // delete the old ref, then install the new one. Without the drain, an in-flight trampoline - // could still call into the just-deleted global ref. Note: this makes setLogger block until - // running log callbacks return — do not call setLogger from within a log callback. - std::unique_lock lk(g_log_mutex); - log_callback = nullptr; - g_log_cv.wait(lk, [] { return g_log_active == 0; }); - if (o_log_callback != nullptr) { - env->DeleteGlobalRef(o_log_callback); - o_log_callback = nullptr; - } - - log_json = env->IsSameObject(log_format, o_log_format_json); - - if (jcallback == nullptr) { + // 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(), + // which every model load runs, re-points llama_log_set() at that same default callback + // without touching the sink. So the logger survives the load whichever order the caller + // chose, and it sees the slot/srv lines llama_log_set() never carried. + // + // Step 1, outside the logger mutex: detach the current sink. This pauses common_log's + // worker, which first drains every queued entry through the OLD callback (so a caller that + // sets null gets a synchronous flush) and then joins. The worker needs g_log_mutex to read + // the callback, so holding it here would deadlock the join. + common_log_set_callback(common_log_main(), nullptr, nullptr); + + { + // Step 2: swap the Java-side state. No new trampoline can start now (the sink is off); + // still DRAIN any trampoline that copied the old std::function before that (g_log_active) + // so the old global ref is never used after it is deleted. + std::unique_lock lk(g_log_mutex); log_callback = nullptr; - llama_log_set(nullptr, nullptr); - } else { - o_log_callback = env->NewGlobalRef(jcallback); - // Capture copies of the global ref and method id so the callback never dereferences the - // logger globals at call time (those may be swapped by a concurrent setLogger). - jobject cb_ref = o_log_callback; - log_callback = [cb_ref](enum ggml_log_level level, const char *text, void *user_data) noexcept { - // Logging can fire from internal native threads with no JNIEnv; skip rather than - // throw (an exception here would unwind through llama.cpp's C frames). - JNIEnv *env = get_jni_env_or_null(); - if (env == nullptr || text == nullptr) { - return; - } - // Log lines can embed payload text (prompts, model metadata), so the - // message must cross as standard UTF-8, not Modified UTF-8. - jstring message = utf8_to_jstring(env, text); - if (message == nullptr) { - env->ExceptionClear(); // allocation failed; drop this log line - return; - } - jobject log_level = log_level_to_jobject(level); - env->CallVoidMethod(cb_ref, m_biconsumer_accept, log_level, message); - env->DeleteLocalRef(message); - }; - // Always set the trampoline — it handles JSON formatting internally - llama_log_set(log_callback_trampoline, nullptr); + g_log_cv.wait(lk, [] { return g_log_active == 0; }); + if (o_log_callback != nullptr) { + env->DeleteGlobalRef(o_log_callback); + o_log_callback = nullptr; + } + + log_json = env->IsSameObject(log_format, o_log_format_json); + + if (jcallback != nullptr) { + o_log_callback = env->NewGlobalRef(jcallback); + // Capture copies of the global ref and method id so the callback never dereferences + // the logger globals at call time (those may be swapped by a concurrent setLogger). + jobject cb_ref = o_log_callback; + log_callback = [cb_ref](enum ggml_log_level level, const char *text, void *user_data) noexcept { + // common_log delivers from its own worker thread, which is not attached to the + // JVM; attach for the call and detach again (see get_jni_env_attaching). + bool attached = false; + JNIEnv *env = get_jni_env_attaching(attached); + if (env == nullptr || text == nullptr) { + return; + } + // Log lines can embed payload text (prompts, model metadata), so the + // message must cross as standard UTF-8, not Modified UTF-8. + jstring message = utf8_to_jstring(env, text); + if (message == nullptr) { + env->ExceptionClear(); // allocation failed; drop this log line + } else { + jobject log_level = log_level_to_jobject(level); + env->CallVoidMethod(cb_ref, m_biconsumer_accept, log_level, message); + if (env->ExceptionCheck()) { + env->ExceptionClear(); // a throwing logger must not poison the worker + } + env->DeleteLocalRef(message); + } + if (attached) { + g_vm->DetachCurrentThread(); + } + }; + } + } + + // Step 3: install the sink (the trampoline handles JSON formatting internally) and make sure + // llama/ggml lines feed common_log even before the first model load runs common_init(). + // A null callback leaves the sink detached: common_log prints to the console again. + if (jcallback != nullptr) { + common_log_set_callback(common_log_main(), log_callback_trampoline, nullptr); + llama_log_set(common_log_default_callback, nullptr); } }); } diff --git a/llama/src/main/java/net/ladenthin/llama/LlamaModel.java b/llama/src/main/java/net/ladenthin/llama/LlamaModel.java index d8c28345..4c84e5be 100644 --- a/llama/src/main/java/net/ladenthin/llama/LlamaModel.java +++ b/llama/src/main/java/net/ladenthin/llama/LlamaModel.java @@ -432,14 +432,33 @@ public String decode(int... tokens) { /** * Sets a callback for native llama.cpp log messages. - * Per default, log messages are written in JSON to stdout. Note, that in text mode the callback will be also - * invoked with log messages of the GGML backend, while JSON mode can only access request log messages. - * In JSON mode, GGML messages will still be written to stdout. - * To only change the log format but keep logging to stdout, the given callback can be null. - * To disable logging, pass an empty callback, i.e., (level, msg) {@literal ->} {}. + * + *

Without a callback, llama.cpp prints its log as text to stderr (with a + * {@code 0.00.035.060 I } timestamp-and-level prefix once a model has been loaded). With a + * callback, every line goes to the callback instead of the console: the server's own + * {@code srv …} / {@code slot …} lines as well as the llama/ggml lines (model loading, backend + * setup). A log file set via {@link ModelParameters#setLogFile(String)} keeps receiving them. + * The callback survives model loads whichever order the caller chooses, so the usual + * {@code setLogger(…)} before {@code new LlamaModel(…)} captures the loading lines too. + * + *

The verbosity threshold applies before the callback is reached: at llama.cpp's default + * (INFO, {@code 3}) the callback sees errors, warnings and the server's INFO lines, while the + * llama/ggml INFO lines are only delivered from {@link ModelParameters#setLogVerbosity(int)} + * {@code 4} on, exactly as on the console. + * + *

{@link LogFormat#TEXT} passes the message as is (no prefix, no timestamp); + * {@link LogFormat#JSON} wraps it into one JSON object per call ({@code level}, {@code message}, + * {@code timestamp}). The format only matters together with a callback: passing {@code null} + * as the callback restores the console output, which is always llama.cpp's own text format. + * + *

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 ->} {}. * * @param format the log format to use - * @param callback a method to call for log messages + * @param callback a method to call for log messages, or {@code null} for the console */ public static native void setLogger(LogFormat format, BiConsumer callback); 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 c2446c82..51e9b96c 100644 --- a/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java +++ b/llama/src/main/java/net/ladenthin/llama/parameters/ModelParameters.java @@ -1210,6 +1210,9 @@ public ModelParameters disableLog() { /** * Set the log file path. * + *

The file is written in addition to the console (or the + * {@link net.ladenthin.llama.LlamaModel#setLogger} callback), not instead of it. + * * @param logFile the path to the log file * @return this builder */ @@ -1230,6 +1233,12 @@ public ModelParameters setVerbose() { /** * Set the verbosity threshold (messages with a higher verbosity will be ignored). * + *

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. + * * @param verbosity the verbosity threshold level * @return this builder */ @@ -1240,6 +1249,10 @@ public ModelParameters setLogVerbosity(int verbosity) { /** * Enable prefix in log messages. * + *

Effectively a no-op: llama.cpp's {@code common_init()} enables the prefix and the + * timestamps unconditionally on every model load, after this flag was parsed. Kept because it + * is a valid server flag. + * * @return this builder */ public ModelParameters enableLogPrefix() { @@ -1249,6 +1262,8 @@ public ModelParameters enableLogPrefix() { /** * Enable timestamps in log messages. * + *

Effectively a no-op, for the same reason as {@link #enableLogPrefix()}. + * * @return this builder */ public ModelParameters enableLogTimestamps() { diff --git a/llama/src/test/cpp/test_common_log_callback.cpp b/llama/src/test/cpp/test_common_log_callback.cpp new file mode 100644 index 00000000..08471b13 --- /dev/null +++ b/llama/src/test/cpp/test_common_log_callback.cpp @@ -0,0 +1,172 @@ +// SPDX-FileCopyrightText: 2026 Bernard Ladenthin +// +// SPDX-License-Identifier: MIT + +// Runnable guard for patches/0014-common-log-callback-sink.patch: the common_log_set_callback() +// sink that lets LlamaModel.setLogger receive the server's SRV_*/SLT_* lines (which never pass +// through llama_log_set). Drives a private common_log instance, never common_log_main(), so the +// process-wide logger the other tests print through is untouched. A llama.cpp bump that drops the +// patch fails this file at compile time on every platform instead of silently muting Java logging. + +#include + +#include "log.h" + +#include +#include +#include +#include +#include +#include +#include + +namespace { + +using entries = std::vector>; + +// The sink is a plain function pointer, so the capture goes through user_data. The worker thread +// writes and the test thread reads only after common_log_flush()/common_log_free() joined it, but +// the mutex keeps the recorder honest if a future test reads while the worker is live. +struct recorder { + std::mutex mtx; + entries got; +}; + +void record(ggml_log_level level, const char *text, void *user_data) { + auto *rec = static_cast(user_data); + std::lock_guard lk(rec->mtx); + rec->got.emplace_back(level, text); +} + +entries snapshot(recorder &rec) { + std::lock_guard lk(rec.mtx); + return rec.got; +} + +std::string read_file(const std::string &path) { + std::ifstream in(path); + std::stringstream ss; + ss << in.rdbuf(); + return ss.str(); +} + +std::string temp_log_path(const char *tag) { + return (std::string(testing::TempDir()) + "jllama-common-log-" + tag + ".log"); +} + +} // namespace + +TEST(CommonLogCallback, CallbackReceivesFormattedMessageAndLevel) { + recorder rec; + common_log *log = common_log_init(); + common_log_set_callback(log, record, &rec); + + common_log_add(log, GGML_LOG_LEVEL_INFO, "hello %d\n", 42); + common_log_add(log, GGML_LOG_LEVEL_ERROR, "boom\n"); + common_log_flush(log); + + const entries got = snapshot(rec); + ASSERT_EQ(got.size(), 2u); + EXPECT_EQ(got[0].first, GGML_LOG_LEVEL_INFO); + EXPECT_EQ(got[0].second, "hello 42\n"); + EXPECT_EQ(got[1].first, GGML_LOG_LEVEL_ERROR); + EXPECT_EQ(got[1].second, "boom\n"); + + common_log_free(log); +} + +TEST(CommonLogCallback, TextCarriesNoPrefixOrTimestampEvenWhenEnabled) { + // common_init() turns both on for every model load; the sink must still get the bare message, + // because the Java side formats (or JSON-wraps) it itself. + recorder rec; + common_log *log = common_log_init(); + common_log_set_prefix(log, true); + common_log_set_timestamps(log, true); + common_log_set_callback(log, record, &rec); + + common_log_add(log, GGML_LOG_LEVEL_WARN, "plain\n"); + common_log_flush(log); + + const entries got = snapshot(rec); + ASSERT_EQ(got.size(), 1u); + EXPECT_EQ(got[0].second, "plain\n"); + + common_log_free(log); +} + +TEST(CommonLogCallback, ClearingTheCallbackStopsDelivery) { + recorder rec; + common_log *log = common_log_init(); + common_log_set_callback(log, record, &rec); + common_log_add(log, GGML_LOG_LEVEL_INFO, "seen\n"); + + common_log_set_callback(log, nullptr, nullptr); + common_log_add(log, GGML_LOG_LEVEL_INFO, "unseen\n"); + common_log_flush(log); + + const entries got = snapshot(rec); + ASSERT_EQ(got.size(), 1u); + EXPECT_EQ(got[0].second, "seen\n"); + + common_log_free(log); +} + +TEST(CommonLogCallback, EntriesQueuedBeforeASwapReachThePreviousSink) { + // This is what makes LlamaModel.setLogger(format, null) a synchronous drain: pause() flushes + // through the old sink before the new one is installed. + recorder first; + recorder second; + common_log *log = common_log_init(); + common_log_set_callback(log, record, &first); + common_log_add(log, GGML_LOG_LEVEL_INFO, "before\n"); + + common_log_set_callback(log, record, &second); + common_log_add(log, GGML_LOG_LEVEL_INFO, "after\n"); + common_log_flush(log); + + const entries got_first = snapshot(first); + const entries got_second = snapshot(second); + ASSERT_EQ(got_first.size(), 1u); + EXPECT_EQ(got_first[0].second, "before\n"); + ASSERT_EQ(got_second.size(), 1u); + EXPECT_EQ(got_second[0].second, "after\n"); + + common_log_free(log); +} + +TEST(CommonLogCallback, FileOutputIsKeptWhileTheCallbackIsSet) { + // The sink replaces the console only; --log-file keeps working alongside a Java logger. + const std::string path = temp_log_path("file-kept"); + recorder rec; + common_log *log = common_log_init(); + common_log_set_file(log, path.c_str()); + common_log_set_callback(log, record, &rec); + + common_log_add(log, GGML_LOG_LEVEL_INFO, "to both\n"); + common_log_free(log); // joins the worker and closes the file + + const entries got = snapshot(rec); + ASSERT_EQ(got.size(), 1u); + EXPECT_EQ(got[0].second, "to both\n"); + EXPECT_NE(read_file(path).find("to both"), std::string::npos); + std::remove(path.c_str()); +} + +TEST(CommonLogCallback, LevelsPassThroughUnchanged) { + recorder rec; + common_log *log = common_log_init(); + common_log_set_callback(log, record, &rec); + + common_log_add(log, GGML_LOG_LEVEL_DEBUG, "d\n"); + common_log_add(log, GGML_LOG_LEVEL_NONE, "o\n"); + common_log_add(log, GGML_LOG_LEVEL_CONT, "c\n"); + common_log_flush(log); + + const entries got = snapshot(rec); + ASSERT_EQ(got.size(), 3u); + EXPECT_EQ(got[0].first, GGML_LOG_LEVEL_DEBUG); + EXPECT_EQ(got[1].first, GGML_LOG_LEVEL_NONE); + EXPECT_EQ(got[2].first, GGML_LOG_LEVEL_CONT); + + common_log_free(log); +} diff --git a/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java new file mode 100644 index 00000000..1692942e --- /dev/null +++ b/llama/src/test/java/net/ladenthin/llama/LlamaLoggerTest.java @@ -0,0 +1,162 @@ +// SPDX-FileCopyrightText: 2026 Bernard Ladenthin +// +// SPDX-License-Identifier: MIT + +package net.ladenthin.llama; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.empty; +import static org.hamcrest.Matchers.hasItem; +import static org.hamcrest.Matchers.hasKey; +import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.not; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assumptions.assumeTrue; + +import com.fasterxml.jackson.databind.JsonNode; +import com.fasterxml.jackson.databind.ObjectMapper; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.ArrayList; +import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.stream.Collectors; +import net.ladenthin.llama.args.LogFormat; +import net.ladenthin.llama.exception.LlamaException; +import net.ladenthin.llama.loader.OSInfo; +import net.ladenthin.llama.parameters.ModelParameters; +import net.ladenthin.llama.value.LogLevel; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; + +/** + * Model-free guard for {@link LlamaModel#setLogger}: a logger set before a load keeps + * receiving lines through the load. Every load runs llama.cpp's {@code common_init()}, which + * re-points {@code llama_log_set} at its own default callback, and until patches/0014 that silently + * dropped a previously set Java logger. The logger is now a sink on {@code common_log}, behind that + * default callback, so it sees both the server's own {@code srv …} lines and the llama/ggml lines. + * The load here is made to fail on purpose (a file that is not a GGUF), which needs no model, no GPU + * and no network and still produces an INFO line from the server and an ERROR line from llama. + * Skips cleanly when {@code libjllama} is not on the classpath (pure-Java checkout). + */ +@ClaudeGenerated( + purpose = "Model-free guard that LlamaModel.setLogger survives a model load (common_init re-points " + + "llama_log_set) and receives the server's own srv/slot lines, in both TEXT and JSON mode, " + + "without a GGUF: the load fails on a non-GGUF file and its log lines are asserted.") +class LlamaLoggerTest { + + private static final ObjectMapper MAPPER = new ObjectMapper(); + + @TempDir + Path tempDir; + + private static boolean nativeLibraryOnClasspath() { + String resource = "/net/ladenthin/llama/" + OSInfo.getNativeLibFolderPathForCurrentOS() + "/" + + System.mapLibraryName("jllama"); + return LlamaLoggerTest.class.getResource(resource) != null; + } + + private static final class Line { + private final LogLevel level; + private final String text; + + private Line(LogLevel level, String text) { + this.level = level; + this.text = text; + } + + @Override + public String toString() { + return level + ": " + text.trim(); + } + } + + @AfterEach + void restoreConsoleLogging() { + LlamaModel.setLogger(LogFormat.TEXT, null); + } + + private Path notAGguf() throws IOException { + Path file = tempDir.resolve("not-a-model.gguf"); + Files.write(file, "this is not a GGUF file".getBytes(StandardCharsets.UTF_8)); + return file; + } + + /** Logs through a failing load and drains the queue; the drain is what makes the assertions safe. */ + private List linesOfAFailedLoad(LogFormat format) 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()); + // Removing the logger flushes every queued message to the previous callback before returning. + LlamaModel.setLogger(LogFormat.TEXT, null); + return lines; + } + + @Test + void loggerSetBeforeTheLoadReceivesTheLoadsOwnLines() throws IOException { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + + List lines = linesOfAFailedLoad(LogFormat.TEXT); + + 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")), + is(true)); + assertThat( + "llama's own error line must reach the logger too: " + lines, + lines.stream().map(l -> l.level).collect(Collectors.toList()), + hasItem(LogLevel.ERROR)); + assertThat( + "text mode hands over the bare message, no prefix/timestamp: " + lines, + lines.stream().noneMatch(l -> l.text.matches("^\\d+\\.\\d+\\.\\d+\\.\\d+ [IWED] .*")), + is(true)); + } + + @Test + void jsonModeWrapsEveryLineIntoOneObject() throws IOException { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + + List lines = linesOfAFailedLoad(LogFormat.JSON); + + assertThat("a failed load must log something: " + lines, lines, not(empty())); + for (Line line : lines) { + JsonNode node = MAPPER.readTree(line.text); + assertThat("every line is one JSON object: " + line.text, node.isObject(), is(true)); + assertThat(toMap(node), hasKey("level")); + assertThat(toMap(node), hasKey("message")); + assertThat(toMap(node), hasKey("timestamp")); + } + } + + @Test + void anEmptyCallbackDiscardsWithoutFailingTheLoad() throws IOException { + assumeTrue(nativeLibraryOnClasspath(), "libjllama not on classpath — skipping logger guard"); + LlamaModel.setLogger(LogFormat.TEXT, (level, text) -> {}); + Path file = notAGguf(); + + // The load still fails for its own reason; the muted logger must not change that or hang the drain. + assertThrows( + LlamaException.class, + () -> new LlamaModel( + new ModelParameters().setModel(file.toString()).setDevices("none")) + .close()); + LlamaModel.setLogger(LogFormat.TEXT, null); + } + + private static Map toMap(JsonNode node) { + Map map = new HashMap<>(); + node.fields().forEachRemaining(e -> map.put(e.getKey(), e.getValue())); + return map; + } +} diff --git a/llama/src/test/java/net/ladenthin/llama/LlamaModelTest.java b/llama/src/test/java/net/ladenthin/llama/LlamaModelTest.java index 778b5345..8d45d819 100644 --- a/llama/src/test/java/net/ladenthin/llama/LlamaModelTest.java +++ b/llama/src/test/java/net/ladenthin/llama/LlamaModelTest.java @@ -661,40 +661,96 @@ public void testVocabOnlyCoexistsWithFullModel() { } } - @Disabled + /** + * The logger receives the per-request {@code slot …} / {@code srv …} lines: they are written by + * the server's own macros straight into llama.cpp's {@code common_log}, which {@code llama_log_set} + * never carried, so this used to see nothing at all (the reason both log tests were disabled). + * Delivery is asynchronous from the log worker thread; removing the logger drains the queue. + */ + @Test public void testLogText() { - List messages = new ArrayList<>(); - LlamaModel.setLogger(LogFormat.TEXT, (level, msg) -> messages.add(new LogMessage(level, msg))); + List messages = Collections.synchronizedList(new ArrayList<>()); + try { + LlamaModel.setLogger(LogFormat.TEXT, (level, msg) -> messages.add(new LogMessage(level, msg))); - InferenceParameters params = - new InferenceParameters(prefix).withNPredict(nPredict).withSeed(42); - model.complete(params); + InferenceParameters params = + new InferenceParameters(prefix).withNPredict(nPredict).withSeed(42); + model.complete(params); + } finally { + LlamaModel.setLogger(LogFormat.TEXT, null); + } - assertFalse(messages.isEmpty()); + assertFalse(messages.isEmpty(), "a completion must log at least one line at the default threshold"); Pattern jsonPattern = Pattern.compile("^\\s*[\\[{].*[}\\]]\\s*$"); for (LogMessage message : messages) { assertNotNull(message.level); - assertFalse(jsonPattern.matcher(message.text).matches()); + assertFalse(jsonPattern.matcher(message.text).matches(), "text mode must not wrap: " + message.text); } + assertTrue( + messages.stream().anyMatch(m -> m.text.startsWith("slot ") || m.text.startsWith("srv ")), + "the server's own slot/srv lines must reach the logger, got: " + describe(messages)); } - @Disabled + @Test public void testLogJSON() { - List messages = new ArrayList<>(); - LlamaModel.setLogger(LogFormat.JSON, (level, msg) -> messages.add(new LogMessage(level, msg))); + List messages = Collections.synchronizedList(new ArrayList<>()); + try { + LlamaModel.setLogger(LogFormat.JSON, (level, msg) -> messages.add(new LogMessage(level, msg))); - InferenceParameters params = - new InferenceParameters(prefix).withNPredict(nPredict).withSeed(42); - model.complete(params); + InferenceParameters params = + new InferenceParameters(prefix).withNPredict(nPredict).withSeed(42); + model.complete(params); + } finally { + LlamaModel.setLogger(LogFormat.TEXT, null); + } assertFalse(messages.isEmpty()); - Pattern jsonPattern = Pattern.compile("^\\s*[\\[{].*[}\\]]\\s*$"); + Pattern jsonPattern = Pattern.compile("^\\s*[\\[{].*[}\\]]\\s*$", Pattern.DOTALL); for (LogMessage message : messages) { assertNotNull(message.level); - assertTrue(jsonPattern.matcher(message.text).matches()); + assertTrue(jsonPattern.matcher(message.text).matches(), "JSON mode must wrap: " + message.text); + } + } + + /** + * Every model load runs llama.cpp's {@code common_init()}, which re-points {@code llama_log_set} + * at its default callback. The Java logger is a sink behind that callback (patches/0014), so a + * logger installed before the load keeps receiving lines through and after it. This + * pins the ordering every consumer uses: {@code setLogger(…)} first, {@code new LlamaModel(…)} + * second. A vocab-only load is enough: it runs the same {@code common_init()} and logs the + * {@code srv … loading tokenizer} line at INFO. + */ + @Test + public void testLoggerSetBeforeLoadSurvivesTheLoad() { + List messages = Collections.synchronizedList(new ArrayList<>()); + try { + LlamaModel.setLogger(LogFormat.TEXT, (level, msg) -> messages.add(new LogMessage(level, msg))); + try (LlamaModel vocabModel = new LlamaModel( + new ModelParameters().setModel(TestConstants.MODEL_PATH).setVocabOnly())) { + assertTrue(vocabModel.encode("hello").length > 0); + } + } finally { + LlamaModel.setLogger(LogFormat.TEXT, null); + } + + assertTrue( + messages.stream().anyMatch(m -> m.text.contains("loading tokenizer")), + "the load's own log line must reach a logger set before the load, got: " + describe(messages)); + assertTrue( + messages.stream().allMatch(m -> m.level != null), + "every line carries a level, got: " + describe(messages)); + } + + private static String describe(List messages) { + StringBuilder sb = new StringBuilder(); + synchronized (messages) { + for (LogMessage m : messages) { + sb.append(m.level).append(": ").append(m.text.trim()).append('\n'); + } } + return sb.toString(); } @Disabled