Skip to content

feat: add take-orders tracing#2566

Open
findolor wants to merge 1 commit intomainfrom
arda/take-orders-tracing
Open

feat: add take-orders tracing#2566
findolor wants to merge 1 commit intomainfrom
arda/take-orders-tracing

Conversation

@findolor
Copy link
Copy Markdown
Collaborator

@findolor findolor commented May 7, 2026

Motivation

Production take-orders failures are hard to diagnose because the existing flow does not expose enough structured context to explain where liquidity disappeared, which orders/vaults were considered, why candidates were rejected, or which order failed preflight simulation.

Solution

Add bounded structured tracing across the take-orders path:

  • Log request parsing, RPC resolution, latest block lookup, approval checks, preflight iterations, and final calldata readiness.
  • Log order fetch source, returned order counts, and bounded order/vault inventory for the requested pair.
  • Log quote batch summaries and quote failures.
  • Log bounded candidate rejection reasons for failed quotes, missing quote data, wrong direction, invalid IO indices, zero/non-positive capacity, and price-cap rejection.
  • Log selected and final take-order legs, with caps and omitted counts to avoid unbounded production log volume.
  • Log preflight simulation failures, removed failing legs/orders, and terminal preflight errors.
  • Truncate provider/revert error strings safely before logging.

Checks

By submitting this for review, I'm confirming I've done the following:

  • made this PR as small as possible
  • unit-tested any new functionality
  • linked any relevant issues or PRs
  • included screenshots (if this involves a front-end change)

Verified locally:

  • cargo fmt --all -- --check
  • nix develop -c cargo check -p rain_orderbook_common
  • nix develop -c cargo clippy -p rain_orderbook_common --all-targets -- -D warnings

Summary by CodeRabbit

  • Chores
    • Improved observability across quoting, order fetching, take-order construction, approval checks, and simulations: added execution timing, richer structured logs, per-source and inventory counts, per-quote/order failure details, and capped verbose rejection logs to aid troubleshooting without changing behavior.

Review Change Stack

@findolor findolor changed the title Add take-orders tracing feat: add take-orders tracing May 7, 2026
@coderabbitai
Copy link
Copy Markdown
Contributor

coderabbitai Bot commented May 7, 2026

Note

Currently processing new changes in this PR. This may take a few minutes, please wait...

⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Pro

Run ID: 0f57a745-2c86-4b0c-b8e4-4d5660604fc4

📥 Commits

Reviewing files that changed from the base of the PR and between 866d259 and 191a997.

📒 Files selected for processing (11)
  • crates/common/src/raindex_client/order_quotes.rs
  • crates/common/src/raindex_client/orders.rs
  • crates/common/src/raindex_client/take_orders/approval.rs
  • crates/common/src/raindex_client/take_orders/mod.rs
  • crates/common/src/raindex_client/take_orders/selection.rs
  • crates/common/src/raindex_client/vaults.rs
  • crates/common/src/take_orders/candidates.rs
  • crates/common/src/take_orders/preflight.rs
  • crates/common/src/take_orders/simulation.rs
  • crates/common/src/utils/mod.rs
  • crates/common/src/utils/timing.rs
 _________________________________________________________________
< I have no memory of this place...but I'll find the bugs anyway. >
 -----------------------------------------------------------------
  \
   \   \
        \ /\
        ( )
      .( o ).
📝 Walkthrough

Walkthrough

Adds structured tracing and timing across the order pipeline: quote batching, order fetching and inventory logs, candidate construction with per-quote stats, price-cap filtering and simulations, orderbook selection, preflight iteration with failing-order removal, and approval checks.

Changes

Order Pipeline Instrumentation

