web3-proxy/web3_proxy/src/rpcs/request.rs

417 lines
16 KiB
Rust
Raw Normal View History

2022-08-24 03:11:49 +03:00
use super::connection::Web3Connection;
use super::provider::Web3Provider;
2022-12-12 07:39:54 +03:00
use crate::frontend::authorization::{Authorization, AuthorizationType};
2022-09-20 09:56:24 +03:00
use crate::metered::{JsonRpcErrorCount, ProviderErrorCount};
use anyhow::Context;
use chrono::Utc;
2022-11-01 21:54:39 +03:00
use entities::revert_log;
use entities::sea_orm_active_enums::Method;
use ethers::providers::{HttpClientError, ProviderError, WsClientError};
use ethers::types::{Address, Bytes};
2022-12-08 09:54:38 +03:00
use log::{debug, error, trace, warn, Level};
2022-09-09 06:53:16 +03:00
use metered::metered;
use metered::HitCount;
use metered::ResponseTime;
use metered::Throughput;
2022-11-14 21:24:52 +03:00
use migration::sea_orm::{self, ActiveEnum, ActiveModelTrait};
use serde_json::json;
2022-08-24 03:11:49 +03:00
use std::fmt;
2022-09-23 00:03:37 +03:00
use std::sync::atomic::{self, AtomicBool, Ordering};
2022-08-24 03:14:49 +03:00
use std::sync::Arc;
2022-11-12 09:11:58 +03:00
use thread_fast_rng::rand::Rng;
2022-08-30 23:01:42 +03:00
use tokio::time::{sleep, Duration, Instant};
2022-08-24 03:11:49 +03:00
2022-08-30 23:01:42 +03:00
#[derive(Debug)]
2022-08-24 03:14:49 +03:00
pub enum OpenRequestResult {
2022-08-24 03:59:05 +03:00
Handle(OpenRequestHandle),
/// Unable to start a request. Retry at the given time.
2022-08-24 03:11:49 +03:00
RetryAt(Instant),
2022-11-25 10:41:53 +03:00
/// Unable to start a request because the server is not synced
2022-12-06 00:13:36 +03:00
NotReady,
2022-08-24 03:11:49 +03:00
}
2022-08-24 03:59:05 +03:00
/// Make RPC requests through this handle and drop it when you are done.
2022-08-30 23:01:42 +03:00
#[derive(Debug)]
2022-09-09 06:53:16 +03:00
pub struct OpenRequestHandle {
authorization: Arc<Authorization>,
2022-09-23 00:03:37 +03:00
conn: Arc<Web3Connection>,
// TODO: this is the same metrics on the conn. use a reference?
2022-09-09 06:53:16 +03:00
metrics: Arc<OpenRequestHandleMetrics>,
2022-12-06 03:06:28 +03:00
provider: Arc<Web3Provider>,
2022-09-23 00:03:37 +03:00
used: AtomicBool,
2022-09-09 06:53:16 +03:00
}
2022-08-24 03:11:49 +03:00
2022-09-23 01:34:43 +03:00
/// Depending on the context, RPC errors can require different handling.
2023-01-17 09:54:40 +03:00
pub enum RequestRevertHandler {
/// Log at the trace level. Use when errors are expected.
TraceLevel,
2022-09-23 01:15:56 +03:00
/// Log at the debug level. Use when errors are expected.
DebugLevel,
2022-09-23 01:15:56 +03:00
/// Log at the error level. Use when errors are bad.
ErrorLevel,
2022-09-23 01:15:56 +03:00
/// Log at the warn level. Use when errors do not cause problems.
WarnLevel,
/// Potentially save the revert. Users can tune how often this happens
2023-01-17 09:54:40 +03:00
Save,
}
2022-09-24 10:04:11 +03:00
// TODO: second param could be skipped since we don't need it here
#[derive(serde::Deserialize, serde::Serialize)]
2022-09-24 10:04:11 +03:00
struct EthCallParams((EthCallFirstParams, Option<serde_json::Value>));
#[derive(serde::Deserialize, serde::Serialize)]
struct EthCallFirstParams {
to: Address,
data: Option<Bytes>,
}
2023-01-17 09:54:40 +03:00
impl From<Level> for RequestRevertHandler {
fn from(level: Level) -> Self {
match level {
2023-01-17 09:54:40 +03:00
Level::Trace => RequestRevertHandler::TraceLevel,
Level::Debug => RequestRevertHandler::DebugLevel,
Level::Error => RequestRevertHandler::ErrorLevel,
Level::Warn => RequestRevertHandler::WarnLevel,
2022-09-23 01:15:56 +03:00
_ => unimplemented!("unexpected tracing Level"),
}
}
}
impl Authorization {
2022-09-23 01:34:43 +03:00
/// Save a RPC call that return "execution reverted" to the database.
async fn save_revert(
self: Arc<Self>,
method: Method,
params: EthCallFirstParams,
) -> anyhow::Result<()> {
2023-01-19 03:17:43 +03:00
let rpc_key_id = match self.checks.rpc_secret_key_id {
Some(rpc_key_id) => rpc_key_id.into(),
None => {
2022-11-12 11:24:32 +03:00
// // trace!(?self, "cannot save revert without rpc_key_id");
return Ok(());
}
};
let db_conn = self.db_conn.as_ref().context("no database connection")?;
// TODO: should the database set the timestamp?
// we intentionally use "now" and not the time the request started
// why? because we aggregate stats and setting one in the past could cause confusion
let timestamp = Utc::now();
let to: Vec<u8> = params
.to
.as_bytes()
.try_into()
.expect("address should always convert to a Vec<u8>");
let call_data = params.data.map(|x| format!("{}", x));
let rl = revert_log::ActiveModel {
rpc_key_id: sea_orm::Set(rpc_key_id),
method: sea_orm::Set(method),
to: sea_orm::Set(to),
call_data: sea_orm::Set(call_data),
timestamp: sea_orm::Set(timestamp),
..Default::default()
};
let rl = rl
.save(db_conn)
.await
.context("Failed saving new revert log")?;
// TODO: what log level?
// TODO: better format
2022-11-16 10:19:56 +03:00
trace!("revert_log: {:?}", rl);
// TODO: return something useful
Ok(())
2022-09-23 00:51:52 +03:00
}
}
2022-09-09 06:53:16 +03:00
#[metered(registry = OpenRequestHandleMetrics, visibility = pub)]
2022-08-24 03:14:49 +03:00
impl OpenRequestHandle {
2022-12-06 03:06:28 +03:00
pub async fn new(authorization: Arc<Authorization>, conn: Arc<Web3Connection>) -> Self {
// TODO: take request_id as an argument?
// TODO: attach a unique id to this? customer requests have one, but not internal queries
2022-08-24 03:11:49 +03:00
// TODO: what ordering?!
2022-09-09 06:53:16 +03:00
// TODO: should we be using metered, or not? i think not because we want stats for each handle
// TODO: these should maybe be sent to an influxdb instance?
conn.active_requests.fetch_add(1, atomic::Ordering::Relaxed);
2022-08-24 03:11:49 +03:00
2022-12-06 03:06:28 +03:00
let mut provider = None;
let mut logged = false;
while provider.is_none() {
// trace!("waiting on provider: locking...");
let ready_provider = conn
.provider_state
.read()
.await
// TODO: hard code true, or take a bool in the `new` function?
.provider(true)
.await
.cloned();
// trace!("waiting on provider: unlocked!");
match ready_provider {
None => {
if !logged {
logged = true;
warn!("no provider for {}!", conn);
}
// TODO: how should this work? a reconnect should be in progress. but maybe force one now?
// TODO: sleep how long? subscribe to something instead? maybe use a watch handle?
// TODO: this is going to be way too verbose!
sleep(Duration::from_millis(100)).await
}
Some(x) => provider = Some(x),
}
}
let provider = provider.expect("provider was checked already");
// TODO: handle overflows?
// TODO: what ordering?
match authorization.as_ref().authorization_type {
2022-12-12 07:39:54 +03:00
AuthorizationType::Frontend => {
conn.frontend_requests
.fetch_add(1, atomic::Ordering::Relaxed);
}
2022-12-12 07:39:54 +03:00
AuthorizationType::Internal => {
conn.internal_requests
.fetch_add(1, atomic::Ordering::Relaxed);
}
}
2022-09-09 06:53:16 +03:00
let metrics = conn.open_request_handle_metrics.clone();
2022-09-23 00:03:37 +03:00
let used = false.into();
2022-09-23 00:03:37 +03:00
Self {
authorization,
2022-09-23 00:03:37 +03:00
conn,
metrics,
2022-12-06 03:06:28 +03:00
provider,
2022-09-23 00:03:37 +03:00
used,
}
2022-08-24 03:11:49 +03:00
}
2022-12-20 02:59:01 +03:00
pub fn connection_name(&self) -> String {
self.conn.name.clone()
}
2022-09-23 01:34:43 +03:00
#[inline]
2022-08-24 03:11:49 +03:00
pub fn clone_connection(&self) -> Arc<Web3Connection> {
2022-09-23 00:03:37 +03:00
self.conn.clone()
2022-08-24 03:11:49 +03:00
}
/// Send a web3 request
/// By having the request method here, we ensure that the rate limiter was called and connection counts were properly incremented
/// TODO: we no longer take self because metered doesn't like that
/// TODO: ErrorCount includes too many types of errors, such as transaction reverts
2022-09-20 09:56:24 +03:00
#[measure([JsonRpcErrorCount, HitCount, ProviderErrorCount, ResponseTime, Throughput])]
pub async fn request<P, R>(
2022-08-24 03:11:49 +03:00
&self,
method: &str,
params: &P,
2023-01-17 09:54:40 +03:00
revert_handler: RequestRevertHandler,
) -> Result<R, ProviderError>
2022-08-24 03:11:49 +03:00
where
2022-09-23 00:51:52 +03:00
// TODO: not sure about this type. would be better to not need clones, but measure and spawns combine to need it
P: Clone + fmt::Debug + serde::Serialize + Send + Sync + 'static,
2022-08-24 03:11:49 +03:00
R: serde::Serialize + serde::de::DeserializeOwned + fmt::Debug,
{
2022-09-23 00:03:37 +03:00
// ensure this function only runs once
if self.used.swap(true, Ordering::Release) {
unimplemented!("a request handle should only be used once");
}
2022-09-23 00:51:52 +03:00
// TODO: use tracing spans
2022-08-30 23:01:42 +03:00
// TODO: requests from customers have request ids, but we should add
2022-08-24 03:11:49 +03:00
// TODO: including params in this is way too verbose
// the authorization field is already on a parent span
2022-11-12 11:24:32 +03:00
// trace!(rpc=%self.conn, %method, "request");
2022-08-24 03:11:49 +03:00
2022-12-06 00:13:36 +03:00
// trace!("got provider for {:?}", self);
2022-09-23 00:51:52 +03:00
// TODO: really sucks that we have to clone here
2022-12-06 03:06:28 +03:00
let response = match &*self.provider {
Web3Provider::Mock => unimplemented!(),
2022-09-23 01:14:24 +03:00
Web3Provider::Http(provider) => provider.request(method, params).await,
Web3Provider::Ws(provider) => provider.request(method, params).await,
2022-08-24 03:11:49 +03:00
};
2023-01-19 03:17:43 +03:00
// // TODO: i think ethers already has trace logging (and does it much more fancy)
// trace!(
// "response from {} for {} {:?}: {:?}",
// self.conn,
// method,
// params,
// response,
// );
2022-12-06 00:13:36 +03:00
if let Err(err) = &response {
2022-09-23 01:42:44 +03:00
// only save reverts for some types of calls
// TODO: do something special for eth_sendRawTransaction too
2023-01-17 09:54:40 +03:00
let revert_handler = if let RequestRevertHandler::Save = revert_handler {
2022-11-26 07:57:25 +03:00
// TODO: should all these be Trace or Debug or a mix?
2022-09-24 10:04:11 +03:00
if !["eth_call", "eth_estimateGas"].contains(&method) {
2022-11-12 11:24:32 +03:00
// trace!(%method, "skipping save on revert");
2023-01-17 09:54:40 +03:00
RequestRevertHandler::TraceLevel
} else if self.authorization.db_conn.is_some() {
let log_revert_chance = self.authorization.checks.log_revert_chance;
if log_revert_chance == 0.0 {
2022-11-12 11:24:32 +03:00
// trace!(%method, "no chance. skipping save on revert");
2023-01-17 09:54:40 +03:00
RequestRevertHandler::TraceLevel
} else if log_revert_chance == 1.0 {
2022-11-12 11:24:32 +03:00
// trace!(%method, "gaurenteed chance. SAVING on revert");
2023-01-17 09:54:40 +03:00
revert_handler
2022-11-12 09:11:58 +03:00
} else if thread_fast_rng::thread_fast_rng().gen_range(0.0f64..=1.0)
< log_revert_chance
{
2022-11-12 11:24:32 +03:00
// trace!(%method, "missed chance. skipping save on revert");
2023-01-17 09:54:40 +03:00
RequestRevertHandler::TraceLevel
2022-09-24 10:04:11 +03:00
} else {
2022-11-12 11:24:32 +03:00
// trace!("Saving on revert");
// TODO: is always logging at debug level fine?
2023-01-17 09:54:40 +03:00
revert_handler
2022-09-24 10:04:11 +03:00
}
2022-09-23 01:42:44 +03:00
} else {
2022-11-12 11:24:32 +03:00
// trace!(%method, "no database. skipping save on revert");
2023-01-17 09:54:40 +03:00
RequestRevertHandler::TraceLevel
}
2022-09-23 01:42:44 +03:00
} else {
2023-01-17 09:54:40 +03:00
revert_handler
2022-09-23 01:42:44 +03:00
};
enum ResponseTypes {
Revert,
RateLimit,
Ok,
}
2022-10-12 00:31:34 +03:00
// check for "execution reverted" here
let response_type = if let ProviderError::JsonRpcClientError(err) = err {
2022-10-12 00:31:34 +03:00
// Http and Ws errors are very similar, but different types
2022-12-06 03:06:28 +03:00
let msg = match &*self.provider {
Web3Provider::Mock => unimplemented!(),
2022-10-12 00:31:34 +03:00
Web3Provider::Http(_) => {
if let Some(HttpClientError::JsonRpcError(err)) =
err.downcast_ref::<HttpClientError>()
{
Some(&err.message)
} else {
None
}
}
Web3Provider::Ws(_) => {
if let Some(WsClientError::JsonRpcError(err)) =
err.downcast_ref::<WsClientError>()
{
Some(&err.message)
} else {
None
}
}
};
if let Some(msg) = msg {
if msg.starts_with("execution reverted") {
trace!("revert from {}", self.conn);
ResponseTypes::Revert
} else if msg.contains("limit") || msg.contains("request") {
trace!("rate limit from {}", self.conn);
ResponseTypes::RateLimit
} else {
ResponseTypes::Ok
}
2022-10-12 00:31:34 +03:00
} else {
ResponseTypes::Ok
2022-10-12 00:31:34 +03:00
}
} else {
ResponseTypes::Ok
2022-10-12 00:31:34 +03:00
};
2022-10-10 07:15:07 +03:00
if matches!(response_type, ResponseTypes::RateLimit) {
if let Some(hard_limit_until) = self.conn.hard_limit_until.as_ref() {
let retry_at = Instant::now() + Duration::from_secs(1);
trace!("retry {} at: {:?}", self.conn, retry_at);
hard_limit_until
.send(retry_at)
.expect("sending hard limit retry times should always work");
}
2022-12-20 00:53:38 +03:00
}
// TODO: think more about the method and param logs. those can be sensitive information
2023-01-17 09:54:40 +03:00
match revert_handler {
RequestRevertHandler::DebugLevel => {
2022-10-12 00:31:34 +03:00
// TODO: think about this revert check more. sometimes we might want reverts logged so this needs a flag
if matches!(response_type, ResponseTypes::Revert) {
2022-11-14 21:24:52 +03:00
debug!(
"bad response from {}! method={} params={:?} err={:?}",
self.conn, method, params, err
);
2022-10-12 00:31:34 +03:00
}
}
2023-01-17 09:54:40 +03:00
RequestRevertHandler::TraceLevel => {
trace!(
"bad response from {}! method={} params={:?} err={:?}",
self.conn,
method,
params,
err
);
}
2023-01-17 09:54:40 +03:00
RequestRevertHandler::ErrorLevel => {
// TODO: include params if not running in release mode
2022-11-14 21:24:52 +03:00
error!(
"bad response from {}! method={} err={:?}",
self.conn, method, err
2022-11-14 21:24:52 +03:00
);
2022-09-23 01:42:44 +03:00
}
2023-01-17 09:54:40 +03:00
RequestRevertHandler::WarnLevel => {
// TODO: include params if not running in release mode
2022-11-14 21:24:52 +03:00
warn!(
"bad response from {}! method={} err={:?}",
self.conn, method, err
2022-11-14 21:24:52 +03:00
);
}
2023-01-17 09:54:40 +03:00
RequestRevertHandler::Save => {
trace!(
"bad response from {}! method={} params={:?} err={:?}",
self.conn,
method,
params,
err
);
2022-10-12 00:31:34 +03:00
// TODO: do not unwrap! (doesn't matter much since we check method as a string above)
let method: Method = Method::try_from_value(&method.to_string()).unwrap();
// TODO: DO NOT UNWRAP! But also figure out the best way to keep returning ProviderErrors here
let params: EthCallParams = serde_json::from_value(json!(params))
.context("parsing params to EthCallParams")
.unwrap();
// spawn saving to the database so we don't slow down the request
let f = self.authorization.clone().save_revert(method, params.0 .0);
2022-10-12 00:31:34 +03:00
tokio::spawn(f);
}
}
}
2022-08-24 03:11:49 +03:00
response
}
}
2022-08-24 03:14:49 +03:00
impl Drop for OpenRequestHandle {
2022-08-24 03:11:49 +03:00
fn drop(&mut self) {
2022-09-23 00:03:37 +03:00
self.conn
.active_requests
.fetch_sub(1, atomic::Ordering::AcqRel);
2022-08-24 03:11:49 +03:00
}
}