feat: add take-orders tracing

crates/common/src/raindex_client/order_quotes.rs

@@ -1,6 +1,7 @@
 use super::*;
 use crate::raindex_client::orders::RaindexOrder;
 use crate::raindex_client::orders_list::RaindexOrders;
+use crate::utils::timing::Timing;
 use alloy::primitives::Address;
 use rain_math_float::Float;
 use rain_orderbook_bindings::IRaindexV6::{OrderV4, SignedContextV1};
@@ -10,6 +11,7 @@ use rain_orderbook_quote::{
 };
 use rain_orderbook_subgraph_client::utils::float::{F0, F1};
 use std::ops::{Div, Mul};
+use tracing::{debug, info, warn};
 use wasm_bindgen_utils::impl_wasm_traits;
 
 #[derive(Serialize, Deserialize, Debug, Clone, Tsify)]
@@ -269,13 +271,23 @@ pub async fn get_order_quotes_batch_with_injector(
     counterparty: Address,
     injector: &dyn SignedContextInjector,
 ) -> Result<Vec<Vec<RaindexOrderQuote>>, RaindexError> {
+    let started_at = Timing::now();
     if orders.is_empty() {
+        info!(
+            order_count = 0usize,
+            "quote batch skipped for empty order list"
+        );
         return Ok(vec![]);
     }
 
     let expected_chain_id = orders[0].chain_id();
     for order in &orders[1..] {
         if order.chain_id() != expected_chain_id {
+            warn!(
+                expected_chain_id,
+                found_chain_id = order.chain_id(),
+                "quote batch rejected mixed chain IDs"
+            );
             return Err(RaindexError::PreflightError(format!(
                 "All orders must share the same chain ID, expected {} but found {}",
                 expected_chain_id,
@@ -289,6 +301,7 @@ pub async fn get_order_quotes_batch_with_injector(
         .into_iter()
         .map(|u| u.to_string())
         .collect();
+    let rpc_url_count = rpcs.len();
 
     let sg_orders = orders
         .iter()
@@ -310,6 +323,17 @@ pub async fn get_order_quotes_batch_with_injector(
             Ok::<usize, RaindexError>(count)
         })
         .collect::<Result<Vec<_>, _>>()?;
+    let total_pair_count: usize = pair_counts.iter().sum();
+
+    info!(
+        order_count = orders.len(),
+        expected_chain_id,
+        total_pair_count,
+        chunk_size = ?chunk_size,
+        block_number = ?block_number,
+        rpc_url_count,
+        "starting order quote batch"
+    );
 
     let flat_results = get_order_quotes(
         sg_orders,
@@ -325,13 +349,48 @@ pub async fn get_order_quotes_batch_with_injector(
         .into_iter()
         .map(RaindexOrderQuote::try_from_batch_order_quotes_response)
         .collect::<Result<Vec<_>, _>>()?;
+    let successful_quote_count = flat_raindex.iter().filter(|quote| quote.success).count();
+    let failed_quote_count = flat_raindex.len().saturating_sub(successful_quote_count);
+    for quote in flat_raindex.iter().filter(|quote| !quote.success) {
+        debug!(
+            input_index = quote.pair.input_index,
+            output_index = quote.pair.output_index,
+            error = ?quote.error,
+            "order quote failed"
+        );
+    }
 
     let mut result = Vec::with_capacity(orders.len());
     let mut offset = 0;
     for count in pair_counts {
         result.push(flat_raindex[offset..offset + count].to_vec());
         offset += count;
     }
+    for (order, quotes) in orders.iter().zip(&result) {
+        for quote in quotes.iter().filter(|quote| !quote.success) {
+            debug!(
+                order_hash = %order.order_hash(),
+                orderbook = %order.orderbook(),
+                input_index = quote.pair.input_index,
+                output_index = quote.pair.output_index,
+                error = ?quote.error,
+                "order quote failed for order"
+            );
+        }
+    }
+
+    info!(
+        order_count = orders.len(),
+        expected_chain_id,
+        total_pair_count,
+        chunk_size = ?chunk_size,
+        block_number = ?block_number,
+        rpc_url_count,
+        successful_quote_count,
+        failed_quote_count,
+        duration_ms = started_at.elapsed_ms(),
+        "completed order quote batch"
+    );
 
     Ok(result)
 }

crates/common/src/raindex_client/orders.rs

@@ -17,6 +17,7 @@ use crate::raindex_client::take_orders::{
 use crate::raindex_client::vaults_list::RaindexVaultsList;
 use crate::rpc_client::RpcClient;
 use crate::take_orders::{ParsedTakeOrdersMode, TakeOrdersMode};
+use crate::utils::timing::Timing;
 use crate::{
     meta::TryDecodeRainlangSource,
     raindex_client::{
@@ -46,6 +47,7 @@ use rain_orderbook_subgraph_client::{
 };
 use serde::{Deserialize, Serialize};
 use std::{collections::HashSet, io::Cursor, str::FromStr};
+use tracing::{info, warn};
 use tsify::Tsify;
 use wasm_bindgen_utils::impl_wasm_traits;
 #[cfg(target_family = "wasm")]
@@ -54,6 +56,7 @@ use wasm_bindgen_utils::prelude::js_sys::BigInt;
 const DEFAULT_PAGE_SIZE: u16 = 100;
 // Limit concurrent dotrain source fetches to avoid overwhelming the subgraph/metaboard.
 const MAX_CONCURRENT_DOTRAIN_SOURCE_FETCHES: usize = 5;
+const MAX_INFO_ORDER_INVENTORY_LOGS: usize = 50;
 
 #[derive(Serialize, Deserialize, Debug, Clone)]
 #[serde(rename_all = "camelCase")]
@@ -185,6 +188,59 @@ fn get_io_by_type(order: &RaindexOrder, vault_type: RaindexVaultType) -> Vec<Rai
         .collect()
 }
 
+fn format_order_vaults(vaults: &[RaindexVault]) -> Vec<String> {
+    vaults
+        .iter()
+        .map(|vault| {
+            let vault_id = vault.vault_id_string();
+
+            format!(
+                "vault_id={},token={},balance={}",
+                vault_id,
+                vault.token().address(),
+                vault.formatted_balance()
+            )
+        })
+        .collect()
+}
+
+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"
+        );
+    }
+}
+
 impl RaindexOrder {
     pub(crate) fn from_local_db_order(
         raindex_client: ClientRef,
@@ -1315,6 +1371,7 @@ impl RaindexClient {
         sell_token: Address,
         buy_token: Address,
     ) -> Result<Vec<RaindexOrder>, RaindexError> {
+        let started_at = Timing::now();
         let filters = GetOrdersFilters {
             owners: vec![],
             active: Some(true),
@@ -1329,6 +1386,24 @@ impl RaindexClient {
 
         let ids = Some(vec![chain_id]);
         let (local_db, local_ids, sg_ids) = self.classify_chains(ids)?;
+        let local_chain_ids_count = local_ids.len();
+        let subgraph_chain_ids_count = sg_ids.len();
+        let query_source = match (local_db.is_some(), sg_ids.is_empty()) {
+            (true, true) => "local_db",
+            (false, false) => "subgraph",
+            (true, false) => "mixed",
+            (false, true) => "none",
+        };
+
+        info!(
+            chain_id,
+            sell_token = %sell_token,
+            buy_token = %buy_token,
+            query_source,
+            local_chain_ids_count,
+            subgraph_chain_ids_count,
+            "fetching orders for token pair"
+        );
 
         let mut all_orders = Vec::new();
 
@@ -1337,6 +1412,12 @@ impl RaindexClient {
             let result = local_source
                 .list(Some(local_ids), &filters, None, None)
                 .await?;
+            info!(
+                chain_id,
+                source = "local_db",
+                returned_order_count = result.orders.len(),
+                "fetched local orders for token pair"
+            );
             all_orders.extend(result.orders);
         }
 
@@ -1345,13 +1426,44 @@ impl RaindexClient {
             let result = subgraph_source
                 .list(Some(sg_ids), &filters, None, None)
                 .await?;
+            info!(
+                chain_id,
+                source = "subgraph",
+                returned_order_count = result.orders.len(),
+                "fetched subgraph orders for token pair"
+            );
             all_orders.extend(result.orders);
         }
 
         if all_orders.is_empty() {
+            warn!(
+                chain_id,
+                sell_token = %sell_token,
+                buy_token = %buy_token,
+                query_source,
+                local_chain_ids_count,
+                subgraph_chain_ids_count,
+                returned_order_count = 0usize,
+                no_liquidity = true,
+                duration_ms = started_at.elapsed_ms(),
+                "no orders found for token pair"
+            );
             return Err(RaindexError::NoLiquidity);
         }
 
+        info!(
+            chain_id,
+            sell_token = %sell_token,
+            buy_token = %buy_token,
+            query_source,
+            local_chain_ids_count,
+            subgraph_chain_ids_count,
+            returned_order_count = all_orders.len(),
+            no_liquidity = false,
+            duration_ms = started_at.elapsed_ms(),
+            "fetched orders for token pair"
+        );
+        log_order_inventory_for_pair(chain_id, sell_token, buy_token, &all_orders);
         Ok(all_orders)
     }
 }

crates/common/src/raindex_client/take_orders/approval.rs

@@ -1,9 +1,11 @@
 use crate::erc20::ERC20;
 use crate::raindex_client::RaindexError;
 use crate::take_orders::{check_taker_allowance, ParsedTakeOrdersMode};
+use crate::utils::timing::Timing;
 use alloy::primitives::Address;
 use rain_math_float::Float;
 use std::ops::Mul;
+use tracing::info;
 use url::Url;
 
 use super::result::build_approval_result;
@@ -21,7 +23,11 @@ pub struct ApprovalCheckParams {
 pub async fn check_approval_needed(
     params: &ApprovalCheckParams,
 ) -> Result<Option<TakeOrdersCalldataResult>, RaindexError> {
+    let started_at = Timing::now();
     let max_sell_cap = calculate_max_sell_cap(params.mode, params.price_cap)?;
+    let formatted_max_sell_cap = max_sell_cap
+        .format()
+        .unwrap_or_else(|_| "<format_error>".to_string());
 
     let erc20 = ERC20::new(params.rpc_urls.clone(), params.sell_token);
     let decimals = erc20.decimals().await?;
@@ -32,14 +38,41 @@ pub async fn check_approval_needed(
             .await
             .map_err(|e| RaindexError::PreflightError(e.to_string()))?;
 
+    let duration_ms = started_at.elapsed_ms();
     if allowance_result.needs_approval {
+        info!(
+            sell_token = %params.sell_token,
+            taker = %params.taker,
+            orderbook = %params.orderbook,
+            spender = %params.orderbook,
+            max_sell_cap = %formatted_max_sell_cap,
+            token_decimals = decimals,
+            required_fixed_amount = %required_u256,
+            current_allowance = %allowance_result.current_allowance,
+            approval_required = true,
+            duration_ms,
+            "approval required for take-orders calldata"
+        );
         Ok(Some(build_approval_result(
             params.sell_token,
             params.orderbook,
             max_sell_cap,
             decimals,
         )?))
     } else {
+        info!(
+            sell_token = %params.sell_token,
+            taker = %params.taker,
+            orderbook = %params.orderbook,
+            spender = %params.orderbook,
+            max_sell_cap = %formatted_max_sell_cap,
+            token_decimals = decimals,
+            required_fixed_amount = %required_u256,
+            current_allowance = %allowance_result.current_allowance,
+            approval_required = false,
+            duration_ms,
+            "approval check passed"
+        );
         Ok(None)
     }
 }