Layer / File(s) Summary
Common Tracing Helpers & Imports
crates/common/src/raindex_client/order_quotes.rs, crates/common/src/take_orders/simulation.rs
Adds Instant and tracing imports and common helpers for formatting, truncation, and order hashing used by logs.
Order Quote Batch Tracing
crates/common/src/raindex_client/order_quotes.rs
Measures batch duration, logs skip on empty orders, warns on mixed chain IDs, counts RPC URLs, logs per-failed-quote debug entries, and records batch completion with success/failure counts and duration.
Order Fetching & Inventory Logging
crates/common/src/raindex_client/orders.rs
Classifies query source (local_db/subgraph/mixed), logs per-source returned counts and duration, warns on no liquidity, and logs a capped inventory of orders considered for a token pair.
Candidate Building Statistics & Instrumentation
crates/common/src/take_orders/candidates.rs
Adds CandidateBuildStats, per-decision logging in try_build_candidate, aggregates stats in build_take_order_candidates_for_pair, and emits a final summary with counts and duration; updates tests to pass stats.
Simulation Execution & Price-Cap Filtering
crates/common/src/take_orders/simulation.rs
Replaces streaming price-cap filter with an imperative loop that logs rejected candidates (capped) and instruments buy/spend simulations with counts, totals, fully_filled flag, worst ratio, and duration logs.
Orderbook Selection & Candidate Scoring
crates/common/src/raindex_client/take_orders/selection.rs
Times selection, logs per-orderbook candidate counts, skips empty-simulation orderbooks, refactors tie-break into explicit branches, and logs selected orderbook metrics or a NoLiquidity warning.
Preflight Simulation & Failing Order Detection
crates/common/src/take_orders/preflight.rs
Times simulations and failing-order search, logs debug/info/warn with truncated error text and durations, detects/removes single failing orders during preflight, and warns when no failing order can be identified.
Approval Check Instrumentation
crates/common/src/raindex_client/take_orders/approval.rs
Times approval checks, computes a formatted max_sell_cap (with fallback), and logs allowance context and approval_required boolean with elapsed duration.
Main Orchestration & Preflight Loop
crates/common/src/raindex_client/take_orders/mod.rs
Wraps get_take_orders_calldata_with_injector in an info_span, instruments parsing/build/select/approval phases, refactors the preflight loop to iterate and remove failing orders when identifiable, and logs iteration/removal/termination events.
Vault Helper
crates/common/src/raindex_client/vaults.rs
Adds pub(crate) fn vault_id_string(&self) -> String on RaindexVault for logging convenience.
Test Updates for Statistics Parameters
crates/common/src/take_orders/candidates.rs
Updates unit tests to pass CandidateBuildStats to try_build_candidate and preserve signed_context propagation assertions.

Estimated Code Review Effort

🎯 4 (Complex) | ⏱️ ~60 minutes

Poem

A rabbit in logs so deep,
Counts each quote and times each leap,
It hashes orders, trims the noise,
Removes the bad, preserves the poise—
Instrumented hops keep flight precise. 🐰✨

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 42.50% which is insufficient. The required threshold is 80.00%. Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (4 passed)
Check name Status Explanation
Description Check ✅ Passed Check skipped - CodeRabbit’s high-level summary is enabled.
Title check ✅ Passed The title 'feat: add take-orders tracing' accurately summarizes the main change—adding structured observability and logging throughout the take-orders execution path across multiple files.
Linked Issues check ✅ Passed Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check ✅ Passed Check skipped because no linked issues were found for this pull request.

✏️ Tip: You can configure your own custom pre-merge checks in the settings.

✨ Finishing Touches
📝 Generate docstrings
  • Create stacked PR
  • Commit on current branch
🧪 Generate unit tests (beta)
  • Create PR with unit tests
  • Commit unit tests in branch arda/take-orders-tracing

Tip

💬 Introducing Slack Agent: The best way for teams to turn conversations into code.

Slack Agent is built on CodeRabbit's deep understanding of your code, so your team can collaborate across the entire SDLC without losing context.

  • Generate code and open pull requests
  • Plan features and break down work
  • Investigate incidents and troubleshoot customer tickets together
  • Automate recurring tasks and respond to alerts with triggers
  • Summarize progress and report instantly

Built for teams:

  • Shared memory across your entire org—no repeating context
  • Per-thread sandboxes to safely plan and execute work
  • Governance built-in—scoped access, auditability, and budget controls

One agent for your entire SDLC. Right inside Slack.

👉 Get started


Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands and usage tips.

Copy link
Copy Markdown
Collaborator Author

findolor commented May 7, 2026

This stack of pull requests is managed by Graphite. Learn more about stacking.

@findolor findolor self-assigned this May 7, 2026
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 3

🧹 Nitpick comments (4)
crates/common/src/take_orders/candidates.rs (3)

106-186: 💤 Low value

Skip field formatting when INFO is disabled for rejections.

For the rejection branch you already cap info_rejection_logs, but the per-decision field formatting (format_float, truncate_error, order_hash inside the macro call) is still performed unconditionally even when no INFO subscriber is attached. On hot paths with many quote rejections this is wasted work. Consider gating with enabled!(Level::INFO) analogously to how the accepted branch gates on Level::DEBUG.

