Skip to content

Remove excess logging #28

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
0xahzam merged 1 commit into from
Dec 18, 2025
Merged

Remove excess logging #28

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
212 changes: 103 additions & 109 deletions src/liquidator.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -537,8 +537,8 @@ impl LiquidatorBot {
if margin_info.total_collateral < config.min_collateral as i128
&& margin_info.margin_requirement < config.min_collateral as u128
{
exclude_count+=1;
log::debug!(target: TARGET, "excluding user: {:?}. insignificant collateral: {}/{}", user.authority, margin_info.total_collateral, margin_info.margin_requirement);
exclude_count += 1;
// log::debug!(target: TARGET, "excluding user: {:?}. insignificant collateral: {}/{}", user.authority, margin_info.total_collateral, margin_info.margin_requirement);
} else {
let now_ms = current_time_millis();
users.insert(
Expand All @@ -560,8 +560,8 @@ impl LiquidatorBot {
}
});

log::info!(target: TARGET, "filtered #{exclude_count} accounts with dust collateral");
log::info!(target: TARGET, "identified #{initial_high_risk_count} high-risk accounts for monitoring");
log::debug!(target: TARGET, "filtered #{exclude_count} accounts with dust collateral");
log::debug!(target: TARGET, "identified #{initial_high_risk_count} high-risk accounts for monitoring");

// main loop
let mut event_buffer = Vec::<GrpcEvent>::with_capacity(64);
Expand Down Expand Up @@ -603,8 +603,6 @@ impl LiquidatorBot {
}
}

