diff --git a/Cargo.lock b/Cargo.lock index e70e9a98c..d237970fa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1698,19 +1698,6 @@ dependencies = [ "syn 1.0.105", ] -[[package]] -name = "env_logger" -version = "0.8.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a19187fea3ac7e84da7dacf48de0c45d63c6a76f9490dae389aead16c243fce3" -dependencies = [ - "atty", - "humantime", - "log 0.4.17", - "regex", - "termcolor", -] - [[package]] name = "env_logger" version = "0.9.3" @@ -2949,7 +2936,7 @@ dependencies = [ "bytemuck", "default-env", "derivative", - "env_logger 0.9.3", + "env_logger", "fixed", "itertools", "lazy_static", @@ -2983,11 +2970,9 @@ dependencies = [ "anyhow", "clap 3.2.23", "dotenv", - "env_logger 0.8.4", "fixed", "futures 0.3.25", "itertools", - "log 0.4.17", "mango-v4", "mango-v4-client", "pyth-sdk-solana", @@ -2995,6 +2980,7 @@ dependencies = [ "solana-client", "solana-sdk", "tokio", + "tracing", ] [[package]] @@ -3008,6 +2994,7 @@ dependencies = [ "async-channel", "async-once-cell", "async-trait", + "atty", "base64 0.13.1", "bincode", "fixed", @@ -3015,7 +3002,6 @@ dependencies = [ "itertools", "jsonrpc-core 18.0.0 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-core-client", - "log 0.4.17", "mango-feeds-connector", "mango-v4", "pyth-sdk-solana", @@ -3033,6 +3019,8 @@ dependencies = [ "thiserror", "tokio", "tokio-stream", + "tracing", + "tracing-subscriber", ] [[package]] @@ -3045,12 +3033,10 @@ dependencies = [ "anyhow", "clap 3.2.23", "dotenv", - "env_logger 0.8.4", "fixed", "futures 0.3.25", "itertools", "lazy_static", - "log 0.4.17", "mango-v4", "mango-v4-client", "prometheus", @@ -3059,6 +3045,7 @@ dependencies = [ "solana-client", "solana-sdk", "tokio", + "tracing", "warp", ] @@ -3086,7 +3073,6 @@ dependencies = [ "jemallocator", "jsonrpc-core 18.0.0 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-core-client", - "log 0.4.17", "mango-v4", "mango-v4-client", "once_cell", @@ -3105,6 +3091,7 @@ dependencies = [ "tokio", "tokio-stream", "tokio-tungstenite 0.16.1", + "tracing", ] [[package]] @@ -3132,7 +3119,6 @@ dependencies = [ "jemallocator", "jsonrpc-core 18.0.0 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-core-client", - "log 0.4.17", "mango-v4", "mango-v4-client", "once_cell", @@ -3152,6 +3138,16 @@ dependencies = [ "tokio", "tokio-stream", "tokio-tungstenite 0.16.1", + "tracing", +] + +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", ] [[package]] @@ -3425,6 +3421,16 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi 0.3.9", +] + [[package]] name = "num" version = "0.2.1" @@ -3726,6 +3732,12 @@ dependencies = [ "syn 1.0.105", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.9.0" @@ -4520,6 +4532,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.28" @@ -5681,7 +5702,7 @@ version = "1.14.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2b502866be84a799633c0744e1d72b819a256337149e9fb6c7eee4db84ec63f5" dependencies = [ - "env_logger 0.9.3", + "env_logger", "lazy_static", "log 0.4.17", ] @@ -7238,6 +7259,17 @@ dependencies = [ "tracing", ] +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log 0.4.17", + "tracing-core", +] + [[package]] name = "tracing-opentelemetry" version = "0.17.4" @@ -7257,9 +7289,16 @@ version = "0.3.16" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", "sharded-slab", + "smallvec 1.10.0", "thread_local", + "tracing", "tracing-core", + "tracing-log", ] [[package]] diff --git a/bin/cli/Cargo.toml b/bin/cli/Cargo.toml index 8842f19a0..4e5153c7a 100644 --- a/bin/cli/Cargo.toml +++ b/bin/cli/Cargo.toml @@ -16,10 +16,8 @@ anchor-spl = { workspace = true } anyhow = "1.0" clap = { version = "3.1.8", features = ["derive", "env"] } dotenv = "0.15.0" -env_logger = "0.8.4" fixed = { workspace = true, features = ["serde", "borsh"] } futures = "0.3.21" -log = "0.4.0" mango-v4 = { path = "../../programs/mango-v4", features = ["client"] } mango-v4-client = { path = "../../lib/client" } pyth-sdk-solana = { workspace = true } @@ -28,3 +26,4 @@ solana-client = { workspace = true } solana-sdk = { workspace = true } tokio = { version = "1.14.1", features = ["rt-multi-thread", "time", "macros", "sync"] } itertools = "0.10.3" +tracing = "0.1" diff --git a/bin/cli/src/main.rs b/bin/cli/src/main.rs index 9921c147e..819ec4a2f 100644 --- a/bin/cli/src/main.rs +++ b/bin/cli/src/main.rs @@ -137,9 +137,7 @@ impl Rpc { #[tokio::main] async fn main() -> Result<(), anyhow::Error> { - env_logger::init_from_env( - env_logger::Env::default().filter_or(env_logger::DEFAULT_FILTER_ENV, "info"), - ); + mango_v4_client::tracing_subscriber_init(); dotenv::dotenv().ok(); let cli = Cli::parse(); diff --git a/bin/cli/src/test_oracles.rs b/bin/cli/src/test_oracles.rs index 2d85a14af..7f8be54c0 100644 --- a/bin/cli/src/test_oracles.rs +++ b/bin/cli/src/test_oracles.rs @@ -3,6 +3,7 @@ use mango_v4::accounts_zerocopy::KeyedAccount; use mango_v4_client::{Client, MangoGroupContext}; use solana_sdk::commitment_config::CommitmentConfig; use solana_sdk::pubkey::Pubkey; +use tracing::*; pub async fn run(client: &Client, group: Pubkey) -> anyhow::Result<()> { let rpc_async = client.rpc_async(); @@ -23,7 +24,7 @@ pub async fn run(client: &Client, group: Pubkey) -> anyhow::Result<()> { .get_multiple_accounts_with_commitment(&oracles, CommitmentConfig::processed()) .await; if response.is_err() { - log::warn!("could not fetch oracles"); + warn!("could not fetch oracles"); continue; } let response = response.unwrap(); @@ -32,7 +33,7 @@ pub async fn run(client: &Client, group: Pubkey) -> anyhow::Result<()> { for (pubkey, account_opt) in oracles.iter().zip(accounts.into_iter()) { if account_opt.is_none() { - log::warn!("no oracle data for {pubkey}"); + warn!("no oracle data for {pubkey}"); continue; } let keyed_account = KeyedAccount { @@ -53,7 +54,7 @@ pub async fn run(client: &Client, group: Pubkey) -> anyhow::Result<()> { match tc.bank.oracle_price(&keyed_account, Some(slot)) { Ok(p) => price = Some(p), Err(e) => { - log::error!("could not read bank oracle {}: {e:?}", keyed_account.key); + error!("could not read bank oracle {}: {e:?}", keyed_account.key); } } } @@ -61,12 +62,12 @@ pub async fn run(client: &Client, group: Pubkey) -> anyhow::Result<()> { match pc.market.oracle_price(&keyed_account, Some(slot)) { Ok(p) => price = Some(p), Err(e) => { - log::error!("could not read perp oracle {}: {e:?}", keyed_account.key); + error!("could not read perp oracle {}: {e:?}", keyed_account.key); } } } if let Some(p) = price { - log::info!("{pubkey},{p}"); + info!("{pubkey},{p}"); } } } diff --git a/bin/keeper/Cargo.toml b/bin/keeper/Cargo.toml index f7ebae745..0ce59102b 100644 --- a/bin/keeper/Cargo.toml +++ b/bin/keeper/Cargo.toml @@ -16,11 +16,9 @@ anchor-spl = { workspace = true } anyhow = "1.0" clap = { version = "3.1.8", features = ["derive", "env"] } dotenv = "0.15.0" -env_logger = "0.8.4" fixed = { workspace = true, features = ["serde", "borsh"] } futures = "0.3.21" itertools = "0.10.3" -log = "0.4.0" mango-v4 = { path = "../../programs/mango-v4", features = ["client"] } mango-v4-client = { path = "../../lib/client" } pyth-sdk-solana = { workspace = true } @@ -31,3 +29,4 @@ tokio = { version = "1.14.1", features = ["rt-multi-thread", "time", "macros", " prometheus = "0.13.3" warp = "0.3.3" lazy_static = "1.4.0" +tracing = "0.1" diff --git a/bin/keeper/src/crank.rs b/bin/keeper/src/crank.rs index 572a03721..1e82eba4f 100644 --- a/bin/keeper/src/crank.rs +++ b/bin/keeper/src/crank.rs @@ -12,6 +12,7 @@ use solana_sdk::{ pubkey::Pubkey, }; use tokio::time; +use tracing::*; use warp::Filter; lazy_static::lazy_static! { @@ -229,21 +230,18 @@ pub async fn loop_update_index_and_rate( if let Err(e) = sig_result { METRIC_UPDATE_TOKENS_FAILURE.inc(); - log::info!( + info!( "metricName=UpdateTokensV4Failure tokens={} durationMs={} error={}", - token_names, - confirmation_time, - e + token_names, confirmation_time, e ); - log::error!("{:?}", e) + error!("{:?}", e) } else { METRIC_UPDATE_TOKENS_SUCCESS.inc(); - log::info!( + info!( "metricName=UpdateTokensV4Success tokens={} durationMs={}", - token_names, - confirmation_time, + token_names, confirmation_time, ); - log::info!("{:?}", sig_result); + info!("{:?}", sig_result); } } } @@ -304,7 +302,7 @@ pub async fn loop_consume_events( Ok(Some(x)) => x, Ok(None) => continue, Err(err) => { - log::error!("preparing consume_events ams: {err:?}"); + error!("preparing consume_events ams: {err:?}"); continue; } }; @@ -347,23 +345,23 @@ pub async fn loop_consume_events( if let Err(e) = sig_result { METRIC_CONSUME_EVENTS_FAILURE.inc(); - log::info!( + info!( "metricName=ConsumeEventsV4Failure market={} durationMs={} consumed={} error={}", perp_market.name(), confirmation_time, num_of_events, e.to_string() ); - log::error!("{:?}", e) + error!("{:?}", e) } else { METRIC_CONSUME_EVENTS_SUCCESS.inc(); - log::info!( + info!( "metricName=ConsumeEventsV4Success market={} durationMs={} consumed={}", perp_market.name(), confirmation_time, num_of_events, ); - log::info!("{:?}", sig_result); + info!("{:?}", sig_result); } } } @@ -402,21 +400,21 @@ pub async fn loop_update_funding( if let Err(e) = sig_result { METRIC_UPDATE_FUNDING_FAILURE.inc(); - log::error!( + error!( "metricName=UpdateFundingV4Error market={} durationMs={} error={}", perp_market.name(), confirmation_time, e.to_string() ); - log::error!("{:?}", e) + error!("{:?}", e) } else { METRIC_UPDATE_FUNDING_SUCCESS.inc(); - log::info!( + info!( "metricName=UpdateFundingV4Success market={} durationMs={}", perp_market.name(), confirmation_time, ); - log::info!("{:?}", sig_result); + info!("{:?}", sig_result); } } } diff --git a/bin/keeper/src/main.rs b/bin/keeper/src/main.rs index 47ce8f294..f5b88a730 100644 --- a/bin/keeper/src/main.rs +++ b/bin/keeper/src/main.rs @@ -11,6 +11,7 @@ use mango_v4_client::{keypair_from_cli, Client, MangoClient, TransactionBuilderC use solana_sdk::commitment_config::CommitmentConfig; use solana_sdk::pubkey::Pubkey; use tokio::time; +use tracing::*; // TODO // - may be nice to have one-shot cranking as well as the interval cranking @@ -73,9 +74,7 @@ enum Command { #[tokio::main] async fn main() -> Result<(), anyhow::Error> { - env_logger::init_from_env( - env_logger::Env::default().filter_or(env_logger::DEFAULT_FILTER_ENV, "info"), - ); + mango_v4_client::tracing_subscriber_init(); let args = if let Ok(cli_dotenv) = CliDotenv::try_parse() { dotenv::from_path(cli_dotenv.dotenv)?; @@ -121,7 +120,7 @@ async fn main() -> Result<(), anyhow::Error> { interval.tick().await; let client = mango_client.clone(); tokio::task::spawn_blocking(move || { - log::info!( + info!( "Arc::strong_count() {}", Arc::::strong_count(&client) ) diff --git a/bin/keeper/src/taker.rs b/bin/keeper/src/taker.rs index d24f0a965..17cd9ebc2 100644 --- a/bin/keeper/src/taker.rs +++ b/bin/keeper/src/taker.rs @@ -10,6 +10,7 @@ use mango_v4::{ accounts_ix::{Serum3OrderType, Serum3SelfTradeBehavior, Serum3Side}, state::TokenIndex, }; +use tracing::*; use tokio::time; @@ -90,7 +91,7 @@ async fn ensure_deposit(mango_client: &Arc) -> Result<(), anyhow::E Some(token_account) => { let native = token_account.native(&bank); let ui = token_account.ui(&bank); - log::info!("Current balance {} {}", ui, bank.name()); + info!("Current balance {} {}", ui, bank.name()); if native < I80F48::ZERO { desired_balance - native @@ -105,7 +106,7 @@ async fn ensure_deposit(mango_client: &Arc) -> Result<(), anyhow::E continue; } - log::info!("Depositing {} {}", deposit_native, bank.name()); + info!("Depositing {} {}", deposit_native, bank.name()); mango_client .token_deposit(bank.mint, desired_balance.to_num(), false) .await?; @@ -125,7 +126,7 @@ pub async fn loop_blocking_price_update( interval.tick().await; let fresh_price = mango_client.bank_oracle_price(token_index).await.unwrap(); - log::info!("{} Updated price is {:?}", token_name, fresh_price); + info!("{} Updated price is {:?}", token_name, fresh_price); if let Ok(mut price) = price.write() { *price = fresh_price; } @@ -144,7 +145,7 @@ pub async fn loop_blocking_orders( .serum3_cancel_all_orders(&market_name) .await .unwrap(); - log::info!("Cancelled orders - {:?} for {}", orders, market_name); + info!("Cancelled orders - {:?} for {}", orders, market_name); let market_index = mango_client.context.serum3_market_index(&market_name); let s3 = mango_client.context.serum3(market_index); @@ -178,9 +179,9 @@ pub async fn loop_blocking_orders( ) .await; if let Err(e) = res { - log::error!("Error while placing taker bid {:#?}", e) + error!("Error while placing taker bid {:#?}", e) } else { - log::info!("Placed bid at {} for {}", bid_price, market_name) + info!("Placed bid at {} for {}", bid_price, market_name) } let ask_price = fresh_price * 0.9; @@ -200,9 +201,9 @@ pub async fn loop_blocking_orders( ) .await; if let Err(e) = res { - log::error!("Error while placing taker ask {:#?}", e) + error!("Error while placing taker ask {:#?}", e) } else { - log::info!("Placed ask at {} for {}", ask_price, market_name) + info!("Placed ask at {} for {}", ask_price, market_name) } Ok(()) @@ -210,7 +211,7 @@ pub async fn loop_blocking_orders( .await; if let Err(err) = res { - log::error!("{:?}", err); + error!("{:?}", err); } } } diff --git a/bin/liquidator/Cargo.toml b/bin/liquidator/Cargo.toml index 99737f13e..a099d61a2 100644 --- a/bin/liquidator/Cargo.toml +++ b/bin/liquidator/Cargo.toml @@ -30,7 +30,6 @@ itertools = "0.10.3" jemallocator = "0.3.2" jsonrpc-core = "18.0.0" jsonrpc-core-client = { version = "18.0.0", features = ["ws", "http", "tls"] } -log = "0.4" mango-v4 = { path = "../../programs/mango-v4", features = ["client"] } mango-v4-client = { path = "../../lib/client" } once_cell = "1.12.0" @@ -49,3 +48,4 @@ solana-sdk = { workspace = true } tokio = { version = "1", features = ["full"] } tokio-stream = { version = "0.1.9"} tokio-tungstenite = "0.16.1" +tracing = "0.1" diff --git a/bin/liquidator/src/liquidate.rs b/bin/liquidator/src/liquidate.rs index 9a0b09f80..8387789e4 100644 --- a/bin/liquidator/src/liquidate.rs +++ b/bin/liquidator/src/liquidate.rs @@ -8,6 +8,7 @@ use solana_sdk::signature::Signature; use futures::{stream, StreamExt, TryStreamExt}; use rand::seq::SliceRandom; +use tracing::*; use {anyhow::Context, fixed::types::I80F48, solana_sdk::pubkey::Pubkey}; use crate::util; @@ -118,7 +119,7 @@ impl<'a> LiquidateHelper<'a> { } // Cancel all orders on a random serum market let serum_orders = serum_force_cancels.choose(&mut rand::thread_rng()).unwrap(); - let sig = self + let txsig = self .client .serum3_liq_force_cancel_orders( (self.pubkey, &self.liqee), @@ -126,14 +127,12 @@ impl<'a> LiquidateHelper<'a> { &serum_orders.open_orders, ) .await?; - log::info!( - "Force cancelled serum orders on account {}, market index {}, maint_health was {}, tx sig {:?}", - self.pubkey, - serum_orders.market_index, - self.maint_health, - sig + info!( + market_index = serum_orders.market_index, + %txsig, + "Force cancelled serum orders", ); - Ok(Some(sig)) + Ok(Some(txsig)) } async fn perp_close_orders(&self) -> anyhow::Result> { @@ -148,18 +147,16 @@ impl<'a> LiquidateHelper<'a> { // Cancel all orders on a random perp market let perp_market_index = *perp_force_cancels.choose(&mut rand::thread_rng()).unwrap(); - let sig = self + let txsig = self .client .perp_liq_force_cancel_orders((self.pubkey, &self.liqee), perp_market_index) .await?; - log::info!( - "Force cancelled perp orders on account {}, market index {}, maint_health was {}, tx sig {:?}", - self.pubkey, + info!( perp_market_index, - self.maint_health, - sig + %txsig, + "Force cancelled perp orders", ); - Ok(Some(sig)) + Ok(Some(txsig)) } async fn perp_liq_base_or_positive_pnl(&self) -> anyhow::Result> { @@ -254,9 +251,13 @@ impl<'a> LiquidateHelper<'a> { (max_base_transfer, max_pnl_transfer.floor().to_num::()) }; - log::info!("computed max_base_transfer: {max_base_transfer_abs}, max_pnl_transfer: {max_pnl_transfer}"); + trace!( + max_base_transfer_abs, + max_pnl_transfer, + "computed transfer maximums" + ); - let sig = self + let txsig = self .client .perp_liq_base_or_positive_pnl( (self.pubkey, &self.liqee), @@ -265,14 +266,12 @@ impl<'a> LiquidateHelper<'a> { max_pnl_transfer, ) .await?; - log::info!( - "Liquidated base position for perp market on account {}, market index {}, maint_health was {}, tx sig {:?}", - self.pubkey, + info!( perp_market_index, - self.maint_health, - sig + %txsig, + "Liquidated base position for perp market", ); - Ok(Some(sig)) + Ok(Some(txsig)) } async fn perp_liq_negative_pnl_or_bankruptcy(&self) -> anyhow::Result> { @@ -297,7 +296,7 @@ impl<'a> LiquidateHelper<'a> { } let (perp_market_index, _) = perp_negative_pnl.first().unwrap(); - let sig = self + let txsig = self .client .perp_liq_negative_pnl_or_bankruptcy( (self.pubkey, &self.liqee), @@ -306,14 +305,12 @@ impl<'a> LiquidateHelper<'a> { u64::MAX, ) .await?; - log::info!( - "Liquidated negative perp pnl on account {}, market index {}, maint_health was {}, tx sig {:?}", - self.pubkey, + info!( perp_market_index, - self.maint_health, - sig + %txsig, + "Liquidated negative perp pnl", ); - Ok(Some(sig)) + Ok(Some(txsig)) } async fn tokens(&self) -> anyhow::Result> { @@ -415,7 +412,7 @@ impl<'a> LiquidateHelper<'a> { // TODO: log liqor's assets in UI form // TODO: log liquee's liab_needed, need to refactor program code to be able to be accessed from client side // - let sig = self + let txsig = self .client .token_liq_with_token( (self.pubkey, &self.liqee), @@ -425,13 +422,13 @@ impl<'a> LiquidateHelper<'a> { ) .await .context("sending liq_token_with_token")?; - log::info!( - "Liquidated token with token for {}, maint_health was {}, tx sig {:?}", - self.pubkey, - self.maint_health, - sig + info!( + asset_token_index, + liab_token_index, + %txsig, + "Liquidated token with token", ); - Ok(Some(sig)) + Ok(Some(txsig)) } async fn token_liq_bankruptcy(&self) -> anyhow::Result> { @@ -469,7 +466,7 @@ impl<'a> LiquidateHelper<'a> { .max_token_liab_transfer(liab_token_index, quote_token_index) .await?; - let sig = self + let txsig = self .client .token_liq_bankruptcy( (self.pubkey, &self.liqee), @@ -478,15 +475,15 @@ impl<'a> LiquidateHelper<'a> { ) .await .context("sending liq_token_bankruptcy")?; - log::info!( - "Liquidated bankruptcy for {}, maint_health was {}, tx sig {:?}", - self.pubkey, - self.maint_health, - sig + info!( + liab_token_index, + %txsig, + "Liquidated token bankruptcy", ); - Ok(Some(sig)) + Ok(Some(txsig)) } + #[instrument(skip(self), fields(pubkey = %*self.pubkey, maint = %self.maint_health))] async fn send_liq_tx(&self) -> anyhow::Result> { // TODO: Should we make an attempt to settle positive PNL first? // The problem with it is that small market movements can continuously create @@ -529,11 +526,7 @@ impl<'a> LiquidateHelper<'a> { } if self.health_cache.has_perp_open_fills() { - log::info!( - "Account {} has open perp fills, maint_health {}, waiting...", - self.pubkey, - self.maint_health - ); + info!("there are open perp fills, waiting...",); return Ok(None); } @@ -587,11 +580,10 @@ pub async fn maybe_liquidate_account( return Ok(false); } - log::trace!( - "possible candidate: {}, with owner: {}, maint health: {}", - pubkey, - account.fixed.owner, - maint_health, + trace!( + %pubkey, + %maint_health, + "possible candidate", ); // Fetch a fresh account and re-compute @@ -640,7 +632,7 @@ pub async fn maybe_liquidate_account( ) .await { - log::info!("could not refresh after liquidation: {}", e); + info!("could not refresh after liquidation: {}", e); } } diff --git a/bin/liquidator/src/main.rs b/bin/liquidator/src/main.rs index 0463ff9ec..064e49674 100644 --- a/bin/liquidator/src/main.rs +++ b/bin/liquidator/src/main.rs @@ -1,10 +1,10 @@ use std::collections::HashMap; +use std::collections::HashSet; use std::sync::{Arc, RwLock}; use std::time::{Duration, Instant}; use anchor_client::Cluster; use clap::Parser; -use log::*; use mango_v4::state::{PerpMarketIndex, TokenIndex}; use mango_v4_client::{ account_update_stream, chain_data, keypair_from_cli, snapshot_source, websocket_source, @@ -15,7 +15,7 @@ use mango_v4_client::{ use itertools::Itertools; use solana_sdk::commitment_config::CommitmentConfig; use solana_sdk::pubkey::Pubkey; -use std::collections::HashSet; +use tracing::*; pub mod liquidate; pub mod metrics; @@ -41,6 +41,14 @@ struct CliDotenv { remaining_args: Vec, } +// Prefer "--rebalance false" over "--no-rebalance" because it works +// better with REBALANCE=false env values. +#[derive(clap::ValueEnum, Clone, Copy, Debug, PartialEq, Eq)] +enum BoolArg { + True, + False, +} + #[derive(Parser)] #[clap()] struct Cli { @@ -71,8 +79,8 @@ struct Cli { /// if rebalancing is enabled /// /// typically only disabled for tests where swaps are unavailable - #[clap(long, env, default_value = "true")] - rebalance: bool, + #[clap(long, env, value_enum, default_value = "true")] + rebalance: BoolArg, /// max slippage to request on swaps to rebalance spot tokens #[clap(long, env, default_value = "100")] @@ -85,8 +93,8 @@ struct Cli { /// use a jupiter mock instead of actual queries /// /// This is required for devnet testing. - #[clap(long, env, default_value = "false")] - mock_jupiter: bool, + #[clap(long, env, value_enum, default_value = "false")] + mock_jupiter: BoolArg, } pub fn encode_address(addr: &Pubkey) -> String { @@ -95,6 +103,8 @@ pub fn encode_address(addr: &Pubkey) -> String { #[tokio::main] async fn main() -> anyhow::Result<()> { + mango_v4_client::tracing_subscriber_init(); + let args = if let Ok(cli_dotenv) = CliDotenv::try_parse() { dotenv::from_path(cli_dotenv.dotenv)?; cli_dotenv.remaining_args @@ -161,7 +171,6 @@ async fn main() -> anyhow::Result<()> { // FUTURE: decouple feed setup and liquidator business logic // feed should send updates to a channel which liquidator can consume - solana_logger::setup_with_default("info"); info!("startup"); let metrics = metrics::start(); @@ -222,7 +231,7 @@ async fn main() -> anyhow::Result<()> { let token_swap_info_config = token_swap_info::Config { quote_index: 0, // USDC quote_amount: 1_000_000_000, // TODO: config, $1000, should be >= tcs_config.max_trigger_quote_amount - mock_jupiter: cli.mock_jupiter, + mock_jupiter: cli.mock_jupiter == BoolArg::True, }; let token_swap_info_updater = Arc::new(token_swap_info::TokenSwapInfoUpdater::new( @@ -232,7 +241,7 @@ async fn main() -> anyhow::Result<()> { let liq_config = liquidate::Config { min_health_ratio: cli.min_health_ratio, - mock_jupiter: cli.mock_jupiter, + mock_jupiter: cli.mock_jupiter == BoolArg::True, // TODO: config refresh_timeout: Duration::from_secs(30), }; @@ -240,14 +249,14 @@ async fn main() -> anyhow::Result<()> { let tcs_config = trigger_tcs::Config { min_health_ratio: cli.min_health_ratio, max_trigger_quote_amount: 1_000_000_000, // TODO: config, $1000 - mock_jupiter: cli.mock_jupiter, + mock_jupiter: cli.mock_jupiter == BoolArg::True, // TODO: config refresh_timeout: Duration::from_secs(30), }; let mut rebalance_interval = tokio::time::interval(Duration::from_secs(5)); let rebalance_config = rebalance::Config { - enabled: cli.rebalance, + enabled: cli.rebalance == BoolArg::True, slippage_bps: cli.rebalance_slippage_bps, // TODO: config borrow_settle_excess: 1.05, @@ -261,7 +270,7 @@ async fn main() -> anyhow::Result<()> { config: rebalance_config, }); - let mut liquidation = LiquidationState { + let mut liquidation = Box::new(LiquidationState { mango_client, account_fetcher, liquidation_config: liq_config, @@ -280,7 +289,7 @@ async fn main() -> anyhow::Result<()> { reset_duration: std::time::Duration::from_secs(360), ..ErrorTracking::default() }, - }; + }); let (liquidation_trigger_sender, liquidation_trigger_receiver) = async_channel::bounded::<()>(1); @@ -316,7 +325,7 @@ async fn main() -> anyhow::Result<()> { let mut state = shared_state.write().unwrap(); if is_mango_account(&account_write.account, &mango_group).is_some() { // e.g. to render debug logs RUST_LOG="liquidator=debug" - log::debug!( + debug!( "change to mango account {}...", &account_write.pubkey.to_string()[0..3] ); @@ -332,15 +341,15 @@ async fn main() -> anyhow::Result<()> { } else { let mut must_check_all = false; if is_mango_bank(&account_write.account, &mango_group).is_some() { - log::debug!("change to bank {}", &account_write.pubkey); + debug!("change to bank {}", &account_write.pubkey); must_check_all = true; } if is_perp_market(&account_write.account, &mango_group).is_some() { - log::debug!("change to perp market {}", &account_write.pubkey); + debug!("change to perp market {}", &account_write.pubkey); must_check_all = true; } if oracles.contains(&account_write.pubkey) { - log::debug!("change to oracle {}", &account_write.pubkey); + debug!("change to oracle {}", &account_write.pubkey); must_check_all = true; } if must_check_all { @@ -391,7 +400,7 @@ async fn main() -> anyhow::Result<()> { continue; } if let Err(err) = rebalancer.zero_all_non_quote().await { - log::error!("failed to rebalance liqor: {:?}", err); + error!("failed to rebalance liqor: {:?}", err); // Workaround: We really need a sequence enforcer in the liquidator since we don't want to // accidentally send a similar tx again when we incorrectly believe an earlier one got forked @@ -459,7 +468,7 @@ async fn main() -> anyhow::Result<()> { match token_swap_info_updater.update_one(token_index).await { Ok(()) => {} Err(err) => { - log::warn!( + warn!( "failed to update token swap info for token {token_index}: {:?}", err ); @@ -485,7 +494,7 @@ async fn main() -> anyhow::Result<()> { .collect(); jobs.next().await; - log::error!("a critical job aborted, exiting"); + error!("a critical job aborted, exiting"); Ok(()) } @@ -591,7 +600,7 @@ impl LiquidationState { } if let Err(err) = self.rebalancer.zero_all_non_quote().await { - log::error!("failed to rebalance liqor: {:?}", err); + error!("failed to rebalance liqor: {:?}", err); } Ok(true) } @@ -602,7 +611,7 @@ impl LiquidationState { // Skip a pubkey if there've been too many errors recently if let Some(error_entry) = error_tracking.had_too_many_errors(pubkey, now) { - log::trace!( + trace!( "skip checking account {pubkey}, had {} errors recently", error_entry.count ); @@ -622,7 +631,7 @@ impl LiquidationState { error_tracking.record_error(pubkey, now); // Not all errors need to be raised to the user's attention. - let mut log_level = log::Level::Error; + let mut is_error = true; // Simulation errors due to liqee precondition failures on the liquidation instructions // will commonly happen if our liquidator is late or if there are chain forks. @@ -631,12 +640,16 @@ impl LiquidationState { if logs.iter().any(|line| { line.contains("HealthMustBeNegative") || line.contains("IsNotBankrupt") }) { - log_level = log::Level::Trace; + is_error = false; } } _ => {} }; - log::log!(log_level, "liquidating account {}: {:?}", pubkey, err); + if is_error { + error!("liquidating account {}: {:?}", pubkey, err); + } else { + trace!("liquidating account {}: {:?}", pubkey, err); + } } else { error_tracking.clear_errors(pubkey); } @@ -672,7 +685,7 @@ impl LiquidationState { } if let Err(err) = self.rebalancer.zero_all_non_quote().await { - log::error!("failed to rebalance liqor: {:?}", err); + error!("failed to rebalance liqor: {:?}", err); } Ok(()) } @@ -686,7 +699,7 @@ impl LiquidationState { // Skip a pubkey if there've been too many errors recently if let Some(error_entry) = error_tracking.had_too_many_errors(pubkey, now) { - log::trace!( + trace!( "skip checking for tcs on account {pubkey}, had {} errors recently", error_entry.count ); @@ -707,7 +720,7 @@ impl LiquidationState { error_tracking.record_error(pubkey, now); // Not all errors need to be raised to the user's attention. - let mut log_level = log::Level::Error; + let mut is_error = true; // Simulation errors due to liqee precondition failures // will commonly happen if our liquidator is late or if there are chain forks. @@ -717,17 +730,16 @@ impl LiquidationState { .iter() .any(|line| line.contains("TokenConditionalSwapPriceNotInRange")) { - log_level = log::Level::Trace; + is_error = false; } } _ => {} }; - log::log!( - log_level, - "token conditional swap on account {}: {:?}", - pubkey, - err - ); + if is_error { + error!("token conditional swap on account {}: {:?}", pubkey, err); + } else { + trace!("token conditional swap on account {}: {:?}", pubkey, err); + } } else { error_tracking.clear_errors(pubkey); } diff --git a/bin/liquidator/src/metrics.rs b/bin/liquidator/src/metrics.rs index 434d55d17..5f703a08f 100644 --- a/bin/liquidator/src/metrics.rs +++ b/bin/liquidator/src/metrics.rs @@ -2,6 +2,7 @@ use { std::collections::HashMap, std::sync::{atomic, Arc, Mutex, RwLock}, tokio::time, + tracing::*, }; #[derive(Debug)] @@ -151,7 +152,7 @@ pub fn start() -> Metrics { 0 }; let diff = new_value.wrapping_sub(previous_value) as i64; - log::info!("metric: {}: {} ({:+})", name, new_value, diff); + info!("metric: {}: {} ({:+})", name, new_value, diff); } Value::I64(v) => { let new_value = v.load(atomic::Ordering::Acquire); @@ -164,7 +165,7 @@ pub fn start() -> Metrics { 0 }; let diff = new_value - previous_value; - log::info!("metric: {}: {} ({:+})", name, new_value, diff); + info!("metric: {}: {} ({:+})", name, new_value, diff); } Value::String(v) => { let new_value = v.lock().unwrap(); @@ -178,13 +179,11 @@ pub fn start() -> Metrics { "".into() }; if *new_value == previous_value { - log::info!("metric: {}: {} (unchanged)", name, &*new_value); + info!("metric: {}: {} (unchanged)", name, &*new_value); } else { - log::info!( + info!( "metric: {}: {} (before: {})", - name, - &*new_value, - previous_value + name, &*new_value, previous_value ); } } diff --git a/bin/liquidator/src/rebalance.rs b/bin/liquidator/src/rebalance.rs index 11079c2bc..6bd25c1f4 100644 --- a/bin/liquidator/src/rebalance.rs +++ b/bin/liquidator/src/rebalance.rs @@ -1,9 +1,11 @@ use mango_v4::accounts_zerocopy::KeyedAccountSharedData; use mango_v4::state::{ - Bank, BookSide, PlaceOrderType, Side, TokenIndex, TokenPosition, QUOTE_TOKEN_INDEX, + Bank, BookSide, MangoAccountValue, PerpPosition, PlaceOrderType, Side, TokenIndex, + TokenPosition, QUOTE_TOKEN_INDEX, }; use mango_v4_client::{ - chain_data, perp_pnl, AccountFetcher, AnyhowWrap, JupiterSwapMode, MangoClient, TokenContext, + chain_data, perp_pnl, AccountFetcher, AnyhowWrap, JupiterSwapMode, MangoClient, + PerpMarketContext, TokenContext, }; use {fixed::types::I80F48, solana_sdk::pubkey::Pubkey}; @@ -12,6 +14,7 @@ use futures::{stream, StreamExt, TryStreamExt}; use solana_sdk::signature::Signature; use std::sync::Arc; use std::{collections::HashMap, time::Duration}; +use tracing::*; #[derive(Clone)] pub struct Config { @@ -82,7 +85,10 @@ impl Rebalancer { return Ok(()); } - log::trace!("checking for rebalance: {}", self.mango_account_address); + trace!( + pubkey = %self.mango_account_address, + "checking for rebalance" + ); self.rebalance_perps().await?; self.rebalance_tokens().await?; @@ -104,7 +110,7 @@ impl Rebalancer { { // If we don't get fresh data, maybe the tx landed on a fork? // Rebalance is technically still ok. - log::info!("could not refresh account data: {}", e); + info!("could not refresh account data: {}", e); return Ok(false); } Ok(true) @@ -131,7 +137,7 @@ impl Rebalancer { .try_collect() .await; let tokens = tokens?; - log::trace!("account tokens: {:?}", tokens); + trace!(?tokens, "account tokens"); for (token_index, token_state) in tokens { let token = self.mango_client.context.token(token_index); @@ -172,12 +178,12 @@ impl Rebalancer { JupiterSwapMode::ExactIn, ) .await?; - log::info!( - "bought {} {} for {} in tx {}", + info!( + %txsig, + "bought {} {} for {}", token.native_to_ui(buy_amount), token.name, quote_token.name, - txsig ); if !self.refresh_mango_account_after_tx(txsig).await? { return Ok(()); @@ -204,12 +210,12 @@ impl Rebalancer { JupiterSwapMode::ExactIn, ) .await?; - log::info!( - "sold {} {} for {} in tx {}", + info!( + %txsig, + "sold {} {} for {}", token.native_to_ui(amount), token.name, quote_token.name, - txsig ); if !self.refresh_mango_account_after_tx(txsig).await? { return Ok(()); @@ -232,11 +238,11 @@ impl Rebalancer { .mango_client .token_withdraw(token_mint, u64::MAX, allow_borrow) .await?; - log::info!( - "withdrew {} {} to liqor wallet in {}", + info!( + %txsig, + "withdrew {} {} to liqor wallet", token.native_to_ui(amount), token.name, - txsig ); if !self.refresh_mango_account_after_tx(txsig).await? { return Ok(()); @@ -253,174 +259,170 @@ impl Rebalancer { Ok(()) } - async fn rebalance_perps(&self) -> anyhow::Result<()> { + #[instrument( + skip_all, + fields( + perp_market_name = perp.market.name(), + base_lots = perp_position.base_position_lots(), + effective_lots = perp_position.effective_base_position_lots(), + quote_native = %perp_position.quote_position_native() + ) + )] + async fn rebalance_perp( + &self, + account: &MangoAccountValue, + perp: &PerpMarketContext, + perp_position: &PerpPosition, + ) -> anyhow::Result { let now_ts: u64 = std::time::SystemTime::now() .duration_since(std::time::UNIX_EPOCH)? .as_secs() .try_into()?; - let account = self - .account_fetcher - .fetch_mango_account(&self.mango_account_address)?; + + let base_lots = perp_position.base_position_lots(); + let effective_lots = perp_position.effective_base_position_lots(); + let quote_native = perp_position.quote_position_native(); + + if effective_lots != 0 { + // send an ioc order to reduce the base position + let oracle_account_data = self.account_fetcher.fetch_raw(&perp.market.oracle)?; + let oracle_account = + KeyedAccountSharedData::new(perp.market.oracle, oracle_account_data); + let oracle_price = perp.market.oracle_price(&oracle_account, None)?; + let oracle_price_lots = perp.market.native_price_to_lot(oracle_price); + let (side, order_price, oo_lots) = if effective_lots > 0 { + ( + Side::Ask, + oracle_price * (I80F48::ONE - perp.market.base_liquidation_fee), + perp_position.asks_base_lots, + ) + } else { + ( + Side::Bid, + oracle_price * (I80F48::ONE + perp.market.base_liquidation_fee), + perp_position.bids_base_lots, + ) + }; + let price_lots = perp.market.native_price_to_lot(order_price); + let max_base_lots = effective_lots.abs() - oo_lots; + if max_base_lots <= 0 { + warn!(?side, oo_lots, "cannot place reduce-only order",); + return Ok(true); + } + + // Check the orderbook before sending the ioc order to see if we could + // even match anything. That way we don't need to pay the tx fee and + // ioc penalty fee unnecessarily. + let opposite_side_key = match side.invert_side() { + Side::Bid => perp.market.bids, + Side::Ask => perp.market.asks, + }; + let bookside = Box::new(self.account_fetcher.fetch::(&opposite_side_key)?); + if bookside.quantity_at_price(price_lots, now_ts, oracle_price_lots) <= 0 { + warn!( + other_side = ?side.invert_side(), + %order_price, + %oracle_price, + "no liquidity", + ); + return Ok(true); + } + + let txsig = self + .mango_client + .perp_place_order( + perp_position.market_index, + side, + price_lots, + max_base_lots, + i64::MAX, + 0, + PlaceOrderType::ImmediateOrCancel, + true, // reduce only + 0, + 10, + mango_v4::state::SelfTradeBehavior::DecrementTake, + ) + .await?; + info!( + %txsig, + %order_price, + "attempt to ioc reduce perp base position" + ); + if !self.refresh_mango_account_after_tx(txsig).await? { + return Ok(false); + } + } else if base_lots == 0 && quote_native != 0 { + // settle pnl + let direction = if quote_native > 0 { + perp_pnl::Direction::MaxNegative + } else { + perp_pnl::Direction::MaxPositive + }; + let counters = perp_pnl::fetch_top( + &self.mango_client.context, + self.account_fetcher.as_ref(), + perp_position.market_index, + direction, + 2, + ) + .await?; + if counters.is_empty() { + // If we can't settle some positive PNL because we're lacking a suitable counterparty, + // then liquidation should continue, even though this step produced no transaction + info!("could not settle perp pnl on perp market: no counterparty",); + return Ok(true); + } + let (counter_key, counter_acc, _counter_pnl) = counters.first().unwrap(); + + let (account_a, account_b) = if quote_native > 0 { + ( + (&self.mango_account_address, account), + (counter_key, counter_acc), + ) + } else { + ( + (counter_key, counter_acc), + (&self.mango_account_address, account), + ) + }; + let txsig = self + .mango_client + .perp_settle_pnl(perp_position.market_index, account_a, account_b) + .await?; + info!(%txsig, "settled perp pnl"); + if !self.refresh_mango_account_after_tx(txsig).await? { + return Ok(false); + } + } else if base_lots == 0 && quote_native == 0 { + // close perp position + let txsig = self + .mango_client + .perp_deactivate_position(perp_position.market_index) + .await?; + info!( + %txsig, "closed perp position" + ); + if !self.refresh_mango_account_after_tx(txsig).await? { + return Ok(false); + } + } else { + // maybe we're still waiting for consume_events + info!("cannot deactivate perp position, waiting for consume events?"); + } + Ok(true) + } + + async fn rebalance_perps(&self) -> anyhow::Result<()> { + let account = Box::new( + self.account_fetcher + .fetch_mango_account(&self.mango_account_address)?, + ); for perp_position in account.active_perp_positions() { let perp = self.mango_client.context.perp(perp_position.market_index); - let base_lots = perp_position.base_position_lots(); - let effective_lots = perp_position.effective_base_position_lots(); - let quote_native = perp_position.quote_position_native(); - log::info!( - "active perp position on {}, base lots: {}, effective lots: {}, quote native: {}", - perp.market.name(), - base_lots, - effective_lots, - quote_native, - ); - - if effective_lots != 0 { - // send an ioc order to reduce the base position - let oracle_account_data = self.account_fetcher.fetch_raw(&perp.market.oracle)?; - let oracle_account = - KeyedAccountSharedData::new(perp.market.oracle, oracle_account_data); - let oracle_price = perp.market.oracle_price(&oracle_account, None)?; - let oracle_price_lots = perp.market.native_price_to_lot(oracle_price); - let (side, order_price, oo_lots) = if effective_lots > 0 { - ( - Side::Ask, - oracle_price * (I80F48::ONE - perp.market.base_liquidation_fee), - perp_position.asks_base_lots, - ) - } else { - ( - Side::Bid, - oracle_price * (I80F48::ONE + perp.market.base_liquidation_fee), - perp_position.bids_base_lots, - ) - }; - let price_lots = perp.market.native_price_to_lot(order_price); - let max_base_lots = effective_lots.abs() - oo_lots; - if max_base_lots <= 0 { - log::warn!( - "cannot place reduce-only order on {} {:?}, base pos: {}, in open orders: {}", - perp.market.name(), - side, - effective_lots, - oo_lots, - ); - continue; - } - - // Check the orderbook before sending the ioc order to see if we could - // even match anything. That way we don't need to pay the tx fee and - // ioc penalty fee unnecessarily. - let opposite_side_key = match side.invert_side() { - Side::Bid => perp.market.bids, - Side::Ask => perp.market.asks, - }; - let bookside = self.account_fetcher.fetch::(&opposite_side_key)?; - if bookside.quantity_at_price(price_lots, now_ts, oracle_price_lots) <= 0 { - log::warn!( - "no liquidity on {} {:?} at price {}, oracle price {}", - perp.market.name(), - side.invert_side(), - order_price, - oracle_price, - ); - continue; - } - - let txsig = self - .mango_client - .perp_place_order( - perp_position.market_index, - side, - price_lots, - max_base_lots, - i64::MAX, - 0, - PlaceOrderType::ImmediateOrCancel, - true, // reduce only - 0, - 10, - mango_v4::state::SelfTradeBehavior::DecrementTake, - ) - .await?; - log::info!( - "attempt to ioc reduce perp base position of {} {} at price {} in {}", - perp_position.base_position_native(&perp.market), - perp.market.name(), - order_price, - txsig - ); - if !self.refresh_mango_account_after_tx(txsig).await? { - return Ok(()); - } - } else if base_lots == 0 && quote_native != 0 { - // settle pnl - let direction = if quote_native > 0 { - perp_pnl::Direction::MaxNegative - } else { - perp_pnl::Direction::MaxPositive - }; - let counters = perp_pnl::fetch_top( - &self.mango_client.context, - self.account_fetcher.as_ref(), - perp_position.market_index, - direction, - 2, - ) - .await?; - if counters.is_empty() { - // If we can't settle some positive PNL because we're lacking a suitable counterparty, - // then liquidation should continue, even though this step produced no transaction - log::info!( - "could not settle perp pnl on perp market {}: no counterparty", - perp.market.name() - ); - continue; - } - let (counter_key, counter_acc, _counter_pnl) = counters.first().unwrap(); - - let (account_a, account_b) = if quote_native > 0 { - ( - (&self.mango_account_address, &account), - (counter_key, counter_acc), - ) - } else { - ( - (counter_key, counter_acc), - (&self.mango_account_address, &account), - ) - }; - let txsig = self - .mango_client - .perp_settle_pnl(perp_position.market_index, account_a, account_b) - .await?; - log::info!("settled perp {} pnl, tx sig {}", perp.market.name(), txsig); - if !self.refresh_mango_account_after_tx(txsig).await? { - return Ok(()); - } - } else if base_lots == 0 && quote_native == 0 { - // close perp position - let txsig = self - .mango_client - .perp_deactivate_position(perp_position.market_index) - .await?; - log::info!( - "closed perp position on {} in {}", - perp.market.name(), - txsig - ); - if !self.refresh_mango_account_after_tx(txsig).await? { - return Ok(()); - } - } else { - // maybe we're still waiting for consume_events - log::info!( - "cannot deactivate perp {} position, base lots {}, effective lots {}, quote {}", - perp.market.name(), - perp_position.base_position_lots(), - effective_lots, - perp_position.quote_position_native() - ); + if !self.rebalance_perp(&account, perp, perp_position).await? { + return Ok(()); } } diff --git a/bin/liquidator/src/token_swap_info.rs b/bin/liquidator/src/token_swap_info.rs index 413816e8a..5341f4034 100644 --- a/bin/liquidator/src/token_swap_info.rs +++ b/bin/liquidator/src/token_swap_info.rs @@ -2,6 +2,8 @@ use std::collections::HashMap; use std::sync::{Arc, RwLock}; use itertools::Itertools; +use tracing::*; + use mango_v4::state::TokenIndex; use mango_v4_client::jupiter::QueryRoute; use mango_v4_client::{JupiterSwapMode, MangoClient}; @@ -153,6 +155,6 @@ impl TokenSwapInfoUpdater { .unwrap_or_else(|| "no data".into()); msg.push_str(&format!("token {token}, {info}")); } - log::trace!("swap infos:{}", msg); + trace!("swap infos:{}", msg); } } diff --git a/bin/liquidator/src/trigger_tcs.rs b/bin/liquidator/src/trigger_tcs.rs index f805c0d6c..7942e7b9a 100644 --- a/bin/liquidator/src/trigger_tcs.rs +++ b/bin/liquidator/src/trigger_tcs.rs @@ -4,6 +4,7 @@ use mango_v4::state::{MangoAccountValue, TokenConditionalSwap}; use mango_v4_client::{chain_data, health_cache, JupiterSwapMode, MangoClient}; use rand::seq::SliceRandom; +use tracing::*; use {anyhow::Context, fixed::types::I80F48, solana_sdk::pubkey::Pubkey}; use crate::{token_swap_info, util}; @@ -180,7 +181,7 @@ pub async fn maybe_execute_token_conditional_swap_inner( let swap_price = sell_amount / buy_amount; if swap_price > taker_price.to_num::() { - log::trace!( + trace!( "skipping token conditional swap for: {pubkey}, id: {tcs_id}, \ max_buy: {max_buy_token_to_liqee}, max_sell: {max_sell_token_to_liqor}, \ because counter swap price: {swap_price} while taker price: {taker_price}", @@ -189,7 +190,7 @@ pub async fn maybe_execute_token_conditional_swap_inner( } } - log::trace!( + trace!( "executing token conditional swap for: {}, with owner: {}, id: {}, max_buy: {}, max_sell: {}", pubkey, liqee.fixed.owner, @@ -206,11 +207,9 @@ pub async fn maybe_execute_token_conditional_swap_inner( max_sell_token_to_liqor, ) .await?; - log::info!( + info!( "Executed swap account {}, tcs index {}, tx sig {:?}", - pubkey, - tcs_id, - txsig + pubkey, tcs_id, txsig ); let slot = account_fetcher.transaction_max_slot(&[txsig]).await?; @@ -222,7 +221,7 @@ pub async fn maybe_execute_token_conditional_swap_inner( ) .await { - log::info!("could not refresh after tcs: {}", e); + info!("could not refresh after tcs: {}", e); } Ok(true) @@ -238,11 +237,9 @@ pub async fn remove_expired_token_conditional_swap( let txsig = mango_client .token_conditional_swap_trigger((pubkey, &liqee), tcs_id, 0, 0) .await?; - log::info!( + info!( "Removed expired token conditional swap account {}, tcs index {}, tx sig {:?}", - pubkey, - tcs_id, - txsig + pubkey, tcs_id, txsig ); Ok(true) diff --git a/bin/settler/Cargo.toml b/bin/settler/Cargo.toml index 74f5812f1..4af48adf8 100644 --- a/bin/settler/Cargo.toml +++ b/bin/settler/Cargo.toml @@ -31,7 +31,6 @@ itertools = "0.10.3" jemallocator = "0.3.2" jsonrpc-core = "18.0.0" jsonrpc-core-client = { version = "18.0.0", features = ["ws", "http", "tls"] } -log = "0.4" mango-v4 = { path = "../../programs/mango-v4", features = ["client"] } mango-v4-client = { path = "../../lib/client" } once_cell = "1.12.0" @@ -51,3 +50,4 @@ solana-sdk = { workspace = true } tokio = { version = "1", features = ["full"] } tokio-stream = { version = "0.1.9"} tokio-tungstenite = "0.16.1" +tracing = "0.1" diff --git a/bin/settler/src/main.rs b/bin/settler/src/main.rs index 719c57058..c41af0744 100644 --- a/bin/settler/src/main.rs +++ b/bin/settler/src/main.rs @@ -4,12 +4,12 @@ use std::time::Duration; use anchor_client::Cluster; use clap::Parser; -use log::*; use mango_v4::state::{PerpMarketIndex, TokenIndex}; use mango_v4_client::{ account_update_stream, chain_data, keypair_from_cli, snapshot_source, websocket_source, AsyncChannelSendUnlessFull, Client, MangoClient, MangoGroupContext, TransactionBuilderConfig, }; +use tracing::*; use itertools::Itertools; use solana_sdk::commitment_config::CommitmentConfig; @@ -75,6 +75,8 @@ pub fn encode_address(addr: &Pubkey) -> String { #[tokio::main] async fn main() -> anyhow::Result<()> { + mango_v4_client::tracing_subscriber_init(); + let args = if let Ok(cli_dotenv) = CliDotenv::try_parse() { dotenv::from_path(cli_dotenv.dotenv)?; cli_dotenv.remaining_args @@ -234,7 +236,7 @@ async fn main() -> anyhow::Result<()> { let mut state = shared_state.write().unwrap(); if is_mango_account(&account_write.account, &mango_group).is_some() { // e.g. to render debug logs RUST_LOG="liquidator=debug" - log::debug!( + debug!( "change to mango account {}...", &account_write.pubkey.to_string()[0..3] ); @@ -250,15 +252,15 @@ async fn main() -> anyhow::Result<()> { } else { let mut must_check_all = false; if is_mango_bank(&account_write.account, &mango_group).is_some() { - log::debug!("change to bank {}", &account_write.pubkey); + debug!("change to bank {}", &account_write.pubkey); must_check_all = true; } if is_perp_market(&account_write.account, &mango_group).is_some() { - log::debug!("change to perp market {}", &account_write.pubkey); + debug!("change to perp market {}", &account_write.pubkey); must_check_all = true; } if oracles.contains(&account_write.pubkey) { - log::debug!("change to oracle {}", &account_write.pubkey); + debug!("change to oracle {}", &account_write.pubkey); must_check_all = true; } if must_check_all { @@ -324,7 +326,7 @@ async fn main() -> anyhow::Result<()> { vec![data_job, settle_job].into_iter().collect(); jobs.next().await; - log::error!("a critical job aborted, exiting"); + error!("a critical job aborted, exiting"); Ok(()) } diff --git a/bin/settler/src/metrics.rs b/bin/settler/src/metrics.rs index 434d55d17..5f703a08f 100644 --- a/bin/settler/src/metrics.rs +++ b/bin/settler/src/metrics.rs @@ -2,6 +2,7 @@ use { std::collections::HashMap, std::sync::{atomic, Arc, Mutex, RwLock}, tokio::time, + tracing::*, }; #[derive(Debug)] @@ -151,7 +152,7 @@ pub fn start() -> Metrics { 0 }; let diff = new_value.wrapping_sub(previous_value) as i64; - log::info!("metric: {}: {} ({:+})", name, new_value, diff); + info!("metric: {}: {} ({:+})", name, new_value, diff); } Value::I64(v) => { let new_value = v.load(atomic::Ordering::Acquire); @@ -164,7 +165,7 @@ pub fn start() -> Metrics { 0 }; let diff = new_value - previous_value; - log::info!("metric: {}: {} ({:+})", name, new_value, diff); + info!("metric: {}: {} ({:+})", name, new_value, diff); } Value::String(v) => { let new_value = v.lock().unwrap(); @@ -178,13 +179,11 @@ pub fn start() -> Metrics { "".into() }; if *new_value == previous_value { - log::info!("metric: {}: {} (unchanged)", name, &*new_value); + info!("metric: {}: {} (unchanged)", name, &*new_value); } else { - log::info!( + info!( "metric: {}: {} (before: {})", - name, - &*new_value, - previous_value + name, &*new_value, previous_value ); } } diff --git a/bin/settler/src/settle.rs b/bin/settler/src/settle.rs index a23bd7b7d..cced540d1 100644 --- a/bin/settler/src/settle.rs +++ b/bin/settler/src/settle.rs @@ -15,6 +15,7 @@ use solana_sdk::signature::Signature; use solana_sdk::signer::Signer; use solana_sdk::transaction::VersionedTransaction; +use tracing::*; use {anyhow::Context, fixed::types::I80F48, solana_sdk::pubkey::Pubkey}; pub struct Config { @@ -44,7 +45,7 @@ fn perp_markets_and_prices( |v: anyhow::Result<(PerpMarketIndex, (PerpMarket, I80F48))>| match v { Ok(v) => Some(v), Err(err) => { - log::error!("error while retriving perp market and price: {:?}", err); + error!("error while retriving perp market and price: {:?}", err); None } }, @@ -279,12 +280,12 @@ impl<'a> SettleBatchProcessor<'a> { .map_err(|e| prettify_solana_client_error(e)); if let Err(err) = send_result { - log::info!("error while sending settle batch: {}", err); + info!("error while sending settle batch: {}", err); return Ok(None); } let txsig = send_result.unwrap(); - log::info!("sent settle tx: {txsig}"); + info!("sent settle tx: {txsig}"); Ok(Some(txsig)) } diff --git a/lib/client/Cargo.toml b/lib/client/Cargo.toml index 6c896e13e..53345683b 100644 --- a/lib/client/Cargo.toml +++ b/lib/client/Cargo.toml @@ -16,6 +16,7 @@ anyhow = "1.0" async-channel = "1.6" async-once-cell = { version = "0.4.2", features = ["unpin"] } async-trait = "0.1.52" +atty = "0.2" fixed = { workspace = true, features = ["serde", "borsh"] } futures = "0.3.25" itertools = "0.10.3" @@ -33,7 +34,6 @@ solana-address-lookup-table-program = { workspace = true } mango-feeds-connector = "0.1.1" spl-associated-token-account = "1.0.3" thiserror = "1.0.31" -log = "0.4" reqwest = "0.11.11" tokio = { version = "1", features = ["full"] } tokio-stream = { version = "0.1.9"} @@ -41,3 +41,5 @@ serde = "1.0.141" serde_json = "1.0.82" base64 = "0.13.0" bincode = "1.3.3" +tracing = { version = "0.1", features = ["log"] } +tracing-subscriber = { version = "0.3", features = ["env-filter"] } \ No newline at end of file diff --git a/lib/client/src/account_update_stream.rs b/lib/client/src/account_update_stream.rs index 59487d629..d73987e2f 100644 --- a/lib/client/src/account_update_stream.rs +++ b/lib/client/src/account_update_stream.rs @@ -1,8 +1,8 @@ use solana_client::rpc_response::{Response, RpcKeyedAccount}; use solana_sdk::{account::AccountSharedData, pubkey::Pubkey}; -use log::*; use std::{str::FromStr, sync::Arc}; +use tracing::*; use crate::chain_data; diff --git a/lib/client/src/snapshot_source.rs b/lib/client/src/snapshot_source.rs index d667c68c4..8acb629c9 100644 --- a/lib/client/src/snapshot_source.rs +++ b/lib/client/src/snapshot_source.rs @@ -12,10 +12,10 @@ use solana_sdk::{account::AccountSharedData, commitment_config::CommitmentConfig use anyhow::Context; use futures::{stream, StreamExt}; -use log::*; use std::str::FromStr; use std::time::Duration; use tokio::time; +use tracing::*; use crate::account_update_stream::{AccountUpdate, Message}; use crate::AnyhowWrap; @@ -230,10 +230,10 @@ pub fn start(config: Config, mango_oracles: Vec, sender: async_channel:: })) .await .expect("always Ok"); - log::debug!("latest slot for snapshot {}", epoch_info.absolute_slot); + debug!("latest slot for snapshot {}", epoch_info.absolute_slot); if epoch_info.absolute_slot > config.min_slot { - log::debug!("continuing to fetch snapshot now, min_slot {} is older than latest epoch slot {}", config.min_slot, epoch_info.absolute_slot); + debug!("continuing to fetch snapshot now, min_slot {} is older than latest epoch slot {}", config.min_slot, epoch_info.absolute_slot); break; } } diff --git a/lib/client/src/util.rs b/lib/client/src/util.rs index 59da7433d..653ac2f72 100644 --- a/lib/client/src/util.rs +++ b/lib/client/src/util.rs @@ -9,21 +9,6 @@ use solana_sdk::{ use std::{thread, time}; -// #[allow(dead_code)] -// pub fn retry(request: impl Fn() -> Result) -> anyhow::Result { -// for _i in 0..5 { -// match request() { -// Ok(res) => return Ok(res), -// Err(err) => { -// // TODO: only retry for recoverable errors -// log::error!("{:#?}", err); -// continue; -// } -// } -// } -// Err(anyhow!("Retry failed")) -// } - /// Some Result<> types don't convert to anyhow::Result nicely. Force them through stringification. pub trait AnyhowWrap { type Value; @@ -114,3 +99,14 @@ pub fn send_and_confirm_transaction( ) .into()) } + +/// Convenience function used in binaries to set up the fmt tracing_subscriber, +/// with cololring enabled only if logging to a terminal and with EnvFilter. +pub fn tracing_subscriber_init() { + let format = tracing_subscriber::fmt::format().with_ansi(atty::is(atty::Stream::Stdout)); + + tracing_subscriber::fmt() + .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + .event_format(format) + .init(); +} diff --git a/lib/client/src/websocket_source.rs b/lib/client/src/websocket_source.rs index d431bcc2f..61c34ad60 100644 --- a/lib/client/src/websocket_source.rs +++ b/lib/client/src/websocket_source.rs @@ -11,9 +11,9 @@ use solana_rpc::rpc_pubsub::RpcSolPubSubClient; use solana_sdk::{commitment_config::CommitmentConfig, pubkey::Pubkey}; use anyhow::Context; -use log::*; use std::time::Duration; use tokio_stream::StreamMap; +use tracing::*; use crate::account_update_stream::{AccountUpdate, Message}; use crate::AnyhowWrap;