♻️ Proposed sketch
-    } else if stats.info_rejection_logs >= MAX_INFO_CANDIDATE_DECISION_LOGS {
-        stats.omitted_info_rejection_logs += 1;
-        return;
+    } else {
+        if stats.info_rejection_logs >= MAX_INFO_CANDIDATE_DECISION_LOGS {
+            stats.omitted_info_rejection_logs += 1;
+            return;
+        }
+        if !enabled!(Level::INFO) {
+            // Still bump the counter so the cap remains meaningful, but skip
+            // the field formatting cost if no subscriber will record it.
+            stats.info_rejection_logs += 1;
+            return;
+        }
     }
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/take_orders/candidates.rs` around lines 106 - 186, The
rejection branch in log_candidate_decision still computes expensive fields
(format_float, truncate_error, order_hash, etc.) unconditionally; wrap the info!
logging and the precomputed values behind a runtime check enabled!(Level::INFO)
(similar to the existing DEBUG check for accepted decisions) so you only compute
quoted_max_output, quoted_ratio, quote_error, and call order_hash when INFO is
enabled; update the branch that checks stats.info_rejection_logs /
MAX_INFO_CANDIDATE_DECISION_LOGS to perform that enabled!(Level::INFO) check
before doing the formatting and invoking info!, and ensure
stats.info_rejection_logs is incremented only after a logged info call.

274-374: ⚡ Quick win

Redundant debug logs after log_candidate_decision.

Each rejection path now both calls log_candidate_decision(...) (which already emits a structured info!/debug! event with full decision context) and immediately follows with a second debug!(...) carrying a strict subset of that information. The trailing debug! calls are now duplicate noise and can be dropped to keep one source of truth per decision.

♻️ Proposed cleanup
                 reason: "quote_failed",
             });
-            debug!(
-                orderbook = %orderbook,
-                input_index = quote.pair.input_index,
-                output_index = quote.pair.output_index,
-                error = ?quote.error,
-                "skipping failed quote"
-            );
             return Ok(None);

(apply the same removal to the missing_quote_data, out_of_bounds_io_indices, wrong_direction, and zero_or_non_positive_capacity branches)

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/take_orders/candidates.rs` around lines 274 - 374, Remove
the redundant debug! calls that immediately follow log_candidate_decision(...)
in the rejection branches for quote_failed, missing_quote_data,
out_of_bounds_io_indices, wrong_direction, and zero_or_non_positive_capacity:
keep the log_candidate_decision(CandidateDecisionLog { ... }) calls (and stats
increments) and delete the subsequent debug!(...) statements (the ones that log
orderbook/input_io_index/output_io_index and a short message) so each decision
is logged only via log_candidate_decision; ensure no other logic is changed and
that references like quote.pair.input_index/output_index,
input_io_index/output_io_index, stats, orderbook, order, quote, input_token, and
output_token remain intact.

142-186: ⚡ Quick win

Collapse the duplicated accept/reject log bodies.

The if is_accepted { debug!(...) } else { info!(...) } arms emit byte-for-byte the same field set with only the macro level differing. Consider using a single block plus a helper level, e.g. via tracing::event!(level, ...) with the level chosen up front, to remove ~40 lines of duplication and keep the field list in one place going forward.

