From dcb11690fd707dd85326a8b8c318b0d74721f5b8 Mon Sep 17 00:00:00 2001 From: Maximilian Schneider Date: Fri, 8 Nov 2024 00:28:35 +0100 Subject: [PATCH] cleanup all logging --- .../src/dex/generic/generic_adapter.rs | 12 ++------ bin/autobahn-router/src/edge.rs | 4 +-- bin/autobahn-router/src/edge_updater.rs | 3 -- bin/autobahn-router/src/main.rs | 1 - bin/autobahn-router/src/path_warmer.rs | 8 ++--- bin/autobahn-router/src/routing.rs | 24 +++++---------- bin/autobahn-router/src/server/http_server.rs | 30 ++----------------- .../src/source/grpc_plugin_source.rs | 13 ++++---- lib/dex-invariant/src/invariant_dex.rs | 27 +++++++---------- lib/dex-invariant/src/invariant_ix_builder.rs | 1 - lib/router-lib/src/price_feeds/birdeye.rs | 3 ++ lib/router-lib/src/price_feeds/price_cache.rs | 10 +++++-- .../src/instructions/execute_swap_v3.rs | 1 - 13 files changed, 44 insertions(+), 93 deletions(-) diff --git a/bin/autobahn-router/src/dex/generic/generic_adapter.rs b/bin/autobahn-router/src/dex/generic/generic_adapter.rs index d9736df..4be7b4d 100644 --- a/bin/autobahn-router/src/dex/generic/generic_adapter.rs +++ b/bin/autobahn-router/src/dex/generic/generic_adapter.rs @@ -4,7 +4,7 @@ use std::sync::Arc; use itertools::Itertools; use router_lib::dex::{DexInterface, DexSubscriptionMode}; use router_lib::mango::mango_fetcher::MangoMetadata; -use tracing::{info, trace}; +use tracing::info; use crate::edge::Edge; use crate::edge_updater::Dex; @@ -46,11 +46,8 @@ pub async fn build_dex_internal( let edges_per_pk_src = dex.edges_per_pk(); let mut edges_per_pk = HashMap::new(); - info!("dex {} enabled={enabled} add_mango_tokens={add_mango_tokens} take_all_mints={take_all_mints} mints={mints:?} edges={}", dex.name(), edges_per_pk_src.len()); - - for (key, edge_ids) in edges_per_pk_src { - - let edges = edge_ids.clone() + for (key, edges) in edges_per_pk_src { + let edges = edges .into_iter() .filter(|x| { let keep = take_all_mints @@ -68,9 +65,6 @@ pub async fn build_dex_internal( }) }) .collect_vec(); - - trace!("build_dex_internal key={key:?} edge_ids={} edges={}", edge_ids.len(), edges.len()); - if edges.len() > 0 { edges_per_pk.insert(key, edges); } diff --git a/bin/autobahn-router/src/edge.rs b/bin/autobahn-router/src/edge.rs index 53404b9..eebb229 100644 --- a/bin/autobahn-router/src/edge.rs +++ b/bin/autobahn-router/src/edge.rs @@ -240,14 +240,14 @@ impl Edge { let Ok(decimals) = token_cache.token(self.input_mint).map(|x| x.decimals) else { let mut state = self.state.write().unwrap(); - info!("update_internal no decimals for {}", self.input_mint); + trace!("no decimals for {}", self.input_mint); state.is_valid = false; return; }; let Some(price) = price_cache.price_ui(self.input_mint) else { let mut state = self.state.write().unwrap(); state.is_valid = false; - // info!("update_internal no price for {}", self.input_mint); + trace!("no price for {}", self.input_mint); return; }; diff --git a/bin/autobahn-router/src/edge_updater.rs b/bin/autobahn-router/src/edge_updater.rs index c3c27ed..d452aa0 100644 --- a/bin/autobahn-router/src/edge_updater.rs +++ b/bin/autobahn-router/src/edge_updater.rs @@ -209,7 +209,6 @@ pub fn spawn_updater_job( impl EdgeUpdater { fn detect_and_handle_slot_lag(&mut self, slot: Result) { - info!("detect_and_handle_slot_lag {slot:?}"); let state = &mut self.state; if state.latest_slot_processed == 0 { return; @@ -283,7 +282,6 @@ impl EdgeUpdater { } fn on_metadata_update(&mut self, res: Result) { - info!("metadata_update {res:?}"); let state = &mut self.state; match res { Ok(v) => match v { @@ -295,7 +293,6 @@ impl EdgeUpdater { FeedMetadata::SnapshotEnd(x) => { if let Some(x) = x { if x == spl_token::ID { - // TODO: token2022 support for CP style amms // TODO Handle multiples owners state.dirty_token_accounts_for_owners = true; } else { diff --git a/bin/autobahn-router/src/main.rs b/bin/autobahn-router/src/main.rs index 6e3f8fd..5b5043d 100644 --- a/bin/autobahn-router/src/main.rs +++ b/bin/autobahn-router/src/main.rs @@ -241,7 +241,6 @@ async fn main() -> anyhow::Result<()> { }), }; - info!("config = {config:?}"); let dexs: Vec = [ dex::generic::build_dex!( OrcaDex::initialize(&mut router_rpc, orca_config).await?, diff --git a/bin/autobahn-router/src/path_warmer.rs b/bin/autobahn-router/src/path_warmer.rs index f81782a..b51fcfa 100644 --- a/bin/autobahn-router/src/path_warmer.rs +++ b/bin/autobahn-router/src/path_warmer.rs @@ -86,7 +86,6 @@ where all_mints.insert(sol_mint); all_mints.insert(usdc_mint); - let hot_mints = hot_mints_cache.read().unwrap().get(); let mints = match generate_mints( &mode, @@ -99,7 +98,7 @@ where None => break, }; - info!("Running a path warmup loop for {} mints", mints.len()); + debug!("Running a path warmup loop for {} mints", mints.len()); let mut counter = 0; let mut skipped = 0; let time = Instant::now(); @@ -121,13 +120,10 @@ where continue; }; if price_ui <= 0.000001 { - info!("skipped {from_mint:?} price is low {price_ui}"); skipped += 1; continue; } let Ok(token) = token_cache.token(*from_mint) else { - info!("skipped {from_mint:?} no token cache entry"); - skipped += 1; continue; }; @@ -135,7 +131,7 @@ where let decimals = token.decimals; let multiplier = 10u64.pow(decimals as u32) as f64; - info!("Warming up {}", debug_tools::name(&from_mint),); + trace!("Warming up {}", debug_tools::name(&from_mint),); for amount_ui in &path_warming_amounts { let amount_native = diff --git a/bin/autobahn-router/src/routing.rs b/bin/autobahn-router/src/routing.rs index 8e063c6..5682f0d 100644 --- a/bin/autobahn-router/src/routing.rs +++ b/bin/autobahn-router/src/routing.rs @@ -693,15 +693,12 @@ impl Routing { let mut best = HashMap::<(Pubkey, Pubkey), Vec<(EdgeIndex, f64)>>::new(); for (edge_index, edge) in all_edges.iter().enumerate() { - trace!("ix:{edge_index} edge:{edge:?}"); if swap_mode == SwapMode::ExactOut && !edge.supports_exact_out() { continue; } let edge_index: EdgeIndex = edge_index.into(); let state = edge.state.read().unwrap(); - trace!("ix:{edge_index} edge:{edge:?} {:?}", state.cached_prices); - if !state.is_valid() || state.cached_prices.len() < i { continue; } @@ -781,6 +778,7 @@ impl Routing { price_impact, ); + // TODO: make this a config variable for reach network // if price_impact > 0.25 { // skipped_bad_price_impact += 1; // continue; @@ -1249,7 +1247,7 @@ impl Routing { bail!(RoutingError::UnsupportedOutputMint(output_mint.clone())); }; - info!( + trace!( input_index = input_index.idx_raw(), output_index = output_index.idx_raw(), max_path_length, @@ -1270,7 +1268,6 @@ impl Routing { .map(|paths| self.lookup_edge_index_paths(paths.iter())); if (p1.is_none() && p2.is_none()) || ignore_cache { - info!("no cache"); None } else { let cached_paths = p1 @@ -1278,7 +1275,6 @@ impl Routing { .into_iter() .chain(p2.unwrap_or(vec![]).into_iter()) .collect_vec(); - info!("cached {}", cached_paths.len()); Some(cached_paths) } }; @@ -1396,9 +1392,9 @@ impl Routing { } // Debug - if true { + if tracing::event_enabled!(Level::TRACE) { for (path, out_amount, out_amount_dumb) in &path_and_output { - info!( + trace!( "potential path: [out={}] [dumb={}] {}", out_amount, out_amount_dumb, @@ -1453,7 +1449,7 @@ impl Routing { let price_impact = expected_ratio / actual_ratio * 10_000.0 - 10_000.0; let price_impact_bps = price_impact.round() as u64; - info!( + trace!( price_impact_bps, out_amount_for_small_amount, out_amount_for_request, @@ -1489,7 +1485,7 @@ impl Routing { } if self.overquote > 0.0 { - info!( + debug!( actual_in_amount, actual_out_amount, overquote_in_amount, @@ -1504,7 +1500,6 @@ impl Routing { let accounts = self .capture_accounts(chain_data, &out_path, original_amount) .ok(); - return Ok(Route { input_mint: *input_mint, @@ -1550,19 +1545,16 @@ impl Routing { output_index: MintNodeIndex, used_cached_paths: bool, ) -> anyhow::Result { - - - info!("failsafe triggered"); // It is possible for cache path to became invalid after some account write or failed tx (cooldown) // If we used cache but can't find any valid path, try again without the cache let can_try_one_more_hop = max_path_length != self.max_path_length; if !ignore_cache && (used_cached_paths || can_try_one_more_hop) { if used_cached_paths { - info!("Invalid cached path, retrying without cache"); + debug!("Invalid cached path, retrying without cache"); let mut cache = self.path_discovery_cache.write().unwrap(); cache.invalidate(input_index, output_index, max_accounts); } else { - info!("No path within boundaries, retrying with +1 hop"); + debug!("No path within boundaries, retrying with +1 hop"); } return self.find_best_route( chain_data, diff --git a/bin/autobahn-router/src/server/http_server.rs b/bin/autobahn-router/src/server/http_server.rs index e760281..e97ce91 100644 --- a/bin/autobahn-router/src/server/http_server.rs +++ b/bin/autobahn-router/src/server/http_server.rs @@ -1,7 +1,6 @@ use crate::prelude::*; use crate::server::errors::*; use crate::server::route_provider::RouteProvider; -use anchor_spl::token_2022::spl_token_2022; use axum::extract::Query; use axum::response::Html; use axum::{extract::Form, http::header::HeaderMap, routing, Json, Router}; @@ -169,8 +168,6 @@ impl HttpServer { swap_mode, )?; - info!("best route found"); - let (bytes, accounts_count) = Self::build_swap_tx( address_lookup_table_addresses.clone(), hash_provider.clone(), @@ -188,9 +185,6 @@ impl HttpServer { ) .await?; - info!("tx encoded"); - - let tx_size = bytes.len(); if accounts_count <= MAX_ACCOUNTS_PER_TX && tx_size < MAX_TX_SIZE { break Ok(route_candidate); @@ -204,11 +198,9 @@ impl HttpServer { } }; - info!("quote -> err ? {}", route.is_err()); - let route: Route = route?; - Self::log_repriced_amount(live_account_provider, reprice_probability, &route); + Self::log_repriced_amount(live_account_provider.clone(), reprice_probability, &route); let other_amount_threshold = if swap_mode == SwapMode::ExactOut { (route.in_amount as f64 * (10_000f64 + input.slippage_bps as f64) / 10_000f64).floor() @@ -218,8 +210,6 @@ impl HttpServer { .floor() as u64 }; - info!("serialize plan"); - let route_plan = route .steps .iter() @@ -238,9 +228,6 @@ impl HttpServer { }) .collect_vec(); - info!("encode accounts"); - - let accounts = match route.accounts { None => None, Some(a) => Some( @@ -293,7 +280,7 @@ impl HttpServer { ) -> Result, AppError> { let route = route_provider.try_from(&input.quote_response)?; - Self::log_repriced_amount(live_account_provider.clone(), reprice_probability, &route); + Self::log_repriced_amount(live_account_provider, reprice_probability, &route); let swap_mode: SwapMode = SwapMode::from_str(&input.quote_response.swap_mode) .map_err(|_| anyhow::Error::msg("Invalid SwapMode"))?; @@ -307,7 +294,6 @@ impl HttpServer { address_lookup_table_addresses, hash_provider, alt_provider, - live_account_provider, ix_builder, &route, input.user_public_key, @@ -366,8 +352,8 @@ impl HttpServer { async fn build_swap_tx< THashProvider: HashProvider + Send + Sync + 'static, TAltProvider: AltProvider + Send + Sync + 'static, - TAccountProvider: AccountProvider + Send + Sync + 'static, TIxBuilder: SwapInstructionsBuilder + Send + Sync + 'static, + TAccountProvider: AccountProvider + Send + Sync + 'static, >( address_lookup_table_addresses: Vec, hash_provider: Arc, @@ -385,8 +371,6 @@ impl HttpServer { ) -> Result<(Vec, usize), AppError> { let wallet_pk = Pubkey::from_str(&wallet_pk)?; - info!("build_ixs"); - let ixs = ix_builder.build_ixs( live_account_provider, &wallet_pk, @@ -403,8 +387,6 @@ impl HttpServer { ComputeBudgetInstruction::set_compute_unit_limit(ixs.cu_estimate), ]; - info!("serialize ixs"); - let transaction_addresses = ixs.accounts().into_iter().collect(); let instructions = compute_budget_ixs .into_iter() @@ -413,16 +395,11 @@ impl HttpServer { .chain(ixs.cleanup_instructions.into_iter()) .collect_vec(); - - info!("load alts"); let all_alts = Self::load_all_alts(address_lookup_table_addresses, alt_provider).await; - info!("optimize alts"); let alts = alt_optimizer::get_best_alt(&all_alts, &transaction_addresses)?; let accounts = transaction_addresses.iter().unique().count() + alts.iter().map(|x| x.key).unique().count(); - info!("compile message"); - let v0_message = solana_sdk::message::v0::Message::try_compile( &wallet_pk, instructions.as_slice(), @@ -432,7 +409,6 @@ impl HttpServer { let message = VersionedMessage::V0(v0_message); let tx = VersionedTransaction::try_new(message, &[&NullSigner::new(&wallet_pk)])?; - info!("serialize message"); let bytes = bincode::serialize(&tx)?; Ok((bytes, accounts)) diff --git a/bin/autobahn-router/src/source/grpc_plugin_source.rs b/bin/autobahn-router/src/source/grpc_plugin_source.rs index 68aacde..1effc22 100644 --- a/bin/autobahn-router/src/source/grpc_plugin_source.rs +++ b/bin/autobahn-router/src/source/grpc_plugin_source.rs @@ -70,8 +70,6 @@ pub async fn feed_data_geyser( subscribed_token_accounts: &HashSet, sender: async_channel::Sender, ) -> anyhow::Result<()> { - - println!("feed_data_geyser a:{subscribed_accounts:?} p:{subscribed_programs:?} t:{subscribed_token_accounts:?}"); let use_compression = snapshot_config.rpc_support_compression.unwrap_or(false); let number_of_accounts_per_gma = snapshot_config.number_of_accounts_per_gma.unwrap_or(100); let grpc_connection_string = match &grpc_config.connection_string.chars().next().unwrap() { @@ -746,7 +744,7 @@ async fn process_account_updated_from_sources( metrics::ACCOUNT_SNAPSHOTS .with_label_values(&[&label]) .inc(); - info!( + debug!( "processing snapshot for program_id {} -> size={} & missing size={}...", update .program_id @@ -764,11 +762,12 @@ async fn process_account_updated_from_sources( metrics::GRPC_SNAPSHOT_ACCOUNT_WRITES.inc(); metrics::GRPC_ACCOUNT_WRITE_QUEUE.set(account_write_queue_sender.len() as i64); - // if !filters.contains(&account.pubkey) && update.program_id.is_none() { - // info!("filtered account {:?}", account.pubkey); + // TODO: disabled for eclipse launch, was causing issues with the program id + // subscription for invariant + // if !filters.contains(&account.pubkey) { // continue; // } - + updated_accounts.push(account); } account_write_queue_sender @@ -781,7 +780,7 @@ async fn process_account_updated_from_sources( warn!("failed to send feed matadata event: {}", e); } } - info!("processing snapshot done"); + debug!("processing snapshot done"); if let Err(e) = metadata_sender(FeedMetadata::SnapshotEnd(update.program_id)) { warn!("failed to send feed matadata event: {}", e); } diff --git a/lib/dex-invariant/src/invariant_dex.rs b/lib/dex-invariant/src/invariant_dex.rs index 2a0f47e..d904965 100644 --- a/lib/dex-invariant/src/invariant_dex.rs +++ b/lib/dex-invariant/src/invariant_dex.rs @@ -1,5 +1,6 @@ use std::{ - collections::{HashMap, HashSet}, str::FromStr, sync::Arc + collections::{HashMap, HashSet}, + sync::Arc, }; use anchor_lang::{AnchorDeserialize, Id}; @@ -14,7 +15,6 @@ use invariant_types::{ structs::{Pool, Tick, Tickmap, TickmapView, TICK_CROSSES_PER_IX, TICK_LIMIT}, ANCHOR_DISCRIMINATOR_SIZE, TICK_SEED, }; -use itertools::Itertools; use router_feed_lib::router_rpc_client::{RouterRpcClient, RouterRpcClientTrait}; use router_lib::dex::{ AccountProviderView, DexEdge, DexEdgeIdentifier, DexInterface, DexSubscriptionMode, Quote, @@ -26,7 +26,7 @@ use solana_client::{ rpc_filter::RpcFilterType, }; use solana_sdk::{account::ReadableAccount, program_pack::Pack, pubkey::Pubkey}; -use tracing::{debug, error, info}; +use tracing::info; use crate::{ invariant_edge::{InvariantEdge, InvariantEdgeIdentifier, InvariantSimulationParams}, @@ -192,11 +192,9 @@ where { chain_data: &AccountProviderView, ) -> anyhow::Result { let pool_account_data = chain_data.account(&id.pool)?; - let pool = Self::deserialize::(pool_account_data.account.data())?; let tickmap_account_data = chain_data.account(&pool.tickmap)?; - let tickmap = Self::deserialize_tickmap_view( &tickmap_account_data.account.data(), pool.current_tick_index, @@ -261,6 +259,8 @@ impl DexInterface for InvariantDex { || banned_reserves.contains(&p.1.token_y_reserve)) }); + info!("Number of Invariant Pools: {:?}", pools.len()); + let edge_pairs: Vec<(Arc, Arc)> = pools .iter() .map(|(pool_pk, pool)| { @@ -281,7 +281,6 @@ impl DexInterface for InvariantDex { }) .into_iter() .collect(); - let tickmaps = pools.iter().map(|p| p.1.tickmap).collect(); let tickmaps = rpc.get_multiple_accounts(&tickmaps).await?; @@ -293,7 +292,6 @@ impl DexInterface for InvariantDex { { let entry: Vec> = vec![edge_x_to_y.clone(), edge_y_to_x.clone()]; - map.insert(*pool_pk, entry.clone()); map.insert(*tickmap_pk, entry.clone()); @@ -307,11 +305,6 @@ impl DexInterface for InvariantDex { map }; - info!("inv init done"); - let poolpk = Pubkey::from_str("G8Skt6kgqVL9ocYn4aYVGs3gUg8EfQrTJAkA2qt3gcs8").unwrap(); - info!("pool edges: {:?}", edges_per_pk.get(&poolpk).map(|ids| ids.iter().map(|id| vec![id.input_mint(), id.output_mint()]).collect_vec())); - - Ok(Arc::new(InvariantDex { edges: edges_per_pk, })) @@ -342,9 +335,9 @@ impl DexInterface for InvariantDex { .as_any() .downcast_ref::() .unwrap(); - let edge: Result = Self::load_edge(id, chain_data); - debug!("load edge with id={id:?} -> {edge:?}"); - Ok(Arc::new(edge?)) + let edge = Self::load_edge(id, chain_data)?; + + Ok(Arc::new(edge)) } fn quote( @@ -366,7 +359,7 @@ impl DexInterface for InvariantDex { } else { calculate_price_sqrt(get_max_tick(edge.pool.tick_spacing)?) }; - + let simulation = edge .simulate_invariant_swap(&InvariantSimulationParams { x_to_y, @@ -374,7 +367,7 @@ impl DexInterface for InvariantDex { sqrt_price_limit, by_amount_in: true, }) - .map_err(|e| { debug!("quote id={id:?} error: {:?}", e); anyhow::format_err!(e) }) + .map_err(|e| anyhow::format_err!(e)) .with_context(|| format!("pool {} x_to_y {}", id.pool, id.x_to_y))?; let fee_mint = if x_to_y { id.token_x } else { id.token_y }; diff --git a/lib/dex-invariant/src/invariant_ix_builder.rs b/lib/dex-invariant/src/invariant_ix_builder.rs index 715da29..6351642 100644 --- a/lib/dex-invariant/src/invariant_ix_builder.rs +++ b/lib/dex-invariant/src/invariant_ix_builder.rs @@ -8,7 +8,6 @@ use sha2::{Digest, Sha256}; use solana_program::instruction::Instruction; use solana_program::pubkey::Pubkey; use solana_sdk::account::ReadableAccount; -use tracing::info; pub fn build_swap_ix( id: &InvariantEdgeIdentifier, diff --git a/lib/router-lib/src/price_feeds/birdeye.rs b/lib/router-lib/src/price_feeds/birdeye.rs index 71e99df..27eabb7 100644 --- a/lib/router-lib/src/price_feeds/birdeye.rs +++ b/lib/router-lib/src/price_feeds/birdeye.rs @@ -86,7 +86,10 @@ impl BirdeyePriceFeed { mints: &HashSet, sender: broadcast::Sender, ) -> anyhow::Result<()> { + + // TODO: disabled for eclipse launch until traffic is live return Ok(()); + let http_client = reqwest::Client::new(); let mut chunks: Vec> = vec![]; diff --git a/lib/router-lib/src/price_feeds/price_cache.rs b/lib/router-lib/src/price_feeds/price_cache.rs index 6b2e07f..a909b95 100644 --- a/lib/router-lib/src/price_feeds/price_cache.rs +++ b/lib/router-lib/src/price_feeds/price_cache.rs @@ -14,10 +14,14 @@ impl PriceCache { pub fn new( mut exit: tokio::sync::broadcast::Receiver<()>, mut receiver: tokio::sync::broadcast::Receiver, - ) -> (PriceCache, JoinHandle<()>) { + ) -> (PriceCache, JoinHandle<()>) { let latest_prices = Arc::new(DashMap::new()); - //latest_prices.insert(Pubkey::from_str("So11111111111111111111111111111111111111112").unwrap(), 2500.0); - latest_prices.insert(Pubkey::from_str("AKEWE7Bgh87GPp171b4cJPSSZfmZwQ3KaqYqXoKLNAEE").unwrap(), 1.0); + // seed price cache with stable coin prices, as a point of reference + latest_prices.insert( + Pubkey::from_str("AKEWE7Bgh87GPp171b4cJPSSZfmZwQ3KaqYqXoKLNAEE").unwrap(), + 1.0, + ); + let latest_prices_write = latest_prices.clone(); let job = tokio::spawn(async move { diff --git a/programs/autobahn-executor/src/instructions/execute_swap_v3.rs b/programs/autobahn-executor/src/instructions/execute_swap_v3.rs index ef8d90b..10f294c 100644 --- a/programs/autobahn-executor/src/instructions/execute_swap_v3.rs +++ b/programs/autobahn-executor/src/instructions/execute_swap_v3.rs @@ -86,7 +86,6 @@ pub fn execute_swap_v3( let out_amount = balance_after - balance_before; let out_mint = token::get_mint(ix_token_account)?; - if ix_index == 0 { input_amount = input_token_account_balance - token::get_balance(&accounts[0])?; input_mint = in_mint;