From f44c4a80965f689146bd06dd4c8ad4d52060b8b5 Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 15:57:55 +0000 Subject: [PATCH 1/7] update log settings --- Cargo.lock | 1 + bin/pbs.rs | 7 +- bin/signer.rs | 5 +- bin/src/lib.rs | 7 +- config.example.toml | 38 +++++-- crates/cli/src/docker_init.rs | 12 +- crates/common/src/config/log.rs | 75 ++++++++---- crates/common/src/config/mod.rs | 6 +- crates/common/src/utils.rs | 120 ++++++++++++-------- crates/pbs/Cargo.toml | 1 + crates/pbs/src/mev_boost/get_header.rs | 37 +++--- crates/pbs/src/routes/get_header.rs | 3 +- crates/pbs/src/routes/register_validator.rs | 2 - crates/pbs/src/routes/reload.rs | 2 - crates/pbs/src/routes/router.rs | 33 +++++- crates/pbs/src/routes/status.rs | 2 - crates/pbs/src/routes/submit_block.rs | 4 +- crates/pbs/src/service.rs | 2 +- crates/signer/src/service.rs | 2 +- examples/builder_log/src/main.rs | 2 +- examples/da_commit/src/main.rs | 2 +- examples/status_api/src/main.rs | 2 +- tests/tests/commits.rs | 71 ------------ 23 files changed, 234 insertions(+), 202 deletions(-) delete mode 100644 tests/tests/commits.rs diff --git a/Cargo.lock b/Cargo.lock index 39f3d04b..486e09e5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1544,6 +1544,7 @@ dependencies = [ "alloy", "async-trait", "axum 0.8.1", + "axum-extra", "blst", "cb-common", "cb-metrics", diff --git a/bin/pbs.rs b/bin/pbs.rs index a958b2d8..53714fb5 100644 --- a/bin/pbs.rs +++ b/bin/pbs.rs @@ -1,6 +1,6 @@ use cb_common::{ - config::load_pbs_config, - utils::{initialize_pbs_tracing_log, wait_for_signal}, + config::{load_pbs_config, LogsSettings, PBS_MODULE_NAME}, + utils::{initialize_tracing_log, wait_for_signal}, }; use cb_pbs::{DefaultBuilderApi, PbsService, PbsState}; use clap::Parser; @@ -15,7 +15,7 @@ async fn main() -> Result<()> { if std::env::var_os("RUST_BACKTRACE").is_none() { std::env::set_var("RUST_BACKTRACE", "1"); } - let _guard = initialize_pbs_tracing_log(); + let _guard = initialize_tracing_log(PBS_MODULE_NAME, LogsSettings::from_env_config()?); let _args = cb_cli::PbsArgs::parse(); @@ -29,6 +29,7 @@ async fn main() -> Result<()> { maybe_err = server => { if let Err(err) = maybe_err { error!(%err, "PBS service unexpectedly stopped"); + eprintln!("PBS service unexpectedly stopped: {}", err); } }, _ = wait_for_signal() => { diff --git a/bin/signer.rs b/bin/signer.rs index aeaad87e..e7c7da7c 100644 --- a/bin/signer.rs +++ b/bin/signer.rs @@ -1,5 +1,5 @@ use cb_common::{ - config::{StartSignerConfig, SIGNER_MODULE_NAME}, + config::{LogsSettings, StartSignerConfig, SIGNER_MODULE_NAME}, utils::{initialize_tracing_log, wait_for_signal}, }; use cb_signer::service::SigningService; @@ -15,7 +15,7 @@ async fn main() -> Result<()> { if std::env::var_os("RUST_BACKTRACE").is_none() { std::env::set_var("RUST_BACKTRACE", "1"); } - let _guard = initialize_tracing_log(SIGNER_MODULE_NAME); + let _guard = initialize_tracing_log(SIGNER_MODULE_NAME, LogsSettings::from_env_config()?); let _args = cb_cli::SignerArgs::parse(); @@ -26,6 +26,7 @@ async fn main() -> Result<()> { maybe_err = server => { if let Err(err) = maybe_err { error!(%err, "signing server unexpectedly stopped"); + eprintln!("signing server unexpectedly stopped: {}", err); } }, _ = wait_for_signal() => { diff --git a/bin/src/lib.rs b/bin/src/lib.rs index 55961348..0c401bed 100644 --- a/bin/src/lib.rs +++ b/bin/src/lib.rs @@ -7,15 +7,12 @@ pub mod prelude { }, config::{ load_builder_module_config, load_commit_module_config, load_pbs_config, - load_pbs_custom_config, LogsSettings, StartCommitModuleConfig, + load_pbs_custom_config, LogsSettings, StartCommitModuleConfig, PBS_MODULE_NAME, }, pbs::{BuilderEvent, BuilderEventClient, OnBuilderApiEvent}, signer::{BlsPublicKey, BlsSignature, EcdsaPublicKey, EcdsaSignature}, types::Chain, - utils::{ - initialize_pbs_tracing_log, initialize_tracing_log, utcnow_ms, utcnow_ns, utcnow_sec, - utcnow_us, - }, + utils::{initialize_tracing_log, utcnow_ms, utcnow_ns, utcnow_sec, utcnow_us}, }; pub use cb_metrics::provider::MetricsProvider; pub use cb_pbs::{ diff --git a/config.example.toml b/config.example.toml index 5821391c..5fb58e98 100644 --- a/config.example.toml +++ b/config.example.toml @@ -251,15 +251,37 @@ host = "127.0.0.1" # OPTIONAL, DEFAULT: 10000 start_port = 10000 -# Configuration for how logs should be collected and stored -# OPTIONAL, info to stdout if missing -[logs] +# Configuration stdout logs +# OPTIONAL, DEFAULT: enabled +[logs.stdout] +# Whether to enable stdout logging +# OPTIONAL, DEFAULT: true +enabled = true +# Log level. Supported values: trace, debug, info, warn, error +# OPTIONAL, DEFAULT: info +level = "info" +# Log in JSON format +# OPTIONAL, DEFAULT: false +use_json = false +# Whether to enable ANSI color codes +# OPTIONAL, DEFAULT: true +color = true + +# Configuration file logs +# OPTIONAL, DEFAULT: disabled +[logs.file] +# Whether to enable file logging +# OPTIONAL, DEFAULT: false +enabled = true +# Log level. Supported values: trace, debug, info, warn, error +# OPTIONAL, DEFAULT: info +level = "debug" +# Log in JSON format +# OPTIONAL, DEFAULT: true +use_json = true # Path to the log directory # OPTIONAL, DEFAULT: /var/logs/commit-boost -log_dir_path = "./logs" -# Log level. Supported values: trace, debug, info, warn, error -# OPTIONAL, DEFAULT: debug to file, info to stdout -log_level = "debug" +dir_path = "./logs" # Maximum number of log files to keep # OPTIONAL -max_log_files = 30 +max_files = 30 diff --git a/crates/cli/src/docker_init.rs b/crates/cli/src/docker_init.rs index 8a81de1a..768c45b6 100644 --- a/crates/cli/src/docker_init.rs +++ b/crates/cli/src/docker_init.rs @@ -46,7 +46,7 @@ pub async fn handle_docker_init(config_path: PathBuf, output_dir: PathBuf) -> Re let chain_spec_path = CommitBoostConfig::chain_spec_file(&config_path); - let log_to_file = cb_config.logs.is_some(); + let log_to_file = cb_config.logs.file.enabled; let mut metrics_port = cb_config.metrics.as_ref().map(|m| m.start_port).unwrap_or_default(); let mut services = IndexMap::new(); @@ -584,8 +584,8 @@ pub async fn handle_docker_init(config_path: PathBuf, output_dir: PathBuf) -> Re println!() } // if file logging is enabled, warn about permissions - if let Some(logs_config) = cb_config.logs { - let log_dir = logs_config.log_dir_path; + if cb_config.logs.file.enabled { + let log_dir = cb_config.logs.file.dir_path; println!( "Warning: file logging is enabled, you may need to update permissions for the logs directory. e.g. with:\n\t`sudo chown -R 10001:10001 {}`", log_dir.display() @@ -654,9 +654,9 @@ fn get_env_uval(k: &str, v: u64) -> (String, Option) { // (k.into(), Some(SingleValue::Bool(v))) // } -fn get_log_volume(maybe_config: &Option, module_id: &str) -> Option { - maybe_config.as_ref().map(|config| { - let p = config.log_dir_path.join(module_id.to_lowercase()); +fn get_log_volume(config: &LogsSettings, module_id: &str) -> Option { + config.file.enabled.then_some({ + let p = config.file.dir_path.join(module_id.to_lowercase()); Volumes::Simple(format!( "{}:{}", p.to_str().expect("could not convert pathbuf to str"), diff --git a/crates/common/src/config/log.rs b/crates/common/src/config/log.rs index 2e6b2805..383d6fba 100644 --- a/crates/common/src/config/log.rs +++ b/crates/common/src/config/log.rs @@ -4,36 +4,21 @@ use eyre::Result; use serde::{Deserialize, Serialize}; use super::{load_optional_env_var, CommitBoostConfig, LOGS_DIR_DEFAULT, LOGS_DIR_ENV}; +use crate::utils::default_bool; -#[derive(Clone, Debug, Deserialize, Serialize)] +#[derive(Clone, Default, Debug, Deserialize, Serialize)] pub struct LogsSettings { - #[serde(default = "default_log_dir_path")] - pub log_dir_path: PathBuf, - #[serde(default = "default_log_level")] - pub log_level: String, - #[serde(default)] - pub max_log_files: Option, -} - -impl Default for LogsSettings { - fn default() -> Self { - LogsSettings { - log_dir_path: default_log_dir_path(), - log_level: default_log_level(), - max_log_files: None, - } - } + pub stdout: StdoutLogSettings, + pub file: FileLogSettings, } impl LogsSettings { - pub fn from_env_config() -> Result> { + pub fn from_env_config() -> Result { let mut config = CommitBoostConfig::from_env_path()?; // Override log dir path if env var is set - if let Some(log_config) = config.logs.as_mut() { - if let Some(log_dir) = load_optional_env_var(LOGS_DIR_ENV) { - log_config.log_dir_path = log_dir.into(); - } + if let Some(log_dir) = load_optional_env_var(LOGS_DIR_ENV) { + config.logs.file.dir_path = log_dir.into(); } Ok(config.logs) @@ -44,6 +29,50 @@ fn default_log_dir_path() -> PathBuf { LOGS_DIR_DEFAULT.into() } -pub fn default_log_level() -> String { +fn default_level() -> String { "info".into() } + +#[derive(Clone, Debug, Deserialize, Serialize)] +pub struct StdoutLogSettings { + #[serde(default = "default_bool::")] + pub enabled: bool, + #[serde(default = "default_level")] + pub level: String, + #[serde(default = "default_bool::")] + pub use_json: bool, + #[serde(default = "default_bool::")] + pub color: bool, +} + +impl Default for StdoutLogSettings { + fn default() -> Self { + Self { enabled: true, level: "info".into(), use_json: false, color: true } + } +} + +#[derive(Clone, Debug, Deserialize, Serialize)] +pub struct FileLogSettings { + #[serde(default = "default_bool::")] + pub enabled: bool, + #[serde(default = "default_level")] + pub level: String, + #[serde(default = "default_bool::")] + pub use_json: bool, + #[serde(default = "default_log_dir_path")] + pub dir_path: PathBuf, + #[serde(default)] + pub max_files: Option, +} + +impl Default for FileLogSettings { + fn default() -> Self { + Self { + enabled: false, + level: "info".into(), + use_json: true, + dir_path: default_log_dir_path(), + max_files: None, + } + } +} diff --git a/crates/common/src/config/mod.rs b/crates/common/src/config/mod.rs index acb81e5f..75fd3c9d 100644 --- a/crates/common/src/config/mod.rs +++ b/crates/common/src/config/mod.rs @@ -33,7 +33,8 @@ pub struct CommitBoostConfig { pub modules: Option>, pub signer: Option, pub metrics: Option, - pub logs: Option, + #[serde(default)] + pub logs: LogsSettings, } impl CommitBoostConfig { @@ -117,5 +118,6 @@ struct HelperConfig { modules: Option>, signer: Option, metrics: Option, - logs: Option, + #[serde(default)] + logs: LogsSettings, } diff --git a/crates/common/src/utils.rs b/crates/common/src/utils.rs index d5a0f4c0..7835d538 100644 --- a/crates/common/src/utils.rs +++ b/crates/common/src/utils.rs @@ -16,14 +16,14 @@ use serde_json::Value; use ssz::{Decode, Encode}; use tracing::Level; use tracing_appender::{non_blocking::WorkerGuard, rolling::Rotation}; -use tracing_subscriber::{fmt::Layer, prelude::*, EnvFilter}; - -use crate::{ - config::{load_optional_env_var, LogsSettings, PBS_MODULE_NAME}, - pbs::HEADER_VERSION_VALUE, - types::Chain, +use tracing_subscriber::{ + fmt::{format::Format, Layer}, + prelude::*, + EnvFilter, }; +use crate::{config::LogsSettings, pbs::HEADER_VERSION_VALUE, types::Chain}; + const MILLIS_PER_SECOND: u64 = 1_000; pub fn timestamp_of_slot_start_sec(slot: u64, chain: Chain) -> u64 { @@ -149,66 +149,86 @@ pub const fn default_u256() -> U256 { } // LOGGING -pub fn initialize_tracing_log(module_id: &str) -> eyre::Result { - let settings = LogsSettings::from_env_config()?; +pub fn initialize_tracing_log( + module_id: &str, + settings: LogsSettings, +) -> eyre::Result<(Option, Option)> { + let format = Format::default().with_target(false).compact(); - // Use file logs only if setting is set - let use_file_logs = settings.is_some(); - let settings = settings.unwrap_or_default(); + let mut stdout_guard = None; + let mut file_guard = None; + let mut layers = Vec::new(); - // Log level for stdout + if settings.stdout.enabled { + let config = settings.stdout; - let stdout_log_level = if let Some(log_level) = load_optional_env_var("RUST_LOG") { - log_level.parse::().expect("invalid RUST_LOG value") - } else { - settings.log_level.parse::().expect("invalid log_level value in settings") + let (writer, guard) = tracing_appender::non_blocking(std::io::stdout()); + stdout_guard = Some(guard); + + let filter = format_crates_filter(Level::INFO.as_str(), &config.level.as_str()); + let format = format.clone().with_ansi(config.color); + if config.use_json { + let layer = Layer::default() + .event_format(format) + .json() + .flatten_event(true) + .with_writer(writer) + .with_filter(filter) + .boxed(); + + layers.push(layer); + } else { + let layer = Layer::default() + .event_format(format) + .with_writer(writer) + .with_filter(filter) + .boxed(); + + layers.push(layer); + } }; - let stdout_filter = format_crates_filter(Level::INFO.as_str(), stdout_log_level.as_str()); + if settings.file.enabled { + let config = settings.file; - if use_file_logs { - // Log all events to a rolling log file. let mut builder = tracing_appender::rolling::Builder::new().filename_prefix(module_id.to_lowercase()); - if let Some(value) = settings.max_log_files { + if let Some(value) = config.max_files { builder = builder.max_log_files(value); } let file_appender = builder .rotation(Rotation::DAILY) - .build(settings.log_dir_path) + .build(config.dir_path) .expect("failed building rolling file appender"); - let (writer, guard) = tracing_appender::non_blocking(file_appender); + file_guard = Some(guard); + + let filter = format_crates_filter(Level::INFO.as_str(), &config.level.as_str()); + let format = format.clone().with_ansi(false); + if config.use_json { + let layer = Layer::default() + .event_format(format) + .json() + .flatten_event(false) + .with_writer(writer) + .with_filter(filter) + .boxed(); + + layers.push(layer); + } else { + let layer = Layer::default() + .event_format(format) + .with_writer(writer) + .with_filter(filter) + .boxed(); + + layers.push(layer); + } + }; - // at least debug for file logs - let file_log_level = stdout_log_level.max(Level::DEBUG); - let file_log_filter = format_crates_filter(Level::INFO.as_str(), file_log_level.as_str()); - - let stdout_layer = - tracing_subscriber::fmt::layer().with_target(false).with_filter(stdout_filter); - - let file_layer = Layer::new() - .json() - .with_current_span(false) - .with_span_list(true) - .with_writer(writer) - .with_filter(file_log_filter); - - tracing_subscriber::registry().with(stdout_layer.and_then(file_layer)).init(); - Ok(guard) - } else { - let (writer, guard) = tracing_appender::non_blocking(std::io::stdout()); - let stdout_layer = tracing_subscriber::fmt::layer() - .with_target(false) - .with_writer(writer) - .with_filter(stdout_filter); - tracing_subscriber::registry().with(stdout_layer).init(); - Ok(guard) - } -} + tracing_subscriber::registry().with(layers).init(); -pub fn initialize_pbs_tracing_log() -> eyre::Result { - initialize_tracing_log(PBS_MODULE_NAME) + Ok((stdout_guard, file_guard)) } // all commit boost crates diff --git a/crates/pbs/Cargo.toml b/crates/pbs/Cargo.toml index 6630f6e6..be547570 100644 --- a/crates/pbs/Cargo.toml +++ b/crates/pbs/Cargo.toml @@ -14,6 +14,7 @@ alloy.workspace = true # networking axum.workspace = true +axum-extra.workspace = true reqwest.workspace = true # async / threads diff --git a/crates/pbs/src/mev_boost/get_header.rs b/crates/pbs/src/mev_boost/get_header.rs index 6ddbcd20..1d787e00 100644 --- a/crates/pbs/src/mev_boost/get_header.rs +++ b/crates/pbs/src/mev_boost/get_header.rs @@ -48,7 +48,10 @@ pub async fn get_header( let parent_block = Arc::new(RwLock::new(None)); if state.extra_validation_enabled() { if let Some(rpc_url) = state.pbs_config().rpc_url.clone() { - tokio::spawn(fetch_parent_block(rpc_url, params.parent_hash, parent_block.clone())); + tokio::spawn( + fetch_parent_block(rpc_url, params.parent_hash, parent_block.clone()) + .in_current_span(), + ); } } @@ -81,20 +84,23 @@ pub async fn get_header( let mut handles = Vec::with_capacity(relays.len()); for relay in relays.iter() { - handles.push(send_timed_get_header( - params, - relay.clone(), - state.config.chain, - send_headers.clone(), - ms_into_slot, - max_timeout_ms, - ValidationContext { - skip_sigverify: state.pbs_config().skip_sigverify, - min_bid_wei: state.pbs_config().min_bid_wei, - extra_validation_enabled: state.extra_validation_enabled(), - parent_block: parent_block.clone(), - }, - )); + handles.push( + send_timed_get_header( + params, + relay.clone(), + state.config.chain, + send_headers.clone(), + ms_into_slot, + max_timeout_ms, + ValidationContext { + skip_sigverify: state.pbs_config().skip_sigverify, + min_bid_wei: state.pbs_config().min_bid_wei, + extra_validation_enabled: state.extra_validation_enabled(), + parent_block: parent_block.clone(), + }, + ) + .in_current_span(), + ); } let results = join_all(handles).await; @@ -126,7 +132,6 @@ pub async fn get_header( /// Extra validation will be skipped if: /// - relay returns header before parent block is fetched /// - parent block is not found, eg because of a RPC delay -#[tracing::instrument(skip_all, name = "parent_block_fetch")] async fn fetch_parent_block( rpc_url: Url, parent_hash: B256, diff --git a/crates/pbs/src/routes/get_header.rs b/crates/pbs/src/routes/get_header.rs index 919bad11..f35fe76d 100644 --- a/crates/pbs/src/routes/get_header.rs +++ b/crates/pbs/src/routes/get_header.rs @@ -10,7 +10,6 @@ use cb_common::{ }; use reqwest::StatusCode; use tracing::{error, info}; -use uuid::Uuid; use crate::{ api::BuilderApi, @@ -20,12 +19,12 @@ use crate::{ state::{BuilderApiState, PbsStateGuard}, }; -#[tracing::instrument(skip_all, name = "get_header", fields(req_id = %Uuid::new_v4(), slot = params.slot))] pub async fn handle_get_header>( State(state): State>, req_headers: HeaderMap, Path(params): Path, ) -> Result { + tracing::Span::current().record("slot", ¶ms.slot); let state = state.read().clone(); state.publish_event(BuilderEvent::GetHeaderRequest(params)); diff --git a/crates/pbs/src/routes/register_validator.rs b/crates/pbs/src/routes/register_validator.rs index da644642..c64ed6dd 100644 --- a/crates/pbs/src/routes/register_validator.rs +++ b/crates/pbs/src/routes/register_validator.rs @@ -3,7 +3,6 @@ use axum::{extract::State, http::HeaderMap, response::IntoResponse, Json}; use cb_common::{pbs::BuilderEvent, utils::get_user_agent}; use reqwest::StatusCode; use tracing::{error, info, trace}; -use uuid::Uuid; use crate::{ api::BuilderApi, @@ -13,7 +12,6 @@ use crate::{ state::{BuilderApiState, PbsStateGuard}, }; -#[tracing::instrument(skip_all, name = "register_validators", fields(req_id = %Uuid::new_v4()))] pub async fn handle_register_validator>( State(state): State>, req_headers: HeaderMap, diff --git a/crates/pbs/src/routes/reload.rs b/crates/pbs/src/routes/reload.rs index 9b984d3f..5326c726 100644 --- a/crates/pbs/src/routes/reload.rs +++ b/crates/pbs/src/routes/reload.rs @@ -2,7 +2,6 @@ use axum::{extract::State, http::HeaderMap, response::IntoResponse}; use cb_common::{pbs::BuilderEvent, utils::get_user_agent}; use reqwest::StatusCode; use tracing::{error, info}; -use uuid::Uuid; use crate::{ error::PbsClientError, @@ -11,7 +10,6 @@ use crate::{ BuilderApi, RELOAD_ENDPOINT_TAG, }; -#[tracing::instrument(skip_all, name = "reload", fields(req_id = %Uuid::new_v4()))] pub async fn handle_reload>( req_headers: HeaderMap, State(state): State>, diff --git a/crates/pbs/src/routes/router.rs b/crates/pbs/src/routes/router.rs index 54659c5c..e7a60762 100644 --- a/crates/pbs/src/routes/router.rs +++ b/crates/pbs/src/routes/router.rs @@ -1,11 +1,17 @@ use axum::{ + extract::{MatchedPath, Request}, + middleware::{self, Next}, + response::Response, routing::{get, post}, Router, }; +use axum_extra::headers::{ContentType, HeaderMapExt, UserAgent}; use cb_common::pbs::{ BUILDER_API_PATH, GET_HEADER_PATH, GET_STATUS_PATH, REGISTER_VALIDATOR_PATH, RELOAD_PATH, SUBMIT_BLOCK_PATH, }; +use tracing::trace; +use uuid::Uuid; use super::{ handle_get_header, handle_get_status, handle_register_validator, handle_submit_block, @@ -32,5 +38,30 @@ pub fn create_app_router>(state: PbsStateGu builder_api }; - app.with_state(state) + app.layer(middleware::from_fn(tracing_middleware)).with_state(state) +} + +#[tracing::instrument( + name = "request", + skip_all, + fields( + method = %req.extensions().get::().map(|m| m.as_str()).unwrap_or("unknown"), + req_id = ?Uuid::new_v4(), + slot = tracing::field::Empty + ), +)] +pub async fn tracing_middleware(req: Request, next: Next) -> Response { + trace!( + http.method = %req.method(), + http.user_agent = req.headers().typed_get::().map(|ua| ua.to_string()).unwrap_or_default(), + http.content_type = req.headers().typed_get::().map(|ua| ua.to_string()).unwrap_or_default(), + "start request"); + + let response = next.run(req).await; + + let status = response.status(); + + trace!(http.response.status_code = ?status, "end request"); + + response } diff --git a/crates/pbs/src/routes/status.rs b/crates/pbs/src/routes/status.rs index b4262d1f..ea2259c5 100644 --- a/crates/pbs/src/routes/status.rs +++ b/crates/pbs/src/routes/status.rs @@ -2,7 +2,6 @@ use axum::{extract::State, http::HeaderMap, response::IntoResponse}; use cb_common::{pbs::BuilderEvent, utils::get_user_agent}; use reqwest::StatusCode; use tracing::{error, info}; -use uuid::Uuid; use crate::{ api::BuilderApi, @@ -12,7 +11,6 @@ use crate::{ state::{BuilderApiState, PbsStateGuard}, }; -#[tracing::instrument(skip_all, name = "status", fields(req_id = %Uuid::new_v4()))] pub async fn handle_get_status>( req_headers: HeaderMap, State(state): State>, diff --git a/crates/pbs/src/routes/submit_block.rs b/crates/pbs/src/routes/submit_block.rs index 760f17ff..a535a00b 100644 --- a/crates/pbs/src/routes/submit_block.rs +++ b/crates/pbs/src/routes/submit_block.rs @@ -5,7 +5,6 @@ use cb_common::{ }; use reqwest::StatusCode; use tracing::{error, info, trace}; -use uuid::Uuid; use crate::{ api::BuilderApi, @@ -15,12 +14,13 @@ use crate::{ state::{BuilderApiState, PbsStateGuard}, }; -#[tracing::instrument(skip_all, name = "submit_blinded_block", fields(req_id = %Uuid::new_v4(), slot = signed_blinded_block.slot()))] pub async fn handle_submit_block>( State(state): State>, req_headers: HeaderMap, Json(signed_blinded_block): Json, ) -> Result { + tracing::Span::current().record("slot", &signed_blinded_block.slot()); + let state = state.read().clone(); trace!(?signed_blinded_block); diff --git a/crates/pbs/src/service.rs b/crates/pbs/src/service.rs index 6b6fd677..ce8162e4 100644 --- a/crates/pbs/src/service.rs +++ b/crates/pbs/src/service.rs @@ -27,7 +27,7 @@ impl PbsService { let addr = state.config.endpoint; let events_subs = state.config.event_publisher.as_ref().map(|e| e.n_subscribers()).unwrap_or_default(); - info!(version = COMMIT_BOOST_VERSION, commit = COMMIT_BOOST_COMMIT, ?addr, events_subs, chain =? state.config.chain, "starting PBS service"); + info!(version = COMMIT_BOOST_VERSION, commit_hash = COMMIT_BOOST_COMMIT, ?addr, events_subs, chain =? state.config.chain, "starting PBS service"); let app = create_app_router::(RwLock::new(state).into()); let listener = TcpListener::bind(addr).await?; diff --git a/crates/signer/src/service.rs b/crates/signer/src/service.rs index 90a2bb3b..a6a348ca 100644 --- a/crates/signer/src/service.rs +++ b/crates/signer/src/service.rs @@ -67,7 +67,7 @@ impl SigningService { let loaded_consensus = state.manager.read().await.available_consensus_signers(); let loaded_proxies = state.manager.read().await.available_proxy_signers(); - info!(version = COMMIT_BOOST_VERSION, commit = COMMIT_BOOST_COMMIT, modules =? module_ids, port =? config.server_port, loaded_consensus, loaded_proxies, "Starting signing service"); + info!(version = COMMIT_BOOST_VERSION, commit_hash = COMMIT_BOOST_COMMIT, modules =? module_ids, port =? config.server_port, loaded_consensus, loaded_proxies, "Starting signing service"); SigningService::init_metrics(config.chain)?; diff --git a/examples/builder_log/src/main.rs b/examples/builder_log/src/main.rs index aed6a4ba..a40df63d 100644 --- a/examples/builder_log/src/main.rs +++ b/examples/builder_log/src/main.rs @@ -16,7 +16,7 @@ impl OnBuilderApiEvent for LogProcessor { async fn main() -> eyre::Result<()> { match load_builder_module_config::<()>() { Ok(config) => { - let _guard = initialize_tracing_log(&config.id)?; + let _guard = initialize_tracing_log(&config.id, LogsSettings::from_env_config()?); info!(module_id = %config.id, "Starting module"); diff --git a/examples/da_commit/src/main.rs b/examples/da_commit/src/main.rs index 6d4dd59c..ba59212b 100644 --- a/examples/da_commit/src/main.rs +++ b/examples/da_commit/src/main.rs @@ -123,7 +123,7 @@ async fn main() -> Result<()> { match load_commit_module_config::() { Ok(config) => { - let _guard = initialize_tracing_log(&config.id)?; + let _guard = initialize_tracing_log(&config.id, LogsSettings::from_env_config()?); MetricsProvider::load_and_run(config.chain, MY_CUSTOM_REGISTRY.clone())?; diff --git a/examples/status_api/src/main.rs b/examples/status_api/src/main.rs index 973348bc..e4d5ee90 100644 --- a/examples/status_api/src/main.rs +++ b/examples/status_api/src/main.rs @@ -91,7 +91,7 @@ async fn main() -> Result<()> { let (pbs_config, extra) = load_pbs_custom_config::().await?; let chain = pbs_config.chain; - let _guard = initialize_pbs_tracing_log()?; + let _guard = initialize_tracing_log(PBS_MODULE_NAME, LogsSettings::from_env_config()?)?; let custom_state = MyBuilderState::from_config(extra); let state = PbsState::new(pbs_config).with_data(custom_state); diff --git a/tests/tests/commits.rs b/tests/tests/commits.rs deleted file mode 100644 index 957f8628..00000000 --- a/tests/tests/commits.rs +++ /dev/null @@ -1,71 +0,0 @@ -// use alloy::primitives::U256; -// use alloy::rpc::types::beacon::{BlsPublicKey, BlsSignature}; -// use cb_cli::runner::{Runner, SignRequestSender}; -// use cb_common::{config::BuilderConfig, types::Chain}; -// use cb_crypto::{signature::verify_signed_builder_message, -// types::SignRequest}; use cb_pbs::{BuilderState, DefaultBuilderApi}; -// use cb_tests::utils::setup_test_env; -// use tokio::sync::mpsc::{unbounded_channel, UnboundedSender}; -// use tree_hash_derive::TreeHash; - -// #[derive(TreeHash)] -// struct Message { -// data: u64, -// } - -// const MSG: Message = Message { data: 100 }; - -// const COMMIT_ID: &str = "TEST_COMMIT"; - -// async fn test_service( -// tx: SignRequestSender, -// pubkeys: Vec, -// test_tx: UnboundedSender<(BlsPublicKey, BlsSignature)>, -// ) -> eyre::Result<()> { -// let validator_pubkey = pubkeys[0]; - -// let (request, sign_rx) = SignRequest::new(COMMIT_ID, validator_pubkey, -// MSG); - -// tx.send(request).expect("failed sending request"); - -// let signature = sign_rx.await.expect("failed signing").expect("sign -// manager is down"); - -// test_tx.send((validator_pubkey, signature)).unwrap(); - -// Ok(()) -// } - -// #[tokio::test] -// async fn test_commit() { -// setup_test_env(); - -// let chain = Chain::Holesky; - -// let config = BuilderConfig { -// address: format!("0.0.0.0:4000").parse().unwrap(), -// relays: vec![], -// relay_check: true, -// timeout_get_header_ms: u64::MAX, -// timeout_get_payload_ms: u64::MAX, -// timeout_register_validator_ms: u64::MAX, -// skip_sigverify: false, -// min_bid_wei: U256::ZERO, -// }; -// let state = BuilderState::new(chain, config); - -// let mut runner = Runner::<(), DefaultBuilderApi>::new(state); - -// let (test_tx, mut test_rx) = unbounded_channel(); - -// runner.add_commitment(COMMIT_ID, |tx, pubkeys| async move { -// test_service(tx, pubkeys, test_tx).await -// }); - -// tokio::spawn(runner.run()); - -// let (pubkey, signature) = test_rx.recv().await.unwrap(); - -// assert!(verify_signed_builder_message(chain, &pubkey, &MSG, -// &signature).is_ok()) } From dfec141a2ee7973bd24dc3ef41584b8a4f62f397 Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 16:26:23 +0000 Subject: [PATCH 2/7] avoid nested spans --- crates/common/src/pbs/types/beacon_block.rs | 14 +++++++++++ crates/common/src/utils.rs | 2 +- crates/pbs/src/mev_boost/get_header.rs | 24 +++++++++++++------ .../pbs/src/mev_boost/register_validator.rs | 5 ++-- crates/pbs/src/mev_boost/status.rs | 5 ++-- crates/pbs/src/mev_boost/submit_block.rs | 5 ++-- crates/pbs/src/routes/get_header.rs | 3 +++ crates/pbs/src/routes/router.rs | 12 ++++++---- crates/pbs/src/routes/submit_block.rs | 5 ++++ 9 files changed, 56 insertions(+), 19 deletions(-) diff --git a/crates/common/src/pbs/types/beacon_block.rs b/crates/common/src/pbs/types/beacon_block.rs index ea633155..afcc9608 100644 --- a/crates/common/src/pbs/types/beacon_block.rs +++ b/crates/common/src/pbs/types/beacon_block.rs @@ -25,6 +25,20 @@ impl SignedBlindedBeaconBlock { } } + pub fn block_number(&self) -> u64 { + match &self.message { + BlindedBeaconBlock::Electra(b) => b.body.execution_payload_header.block_number, + BlindedBeaconBlock::Deneb(b) => b.body.execution_payload_header.block_number, + } + } + + pub fn parent_hash(&self) -> B256 { + match &self.message { + BlindedBeaconBlock::Electra(b) => b.body.execution_payload_header.parent_hash, + BlindedBeaconBlock::Deneb(b) => b.body.execution_payload_header.parent_hash, + } + } + pub fn slot(&self) -> u64 { match &self.message { BlindedBeaconBlock::Electra(b) => b.slot, diff --git a/crates/common/src/utils.rs b/crates/common/src/utils.rs index 7835d538..82148b68 100644 --- a/crates/common/src/utils.rs +++ b/crates/common/src/utils.rs @@ -209,7 +209,7 @@ pub fn initialize_tracing_log( let layer = Layer::default() .event_format(format) .json() - .flatten_event(false) + .flatten_event(true) .with_writer(writer) .with_filter(filter) .boxed(); diff --git a/crates/pbs/src/mev_boost/get_header.rs b/crates/pbs/src/mev_boost/get_header.rs index 1d787e00..5e168dc5 100644 --- a/crates/pbs/src/mev_boost/get_header.rs +++ b/crates/pbs/src/mev_boost/get_header.rs @@ -153,7 +153,6 @@ async fn fetch_parent_block( } } -#[tracing::instrument(skip_all, name = "handler", fields(relay_id = relay.id.as_ref()))] async fn send_timed_get_header( params: GetHeaderParams, relay: RelayClient, @@ -171,18 +170,27 @@ async fn send_timed_get_header( let delay = target_ms.saturating_sub(ms_into_slot); if delay > 0 { - debug!(target_ms, ms_into_slot, "TG: waiting to send first header request"); + debug!( + relay_id = relay.id.as_ref(), + target_ms, ms_into_slot, "TG: waiting to send first header request" + ); timeout_left_ms = timeout_left_ms.saturating_sub(delay); sleep(Duration::from_millis(delay)).await; } else { - debug!(target_ms, ms_into_slot, "TG: request already late enough in slot"); + debug!( + relay_id = relay.id.as_ref(), + target_ms, ms_into_slot, "TG: request already late enough in slot" + ); } } if let Some(send_freq_ms) = relay.config.frequency_get_header_ms { let mut handles = Vec::new(); - debug!(send_freq_ms, timeout_left_ms, "TG: sending multiple header requests"); + debug!( + relay_id = relay.id.as_ref(), + send_freq_ms, timeout_left_ms, "TG: sending multiple header requests" + ); loop { handles.push(tokio::spawn( @@ -229,18 +237,18 @@ async fn send_timed_get_header( } Err(err) if err.is_timeout() => None, Err(err) => { - error!(%err, "TG: error sending header request"); + error!(relay_id = relay.id.as_ref(),%err, "TG: error sending header request"); None } }) }) .max_by_key(|(start_time, _)| *start_time) { - debug!(n_headers, "TG: received headers from relay"); + debug!(relay_id = relay.id.as_ref(), n_headers, "TG: received headers from relay"); return Ok(maybe_header); } else { // all requests failed - warn!("TG: no headers received"); + warn!(relay_id = relay.id.as_ref(), "TG: no headers received"); return Err(PbsError::RelayResponse { error_msg: "no headers received".to_string(), @@ -324,6 +332,7 @@ async fn send_one_get_header( }; if code == StatusCode::NO_CONTENT { debug!( + relay_id = relay.id.as_ref(), ?code, latency = ?request_latency, response = ?response_bytes, @@ -343,6 +352,7 @@ async fn send_one_get_header( }; debug!( + relay_id = relay.id.as_ref(), latency = ?request_latency, version = get_header_response.version(), value_eth = format_ether(get_header_response.value()), diff --git a/crates/pbs/src/mev_boost/register_validator.rs b/crates/pbs/src/mev_boost/register_validator.rs index 5b0ac097..8a82777e 100644 --- a/crates/pbs/src/mev_boost/register_validator.rs +++ b/crates/pbs/src/mev_boost/register_validator.rs @@ -124,7 +124,6 @@ async fn send_register_validator_with_timeout( } } -#[tracing::instrument(skip_all, name = "handler", fields(relay_id = relay.id.as_ref(), retry = retry))] async fn send_register_validator( url: Url, registrations: &[ValidatorRegistration], @@ -173,11 +172,13 @@ async fn send_register_validator( }; // error here since we check if any success above - error!(%err, "failed registration"); + error!(relay_id = relay.id.as_ref(), retry, %err, "failed registration"); return Err(err); }; debug!( + relay_id = relay.id.as_ref(), + retry, ?code, latency = ?request_latency, num_registrations = registrations.len(), diff --git a/crates/pbs/src/mev_boost/status.rs b/crates/pbs/src/mev_boost/status.rs index 7d9d67d2..591e7cd1 100644 --- a/crates/pbs/src/mev_boost/status.rs +++ b/crates/pbs/src/mev_boost/status.rs @@ -46,7 +46,6 @@ pub async fn get_status( } } -#[tracing::instrument(skip_all, name = "handler", fields(relay_id = relay.id.as_ref()))] async fn send_relay_check(relay: &RelayClient, headers: HeaderMap) -> Result<(), PbsError> { let url = relay.get_status_url()?; @@ -82,11 +81,11 @@ async fn send_relay_check(relay: &RelayClient, headers: HeaderMap) -> Result<(), code: code.as_u16(), }; - error!(%err, "status failed"); + error!(relay_id = relay.id.as_ref(),%err, "status failed"); return Err(err); }; - debug!(?code, latency = ?request_latency, "status passed"); + debug!(relay_id = relay.id.as_ref(),?code, latency = ?request_latency, "status passed"); Ok(()) } diff --git a/crates/pbs/src/mev_boost/submit_block.rs b/crates/pbs/src/mev_boost/submit_block.rs index b96945b5..01525fde 100644 --- a/crates/pbs/src/mev_boost/submit_block.rs +++ b/crates/pbs/src/mev_boost/submit_block.rs @@ -99,7 +99,6 @@ async fn submit_block_with_timeout( // submits blinded signed block and expects the execution payload + blobs bundle // back -#[tracing::instrument(skip_all, name = "handler", fields(relay_id = relay.id.as_ref(), retry = retry))] async fn send_submit_block( url: Url, signed_blinded_block: &SignedBlindedBeaconBlock, @@ -148,7 +147,7 @@ async fn send_submit_block( }; // we requested the payload from all relays, but some may have not received it - warn!(%err, "failed to get payload (this might be ok if other relays have it)"); + warn!(relay_id = relay.id.as_ref(), retry, %err, "failed to get payload (this might be ok if other relays have it)"); return Err(err); }; @@ -164,6 +163,8 @@ async fn send_submit_block( }; debug!( + relay_id = relay.id.as_ref(), + retry, latency = ?request_latency, version = block_response.version(), block_hash = %block_response.block_hash(), diff --git a/crates/pbs/src/routes/get_header.rs b/crates/pbs/src/routes/get_header.rs index f35fe76d..dc2941b2 100644 --- a/crates/pbs/src/routes/get_header.rs +++ b/crates/pbs/src/routes/get_header.rs @@ -25,6 +25,9 @@ pub async fn handle_get_header>( Path(params): Path, ) -> Result { tracing::Span::current().record("slot", ¶ms.slot); + tracing::Span::current().record("parent_hash", &tracing::field::debug(params.parent_hash)); + tracing::Span::current().record("pubkey", &tracing::field::debug(params.pubkey)); + let state = state.read().clone(); state.publish_event(BuilderEvent::GetHeaderRequest(params)); diff --git a/crates/pbs/src/routes/router.rs b/crates/pbs/src/routes/router.rs index e7a60762..260ca9b1 100644 --- a/crates/pbs/src/routes/router.rs +++ b/crates/pbs/src/routes/router.rs @@ -47,7 +47,11 @@ pub fn create_app_router>(state: PbsStateGu fields( method = %req.extensions().get::().map(|m| m.as_str()).unwrap_or("unknown"), req_id = ?Uuid::new_v4(), - slot = tracing::field::Empty + slot = tracing::field::Empty, + block_hash = tracing::field::Empty, + block_number = tracing::field::Empty, + parent_hash = tracing::field::Empty, + pubkey = tracing::field::Empty, ), )] pub async fn tracing_middleware(req: Request, next: Next) -> Response { @@ -56,10 +60,10 @@ pub async fn tracing_middleware(req: Request, next: Next) -> Response { http.user_agent = req.headers().typed_get::().map(|ua| ua.to_string()).unwrap_or_default(), http.content_type = req.headers().typed_get::().map(|ua| ua.to_string()).unwrap_or_default(), "start request"); - + let response = next.run(req).await; - - let status = response.status(); + + let status = response.status(); trace!(http.response.status_code = ?status, "end request"); diff --git a/crates/pbs/src/routes/submit_block.rs b/crates/pbs/src/routes/submit_block.rs index a535a00b..d7bab060 100644 --- a/crates/pbs/src/routes/submit_block.rs +++ b/crates/pbs/src/routes/submit_block.rs @@ -20,6 +20,11 @@ pub async fn handle_submit_block>( Json(signed_blinded_block): Json, ) -> Result { tracing::Span::current().record("slot", &signed_blinded_block.slot()); + tracing::Span::current() + .record("block_hash", &tracing::field::debug(signed_blinded_block.block_hash())); + tracing::Span::current().record("block_number", &signed_blinded_block.block_number()); + tracing::Span::current() + .record("parent_hash", &tracing::field::debug(signed_blinded_block.parent_hash())); let state = state.read().clone(); From 75825e98f9cbf92782dccbcf59dc98941464aa3a Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 18:25:10 +0000 Subject: [PATCH 3/7] fixes --- crates/common/src/utils.rs | 4 ++++ crates/pbs/src/mev_boost/get_header.rs | 5 ++++- crates/pbs/src/routes/get_header.rs | 4 ++-- crates/pbs/src/routes/router.rs | 2 +- crates/pbs/src/routes/submit_block.rs | 3 +-- 5 files changed, 12 insertions(+), 6 deletions(-) diff --git a/crates/common/src/utils.rs b/crates/common/src/utils.rs index 82148b68..e89d71e4 100644 --- a/crates/common/src/utils.rs +++ b/crates/common/src/utils.rs @@ -172,6 +172,8 @@ pub fn initialize_tracing_log( .event_format(format) .json() .flatten_event(true) + .with_current_span(true) + .with_span_list(false) .with_writer(writer) .with_filter(filter) .boxed(); @@ -210,6 +212,8 @@ pub fn initialize_tracing_log( .event_format(format) .json() .flatten_event(true) + .with_current_span(true) + .with_span_list(false) .with_writer(writer) .with_filter(filter) .boxed(); diff --git a/crates/pbs/src/mev_boost/get_header.rs b/crates/pbs/src/mev_boost/get_header.rs index 5e168dc5..4423f249 100644 --- a/crates/pbs/src/mev_boost/get_header.rs +++ b/crates/pbs/src/mev_boost/get_header.rs @@ -423,7 +423,10 @@ async fn send_one_get_header( if let Some(parent_block) = parent_block.as_ref() { extra_validation(parent_block, &get_header_response)?; } else { - warn!("parent block not found, skipping extra validation"); + warn!( + relay_id = relay.id.as_ref(), + "parent block not found, skipping extra validation" + ); } } diff --git a/crates/pbs/src/routes/get_header.rs b/crates/pbs/src/routes/get_header.rs index dc2941b2..a9543fae 100644 --- a/crates/pbs/src/routes/get_header.rs +++ b/crates/pbs/src/routes/get_header.rs @@ -26,7 +26,7 @@ pub async fn handle_get_header>( ) -> Result { tracing::Span::current().record("slot", ¶ms.slot); tracing::Span::current().record("parent_hash", &tracing::field::debug(params.parent_hash)); - tracing::Span::current().record("pubkey", &tracing::field::debug(params.pubkey)); + tracing::Span::current().record("validator", &tracing::field::debug(params.pubkey)); let state = state.read().clone(); @@ -35,7 +35,7 @@ pub async fn handle_get_header>( let ua = get_user_agent(&req_headers); let ms_into_slot = ms_into_slot(params.slot, state.config.chain); - info!(ua, parent_hash=%params.parent_hash, validator_pubkey=%params.pubkey, ms_into_slot); + info!(ua, ms_into_slot); match A::get_header(params, req_headers, state.clone()).await { Ok(res) => { diff --git a/crates/pbs/src/routes/router.rs b/crates/pbs/src/routes/router.rs index 260ca9b1..d52922a3 100644 --- a/crates/pbs/src/routes/router.rs +++ b/crates/pbs/src/routes/router.rs @@ -51,7 +51,7 @@ pub fn create_app_router>(state: PbsStateGu block_hash = tracing::field::Empty, block_number = tracing::field::Empty, parent_hash = tracing::field::Empty, - pubkey = tracing::field::Empty, + validator = tracing::field::Empty, ), )] pub async fn tracing_middleware(req: Request, next: Next) -> Response { diff --git a/crates/pbs/src/routes/submit_block.rs b/crates/pbs/src/routes/submit_block.rs index d7bab060..4668450c 100644 --- a/crates/pbs/src/routes/submit_block.rs +++ b/crates/pbs/src/routes/submit_block.rs @@ -28,7 +28,6 @@ pub async fn handle_submit_block>( let state = state.read().clone(); - trace!(?signed_blinded_block); state.publish_event(BuilderEvent::SubmitBlockRequest(Box::new(signed_blinded_block.clone()))); let now = utcnow_ms(); @@ -37,7 +36,7 @@ pub async fn handle_submit_block>( let slot_start_ms = timestamp_of_slot_start_millis(slot, state.config.chain); let ua = get_user_agent(&req_headers); - info!(ua, ms_into_slot=now.saturating_sub(slot_start_ms), %block_hash); + info!(ua, ms_into_slot = now.saturating_sub(slot_start_ms)); match A::submit_block(signed_blinded_block, req_headers, state.clone()).await { Ok(res) => { From 37e76dd6912042336a1d05457444b219b2c7ad71 Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 18:31:36 +0000 Subject: [PATCH 4/7] span name --- crates/pbs/src/routes/router.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/pbs/src/routes/router.rs b/crates/pbs/src/routes/router.rs index d52922a3..e5a28de5 100644 --- a/crates/pbs/src/routes/router.rs +++ b/crates/pbs/src/routes/router.rs @@ -42,7 +42,7 @@ pub fn create_app_router>(state: PbsStateGu } #[tracing::instrument( - name = "request", + name = "", skip_all, fields( method = %req.extensions().get::().map(|m| m.as_str()).unwrap_or("unknown"), From eb513f4d799d88ede55e62166912e8d39c6123fe Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 18:47:43 +0000 Subject: [PATCH 5/7] fix --- crates/pbs/src/routes/get_header.rs | 2 +- crates/pbs/src/routes/register_validator.rs | 2 +- crates/pbs/src/routes/status.rs | 2 +- crates/pbs/src/routes/submit_block.rs | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/crates/pbs/src/routes/get_header.rs b/crates/pbs/src/routes/get_header.rs index a9543fae..b0617ffe 100644 --- a/crates/pbs/src/routes/get_header.rs +++ b/crates/pbs/src/routes/get_header.rs @@ -35,7 +35,7 @@ pub async fn handle_get_header>( let ua = get_user_agent(&req_headers); let ms_into_slot = ms_into_slot(params.slot, state.config.chain); - info!(ua, ms_into_slot); + info!(ua, ms_into_slot, "new request"); match A::get_header(params, req_headers, state.clone()).await { Ok(res) => { diff --git a/crates/pbs/src/routes/register_validator.rs b/crates/pbs/src/routes/register_validator.rs index c64ed6dd..93c84c3f 100644 --- a/crates/pbs/src/routes/register_validator.rs +++ b/crates/pbs/src/routes/register_validator.rs @@ -24,7 +24,7 @@ pub async fn handle_register_validator>( let ua = get_user_agent(&req_headers); - info!(ua, num_registrations = registrations.len()); + info!(ua, num_registrations = registrations.len(), "new request"); if let Err(err) = A::register_validator(registrations, req_headers, state.clone()).await { state.publish_event(BuilderEvent::RegisterValidatorResponse); diff --git a/crates/pbs/src/routes/status.rs b/crates/pbs/src/routes/status.rs index ea2259c5..b8cf3408 100644 --- a/crates/pbs/src/routes/status.rs +++ b/crates/pbs/src/routes/status.rs @@ -21,7 +21,7 @@ pub async fn handle_get_status>( let ua = get_user_agent(&req_headers); - info!(ua, relay_check = state.config.pbs_config.relay_check); + info!(ua, relay_check = state.config.pbs_config.relay_check, "new request"); match A::get_status(req_headers, state.clone()).await { Ok(_) => { diff --git a/crates/pbs/src/routes/submit_block.rs b/crates/pbs/src/routes/submit_block.rs index 4668450c..439cae24 100644 --- a/crates/pbs/src/routes/submit_block.rs +++ b/crates/pbs/src/routes/submit_block.rs @@ -36,7 +36,7 @@ pub async fn handle_submit_block>( let slot_start_ms = timestamp_of_slot_start_millis(slot, state.config.chain); let ua = get_user_agent(&req_headers); - info!(ua, ms_into_slot = now.saturating_sub(slot_start_ms)); + info!(ua, ms_into_slot = now.saturating_sub(slot_start_ms), "new request"); match A::submit_block(signed_blinded_block, req_headers, state.clone()).await { Ok(res) => { From c86e7e48627478b07cd03afca2891f4ed0023847 Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 18:49:49 +0000 Subject: [PATCH 6/7] fix --- crates/pbs/src/mev_boost/submit_block.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/crates/pbs/src/mev_boost/submit_block.rs b/crates/pbs/src/mev_boost/submit_block.rs index 01525fde..16d098dd 100644 --- a/crates/pbs/src/mev_boost/submit_block.rs +++ b/crates/pbs/src/mev_boost/submit_block.rs @@ -167,7 +167,6 @@ async fn send_submit_block( retry, latency = ?request_latency, version = block_response.version(), - block_hash = %block_response.block_hash(), "received unblinded block" ); From 030b1959bbad1cbbbf9ea700fa4d4bf0168377a4 Mon Sep 17 00:00:00 2001 From: eltitanb Date: Wed, 19 Mar 2025 18:57:54 +0000 Subject: [PATCH 7/7] clippy --- crates/common/src/utils.rs | 4 ++-- crates/pbs/src/routes/get_header.rs | 6 +++--- crates/pbs/src/routes/submit_block.rs | 8 ++++---- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/crates/common/src/utils.rs b/crates/common/src/utils.rs index e89d71e4..108690a2 100644 --- a/crates/common/src/utils.rs +++ b/crates/common/src/utils.rs @@ -165,7 +165,7 @@ pub fn initialize_tracing_log( let (writer, guard) = tracing_appender::non_blocking(std::io::stdout()); stdout_guard = Some(guard); - let filter = format_crates_filter(Level::INFO.as_str(), &config.level.as_str()); + let filter = format_crates_filter(Level::INFO.as_str(), config.level.as_str()); let format = format.clone().with_ansi(config.color); if config.use_json { let layer = Layer::default() @@ -205,7 +205,7 @@ pub fn initialize_tracing_log( let (writer, guard) = tracing_appender::non_blocking(file_appender); file_guard = Some(guard); - let filter = format_crates_filter(Level::INFO.as_str(), &config.level.as_str()); + let filter = format_crates_filter(Level::INFO.as_str(), config.level.as_str()); let format = format.clone().with_ansi(false); if config.use_json { let layer = Layer::default() diff --git a/crates/pbs/src/routes/get_header.rs b/crates/pbs/src/routes/get_header.rs index b0617ffe..b6f55fa0 100644 --- a/crates/pbs/src/routes/get_header.rs +++ b/crates/pbs/src/routes/get_header.rs @@ -24,9 +24,9 @@ pub async fn handle_get_header>( req_headers: HeaderMap, Path(params): Path, ) -> Result { - tracing::Span::current().record("slot", ¶ms.slot); - tracing::Span::current().record("parent_hash", &tracing::field::debug(params.parent_hash)); - tracing::Span::current().record("validator", &tracing::field::debug(params.pubkey)); + tracing::Span::current().record("slot", params.slot); + tracing::Span::current().record("parent_hash", tracing::field::debug(params.parent_hash)); + tracing::Span::current().record("validator", tracing::field::debug(params.pubkey)); let state = state.read().clone(); diff --git a/crates/pbs/src/routes/submit_block.rs b/crates/pbs/src/routes/submit_block.rs index 439cae24..0124a826 100644 --- a/crates/pbs/src/routes/submit_block.rs +++ b/crates/pbs/src/routes/submit_block.rs @@ -19,12 +19,12 @@ pub async fn handle_submit_block>( req_headers: HeaderMap, Json(signed_blinded_block): Json, ) -> Result { - tracing::Span::current().record("slot", &signed_blinded_block.slot()); + tracing::Span::current().record("slot", signed_blinded_block.slot()); tracing::Span::current() - .record("block_hash", &tracing::field::debug(signed_blinded_block.block_hash())); - tracing::Span::current().record("block_number", &signed_blinded_block.block_number()); + .record("block_hash", tracing::field::debug(signed_blinded_block.block_hash())); + tracing::Span::current().record("block_number", signed_blinded_block.block_number()); tracing::Span::current() - .record("parent_hash", &tracing::field::debug(signed_blinded_block.parent_hash())); + .record("parent_hash", tracing::field::debug(signed_blinded_block.parent_hash())); let state = state.read().clone();