♻️ Sketch
let level = if is_accepted { Level::DEBUG } else { Level::INFO };
tracing::event!(
    level,
    orderbook = %orderbook,
    order_hash = %order_hash(order),
    // ... single field list ...
    decision,
    reason,
    "take-order candidate decision"
);
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/take_orders/candidates.rs` around lines 142 - 186, The two
logging branches (the is_accepted condition that calls debug!(...) and the else
that calls info!(...)) duplicate the exact same fields; replace them with a
single tracing::event! call where the level is chosen first (e.g. let level = if
is_accepted { Level::DEBUG } else { Level::INFO }) and then emit the shared
field list (including order_hash(order), quote.pair.*, input.map(|io|
io.token).unwrap_or(Address::ZERO), quoted_max_output, quoted_ratio,
quote.signed_context.len(), decision, reason, etc.) once; ensure you preserve
the stats.info_rejection_logs += 1 side effect only when level == Level::INFO
(i.e. when !is_accepted) so behavior remains identical.
crates/common/src/raindex_client/take_orders/mod.rs (1)

32-122: ⚡ Quick win

De-duplicate logging helpers across take_orders modules.

truncate_error, format_float_for_log, and order_hash_for_leg here are byte-equivalent to truncate_error, format_float, and order_hash in crates/common/src/take_orders/candidates.rs (and per the AI summary, simulation.rs/preflight.rs grow similar helpers). The MAX_LOGGED_ERROR_CHARS/MAX_LEN constants are also duplicated (both 512). Consider extracting these into a small take_orders::log_helpers (or similar) module so the format/truncate semantics stay consistent if they evolve.

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/raindex_client/take_orders/mod.rs` around lines 32 - 122,
Duplicate logging helpers (truncate_error, format_float_for_log,
order_hash_for_leg and the MAX_LEN constant) should be extracted into a single
take_orders::log_helpers module and consumed from there; create log_helpers with
the shared const (use the canonical name MAX_LOGGED_ERROR_CHARS or keep MAX_LEN
but consolidate), move/rename the functions to that module (truncate_error,
format_float, order_hash) and update callers in this file (emit_selected_leg!,
format_float_for_log usage, order_hash_for_leg call sites, and any other
take_orders modules like candidates.rs/simulation.rs/preflight.rs) to use the
centralized functions via use take_orders::log_helpers::{truncate_error,
format_float, order_hash} (or re-exported names) so all duplicate
implementations are removed and semantics remain consistent.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@crates/common/src/raindex_client/orders.rs`:
- Around line 211-246: The per-order inventory logs in
log_order_inventory_for_pair are too heavy for info level; change the per-order
info! calls to debug! and wrap the per-order loop (including calls to
format_order_vaults(&order.inputs) and format_order_vaults(&order.outputs)) in a
log-level guard so formatting is only done when debug is enabled (e.g. if
tracing::level_enabled!(tracing::Level::DEBUG) { ... }). Leave the aggregate
omitted_order_count summary as-is (or keep at info) but ensure any expensive
formatting only runs inside the debug guard; update the code in
log_order_inventory_for_pair to use debug! and the tracing level check.

In `@crates/common/src/raindex_client/take_orders/mod.rs`:
- Around line 34-60: The macro emit_selected_leg! currently indexes
order.validInputs[input_index] and order.validOutputs[output_index] unsafely;
change those to use .get(input_index) and .get(output_index) and fall back to
sentinel/default values when None so the logging path never panics.
Specifically, within emit_selected_leg! replace direct access to input and
output with safe lookups and set input_token/output_token to a sentinel like
"<missing>" (or the existing candidate decision logger sentinel),
input_vault_id/output_vault_id to a safe default, and
selected_input/selected_output to a formatted sentinel when the entry is absent,
while keeping other fields (order_hash_for_leg, format_float_for_log($leg.input)
etc.) intact so logs remain informative but non-panicking.

In `@crates/common/src/take_orders/simulation.rs`:
- Around line 170-193: The per-candidate price-cap rejection events currently
emitted with info! (inside the branch that increments logged_rejections) are too
noisy; change that info! to debug! and guard it with a debug-level enablement
check (e.g. tracing::level_enabled!(tracing::Level::DEBUG) or equivalent) so the
structured fields (orderbook, order_hash(&candidate), input_io_index,
output_io_index, max_output, ratio, price_cap, decision, reason) are only
evaluated when debug logging is enabled; keep the aggregate info! at the end
that logs logged_rejections and omitted_rejections unchanged and continue to
increment logged_rejections/omitted_rejections using the existing
MAX_INFO_PRICE_CAP_REJECTION_LOGS logic.

---

Nitpick comments:
In `@crates/common/src/raindex_client/take_orders/mod.rs`:
- Around line 32-122: Duplicate logging helpers (truncate_error,
format_float_for_log, order_hash_for_leg and the MAX_LEN constant) should be
extracted into a single take_orders::log_helpers module and consumed from there;
create log_helpers with the shared const (use the canonical name
MAX_LOGGED_ERROR_CHARS or keep MAX_LEN but consolidate), move/rename the
functions to that module (truncate_error, format_float, order_hash) and update
callers in this file (emit_selected_leg!, format_float_for_log usage,
order_hash_for_leg call sites, and any other take_orders modules like
candidates.rs/simulation.rs/preflight.rs) to use the centralized functions via
use take_orders::log_helpers::{truncate_error, format_float, order_hash} (or
re-exported names) so all duplicate implementations are removed and semantics
remain consistent.

In `@crates/common/src/take_orders/candidates.rs`:
- Around line 106-186: The rejection branch in log_candidate_decision still
computes expensive fields (format_float, truncate_error, order_hash, etc.)
unconditionally; wrap the info! logging and the precomputed values behind a
runtime check enabled!(Level::INFO) (similar to the existing DEBUG check for
accepted decisions) so you only compute quoted_max_output, quoted_ratio,
quote_error, and call order_hash when INFO is enabled; update the branch that
checks stats.info_rejection_logs / MAX_INFO_CANDIDATE_DECISION_LOGS to perform
that enabled!(Level::INFO) check before doing the formatting and invoking info!,
and ensure stats.info_rejection_logs is incremented only after a logged info
call.
- Around line 274-374: Remove the redundant debug! calls that immediately follow
log_candidate_decision(...) in the rejection branches for quote_failed,
missing_quote_data, out_of_bounds_io_indices, wrong_direction, and
zero_or_non_positive_capacity: keep the
log_candidate_decision(CandidateDecisionLog { ... }) calls (and stats
increments) and delete the subsequent debug!(...) statements (the ones that log
orderbook/input_io_index/output_io_index and a short message) so each decision
is logged only via log_candidate_decision; ensure no other logic is changed and
that references like quote.pair.input_index/output_index,
input_io_index/output_io_index, stats, orderbook, order, quote, input_token, and
output_token remain intact.
- Around line 142-186: The two logging branches (the is_accepted condition that
calls debug!(...) and the else that calls info!(...)) duplicate the exact same
fields; replace them with a single tracing::event! call where the level is
chosen first (e.g. let level = if is_accepted { Level::DEBUG } else {
Level::INFO }) and then emit the shared field list (including order_hash(order),
quote.pair.*, input.map(|io| io.token).unwrap_or(Address::ZERO),
quoted_max_output, quoted_ratio, quote.signed_context.len(), decision, reason,
etc.) once; ensure you preserve the stats.info_rejection_logs += 1 side effect
only when level == Level::INFO (i.e. when !is_accepted) so behavior remains
identical.
🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

  • Push a commit to this branch (recommended)
  • Create a new PR with the fixes

ℹ️ Review info
⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Pro

Run ID: fe362291-3ba0-4e6d-88a9-1856b1c2e341

📥 Commits

Reviewing files that changed from the base of the PR and between 5d9b9e6 and a1a5dc6.

📒 Files selected for processing (8)
  • crates/common/src/raindex_client/order_quotes.rs
  • crates/common/src/raindex_client/orders.rs
  • crates/common/src/raindex_client/take_orders/approval.rs
  • crates/common/src/raindex_client/take_orders/mod.rs
  • crates/common/src/raindex_client/take_orders/selection.rs
  • crates/common/src/take_orders/candidates.rs
  • crates/common/src/take_orders/preflight.rs
  • crates/common/src/take_orders/simulation.rs

Comment on lines +211 to +246
fn log_order_inventory_for_pair(
chain_id: u32,
sell_token: Address,
buy_token: Address,
orders: &[RaindexOrder],
) {
for (order_index, order) in orders
.iter()
.take(MAX_INFO_ORDER_INVENTORY_LOGS)
.enumerate()
{
info!(
chain_id,
sell_token = %sell_token,
buy_token = %buy_token,
order_index,
order_hash = %order.order_hash(),
orderbook = %order.orderbook(),
input_vaults = ?format_order_vaults(&order.inputs),
output_vaults = ?format_order_vaults(&order.outputs),
"order considered for take-orders pair"
);
}

let omitted = orders.len().saturating_sub(MAX_INFO_ORDER_INVENTORY_LOGS);
if omitted > 0 {
info!(
chain_id,
sell_token = %sell_token,
buy_token = %buy_token,
logged_order_count = MAX_INFO_ORDER_INVENTORY_LOGS,
omitted_order_count = omitted,
"omitted additional order inventory logs"
);
}
}
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major | ⚡ Quick win

Per-order inventory logging is too expensive at info on a hot path.

This path can emit up to 50 detailed inventory events per request and formats vault-level values eagerly, which can materially increase latency and log ingestion cost under load. Move detailed inventory logs to debug and guard the function by log-level enablement.

💡 Suggested change
-use tracing::{info, warn};
+use tracing::{debug, info, warn, Level};

 fn log_order_inventory_for_pair(
     chain_id: u32,
     sell_token: Address,
     buy_token: Address,
     orders: &[RaindexOrder],
 ) {
+    if !tracing::enabled!(Level::DEBUG) {
+        return;
+    }
+
     for (order_index, order) in orders
         .iter()
         .take(MAX_INFO_ORDER_INVENTORY_LOGS)
         .enumerate()
     {
-        info!(
+        debug!(
             chain_id,
             sell_token = %sell_token,
             buy_token = %buy_token,
             order_index,
             order_hash = %order.order_hash(),
             orderbook = %order.orderbook(),
             input_vaults = ?format_order_vaults(&order.inputs),
             output_vaults = ?format_order_vaults(&order.outputs),
             "order considered for take-orders pair"
         );
     }

     let omitted = orders.len().saturating_sub(MAX_INFO_ORDER_INVENTORY_LOGS);
     if omitted > 0 {
-        info!(
+        debug!(
             chain_id,
             sell_token = %sell_token,
             buy_token = %buy_token,
             logged_order_count = MAX_INFO_ORDER_INVENTORY_LOGS,
             omitted_order_count = omitted,
             "omitted additional order inventory logs"
         );
     }
 }

Also applies to: 1469-1469

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/raindex_client/orders.rs` around lines 211 - 246, The
per-order inventory logs in log_order_inventory_for_pair are too heavy for info
level; change the per-order info! calls to debug! and wrap the per-order loop
(including calls to format_order_vaults(&order.inputs) and
format_order_vaults(&order.outputs)) in a log-level guard so formatting is only
done when debug is enabled (e.g. if
tracing::level_enabled!(tracing::Level::DEBUG) { ... }). Leave the aggregate
omitted_order_count summary as-is (or keep at info) but ensure any expensive
formatting only runs inside the debug guard; update the code in
log_order_inventory_for_pair to use debug! and the tracing level check.

