liquidator: avoid logging same oracle error (same token) in loop (#889)

* liquidator: avoid logging same oracle error (same token) in loop

Cargo.lock

@@ -3531,6 +3531,7 @@ dependencies = [
  "once_cell",
  "pyth-sdk-solana",
  "rand 0.7.3",
+ "regex",
  "serde",
  "serde_derive",
  "serde_json",

bin/liquidator/Cargo.toml

@@ -48,3 +48,4 @@ tokio = { version = "1", features = ["full"] }
 tokio-stream = { version = "0.1.9"}
 tokio-tungstenite = "0.16.1"
 tracing = "0.1"
+regex = "1.9.5"

bin/liquidator/src/cli_args.rs

@@ -204,4 +204,8 @@ pub struct Cli {
     /// when empty, allows all pairs
     #[clap(long, env, value_parser, value_delimiter = ' ')]
     pub(crate) liquidation_only_allow_perp_markets: Option<Vec<u16>>,
+
+    /// how long should it wait before logging an oracle error again (for the same token)
+    #[clap(long, env, default_value = "30")]
+    pub(crate) skip_oracle_error_in_logs_duration_secs: u64,
 }

bin/liquidator/src/main.rs

@@ -27,8 +27,10 @@ pub mod rebalance;
 pub mod telemetry;
 pub mod token_swap_info;
 pub mod trigger_tcs;
+mod unwrappable_oracle_error;
 pub mod util;
 
+use crate::unwrappable_oracle_error::UnwrappableOracleError;
 use crate::util::{is_mango_account, is_mint_info, is_perp_market};
 
 // jemalloc seems to be better at keeping the memory footprint reasonable over
@@ -262,6 +264,12 @@ async fn main() -> anyhow::Result<()> {
             .skip_threshold_for_type(LiqErrorType::Liq, 5)
             .skip_duration(Duration::from_secs(120))
             .build()?,
+        oracle_errors: ErrorTracking::builder()
+            .skip_threshold(1)
+            .skip_duration(Duration::from_secs(
+                cli.skip_oracle_error_in_logs_duration_secs,
+            ))
+            .build()?,
     });
 
     info!("main loop");
@@ -375,6 +383,7 @@ async fn main() -> anyhow::Result<()> {
                 };
 
                 liquidation.errors.update();
+                liquidation.oracle_errors.update();
 
                 let liquidated = liquidation
                     .maybe_liquidate_one(account_addresses.iter())
@@ -499,6 +508,7 @@ struct LiquidationState {
     trigger_tcs_config: trigger_tcs::Config,
 
     errors: ErrorTracking<Pubkey, LiqErrorType>,
+    oracle_errors: ErrorTracking<TokenIndex, LiqErrorType>,
 }
 
 impl LiquidationState {
@@ -552,6 +562,25 @@ impl LiquidationState {
         .await;
 
         if let Err(err) = result.as_ref() {
+            if let Some((ti, ti_name)) = err.try_unwrap_oracle_error() {
+                if self
+                    .oracle_errors
+                    .had_too_many_errors(LiqErrorType::Liq, &ti, Instant::now())
+                    .is_none()
+                {
+                    warn!(
+                        "{:?} recording oracle error for token {} {}",
+                        chrono::offset::Utc::now(),
+                        ti_name,
+                        ti
+                    );
+                }
+
+                self.oracle_errors
+                    .record(LiqErrorType::Liq, &ti, err.to_string());
+                return result;
+            }
+
             // Keep track of pubkeys that had errors
             error_tracking.record(LiqErrorType::Liq, pubkey, err.to_string());
 

bin/liquidator/src/unwrappable_oracle_error.rs

@@ -0,0 +1,126 @@
+use anchor_lang::error::Error::AnchorError;
+use mango_v4::error::MangoError;
+use mango_v4::state::TokenIndex;
+use regex::Regex;
+
+pub trait UnwrappableOracleError {
+    fn try_unwrap_oracle_error(&self) -> Option<(TokenIndex, String)>;
+}
+
+impl UnwrappableOracleError for anyhow::Error {
+    fn try_unwrap_oracle_error(&self) -> Option<(TokenIndex, String)> {
+        let root_cause = self
+            .root_cause()
+            .downcast_ref::<anchor_lang::error::Error>();
+
+        if root_cause.is_none() {
+            return None;
+        }
+
+        if let AnchorError(ae) = root_cause.unwrap() {
+            let is_oracle_error = ae.error_code_number == MangoError::OracleConfidence.error_code()
+                || ae.error_code_number == MangoError::OracleStale.error_code();
+
+            if !is_oracle_error {
+                return None;
+            }
+
+            let error_str = ae.to_string();
+            return parse_oracle_error_string(&error_str);
+        }
+
+        None
+    }
+}
+
+fn parse_oracle_error_string(error_str: &str) -> Option<(TokenIndex, String)> {
+    let token_name_regex = Regex::new(r#"name: (\w+)"#).unwrap();
+    let token_index_regex = Regex::new(r#"token index (\d+)"#).unwrap();
+    let token_name = token_name_regex
+        .captures(error_str)
+        .map(|c| c[1].to_string())
+        .unwrap_or_default();
+    let token_index = token_index_regex
+        .captures(error_str)
+        .map(|c| c[1].parse::<u16>().ok())
+        .unwrap_or_default();
+
+    if token_index.is_some() {
+        return Some((TokenIndex::from(token_index.unwrap()), token_name));
+    }
+
+    None
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use anchor_lang::error;
+    use anyhow::Context;
+    use mango_v4::error::Contextable;
+    use mango_v4::error::MangoError;
+    use mango_v4::state::{oracle_log_context, OracleConfig, OracleState, OracleType};
+
+    fn generate_errored_res() -> std::result::Result<u8, error::Error> {
+        return Err(MangoError::OracleConfidence.into());
+    }
+
+    fn generate_errored_res_with_context() -> anyhow::Result<u8> {
+        let value = Contextable::with_context(
+            Contextable::with_context(generate_errored_res(), || {
+                oracle_log_context(
+                    "SOL",
+                    &OracleState {
+                        price: Default::default(),
+                        deviation: Default::default(),
+                        last_update_slot: 0,
+                        oracle_type: OracleType::Pyth,
+                    },
+                    &OracleConfig {
+                        conf_filter: Default::default(),
+                        max_staleness_slots: 0,
+                        reserved: [0; 72],
+                    },
+                    None,
+                )
+            }),
+            || {
+                format!(
+                    "getting oracle for bank with health account index {} and token index {}, passed account {}",
+                    10,
+                    11,
+                    12,
+                )
+            },
+        )?;
+
+        Ok(value)
+    }
+
+    #[test]
+    fn should_extract_oracle_error_and_token_infos() {
+        let error = generate_errored_res_with_context()
+            .context("Something")
+            .unwrap_err();
+        println!("{}", error);
+        println!("{}", error.root_cause());
+        let oracle_error_opt = error.try_unwrap_oracle_error();
+
+        assert!(oracle_error_opt.is_some());
+        assert_eq!(
+            oracle_error_opt.unwrap(),
+            (TokenIndex::from(11u16), "SOL".to_string())
+        );
+    }
+
+    #[test]
+    fn should_parse_oracle_error_message() {
+        assert!(parse_oracle_error_string("").is_none());
+        assert!(parse_oracle_error_string("Something went wrong").is_none());
+        assert_eq!(
+            parse_oracle_error_string("Something went wrong token index 4, name: SOL, Stale")
+                .unwrap(),
+            (TokenIndex::from(4u16), "SOL".to_string())
+        );
+    }
+}