Repository navigation
Calvin: a participant's stage refusal is not logged on the node — an aborted commit cannot be traced to its cause from the server side #425
Description
Version / build tested against
origin/main @ d1e957217 (debug build, nodedb 0.7.0-dev, in-process test server, RUST_LOG=trace).
Deployment mode
Origin — single node (local)
Engine(s) involved
pgwire, Document (the Calvin transaction path)
Summary
When a Calvin participant refuses its slice of a staged transaction, calvin_stage_refusal (nodedb/src/data/executor/handlers/control/calvin/shared.rs) turns the error into a vote and a response. Nothing logs the error. The response is the only carrier: it becomes the abort vote's refusal, travels to the coordinator, and the coordinator returns it to the client. Since #422 the coordinator's client sees it. In a cluster every replica of the participant vShard stages the same slice and raises the same refusal. No node logs it, and only the coordinator's client receives it. A client that discards the error text, such as a pooled connection or an ORM that retries on the error class, leaves none either.
The log of one failing COMMIT on main, at RUST_LOG=trace, has 4,645 lines. It has no WARN or ERROR line about the commit. DEBUG shows the stage starting on two vShards, discarding staged commit for both, and a completion ack. No line says which vShard refused or why. The error text appears once, in the client's reply.
Before #422 the client saw only SQLSTATE 40000 and "a participant vShard returned an error before any read-set was validated; retry". That is a retry class for an error that is deterministic, and the log was as silent. It hid the cause of #424 until a build that logged the participant's error showed it.
Excerpt, counts per level and the capture method: https://github.com/EnRaiha/nodedb-fusion-evidence
Steps to reproduce
Any stage refusal reproduces it. Defect A of #424 is the trigger on main today:
CREATE COLLECTION g;
UPSERT INTO g { id: 'd0', title: 't0' };
UPSERT INTO g { id: 'd1', title: 't1' };
UPSERT INTO g { id: 'd2', title: 't2' };
UPSERT INTO g { id: 'd3', title: 't3' };
GRAPH INSERT EDGE IN 'g' FROM 'd0' TO 'd1' TYPE 'l';
BEGIN;
DELETE FROM g WHERE id = 'd3';
COMMIT;The client receives the refusal. Search the server log for the same text:
ERROR: internal error: calvin bulk predicate write reached overlay staging without ollp_predicted_surrogates for collection 'g'; a Calvin bulk plan must be recon-injected before dispatch (SQLSTATE XX000)
No log line contains ollp_predicted_surrogates.
The in-process test server installs a subscriber only when a test calls nodedb_test_support::test_tracing::init() and RUST_LOG is set. The capture adds that call to the failing test. The command is in the evidence repository.
Expected behavior
One log line for each refusal, under a stable target, with the request id, the vShard, the vote and the error code.
Actual behavior
No line. The error exists only in the response.
What actually happened? (check all that are true)
- Acknowledged/committed data was lost, corrupted, or silently wrong
- The server crashed, hung, or failed to start
- A security or isolation boundary was crossed
- Core functionality is broken with no acceptable workaround
- A workaround exists (rewrite the query, avoid one path, etc.)
The workaround is the client's error text, which reaches the coordinator's client since #422.
Proposed severity
SEV-3 — Medium: feature wrong, but operational and a workaround exists. No data is affected. The gap is diagnosability.
Reproducibility
Always — every attempt
Last known-good version / commit (if a regression)
Unknown. Not a regression as far as checked.
Environment & logs
Linux x86_64, debug build through cargo test (in-process server, trust mode, fresh data directory, RUST_LOG=trace). Log excerpt and counts are in the evidence repository.
Proposed change
Every stage failure reaches calvin_stage_refusal through calvin_stage_failure, so one line there covers all refusals:
pub(super) fn calvin_stage_refusal(&self, task: &ExecutionTask, error: ErrorCode) -> Response {
let vote = StageVote::of_stage_error(&error);
+ tracing::warn!(
+ target: "nodedb::txn",
+ request_id = ?task.request.request_id,
+ vshard = ?task.request.vshard_id,
+ vote = ?vote,
+ error = ?error,
+ "calvin stage refused"
+ );This is written against the same function on d1e957217 and is not built there. An earlier head carried the same line, and it is how the cause of #424 was found. Some refusals are client errors, such as a NOT NULL violation, so the level is for the maintainers to set. A PR is available on request.
Before submitting
- I searched existing issues and this is not a duplicate. Related: Calvin infra aborts are reported to clients as serialization conflicts #266 (closed, it maps the abort reason, not the node log), feat(array): SQL relations, bulk load, region aggregates, narrow types and SRIDs; fix SQL output, redaction, audit and Calvin refusals #422 (carries the refusal to the client) and Calvin commit refuses a predicate UPDATE or DELETE with XX000, and GRAPH RAG FUSION names a hit in no edge by its surrogate — transaction blocks and trigger bodies fail, fusion rows do not join to documents #424 (the defect this hid).
- I reproduced this on a current
mainbuild (d1e957217), not a stale local branch. - This is not a security vulnerability (those go to a private advisory).
Update 2026-10-19: lines added in PR #426
The PR logs three events on the node, none of which logged before:
- a refused stage, at the scheduler's vote cast: vShard, epoch, position and the refusal text. It also covers a degraded core's rejection;
- a global ABORT verdict that is not a serialization conflict or prediction drift, at the coordinator;
- a collection that no longer holds its planned incarnation.
The refusal text can include a key value, as the client's error text does. Echo sites (the verdict resume, the protocol adapters, the install reply) are not logged, to avoid duplicates. A fuller list of the silent sites is in the PR discussion.
Activity