Comment on lines +34 to +60
macro_rules! emit_selected_leg {
($level:ident, $leg_index:expr, $leg:expr, $orderbook:expr, $block_number:expr, $message:expr) => {{
let order = &$leg.candidate.order;
let input_index = $leg.candidate.input_io_index as usize;
let output_index = $leg.candidate.output_io_index as usize;
let input = &order.validInputs[input_index];
let output = &order.validOutputs[output_index];

$level!(
orderbook = %$orderbook,
block_number = $block_number,
leg_index = $leg_index,
order_hash = %order_hash_for_leg($leg),
input_io_index = $leg.candidate.input_io_index,
output_io_index = $leg.candidate.output_io_index,
input_token = %input.token,
output_token = %output.token,
input_vault_id = %input.vaultId,
output_vault_id = %output.vaultId,
selected_input = %format_float_for_log($leg.input),
selected_output = %format_float_for_log($leg.output),
ratio = %format_float_for_log($leg.candidate.ratio),
event = $message,
"take-order leg"
);
}};
}
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟡 Minor | ⚡ Quick win

Defensive indexing in the leg-logging macro.

emit_selected_leg! indexes order.validInputs[input_index] and order.validOutputs[output_index] directly. In practice these indices come from a TakeOrderCandidate that already passed indices_in_bounds, but a panic in logging code (e.g. if a future caller constructs a SelectedTakeOrderLeg from a different source, or if the underlying order is mutated upstream) is an unpleasant failure mode for an instrumentation path. Prefer .get(...) with a sentinel like the candidate decision logger already does.

