From fba41b9bc294483024c2293bd9539ab75f079db9 Mon Sep 17 00:00:00 2001 From: Bryan Stitt Date: Wed, 28 Jun 2023 21:30:00 -0700 Subject: [PATCH] lots of tracing improvements --- web3_proxy/src/app/mod.rs | 18 +++---- web3_proxy/src/bin/wait_for_sync.rs | 2 +- web3_proxy/src/bin/web3_proxy_cli/proxyd.rs | 6 +-- .../src/bin/web3_proxy_cli/sentryd/mod.rs | 2 +- .../src/bin/web3_proxy_cli/user_import.rs | 6 +-- web3_proxy/src/block_number.rs | 2 +- web3_proxy/src/config.rs | 2 +- web3_proxy/src/errors.rs | 54 +++++++++---------- web3_proxy/src/frontend/admin.rs | 2 +- web3_proxy/src/frontend/authorization.rs | 6 +-- .../src/frontend/users/authentication.rs | 2 +- web3_proxy/src/http_params.rs | 2 +- web3_proxy/src/pagerduty.rs | 4 +- web3_proxy/src/rpcs/many.rs | 22 ++++---- web3_proxy/src/rpcs/one.rs | 2 +- web3_proxy/src/stats/db_queries.rs | 2 +- 16 files changed, 67 insertions(+), 67 deletions(-) diff --git a/web3_proxy/src/app/mod.rs b/web3_proxy/src/app/mod.rs index d213c5ff..436051fd 100644 --- a/web3_proxy/src/app/mod.rs +++ b/web3_proxy/src/app/mod.rs @@ -204,15 +204,15 @@ impl Web3ProxyApp { if !top_config.extra.is_empty() { warn!( - "unknown TopConfig fields!: {:?}", - top_config.app.extra.keys() + extra=?top_config.extra.keys(), + "unknown TopConfig fields!", ); } if !top_config.app.extra.is_empty() { warn!( - "unknown Web3ProxyAppConfig fields!: {:?}", - top_config.app.extra.keys() + extra=?top_config.app.extra.keys(), + "unknown Web3ProxyAppConfig fields!", ); } @@ -750,7 +750,7 @@ impl Web3ProxyApp { match user::Entity::find().count(db).await { Ok(user_count) => UserCount(user_count as i64), Err(err) => { - warn!("unable to count users: {:?}", err); + warn!(?err, "unable to count users"); UserCount(-1) } } @@ -863,7 +863,7 @@ impl Web3ProxyApp { (recent_ip_counts, recent_user_id_counts, recent_tx_counts) } Err(err) => { - warn!("unable to count recent users: {}", err); + warn!(?err, "unable to count recent users"); ( RecentCounts::for_err(), RecentCounts::for_err(), @@ -873,7 +873,7 @@ impl Web3ProxyApp { } } 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(), @@ -1510,8 +1510,8 @@ impl Web3ProxyApp { Err(Web3ProxyError::NoDatabase) => {}, Err(err) => { warn!( - "unable to save stats for eth_sendRawTransaction: {:?}", - err + ?err, + "unable to save stats for eth_sendRawTransaction", ) } } diff --git a/web3_proxy/src/bin/wait_for_sync.rs b/web3_proxy/src/bin/wait_for_sync.rs index 47749bb0..95165e87 100644 --- a/web3_proxy/src/bin/wait_for_sync.rs +++ b/web3_proxy/src/bin/wait_for_sync.rs @@ -107,7 +107,7 @@ async fn main() -> anyhow::Result<()> { match main_loop(&check_url, &compare_url, &client, &counter).await { Ok(()) => break, Err(err) => { - warn!("{:?}", err); + warn!(?err, "main_loop"); if let Some(max_wait) = cli_config.max_wait { if max_wait == 0 || start.elapsed().as_secs() > max_wait { diff --git a/web3_proxy/src/bin/web3_proxy_cli/proxyd.rs b/web3_proxy/src/bin/web3_proxy_cli/proxyd.rs index 3dfe8e3c..beb76bd3 100644 --- a/web3_proxy/src/bin/web3_proxy_cli/proxyd.rs +++ b/web3_proxy/src/bin/web3_proxy_cli/proxyd.rs @@ -217,21 +217,21 @@ async fn run( if !frontend_exited { if let Err(err) = frontend_shutdown_sender.send(()) { // 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: wait until the frontend completes if let Err(err) = frontend_shutdown_complete_receiver.recv().await { - warn!("shutdown completition err={:?}", err); + warn!(?err, "shutdown completition"); } else { info!("frontend exited gracefully"); } // now that the frontend is complete, tell all the other futures to finish if let Err(err) = app_shutdown_sender.send(()) { - warn!("backend sender err={:?}", err); + warn!(?err, "backend sender"); }; info!( diff --git a/web3_proxy/src/bin/web3_proxy_cli/sentryd/mod.rs b/web3_proxy/src/bin/web3_proxy_cli/sentryd/mod.rs index 43a5a30d..1867911c 100644 --- a/web3_proxy/src/bin/web3_proxy_cli/sentryd/mod.rs +++ b/web3_proxy/src/bin/web3_proxy_cli/sentryd/mod.rs @@ -126,7 +126,7 @@ impl SentrydSubCommand { while let Some(err) = error_receiver.recv().await { if matches!(err.level, Level::ERROR) { - warn!("check failed: {:#?}", err); + warn!(?err, "check failed"); let alert = pagerduty_alert( Some(chain_id), diff --git a/web3_proxy/src/bin/web3_proxy_cli/user_import.rs b/web3_proxy/src/bin/web3_proxy_cli/user_import.rs index 482d981e..9b7c7815 100644 --- a/web3_proxy/src/bin/web3_proxy_cli/user_import.rs +++ b/web3_proxy/src/bin/web3_proxy_cli/user_import.rs @@ -10,7 +10,7 @@ use migration::sea_orm::{ }; use std::path::{Path, PathBuf}; use std::{fs::File, io::BufReader}; -use tracing::{info, warn}; +use tracing::{info}; #[derive(FromArgs, PartialEq, Eq, Debug)] /// Import users from another database. @@ -54,7 +54,7 @@ impl UserImportSubCommand { self.import_user_file(db_conn, path, &mut user_map).await? } Err(e) => { - warn!( + info!( "imported {} users from {} files.", imported_user_count, user_file_count ); @@ -87,7 +87,7 @@ impl UserImportSubCommand { self.import_rpc_key_file(db_conn, path, &user_map).await? } Err(e) => { - warn!( + info!( "imported {} users from {} files.", imported_rpc_key_count, rpc_key_file_count ); diff --git a/web3_proxy/src/block_number.rs b/web3_proxy/src/block_number.rs index f299640d..64e6ab08 100644 --- a/web3_proxy/src/block_number.rs +++ b/web3_proxy/src/block_number.rs @@ -352,7 +352,7 @@ impl CacheMode { cache_errors: true, }), Err(err) => { - warn!("could not get block from params. err={:?}", err); + warn!(%method, ?params, ?err, "could not get block from params"); Ok(CacheMode::Cache { block: head_block.into(), cache_errors: true, diff --git a/web3_proxy/src/config.rs b/web3_proxy/src/config.rs index c7b97bf8..16e42a80 100644 --- a/web3_proxy/src/config.rs +++ b/web3_proxy/src/config.rs @@ -306,7 +306,7 @@ impl Web3RpcConfig { tx_id_sender: Option>, ) -> anyhow::Result<(Arc, Web3ProxyJoinHandle<()>)> { if !self.extra.is_empty() { - warn!("unknown Web3RpcConfig fields!: {:?}", self.extra.keys()); + warn!(extra=?self.extra.keys(), "unknown Web3RpcConfig fields!"); } Web3Rpc::spawn( diff --git a/web3_proxy/src/errors.rs b/web3_proxy/src/errors.rs index 38ca9eea..2365f052 100644 --- a/web3_proxy/src/errors.rs +++ b/web3_proxy/src/errors.rs @@ -340,7 +340,7 @@ impl Web3ProxyError { } } Self::FlumeRecv(err) => { - warn!("FlumeRecvError err={:#?}", err); + warn!(?err, "FlumeRecvError"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -363,7 +363,7 @@ impl Web3ProxyError { ) } Self::HdrRecord(err) => { - warn!("HdrRecord {:#?}", err); + warn!(?err, "HdrRecord"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -374,7 +374,7 @@ impl Web3ProxyError { ) } Self::Headers(err) => { - trace!("HeadersError {:#?}", err); + trace!(?err, "HeadersError"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -385,7 +385,7 @@ impl Web3ProxyError { ) } Self::HeaderToString(err) => { - // trace!(?err, "HeaderToString"); + trace!(?err, "HeaderToString"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -396,7 +396,7 @@ impl Web3ProxyError { ) } Self::HttpUri(err) => { - trace!("HttpUri {:#?}", err); + trace!(?err, "HttpUri"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -407,7 +407,7 @@ impl Web3ProxyError { ) } Self::Hyper(err) => { - warn!("hyper err={:#?}", err); + warn!(?err, "hyper"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -420,7 +420,7 @@ impl Web3ProxyError { } 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 - error!("influxdb2 err={:#?}", err); + error!(?err, "influxdb2"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -431,7 +431,7 @@ impl Web3ProxyError { ) } Self::InvalidBlockBounds { min, max } => { - trace!("InvalidBlockBounds min={} max={}", min, max); + trace!(%min, %max, "InvalidBlockBounds"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -446,7 +446,7 @@ impl Web3ProxyError { ) } Self::IpAddrParse(err) => { - debug!("IpAddrParse err={:#?}", err); + debug!(?err, "IpAddrParse"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -457,7 +457,7 @@ impl Web3ProxyError { ) } Self::IpNotAllowed(ip) => { - trace!("IpNotAllowed ip={:#?})", ip); + trace!(?ip, "IpNotAllowed"); ( StatusCode::FORBIDDEN, JsonRpcErrorData { @@ -468,7 +468,7 @@ impl Web3ProxyError { ) } Self::InvalidHeaderValue(err) => { - trace!("InvalidHeaderValue err={:#?}", err); + trace!(?err, "InvalidHeaderValue"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -501,7 +501,7 @@ impl Web3ProxyError { ) } Self::Io(err) => { - warn!("std io err={:#?}", err); + warn!(?err, "std io"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -569,10 +569,10 @@ impl Web3ProxyError { } Self::JoinError(err) => { let code = if err.is_cancelled() { - trace!("JoinError. likely shutting down. err={:?}", err); + trace!(?err, "JoinError. likely shutting down"); StatusCode::BAD_GATEWAY } else { - warn!("JoinError. err={:?}", err); + warn!(?err, "JoinError"); StatusCode::INTERNAL_SERVER_ERROR }; @@ -591,7 +591,7 @@ impl Web3ProxyError { (StatusCode::OK, jsonrpc_error_data.clone()) } Self::MsgPackEncode(err) => { - warn!("MsgPackEncode Error: {:#?}", err); + warn!(?err, "MsgPackEncode"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -833,7 +833,7 @@ impl Web3ProxyError { ) } Self::Redis(err) => { - warn!("redis err={:#?}", err); + warn!(?err, "redis"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -844,7 +844,7 @@ impl Web3ProxyError { ) } Self::RedisDeadpool(err) => { - error!("redis deadpool err={:#?}", err); + error!(?err, "redis deadpool"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -867,7 +867,7 @@ impl Web3ProxyError { ) } Self::RefererNotAllowed(referer) => { - trace!("referer not allowed referer={:?}", referer); + trace!(?referer, "referer not allowed"); ( StatusCode::FORBIDDEN, JsonRpcErrorData { @@ -878,7 +878,7 @@ impl Web3ProxyError { ) } Self::SemaphoreAcquireError(err) => { - warn!("semaphore acquire err={:#?}", err); + error!(?err, "semaphore acquire"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -890,7 +890,7 @@ impl Web3ProxyError { ) } Self::SendAppStatError(err) => { - error!("SendAppStatError err={:#?}", err); + error!(?err, "SendAppStatError"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { @@ -901,7 +901,7 @@ impl Web3ProxyError { ) } Self::SerdeJson(err) => { - trace!("serde json err={:#?}", err); + trace!(?err, "serde json"); ( StatusCode::BAD_REQUEST, JsonRpcErrorData { @@ -912,11 +912,11 @@ impl Web3ProxyError { ) } Self::SiweVerification(err) => { - trace!("Siwe Verification err={:#?}", err,); + trace!(?err, "Siwe Verification"); ( StatusCode::UNAUTHORIZED, JsonRpcErrorData { - message: format!("siwe verification error: {:#?}", err).into(), + message: format!("siwe verification error: {}", err.to_string()).into(), code: StatusCode::UNAUTHORIZED.as_u16().into(), data: None, }, @@ -926,9 +926,9 @@ impl Web3ProxyError { // different status codes should get different error levels. 500s should warn. 400s should stat let code = status_code.as_u16(); if (500..600).contains(&code) { - warn!("server error {} {:?}: {:#?}", code, err_msg, err); + warn!(%err_msg, ?err, "server error {}", code); } 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 { Some(err) => { - warn!("{:#?} w/ context {}", err, msg); + warn!(?err, %msg, "error w/ context"); return err.as_response_parts(); } None => { - warn!("error w/ context {}", msg); + warn!(%msg, "error w/ context"); ( StatusCode::INTERNAL_SERVER_ERROR, JsonRpcErrorData { diff --git a/web3_proxy/src/frontend/admin.rs b/web3_proxy/src/frontend/admin.rs index 21dabe3b..5d130097 100644 --- a/web3_proxy/src/frontend/admin.rs +++ b/web3_proxy/src/frontend/admin.rs @@ -456,7 +456,7 @@ pub async fn admin_imitate_login_post( .web3_context("saving user login")?; 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) diff --git a/web3_proxy/src/frontend/authorization.rs b/web3_proxy/src/frontend/authorization.rs index 3499dfbf..fe201262 100644 --- a/web3_proxy/src/frontend/authorization.rs +++ b/web3_proxy/src/frontend/authorization.rs @@ -610,7 +610,7 @@ impl Drop for RequestMetadata { // turn `&mut self` into `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(); } } @@ -881,7 +881,7 @@ pub async fn ip_is_authorized( Ok::<_, Web3ProxyError>(()) } .map_err(|err| { - warn!("background update of recent_users:ip failed: {}", err); + warn!(?err, "background update of recent_users:ip failed"); err }); @@ -945,7 +945,7 @@ pub async fn key_is_authorized( Ok::<_, Web3ProxyError>(()) } .map_err(|err| { - warn!("background update of recent_users:id failed: {}", err); + warn!(?err, "background update of recent_users:id failed"); err }); diff --git a/web3_proxy/src/frontend/users/authentication.rs b/web3_proxy/src/frontend/users/authentication.rs index a874f579..149beea1 100644 --- a/web3_proxy/src/frontend/users/authentication.rs +++ b/web3_proxy/src/frontend/users/authentication.rs @@ -426,7 +426,7 @@ pub async fn user_logout_post( .exec(db_conn) .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 diff --git a/web3_proxy/src/http_params.rs b/web3_proxy/src/http_params.rs index 4939210b..52e47d1f 100644 --- a/web3_proxy/src/http_params.rs +++ b/web3_proxy/src/http_params.rs @@ -86,7 +86,7 @@ pub async fn get_user_id_from_params( .set_ex::<_, _, ()>(user_redis_key, user_id, ONE_DAY) .await { - warn!("Unable to save user bearer token to redis: {}", err) + warn!(?err, "Unable to save user bearer token to redis") } } diff --git a/web3_proxy/src/pagerduty.rs b/web3_proxy/src/pagerduty.rs index b5105f6f..90cc4d1e 100644 --- a/web3_proxy/src/pagerduty.rs +++ b/web3_proxy/src/pagerduty.rs @@ -112,7 +112,7 @@ pub fn panic_handler( let event = Event::AlertTrigger(alert); 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( .unwrap() .into_string() .unwrap_or_else(|err| { - warn!("unable to handle hostname: {:#?}", err); + warn!(?err, "unable to handle hostname"); "unknown".to_string() }) }); diff --git a/web3_proxy/src/rpcs/many.rs b/web3_proxy/src/rpcs/many.rs index f913a73c..1a08c32c 100644 --- a/web3_proxy/src/rpcs/many.rs +++ b/web3_proxy/src/rpcs/many.rs @@ -620,15 +620,15 @@ impl Web3Rpcs { if let Some(retry_at) = earliest_retry_at { // TODO: log the server that retry_at came from warn!( - "no servers in {} ready! Skipped {:?}. Retry in {:?}s", - self, - skip_rpcs, - retry_at.duration_since(Instant::now()).as_secs_f32() + ?skip_rpcs, + retry_in_s=?retry_at.duration_since(Instant::now()).as_secs_f32(), + "no servers in {} ready!", + self, ); Ok(OpenRequestResult::RetryAt(retry_at)) } else { - warn!("no servers in {} ready! Skipped {:?}", self, skip_rpcs); + warn!(?skip_rpcs, "no servers in {} ready!", self); Ok(OpenRequestResult::NotReady) } @@ -714,7 +714,7 @@ impl Web3Rpcs { warn!("no request handle for {}", rpc) } 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 { // they hit a limit lower than what we expect warn!( - "unexpected result limit ({}) by {}", - error_msg, - skip_rpcs.last().unwrap() + %error_msg, + "unexpected result limitby {}", + skip_rpcs.last().unwrap(), ); continue; } } else { warn!( - "rate limited ({}) by {}", - error_msg, + %error_msg, + "rate limited by {}", skip_rpcs.last().unwrap() ); continue; diff --git a/web3_proxy/src/rpcs/one.rs b/web3_proxy/src/rpcs/one.rs index 396016e5..cc43f240 100644 --- a/web3_proxy/src/rpcs/one.rs +++ b/web3_proxy/src/rpcs/one.rs @@ -782,7 +782,7 @@ impl Web3Rpc { // try_join on the futures if let Err(err) = try_join_all(futures).await { - warn!("subscription erred: {:?}", err); + warn!(?err, "subscription erred"); } debug!("subscriptions on {} exited", self); diff --git a/web3_proxy/src/stats/db_queries.rs b/web3_proxy/src/stats/db_queries.rs index ba6ced2b..7ffac642 100644 --- a/web3_proxy/src/stats/db_queries.rs +++ b/web3_proxy/src/stats/db_queries.rs @@ -273,7 +273,7 @@ pub async fn query_user_stats<'a>( .set_ex::<_, _, ()>(cache_key, cache_body, ttl) .await { - warn!("Redis error while caching query_user_stats: {:?}", err); + warn!(?err, "Redis error while caching query_user_stats"); } } else { headers.insert(