Disable CRDT debug logging in default features — fixes runtime stalls

logging-list/logging-json were in bft-json-crdt's default feature set,
so every production build printed multi-KB debug dumps on every CRDT
op — executed INSIDE the global CRDT_STATE mutex. A stdout write that
stalls while holding that lock blocks every task touching the CRDT
(tick loop, watchers, MCP, RPC), each one pinning an OS worker thread
until the tokio pool is exhausted: liveness heartbeat stops, /health
dies, zero CPU. This is the mechanism behind bug 1170 (two full-sled
freezes on huskies-server, both seconds after a CRDT write burst, the
second insert's dump truncated mid-print in the log).

The features remain available for CRDT debugging via explicit opt-in.

Also fixes a latent race in persist_tx_send_success_emits_no_warn:
it counted [crdt_persist] warns in the process-global log buffer,
which parallel tests also write to; the debug prints had been acting
as an accidental serializer. Now filters for its own story id.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_019fHdm92yjvguPi2LiXfLB9
This commit is contained in:
Timmy
2026-07-15 18:37:47 +01:00
co-authored by Claude Fable 5
parent be0c88c801
commit 6cceec9c26
2 changed files with 25 additions and 15 deletions
+7 -1
View File
@@ -6,8 +6,14 @@ edition = "2021"
[lib]
crate-type = ["lib"]
# The logging-* features print multi-KB debug dumps on every CRDT op — and
# they execute inside the global CRDT state mutex in the server, so a stalled
# stdout write while holding that lock can pin every tokio worker and freeze
# the whole process (bug 1170). They are development tools: opt in explicitly
# with `--features bft-json-crdt/logging-list` when debugging CRDT internals.
# Never enable them in a production build.
[features]
default = ["bft", "logging-list", "logging-json"]
default = ["bft"]
logging-list = ["logging-base"]
logging-json = ["logging-base"]
logging-base = []
+18 -14
View File
@@ -330,23 +330,27 @@ fn persist_tx_send_success_emits_no_warn() {
})
.into();
let before_warns = crate::log_buffer::global()
.get_recent_entries(
1000,
Some("[crdt_persist]"),
Some(&crate::log_buffer::LogLevel::Warn),
)
.len();
// Count only warns mentioning THIS test's story: the log buffer is
// process-global, so parallel tests emit their own [crdt_persist] warns
// and a bare count races (flaked when the logging-list feature removal
// changed test timing).
let count_own_warns = || {
crate::log_buffer::global()
.get_recent_entries(
1000,
Some("[crdt_persist]"),
Some(&crate::log_buffer::LogLevel::Warn),
)
.iter()
.filter(|e| e.message.contains("676_story_happy_path"))
.count()
};
let before_warns = count_own_warns();
apply_and_persist(&mut state, |s| s.crdt.doc.items.insert(ROOT_ID, item_json));
let after_warns = crate::log_buffer::global()
.get_recent_entries(
1000,
Some("[crdt_persist]"),
Some(&crate::log_buffer::LogLevel::Warn),
)
.len();
let after_warns = count_own_warns();
assert_eq!(
after_warns, before_warns,