🛡️ Proposed fix
-        let input_index = $leg.candidate.input_io_index as usize;
-        let output_index = $leg.candidate.output_io_index as usize;
-        let input = &order.validInputs[input_index];
-        let output = &order.validOutputs[output_index];
+        let input_index = $leg.candidate.input_io_index as usize;
+        let output_index = $leg.candidate.output_io_index as usize;
+        let input = order.validInputs.get(input_index);
+        let output = order.validOutputs.get(output_index);
@@
-            input_token = %input.token,
-            output_token = %output.token,
-            input_vault_id = %input.vaultId,
-            output_vault_id = %output.vaultId,
+            input_token = %input.map(|io| io.token).unwrap_or(alloy::primitives::Address::ZERO),
+            output_token = %output.map(|io| io.token).unwrap_or(alloy::primitives::Address::ZERO),
+            input_vault_id = %input.map(|io| io.vaultId).unwrap_or_default(),
+            output_vault_id = %output.map(|io| io.vaultId).unwrap_or_default(),
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/raindex_client/take_orders/mod.rs` around lines 34 - 60,
The macro emit_selected_leg! currently indexes order.validInputs[input_index]
and order.validOutputs[output_index] unsafely; change those to use
.get(input_index) and .get(output_index) and fall back to sentinel/default
values when None so the logging path never panics. Specifically, within
emit_selected_leg! replace direct access to input and output with safe lookups
and set input_token/output_token to a sentinel like "<missing>" (or the existing
candidate decision logger sentinel), input_vault_id/output_vault_id to a safe
default, and selected_input/selected_output to a formatted sentinel when the
entry is absent, while keeping other fields (order_hash_for_leg,
format_float_for_log($leg.input) etc.) intact so logs remain informative but
non-panicking.

Comment on lines +170 to +193
} else if logged_rejections < MAX_INFO_PRICE_CAP_REJECTION_LOGS {
info!(
orderbook = %candidate.orderbook,
order_hash = %order_hash(&candidate),
input_io_index = candidate.input_io_index,
output_io_index = candidate.output_io_index,
max_output = %format_float(candidate.max_output),
ratio = %format_float(candidate.ratio),
price_cap = %format_float(price_cap),
decision = "rejected",
reason = "above_price_cap",
"take-order candidate decision"
);
logged_rejections += 1;
} else {
omitted_rejections += 1;
}
}

if omitted_rejections > 0 {
info!(
logged_rejections,
omitted_rejections, "omitted additional price-cap candidate rejection logs"
);
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major | ⚡ Quick win

Price-cap rejection events should not be emitted at info for each candidate.

This can generate up to 100 structured events per simulation call and adds avoidable CPU/logging overhead in a frequently executed path. Emit these as debug (with an enablement guard) and keep only aggregate counts at info.

💡 Suggested change
-use tracing::info;
+use tracing::{debug, info, Level};

 fn filter_candidates_by_price_cap(
     candidates: Vec<TakeOrderCandidate>,
     price_cap: Float,
 ) -> Result<Vec<TakeOrderCandidate>, RaindexError> {
+    let log_rejections = tracing::enabled!(Level::DEBUG);
     let mut filtered = Vec::new();
     let mut logged_rejections = 0usize;
     let mut omitted_rejections = 0usize;

     for candidate in candidates {
         let ratio = candidate.ratio;
         if ratio.lte(price_cap)? {
             filtered.push(candidate);
-        } else if logged_rejections < MAX_INFO_PRICE_CAP_REJECTION_LOGS {
-            info!(
+        } else if log_rejections && logged_rejections < MAX_INFO_PRICE_CAP_REJECTION_LOGS {
+            debug!(
                 orderbook = %candidate.orderbook,
                 order_hash = %order_hash(&candidate),
                 input_io_index = candidate.input_io_index,
                 output_io_index = candidate.output_io_index,
                 max_output = %format_float(candidate.max_output),
                 ratio = %format_float(candidate.ratio),
                 price_cap = %format_float(price_cap),
                 decision = "rejected",
                 reason = "above_price_cap",
                 "take-order candidate decision"
             );
             logged_rejections += 1;
         } else {
             omitted_rejections += 1;
         }
     }
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/common/src/take_orders/simulation.rs` around lines 170 - 193, The
per-candidate price-cap rejection events currently emitted with info! (inside
the branch that increments logged_rejections) are too noisy; change that info!
to debug! and guard it with a debug-level enablement check (e.g.
tracing::level_enabled!(tracing::Level::DEBUG) or equivalent) so the structured
fields (orderbook, order_hash(&candidate), input_io_index, output_io_index,
max_output, ratio, price_cap, decision, reason) are only evaluated when debug
logging is enabled; keep the aggregate info! at the end that logs
logged_rejections and omitted_rejections unchanged and continue to increment
logged_rejections/omitted_rejections using the existing
MAX_INFO_PRICE_CAP_REJECTION_LOGS logic.

@findolor findolor force-pushed the arda/take-orders-tracing branch from a1a5dc6 to 866d259 Compare May 11, 2026 06:56
@findolor findolor force-pushed the arda/take-orders-tracing branch from 866d259 to 191a997 Compare May 11, 2026 07:59
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.

1 participant