lots of tracing improvements

This commit is contained in:
Bryan Stitt 2023-06-28 21:30:00 -07:00
parent 25b04db3b5
commit fba41b9bc2
16 changed files with 67 additions and 67 deletions

View File

@ -204,15 +204,15 @@ impl Web3ProxyApp {
if !top_config.extra.is_empty() { if !top_config.extra.is_empty() {
warn!( warn!(
"unknown TopConfig fields!: {:?}", extra=?top_config.extra.keys(),
top_config.app.extra.keys() "unknown TopConfig fields!",
); );
} }
if !top_config.app.extra.is_empty() { if !top_config.app.extra.is_empty() {
warn!( warn!(
"unknown Web3ProxyAppConfig fields!: {:?}", extra=?top_config.app.extra.keys(),
top_config.app.extra.keys() "unknown Web3ProxyAppConfig fields!",
); );
} }
@ -750,7 +750,7 @@ impl Web3ProxyApp {
match user::Entity::find().count(db).await { match user::Entity::find().count(db).await {
Ok(user_count) => UserCount(user_count as i64), Ok(user_count) => UserCount(user_count as i64),
Err(err) => { Err(err) => {
warn!("unable to count users: {:?}", err); warn!(?err, "unable to count users");
UserCount(-1) UserCount(-1)
} }
} }
@ -863,7 +863,7 @@ impl Web3ProxyApp {
(recent_ip_counts, recent_user_id_counts, recent_tx_counts) (recent_ip_counts, recent_user_id_counts, recent_tx_counts)
} }
Err(err) => { Err(err) => {
warn!("unable to count recent users: {}", err); warn!(?err, "unable to count recent users");
( (
RecentCounts::for_err(), RecentCounts::for_err(),
RecentCounts::for_err(), RecentCounts::for_err(),
@ -873,7 +873,7 @@ impl Web3ProxyApp {
} }
} }
Err(err) => { Err(err) => {
warn!("unable to connect to redis while counting users: {:?}", err); warn!(?err, "unable to connect to redis while counting users");
( (
RecentCounts::for_err(), RecentCounts::for_err(),
RecentCounts::for_err(), RecentCounts::for_err(),
@ -1510,8 +1510,8 @@ impl Web3ProxyApp {
Err(Web3ProxyError::NoDatabase) => {}, Err(Web3ProxyError::NoDatabase) => {},
Err(err) => { Err(err) => {
warn!( warn!(
"unable to save stats for eth_sendRawTransaction: {:?}", ?err,
err "unable to save stats for eth_sendRawTransaction",
) )
} }
} }

View File

@ -107,7 +107,7 @@ async fn main() -> anyhow::Result<()> {
match main_loop(&check_url, &compare_url, &client, &counter).await { match main_loop(&check_url, &compare_url, &client, &counter).await {
Ok(()) => break, Ok(()) => break,
Err(err) => { Err(err) => {
warn!("{:?}", err); warn!(?err, "main_loop");
if let Some(max_wait) = cli_config.max_wait { if let Some(max_wait) = cli_config.max_wait {
if max_wait == 0 || start.elapsed().as_secs() > max_wait { if max_wait == 0 || start.elapsed().as_secs() > max_wait {

View File

@ -217,21 +217,21 @@ async fn run(
if !frontend_exited { if !frontend_exited {
if let Err(err) = frontend_shutdown_sender.send(()) { if let Err(err) = frontend_shutdown_sender.send(()) {
// TODO: this is actually expected if the frontend is already shut down // TODO: this is actually expected if the frontend is already shut down
warn!("shutdown sender err={:?}", err); warn!(?err, "shutdown sender");
}; };
} }
// TODO: Also not there on main branch // TODO: Also not there on main branch
// TODO: wait until the frontend completes // TODO: wait until the frontend completes
if let Err(err) = frontend_shutdown_complete_receiver.recv().await { if let Err(err) = frontend_shutdown_complete_receiver.recv().await {
warn!("shutdown completition err={:?}", err); warn!(?err, "shutdown completition");
} else { } else {
info!("frontend exited gracefully"); info!("frontend exited gracefully");
} }
// now that the frontend is complete, tell all the other futures to finish // now that the frontend is complete, tell all the other futures to finish
if let Err(err) = app_shutdown_sender.send(()) { if let Err(err) = app_shutdown_sender.send(()) {
warn!("backend sender err={:?}", err); warn!(?err, "backend sender");
}; };
info!( info!(

View File

@ -126,7 +126,7 @@ impl SentrydSubCommand {
while let Some(err) = error_receiver.recv().await { while let Some(err) = error_receiver.recv().await {
if matches!(err.level, Level::ERROR) { if matches!(err.level, Level::ERROR) {
warn!("check failed: {:#?}", err); warn!(?err, "check failed");
let alert = pagerduty_alert( let alert = pagerduty_alert(
Some(chain_id), Some(chain_id),

View File

@ -10,7 +10,7 @@ use migration::sea_orm::{
}; };
use std::path::{Path, PathBuf}; use std::path::{Path, PathBuf};
use std::{fs::File, io::BufReader}; use std::{fs::File, io::BufReader};
use tracing::{info, warn}; use tracing::{info};
#[derive(FromArgs, PartialEq, Eq, Debug)] #[derive(FromArgs, PartialEq, Eq, Debug)]
/// Import users from another database. /// Import users from another database.
@ -54,7 +54,7 @@ impl UserImportSubCommand {
self.import_user_file(db_conn, path, &mut user_map).await? self.import_user_file(db_conn, path, &mut user_map).await?
} }
Err(e) => { Err(e) => {
warn!( info!(
"imported {} users from {} files.", "imported {} users from {} files.",
imported_user_count, user_file_count imported_user_count, user_file_count
); );
@ -87,7 +87,7 @@ impl UserImportSubCommand {
self.import_rpc_key_file(db_conn, path, &user_map).await? self.import_rpc_key_file(db_conn, path, &user_map).await?
} }
Err(e) => { Err(e) => {
warn!( info!(
"imported {} users from {} files.", "imported {} users from {} files.",
imported_rpc_key_count, rpc_key_file_count imported_rpc_key_count, rpc_key_file_count
); );

View File

@ -352,7 +352,7 @@ impl CacheMode {
cache_errors: true, cache_errors: true,
}), }),
Err(err) => { Err(err) => {
warn!("could not get block from params. err={:?}", err); warn!(%method, ?params, ?err, "could not get block from params");
Ok(CacheMode::Cache { Ok(CacheMode::Cache {
block: head_block.into(), block: head_block.into(),
cache_errors: true, cache_errors: true,

View File

@ -306,7 +306,7 @@ impl Web3RpcConfig {
tx_id_sender: Option<flume::Sender<TxHashAndRpc>>, tx_id_sender: Option<flume::Sender<TxHashAndRpc>>,
) -> anyhow::Result<(Arc<Web3Rpc>, Web3ProxyJoinHandle<()>)> { ) -> anyhow::Result<(Arc<Web3Rpc>, Web3ProxyJoinHandle<()>)> {
if !self.extra.is_empty() { if !self.extra.is_empty() {
warn!("unknown Web3RpcConfig fields!: {:?}", self.extra.keys()); warn!(extra=?self.extra.keys(), "unknown Web3RpcConfig fields!");
} }
Web3Rpc::spawn( Web3Rpc::spawn(

View File

@ -340,7 +340,7 @@ impl Web3ProxyError {
} }
} }
Self::FlumeRecv(err) => { Self::FlumeRecv(err) => {
warn!("FlumeRecvError err={:#?}", err); warn!(?err, "FlumeRecvError");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -363,7 +363,7 @@ impl Web3ProxyError {
) )
} }
Self::HdrRecord(err) => { Self::HdrRecord(err) => {
warn!("HdrRecord {:#?}", err); warn!(?err, "HdrRecord");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -374,7 +374,7 @@ impl Web3ProxyError {
) )
} }
Self::Headers(err) => { Self::Headers(err) => {
trace!("HeadersError {:#?}", err); trace!(?err, "HeadersError");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -385,7 +385,7 @@ impl Web3ProxyError {
) )
} }
Self::HeaderToString(err) => { Self::HeaderToString(err) => {
// trace!(?err, "HeaderToString"); trace!(?err, "HeaderToString");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -396,7 +396,7 @@ impl Web3ProxyError {
) )
} }
Self::HttpUri(err) => { Self::HttpUri(err) => {
trace!("HttpUri {:#?}", err); trace!(?err, "HttpUri");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -407,7 +407,7 @@ impl Web3ProxyError {
) )
} }
Self::Hyper(err) => { Self::Hyper(err) => {
warn!("hyper err={:#?}", err); warn!(?err, "hyper");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -420,7 +420,7 @@ impl Web3ProxyError {
} }
Self::InfluxDb2Request(err) => { Self::InfluxDb2Request(err) => {
// TODO: attach a request id to the message and to this error so that if people report problems, we can dig in sentry to find out more // TODO: attach a request id to the message and to this error so that if people report problems, we can dig in sentry to find out more
error!("influxdb2 err={:#?}", err); error!(?err, "influxdb2");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -431,7 +431,7 @@ impl Web3ProxyError {
) )
} }
Self::InvalidBlockBounds { min, max } => { Self::InvalidBlockBounds { min, max } => {
trace!("InvalidBlockBounds min={} max={}", min, max); trace!(%min, %max, "InvalidBlockBounds");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -446,7 +446,7 @@ impl Web3ProxyError {
) )
} }
Self::IpAddrParse(err) => { Self::IpAddrParse(err) => {
debug!("IpAddrParse err={:#?}", err); debug!(?err, "IpAddrParse");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -457,7 +457,7 @@ impl Web3ProxyError {
) )
} }
Self::IpNotAllowed(ip) => { Self::IpNotAllowed(ip) => {
trace!("IpNotAllowed ip={:#?})", ip); trace!(?ip, "IpNotAllowed");
( (
StatusCode::FORBIDDEN, StatusCode::FORBIDDEN,
JsonRpcErrorData { JsonRpcErrorData {
@ -468,7 +468,7 @@ impl Web3ProxyError {
) )
} }
Self::InvalidHeaderValue(err) => { Self::InvalidHeaderValue(err) => {
trace!("InvalidHeaderValue err={:#?}", err); trace!(?err, "InvalidHeaderValue");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -501,7 +501,7 @@ impl Web3ProxyError {
) )
} }
Self::Io(err) => { Self::Io(err) => {
warn!("std io err={:#?}", err); warn!(?err, "std io");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -569,10 +569,10 @@ impl Web3ProxyError {
} }
Self::JoinError(err) => { Self::JoinError(err) => {
let code = if err.is_cancelled() { let code = if err.is_cancelled() {
trace!("JoinError. likely shutting down. err={:?}", err); trace!(?err, "JoinError. likely shutting down");
StatusCode::BAD_GATEWAY StatusCode::BAD_GATEWAY
} else { } else {
warn!("JoinError. err={:?}", err); warn!(?err, "JoinError");
StatusCode::INTERNAL_SERVER_ERROR StatusCode::INTERNAL_SERVER_ERROR
}; };
@ -591,7 +591,7 @@ impl Web3ProxyError {
(StatusCode::OK, jsonrpc_error_data.clone()) (StatusCode::OK, jsonrpc_error_data.clone())
} }
Self::MsgPackEncode(err) => { Self::MsgPackEncode(err) => {
warn!("MsgPackEncode Error: {:#?}", err); warn!(?err, "MsgPackEncode");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -833,7 +833,7 @@ impl Web3ProxyError {
) )
} }
Self::Redis(err) => { Self::Redis(err) => {
warn!("redis err={:#?}", err); warn!(?err, "redis");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -844,7 +844,7 @@ impl Web3ProxyError {
) )
} }
Self::RedisDeadpool(err) => { Self::RedisDeadpool(err) => {
error!("redis deadpool err={:#?}", err); error!(?err, "redis deadpool");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -867,7 +867,7 @@ impl Web3ProxyError {
) )
} }
Self::RefererNotAllowed(referer) => { Self::RefererNotAllowed(referer) => {
trace!("referer not allowed referer={:?}", referer); trace!(?referer, "referer not allowed");
( (
StatusCode::FORBIDDEN, StatusCode::FORBIDDEN,
JsonRpcErrorData { JsonRpcErrorData {
@ -878,7 +878,7 @@ impl Web3ProxyError {
) )
} }
Self::SemaphoreAcquireError(err) => { Self::SemaphoreAcquireError(err) => {
warn!("semaphore acquire err={:#?}", err); error!(?err, "semaphore acquire");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -890,7 +890,7 @@ impl Web3ProxyError {
) )
} }
Self::SendAppStatError(err) => { Self::SendAppStatError(err) => {
error!("SendAppStatError err={:#?}", err); error!(?err, "SendAppStatError");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {
@ -901,7 +901,7 @@ impl Web3ProxyError {
) )
} }
Self::SerdeJson(err) => { Self::SerdeJson(err) => {
trace!("serde json err={:#?}", err); trace!(?err, "serde json");
( (
StatusCode::BAD_REQUEST, StatusCode::BAD_REQUEST,
JsonRpcErrorData { JsonRpcErrorData {
@ -912,11 +912,11 @@ impl Web3ProxyError {
) )
} }
Self::SiweVerification(err) => { Self::SiweVerification(err) => {
trace!("Siwe Verification err={:#?}", err,); trace!(?err, "Siwe Verification");
( (
StatusCode::UNAUTHORIZED, StatusCode::UNAUTHORIZED,
JsonRpcErrorData { JsonRpcErrorData {
message: format!("siwe verification error: {:#?}", err).into(), message: format!("siwe verification error: {}", err.to_string()).into(),
code: StatusCode::UNAUTHORIZED.as_u16().into(), code: StatusCode::UNAUTHORIZED.as_u16().into(),
data: None, data: None,
}, },
@ -926,9 +926,9 @@ impl Web3ProxyError {
// different status codes should get different error levels. 500s should warn. 400s should stat // different status codes should get different error levels. 500s should warn. 400s should stat
let code = status_code.as_u16(); let code = status_code.as_u16();
if (500..600).contains(&code) { if (500..600).contains(&code) {
warn!("server error {} {:?}: {:#?}", code, err_msg, err); warn!(%err_msg, ?err, "server error {}", code);
} else { } else {
trace!("user error {} {:?}: {:#?}", code, err_msg, err); trace!(%err_msg, ?err, "user error {}", code);
} }
( (
@ -1071,11 +1071,11 @@ impl Web3ProxyError {
} }
Self::WithContext(err, msg) => match err { Self::WithContext(err, msg) => match err {
Some(err) => { Some(err) => {
warn!("{:#?} w/ context {}", err, msg); warn!(?err, %msg, "error w/ context");
return err.as_response_parts(); return err.as_response_parts();
} }
None => { None => {
warn!("error w/ context {}", msg); warn!(%msg, "error w/ context");
( (
StatusCode::INTERNAL_SERVER_ERROR, StatusCode::INTERNAL_SERVER_ERROR,
JsonRpcErrorData { JsonRpcErrorData {

View File

@ -456,7 +456,7 @@ pub async fn admin_imitate_login_post(
.web3_context("saving user login")?; .web3_context("saving user login")?;
if let Err(err) = user_pending_login.into_active_model().delete(db_conn).await { if let Err(err) = user_pending_login.into_active_model().delete(db_conn).await {
warn!("Failed to delete nonce:{}: {}", login_nonce.0, err); warn!(none=?login_nonce.0, ?err, "Failed to delete nonce");
} }
Ok(response) Ok(response)

View File

@ -610,7 +610,7 @@ impl Drop for RequestMetadata {
// turn `&mut self` into `self` // turn `&mut self` into `self`
let x = mem::take(self); let x = mem::take(self);
// warn!("request metadata dropped without stat send! {:?}", self); trace!(?self, "request metadata dropped without stat send");
let _ = x.try_send_stat(); let _ = x.try_send_stat();
} }
} }
@ -881,7 +881,7 @@ pub async fn ip_is_authorized(
Ok::<_, Web3ProxyError>(()) Ok::<_, Web3ProxyError>(())
} }
.map_err(|err| { .map_err(|err| {
warn!("background update of recent_users:ip failed: {}", err); warn!(?err, "background update of recent_users:ip failed");
err err
}); });
@ -945,7 +945,7 @@ pub async fn key_is_authorized(
Ok::<_, Web3ProxyError>(()) Ok::<_, Web3ProxyError>(())
} }
.map_err(|err| { .map_err(|err| {
warn!("background update of recent_users:id failed: {}", err); warn!(?err, "background update of recent_users:id failed");
err err
}); });

View File

@ -426,7 +426,7 @@ pub async fn user_logout_post(
.exec(db_conn) .exec(db_conn)
.await .await
{ {
warn!("Failed to delete {}: {}", user_bearer.redis_key(), err); warn!(key=%user_bearer.redis_key(), ?err, "Failed to delete from redis");
} }
// TODO: what should the response be? probably json something // TODO: what should the response be? probably json something

View File

@ -86,7 +86,7 @@ pub async fn get_user_id_from_params(
.set_ex::<_, _, ()>(user_redis_key, user_id, ONE_DAY) .set_ex::<_, _, ()>(user_redis_key, user_id, ONE_DAY)
.await .await
{ {
warn!("Unable to save user bearer token to redis: {}", err) warn!(?err, "Unable to save user bearer token to redis")
} }
} }

View File

@ -112,7 +112,7 @@ pub fn panic_handler(
let event = Event::AlertTrigger(alert); let event = Event::AlertTrigger(alert);
if let Err(err) = pagerduty_sync.event(event) { if let Err(err) = pagerduty_sync.event(event) {
error!("Failed sending alert to pagerduty! {:#?}", err); error!(?err, "Failed sending alert to pagerduty!");
} }
} }
@ -165,7 +165,7 @@ pub fn pagerduty_alert<T: Serialize>(
.unwrap() .unwrap()
.into_string() .into_string()
.unwrap_or_else(|err| { .unwrap_or_else(|err| {
warn!("unable to handle hostname: {:#?}", err); warn!(?err, "unable to handle hostname");
"unknown".to_string() "unknown".to_string()
}) })
}); });

View File

@ -620,15 +620,15 @@ impl Web3Rpcs {
if let Some(retry_at) = earliest_retry_at { if let Some(retry_at) = earliest_retry_at {
// TODO: log the server that retry_at came from // TODO: log the server that retry_at came from
warn!( warn!(
"no servers in {} ready! Skipped {:?}. Retry in {:?}s", ?skip_rpcs,
self, retry_in_s=?retry_at.duration_since(Instant::now()).as_secs_f32(),
skip_rpcs, "no servers in {} ready!",
retry_at.duration_since(Instant::now()).as_secs_f32() self,
); );
Ok(OpenRequestResult::RetryAt(retry_at)) Ok(OpenRequestResult::RetryAt(retry_at))
} else { } else {
warn!("no servers in {} ready! Skipped {:?}", self, skip_rpcs); warn!(?skip_rpcs, "no servers in {} ready!", self);
Ok(OpenRequestResult::NotReady) Ok(OpenRequestResult::NotReady)
} }
@ -714,7 +714,7 @@ impl Web3Rpcs {
warn!("no request handle for {}", rpc) warn!("no request handle for {}", rpc)
} }
Err(err) => { Err(err) => {
warn!("error getting request handle for {}. err={:?}", rpc, err) warn!(?err, "error getting request handle for {}", rpc)
} }
} }
} }
@ -902,16 +902,16 @@ impl Web3Rpcs {
} else { } else {
// they hit a limit lower than what we expect // they hit a limit lower than what we expect
warn!( warn!(
"unexpected result limit ({}) by {}", %error_msg,
error_msg, "unexpected result limitby {}",
skip_rpcs.last().unwrap() skip_rpcs.last().unwrap(),
); );
continue; continue;
} }
} else { } else {
warn!( warn!(
"rate limited ({}) by {}", %error_msg,
error_msg, "rate limited by {}",
skip_rpcs.last().unwrap() skip_rpcs.last().unwrap()
); );
continue; continue;

View File

@ -782,7 +782,7 @@ impl Web3Rpc {
// try_join on the futures // try_join on the futures
if let Err(err) = try_join_all(futures).await { if let Err(err) = try_join_all(futures).await {
warn!("subscription erred: {:?}", err); warn!(?err, "subscription erred");
} }
debug!("subscriptions on {} exited", self); debug!("subscriptions on {} exited", self);

View File

@ -273,7 +273,7 @@ pub async fn query_user_stats<'a>(
.set_ex::<_, _, ()>(cache_key, cache_body, ttl) .set_ex::<_, _, ()>(cache_key, cache_body, ttl)
.await .await
{ {
warn!("Redis error while caching query_user_stats: {:?}", err); warn!(?err, "Redis error while caching query_user_stats");
} }
} else { } else {
headers.insert( headers.insert(