let n_read = events_rx.recv_many(&mut event_buffer, 64).await;
log::trace!(target: TARGET, "read: {n_read}, remaning: {:?}", events_rx.len());
for event in event_buffer.drain(..) {
match event {
GrpcEvent::UserUpdate {
Expand All @@ -631,18 +629,18 @@ impl LiquidatorBot {
{
match staleness_err {
StalenessError::UserAccountStale { age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for stale user {:?}: user account {} slots old",
pubkey, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for stale user {:?}: user account {} slots old",
// pubkey, age_slots
// );
}
StalenessError::OraclePriceStale { market, age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
pubkey, market, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
// pubkey, market, age_slots
// );
}
StalenessError::PythPriceStale { .. } => {
// Pyth staleness checked separately
Expand All @@ -668,13 +666,13 @@ impl LiquidatorBot {
if margin_info.total_collateral < config.min_collateral as i128
&& margin_info.margin_requirement < config.min_collateral as u128
{
log::trace!(target: TARGET, "filtered account with dust collateral: {pubkey:?}");
// log::debug!(target: TARGET, "filtered account with dust collateral: {pubkey:?}");
high_risk.remove(&pubkey);
users.remove(&pubkey);
} else {
match check_margin_status(&margin_info) {
MarginStatus::Liquidatable => {
log::debug!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");
// log::debug!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");
high_risk.insert(pubkey);
}
MarginStatus::HighRisk => {
Expand Down Expand Up @@ -756,18 +754,18 @@ impl LiquidatorBot {
{
match staleness_err {
StalenessError::UserAccountStale { age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for stale user {:?}: user account {} slots old",
pubkey, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for stale user {:?}: user account {} slots old",
// pubkey, age_slots
// );
}
StalenessError::OraclePriceStale { market, age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
pubkey, market, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
// pubkey, market, age_slots
// );
}
StalenessError::PythPriceStale { .. } => {
// Pyth staleness checked separately
Expand All @@ -791,7 +789,7 @@ impl LiquidatorBot {

match check_margin_status(&margin_info) {
MarginStatus::Liquidatable => {
log::debug!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");
// log::debug!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");
liquidatable_users.push((pubkey, user_meta.user.clone()));
}
_ => {}
Expand Down Expand Up @@ -843,33 +841,35 @@ impl LiquidatorBot {
}
}

log::trace!(
target: TARGET,
"processed {} high-risk margin updates in {}ms",
high_risk_count,
current_time_millis() - t0,
);
// log::debug!(
// target: TARGET,
// "processed {} high-risk margin updates in {}ms",
// high_risk_count,
// current_time_millis() - t0,
// );

// Update high_risk set synchronously but quickly (just remove safe users)
let t0 = current_time_millis();
high_risk.retain(|pubkey| {
if let Some(user_meta) = users.get(pubkey) {
// Log staleness but still check margin status
if let Err(staleness_err) = validate_data_freshness(user_meta, &oracle_prices, current_slot) {
if let Err(staleness_err) =
validate_data_freshness(user_meta, &oracle_prices, current_slot)
{
match staleness_err {
StalenessError::UserAccountStale { age_slots } => {
log::trace!(
target: TARGET,
"Checking stale user {:?} for high-risk status: {} slots old",
pubkey, age_slots
);
// log::debug!(
// target: TARGET,
// "Checking stale user {:?} for high-risk status: {} slots old",
// pubkey, age_slots
// );
}
StalenessError::OraclePriceStale { market, age_slots } => {
log::trace!(
target: TARGET,
"Checking {:?} with stale oracle {:?}: {} slots old",
pubkey, market, age_slots
);
// log::debug!(
// target: TARGET,
// "Checking {:?} with stale oracle {:?}: {} slots old",
// pubkey, market, age_slots
// );
}
StalenessError::PythPriceStale { .. } => {}
}
Expand All @@ -894,12 +894,12 @@ impl LiquidatorBot {
}
});

log::trace!(
target: TARGET,
"updated high_risk set in {}ms (now {} users)",
current_time_millis() - t0,
high_risk.len(),
);
// log::debug!(
// target: TARGET,
// "updated high_risk set in {}ms (now {} users)",
// current_time_millis() - t0,
// high_risk.len(),
// );
}

// Every RECHECK_CYCLE_INTERVAL cycles, recheck all users to find new high-risk users
Expand Down Expand Up @@ -932,18 +932,18 @@ impl LiquidatorBot {
{
match staleness_err {
StalenessError::UserAccountStale { age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for stale user {:?}: user account {} slots old",
pubkey, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for stale user {:?}: user account {} slots old",
// pubkey, age_slots
// );
}
StalenessError::OraclePriceStale { market, age_slots } => {
log::trace!(
target: TARGET,
"Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
pubkey, market, age_slots
);
// log::debug!(
// target: TARGET,
// "Recalculating margin for {:?} with stale oracle: {:?} is {} slots old",
// pubkey, market, age_slots
// );
}
StalenessError::PythPriceStale { .. } => {
// Pyth staleness checked separately
Expand All @@ -969,7 +969,7 @@ impl LiquidatorBot {
MarginStatus::Liquidatable => {
high_risk.insert(*pubkey);
newly_high_risk += 1;
log::info!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");
log::debug!(target: TARGET, "found liquidatable user: {pubkey:?}, margin:{margin_info:?}");

let pyth_price_update = user_meta
.user
Expand Down Expand Up @@ -1021,12 +1021,12 @@ impl LiquidatorBot {
}
}

log::debug!(
target: TARGET,
"margin recheck: checked {} users, {newly_high_risk} newly high-risk, took {}ms",
users.len(),
current_time_millis() - t0
);
// log::debug!(
// target: TARGET,
// "margin recheck: checked {} users, {newly_high_risk} newly high-risk, took {}ms",
// users.len(),
// current_time_millis() - t0
// );
}
}
}
Expand Down Expand Up @@ -1272,12 +1272,12 @@ fn spawn_liquidation_worker(
// Drop entries older than 1 second to handle backpressure
let now = current_time_millis();
if now.saturating_sub(ts) > MAX_LIQUIDATION_AGE_MS {
log::debug!(
target: TARGET,
"dropping stale liquidation for {:?} (age: {}ms)",
liquidatee,
now.saturating_sub(ts)
);
// log::debug!(
// target: TARGET,
// "dropping stale liquidation for {:?} (age: {}ms)",
// liquidatee,
// now.saturating_sub(ts)
// );
continue;
}

Expand Down Expand Up @@ -1327,12 +1327,12 @@ fn spawn_liquidation_worker(
LIQUIDATION_DEADLINE_MS
);
} else {
log::trace!(
target: TARGET,
"liquidation for {:?} completed in {}ms",
liquidatee_clone,
elapsed.as_millis()
);
// log::debug!(
// target: TARGET,
// "liquidation for {:?} completed in {}ms",
// liquidatee_clone,
// elapsed.as_millis()
// );
}
}
Err(_) => {
Expand Down Expand Up @@ -1441,12 +1441,6 @@ impl LiquidateWithMatchStrategy {
.with_label_values(&["perp"])
.inc();

log::info!(
target: TARGET,
"try liquidate: https://app.drift.trade/?userAccount={liquidatee:?}, market={}",
pos.market_index
);

let Some(makers) = Self::find_top_makers(
drift,
dlob,
Expand Down Expand Up @@ -1509,12 +1503,12 @@ impl LiquidateWithMatchStrategy {

// Filter dust positions
if token_amount < spot_market.min_order_size * 2 {
log::trace!(
target: TARGET,
"skip dust spot position. market={}, amount={}",
pos.market_index,
token_amount
);
// log::debug!(
// target: TARGET,
// "skip dust spot position. market={}, amount={}",
// pos.market_index,
// token_amount
// );
continue;
}

Expand All @@ -1539,7 +1533,7 @@ impl LiquidateWithMatchStrategy {
continue;
};

log::info!(
log::debug!(
target: TARGET,
"attempting spot liquidation: user={:?}, asset_market={}, liability_market={}, amount={}",
liquidatee,
Expand Down Expand Up @@ -1625,24 +1619,24 @@ impl LiquidateWithMatchStrategy {
let use_titan = match (&jupiter_result, &titan_result) {
(Ok(jup), Ok(titan)) => {
let use_titan = titan.quote.out_amount > jup.quote.out_amount;
log::debug!(
target: TARGET,
"got quotes in {}ms - jup: {}, titan: {} - using {}",
quote_latency_ms,
jup.quote.out_amount,
titan.quote.out_amount,
if use_titan { "titan" } else { "jupiter" }
);
// log::debug!(
// target: TARGET,
// "got quotes in {}ms - jup: {}, titan: {} - using {}",
// quote_latency_ms,
// jup.quote.out_amount,
// titan.quote.out_amount,
// if use_titan { "titan" } else { "jupiter" }
// );
use_titan
}
(Ok(_), Err(e)) => {
metrics.titan_quote_failures.inc();
log::debug!(target: TARGET, "titan failed in {}ms, using jupiter: {:?}", quote_latency_ms, e);
log::warn!(target: TARGET, "titan failed in {}ms, using jupiter: {:?}", quote_latency_ms, e);
false
}
(Err(e), Ok(_)) => {
metrics.jupiter_quote_failures.inc();
log::debug!(target: TARGET, "jupiter failed in {}ms, using titan: {:?}", quote_latency_ms, e);
log::warn!(target: TARGET, "jupiter failed in {}ms, using titan: {:?}", quote_latency_ms, e);
true
}
_ => unreachable!(),
Expand Down Expand Up @@ -1687,11 +1681,11 @@ impl LiquidateWithMatchStrategy {
)
.build()
};
log::debug!(
target: TARGET,
"sending spot liq tx: {liquidatee:?}, asset={asset_market_index}, liability={}",
liability_market_index
);
// log::debug!(
// target: TARGET,
// "sending spot liq tx: {liquidatee:?}, asset={asset_market_index}, liability={}",
// liability_market_index
// );
tx_sender.send_tx(
tx,
TxIntent::LiquidateSpot {
Expand Down