logging improvements (#641)

- switch logging to tracing crate
- update liquidator logging to use tracing features

(cherry picked from commit b8376b4b89)
This commit is contained in:
Christian Kamm 2023-07-12 08:38:38 +02:00
parent d243035da0
commit 81525ed139
24 changed files with 426 additions and 388 deletions

83
Cargo.lock generated
View File

@ -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]]

View File

@ -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"

View File

@ -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();

View File

@ -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}");
}
}
}

View File

@ -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"

View File

@ -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);
}
}
}

View File

@ -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<MangoClient>::strong_count() {}",
Arc::<MangoClient>::strong_count(&client)
)

View File

@ -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<MangoClient>) -> 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<MangoClient>) -> 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);
}
}
}

View File

@ -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"

View File

@ -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<Option<Signature>> {
@ -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<Option<Signature>> {
@ -254,9 +251,13 @@ impl<'a> LiquidateHelper<'a> {
(max_base_transfer, max_pnl_transfer.floor().to_num::<u64>())
};
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<Option<Signature>> {
@ -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<Vec<(TokenIndex, I80F48, I80F48)>> {
@ -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<Option<Signature>> {
@ -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<Option<Signature>> {
// 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);
}
}

View File

@ -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<std::ffi::OsString>,
}
// 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);
}

View File

@ -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
);
}
}

View File

@ -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<bool> {
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::<BookSide>(&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::<BookSide>(&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(());
}
}

View File

@ -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);
}
}

View File

@ -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::<f64>() {
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)

View File

@ -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"

View File

@ -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(())
}

View File

@ -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
);
}
}

View File

@ -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))
}

View File

@ -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"] }

View File

@ -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;

View File

@ -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<Pubkey>, 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;
}
}

View File

@ -9,21 +9,6 @@ use solana_sdk::{
use std::{thread, time};
// #[allow(dead_code)]
// pub fn retry<T>(request: impl Fn() -> Result<T, anchor_client::ClientError>) -> anyhow::Result<T> {
// 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();
}

View File

@ -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;