Skip to content

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

Merged
bernardladenthin merged 3 commits into
mainfrom
claude/jolly-noether-jlebto
Sep 21, 2026
Merged

bernardladenthin merged 3 commits into
mainfrom
claude/jolly-noether-jlebto

Conversation

@bernardladenthin

Copy link
Copy Markdown
Owner

Summary

Follow-up to #447 (merged before these three commits landed on the branch; rebased onto main).

  • Fix: concurrent setLogger calls crashed the JVM. The sink swap introduced in Logging: route setLogger through a common_log sink (patch 0014); quiet agent console #447 pauses (joins) and resumes (assigns a fresh std::thread) llama.cpp's log worker. Two unserialized callers raced on that std::thread: one joined it while the other assigned over the still-joinable object, which is std::terminate (terminate called without an active exception, whole JVM gone). The old llama_log_set implementation held g_log_mutex for the whole swap; the sink swap cannot (the join needs that mutex on the worker), so a separate g_set_logger_mutex now serializes callers; the trampoline never takes it, so no deadlock with the join. LlamaLoggerTest#concurrentSetLoggerCallsDoNotRaceOnTheLogWorker (4 threads × 200 swaps) reproduced the crash before the fix and passes after it.
  • Tests pinning the logging contracts, all model-free against the real libjllama: verbosityThresholdIsProcessWideAndEveryLoadSetsIt (-lv 1 hides the server's INFO line, keeps llama's ERROR line; a load without -lv resets the threshold to 3 — common_params_parse ends with common_log_set_verbosity_thold(params.verbosity), default 3, which a review had assumed the other way round), deliveryIsAsynchronousOnTheLogWorkerAndRemovingTheLoggerDrains (never on the caller's thread, always native-attached, setLogger(format, null) returns only after the drain; prints the distinct-Thread count: 13 lines → 13 objects today), and the agent's mavenJvmConfigPinsAUtf8ConsoleForExecJava (.mvn/jvm.config keeps both UTF-8 flags). The srv-line matcher is exact now; the loose contains("loading model") also matched llama's error loading model.
  • Docs: setLogger Javadoc names the second deadlock rule (do not hold a lock the previous callback needs while the drain runs it on the worker); setLogVerbosity Javadoc states the measured every-load reset; the per-line attach/detach of the worker thread is documented as the simple, not the cheapest, choice, with the thread_local-guard optimisation and its caveats filed in TODO.md; CLAUDE.md patch-table row updated accordingly.

Test plan

  • Affected unit / integration tests pass locally — fresh native build in the sandbox: LlamaLoggerTest 6/6 (incl. the race test, which crashed the JVM against the unfixed library), NativeLibraryLoadSmokeTest 4/4, agent LocalAgentTest 6/6 + AgentOptionsTest 8/8; javadoc and spotbugs clean; clang-format 23.1.1 applied.
  • CI is green on this branch
  • Docs / CHANGELOG updated where applicable (CHANGELOG unchanged on purpose: the race never shipped in a release, it was introduced and fixed within the unreleased Logging: route setLogger through a common_log sink (patch 0014); quiet agent console #447 line)

Related issues / PRs

Follow-up to #447. Refs #444 / #445 / #446 (the Atmosphere agent).

Checklist

  • I have read CONTRIBUTING.md and CODE_OF_CONDUCT.md
  • My commits follow Conventional Commits
  • No security-sensitive changes (if there are, I have notified the maintainer privately per SECURITY.md)

🤖 Generated with Claude Code

https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH


Generated by Claude Code

Two concurrent setLogger calls raced on common_log's worker std::thread:
the swap pauses (joins) and resumes (assigns a fresh thread) the worker,
and without serialization one caller joined while the other assigned over
the still-joinable object, which is std::terminate -- the JVM died with
"terminate called without an active exception". The previous llama_log_set
implementation held g_log_mutex for the whole swap; the sink swap cannot
(the join needs that mutex on the worker), so a separate g_set_logger_mutex
now serializes callers. LlamaLoggerTest#concurrentSetLoggerCallsDoNotRace
OnTheLogWorker (4 threads x 200 swaps) reproduced the crash before the fix
and passes after it.

Javadoc: setLogger now names the second deadlock rule (do not hold a lock
the previous callback needs while the drain runs it on the worker);
setLogVerbosity no longer claims "the last model loaded wins" -- a load
without -lv leaves the process-wide threshold untouched. The per-line
attach/detach of the worker thread is documented as the simple, not the
cheapest, choice, with the thread_local-guard optimisation filed in TODO.md.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH
LlamaLoggerTest gains three tests, all against the real libjllama and a
deliberately failing load, no GGUF needed:

- verbosityThresholdIsProcessWideAndEveryLoadSetsIt: -lv 1 hides the
  server's INFO line and keeps llama's ERROR line; a load WITHOUT -lv puts
  the threshold back to 3. That last part corrects the previous commit's
  Javadoc, which followed a review remark claiming such a load leaves the
  threshold untouched -- measured, it does not: common_params_parse ends
  with common_log_set_verbosity_thold(params.verbosity), default 3. The
  Javadoc and CLAUDE.md now say what the test shows.
- deliveryIsAsynchronousOnTheLogWorkerAndRemovingTheLoggerDrains: lines
  never arrive on the caller's thread, always on a native-attached one, and
  setLogger(format, null) returns only after the queue is drained -- the
  facts behind both deadlock rules. It prints the distinct Thread count
  (13 lines -> 13 Thread objects today), recorded in TODO.md for the
  thread_local-guard optimisation.
- The srv-line matcher is exact now ("srv … loading model '"); the loose
  contains("loading model") also matched llama's "error loading model".

LocalAgentTest pins .mvn/jvm.config with -Dstdout.encoding=UTF-8 and
-Dstderr.encoding=UTF-8, so the Windows console fix cannot be dropped
unnoticed.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH
…mit described

The LocalAgentTest addition announced in 8753693 had not been written to
disk (the script that carried it aborted earlier); this is that test.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UVwj2UuMPybiK1bHyG9toH
@bernardladenthin
bernardladenthin merged commit 65abc77 into main Sep 21, 2026
5 of 14 checks passed
@bernardladenthin
bernardladenthin deleted the claude/jolly-noether-jlebto branch September 21, 2026 17:47

This branch had an error being deployed

1 failed deployment
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants