diff --git a/Cargo.toml b/Cargo.toml index 990d8538..279fdb12 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -54,6 +54,7 @@ serde_yaml = "0.9.33" # telemetry tracing = "0.1.40" tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } +tracing-appender = "0.2.3" prometheus = "0.13.4" # crypto diff --git a/bin/default_pbs.rs b/bin/default_pbs.rs index 0e5bf8a3..09b24f23 100644 --- a/bin/default_pbs.rs +++ b/bin/default_pbs.rs @@ -1,4 +1,6 @@ -use cb_common::{config::load_pbs_config, utils::initialize_tracing_log}; +use cb_common::{ + config::load_pbs_config, module_names::PBS_MODULE_NAME, utils::initialize_tracing_log, +}; use cb_pbs::{DefaultBuilderApi, PbsService, PbsState}; use eyre::Result; @@ -11,12 +13,10 @@ async fn main() -> Result<()> { std::env::set_var("RUST_BACKTRACE", "1"); } - initialize_tracing_log(); - // TODO: handle errors let pbs_config = load_pbs_config().expect("failed to load pbs config"); + let _guard = initialize_tracing_log(PBS_MODULE_NAME); let state = PbsState::<()>::new(pbs_config); - PbsService::init_metrics()?; PbsService::run::<(), DefaultBuilderApi>(state).await; Ok(()) diff --git a/bin/signer_module.rs b/bin/signer_module.rs index c1c9ea79..6d0f328b 100644 --- a/bin/signer_module.rs +++ b/bin/signer_module.rs @@ -1,4 +1,6 @@ -use cb_common::{config::StartSignerConfig, utils::initialize_tracing_log}; +use cb_common::{ + config::StartSignerConfig, module_names::SIGNER_MODULE_NAME, utils::initialize_tracing_log, +}; use cb_signer::service::SigningService; use eyre::Result; @@ -11,8 +13,7 @@ async fn main() -> Result<()> { std::env::set_var("RUST_BACKTRACE", "1"); } - initialize_tracing_log(); - let config = StartSignerConfig::load_from_env()?; + let _guard = initialize_tracing_log(SIGNER_MODULE_NAME); SigningService::run(config).await } diff --git a/config.example.toml b/config.example.toml index d3ed18e5..ac054924 100644 --- a/config.example.toml +++ b/config.example.toml @@ -39,3 +39,8 @@ sleep_secs = 5 id = "BUILDER_LOG" type = "events" docker_image = "test_builder_log" + +[logs] +duration = "daily" +host-path="./logs" +rust-log="info" \ No newline at end of file diff --git a/crates/cli/src/docker_init.rs b/crates/cli/src/docker_init.rs index adc98ad5..1465e699 100644 --- a/crates/cli/src/docker_init.rs +++ b/crates/cli/src/docker_init.rs @@ -2,13 +2,13 @@ use std::{path::Path, vec}; use cb_common::{ config::{ - CommitBoostConfig, ModuleKind, BUILDER_SERVER_ENV, CB_CONFIG_ENV, CB_CONFIG_NAME, JWTS_ENV, - METRICS_SERVER_ENV, MODULE_ID_ENV, MODULE_JWT_ENV, SIGNER_DIR_KEYS, SIGNER_DIR_KEYS_ENV, - SIGNER_DIR_SECRETS, SIGNER_DIR_SECRETS_ENV, SIGNER_KEYS, SIGNER_KEYS_ENV, - SIGNER_SERVER_ENV, + CommitBoostConfig, ModuleKind, BUILDER_SERVER_ENV, CB_BASE_LOG_PATH, CB_CONFIG_ENV, + CB_CONFIG_NAME, JWTS_ENV, METRICS_SERVER_ENV, MODULE_ID_ENV, MODULE_JWT_ENV, + SIGNER_DIR_KEYS, SIGNER_DIR_KEYS_ENV, SIGNER_DIR_SECRETS, SIGNER_DIR_SECRETS_ENV, + SIGNER_KEYS, SIGNER_KEYS_ENV, SIGNER_SERVER_ENV, }, loader::SignerLoader, - utils::random_jwt, + utils::{random_jwt, ENV_ROLLING_DURATION}, }; use docker_compose_types::{ Compose, ComposeVolume, DependsOnOptions, Environment, Labels, LoggingParameters, MapOrEmpty, @@ -27,6 +27,8 @@ pub(super) const PROMETHEUS_DATA_VOLUME: &str = "prometheus-data"; const METRICS_NETWORK: &str = "monitoring_network"; const SIGNER_NETWORK: &str = "signer_network"; +const ENV_RUST_LOG: &str = "RUST_LOG"; + /// Builds the docker compose file for the Commit-Boost services // TODO: do more validation for paths, images, etc @@ -41,11 +43,17 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> // config volume to pass to all services let config_volume = Volumes::Simple(format!("./{}:{}:ro", config_path, CB_CONFIG_NAME)); + let log_volume = Volumes::Simple(format!( + "{}:{}", + cb_config.logs.host_path.to_str().unwrap(), + CB_BASE_LOG_PATH + )); let mut jwts = IndexMap::new(); // envs to write in .env file let mut envs = IndexMap::from([(CB_CONFIG_ENV.into(), CB_CONFIG_NAME.into())]); - + envs.insert(ENV_ROLLING_DURATION.into(), cb_config.logs.duration.to_string()); + envs.insert(ENV_RUST_LOG.into(), cb_config.logs.rust_log); // targets to pass to prometheus let mut targets = Vec::new(); let metrics_port = 10000; @@ -109,7 +117,7 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> METRICS_NETWORK.to_owned(), SIGNER_NETWORK.to_owned(), ]), - volumes: vec![config_volume.clone()], + volumes: vec![config_volume.clone(), log_volume.clone()], environment: Environment::KvPair(module_envs), depends_on: DependsOnOptions::Simple(vec!["cb_signer".to_owned()]), ..Service::default() @@ -131,7 +139,7 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> container_name: Some(module_cid.clone()), image: Some(module.docker_image), networks: Networks::Simple(vec![METRICS_NETWORK.to_owned()]), - volumes: vec![config_volume.clone()], + volumes: vec![config_volume.clone(), log_volume.clone()], environment: Environment::KvPair(module_envs), depends_on: DependsOnOptions::Simple(vec!["cb_pbs".to_owned()]), ..Service::default() @@ -157,7 +165,7 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> cb_config.pbs.pbs_config.port, cb_config.pbs.pbs_config.port )]), networks: Networks::Simple(vec![METRICS_NETWORK.to_owned()]), - volumes: vec![config_volume.clone()], + volumes: vec![config_volume.clone(), log_volume.clone()], environment: Environment::KvPair(pbs_envs), ..Service::default() }; @@ -170,7 +178,7 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> if let Some(signer_config) = cb_config.signer { if needs_signer_module { - let mut volumes = vec![config_volume.clone()]; + let mut volumes = vec![config_volume.clone(), log_volume.clone()]; targets.push(PrometheusTargetConfig { targets: vec![format!("cb_signer:{metrics_port}")], @@ -288,7 +296,14 @@ pub fn handle_docker_init(config_path: String, output_dir: String) -> Result<()> networks: Networks::Simple(vec![METRICS_NETWORK.to_owned()]), depends_on: DependsOnOptions::Simple(vec!["cb_prometheus".to_owned()]), environment: Environment::List(vec!["GF_SECURITY_ADMIN_PASSWORD=admin".to_owned()]), - volumes: vec![Volumes::Simple("./grafana/dashboards:/etc/grafana/provisioning/dashboards".to_owned()), Volumes::Simple("./grafana/datasources:/etc/grafana/provisioning/datasources".to_owned())], + volumes: vec![ + Volumes::Simple( + "./grafana/dashboards:/etc/grafana/provisioning/dashboards".to_owned(), + ), + Volumes::Simple( + "./grafana/datasources:/etc/grafana/provisioning/datasources".to_owned(), + ), + ], // TODO: re-enable logging here once we move away from docker logs logging: Some(LoggingParameters { driver: Some("none".to_owned()), options: None }), ..Service::default() diff --git a/crates/common/Cargo.toml b/crates/common/Cargo.toml index f85a66e3..f4b6cd9e 100644 --- a/crates/common/Cargo.toml +++ b/crates/common/Cargo.toml @@ -28,6 +28,7 @@ serde_json.workspace = true # telemetry tracing.workspace = true tracing-subscriber.workspace = true +tracing-appender.workspace = true # crypto blst.workspace = true diff --git a/crates/common/src/config/constants.rs b/crates/common/src/config/constants.rs index 4d96d80f..f5c565aa 100644 --- a/crates/common/src/config/constants.rs +++ b/crates/common/src/config/constants.rs @@ -4,6 +4,8 @@ pub const METRICS_SERVER_ENV: &str = "METRICS_SERVER"; pub const SIGNER_SERVER_ENV: &str = "SIGNER_SERVER"; pub const BUILDER_SERVER_ENV: &str = "BUILDER_SERVER"; +pub const CB_BASE_LOG_PATH: &str = "/var/logs/commit-boost"; + pub const CB_CONFIG_ENV: &str = "CB_CONFIG"; pub const CB_CONFIG_NAME: &str = "/cb-config.toml"; diff --git a/crates/common/src/config/log.rs b/crates/common/src/config/log.rs new file mode 100644 index 00000000..3bab57f8 --- /dev/null +++ b/crates/common/src/config/log.rs @@ -0,0 +1,52 @@ +use std::{ + fmt::{Display, Formatter}, + path::PathBuf, +}; + +use serde::{Deserialize, Serialize}; + +#[derive(Clone, Debug, Deserialize, Serialize)] +pub struct LogsSettings { + #[serde(default)] + pub duration: RollingDuration, + #[serde(default, rename = "host-path")] + pub host_path: PathBuf, + #[serde(default, rename = "rust-log")] + pub rust_log: String, +} + +impl Default for LogsSettings { + fn default() -> Self { + Self { + duration: RollingDuration::Hourly, + host_path: "/var/log/pbs".into(), + rust_log: "info".to_string(), + } + } +} + +#[derive(Clone, Debug, Deserialize, Serialize)] +#[serde(rename_all = "lowercase")] +pub enum RollingDuration { + Minutely, + Hourly, + Daily, + Never, +} + +impl Display for RollingDuration { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + match self { + RollingDuration::Minutely => write!(f, "minutely"), + RollingDuration::Hourly => write!(f, "hourly"), + RollingDuration::Daily => write!(f, "daily"), + RollingDuration::Never => write!(f, "never"), + } + } +} + +impl Default for RollingDuration { + fn default() -> Self { + Self::Daily + } +} diff --git a/crates/common/src/config/mod.rs b/crates/common/src/config/mod.rs index ce1ce185..a3ece576 100644 --- a/crates/common/src/config/mod.rs +++ b/crates/common/src/config/mod.rs @@ -10,7 +10,10 @@ mod pbs; mod signer; mod utils; +mod log; + pub use constants::*; +pub use log::*; pub use metrics::*; pub use module::*; pub use pbs::*; @@ -26,6 +29,8 @@ pub struct CommitBoostConfig { pub modules: Option>, pub signer: Option, pub metrics: MetricsConfig, + #[serde(default)] + pub logs: LogsSettings, } impl CommitBoostConfig { diff --git a/crates/common/src/lib.rs b/crates/common/src/lib.rs index 33a44ab4..bc32e50d 100644 --- a/crates/common/src/lib.rs +++ b/crates/common/src/lib.rs @@ -5,6 +5,7 @@ pub mod config; pub mod constants; pub mod error; pub mod loader; +pub mod module_names; pub mod pbs; pub mod signature; pub mod signer; diff --git a/crates/common/src/module_names.rs b/crates/common/src/module_names.rs new file mode 100644 index 00000000..54faaa75 --- /dev/null +++ b/crates/common/src/module_names.rs @@ -0,0 +1,2 @@ +pub const PBS_MODULE_NAME: &str = "pbs"; +pub const SIGNER_MODULE_NAME: &str = "signer"; diff --git a/crates/common/src/utils.rs b/crates/common/src/utils.rs index 6cb17cfc..c7299076 100644 --- a/crates/common/src/utils.rs +++ b/crates/common/src/utils.rs @@ -1,4 +1,8 @@ -use std::time::{SystemTime, UNIX_EPOCH}; +use std::{ + env, + str::FromStr, + time::{SystemTime, UNIX_EPOCH}, +}; use alloy::{ primitives::U256, @@ -7,13 +11,16 @@ use alloy::{ use blst::min_pk::{PublicKey, Signature}; use rand::{distributions::Alphanumeric, Rng}; use reqwest::header::HeaderMap; -use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; +use tracing_appender::non_blocking::WorkerGuard; +use tracing_subscriber::{fmt::Layer, prelude::*, EnvFilter}; -use crate::types::Chain; +use crate::{config::CB_BASE_LOG_PATH, types::Chain}; const SECONDS_PER_SLOT: u64 = 12; const MILLIS_PER_SECOND: u64 = 1_000; +pub const ENV_ROLLING_DURATION: &str = "ROLLING_DURATION"; + pub fn timestamp_of_slot_start_millis(slot: u64, chain: Chain) -> u64 { let seconds_since_genesis = chain.genesis_time_sec() + slot * SECONDS_PER_SLOT; seconds_since_genesis * MILLIS_PER_SECOND @@ -110,9 +117,17 @@ pub const fn default_u256() -> U256 { } // LOGGING -// TODO: more customized logging + logging guard -pub fn initialize_tracing_log() { +pub fn initialize_tracing_log(module_id: &str) -> WorkerGuard { let level_env = std::env::var("RUST_LOG").unwrap_or("info".to_owned()); + // Log all events to a rolling log file. + + let log_file = match env::var(ENV_ROLLING_DURATION).unwrap_or("daily".into()).as_str() { + "minutely" => tracing_appender::rolling::minutely(CB_BASE_LOG_PATH, module_id), + "hourly" => tracing_appender::rolling::hourly(CB_BASE_LOG_PATH, module_id), + "daily" => tracing_appender::rolling::daily(CB_BASE_LOG_PATH, module_id), + "never" => tracing_appender::rolling::never(CB_BASE_LOG_PATH, module_id), + _ => panic!("unknown rolling duration value"), + }; let filter = match level_env.parse::() { Ok(f) => f, @@ -121,12 +136,19 @@ pub fn initialize_tracing_log() { EnvFilter::new("info") } }; + let logging_level = if matches!(level_env.as_str(), "info" | "warning" | "error") { + tracing::Level::DEBUG + } else { + tracing::Level::from_str(&level_env) + .unwrap_or_else(|_| panic!("invalid value for tracing. Got {level_env}")) + }; + let stdout_log = tracing_subscriber::fmt::layer().pretty(); + let (default, guard) = tracing_appender::non_blocking(log_file); + let log_file = Layer::new().with_writer(default.with_max_level(logging_level)); + + tracing_subscriber::registry().with(stdout_log.with_filter(filter).and_then(log_file)).init(); - tracing_subscriber::registry() - .with(filter) - .with(fmt::layer().with_target(false)) - .try_init() - .unwrap(); + guard } pub fn print_logo() { diff --git a/crates/pbs/src/mev_boost/get_header.rs b/crates/pbs/src/mev_boost/get_header.rs index be453843..54c20414 100644 --- a/crates/pbs/src/mev_boost/get_header.rs +++ b/crates/pbs/src/mev_boost/get_header.rs @@ -47,7 +47,7 @@ pub async fn get_header( "late in slot, skipping relay requests" ); - return Ok(None) + return Ok(None); } let (_, slot_uuid) = state.get_slot_and_uuid(); @@ -168,7 +168,7 @@ async fn send_timed_get_header( .max_by_key(|(start_time, _)| *start_time) { debug!(n_headers, "TG: received headers from relay"); - return Ok(maybe_header) + return Ok(maybe_header); } else { // all requests failed warn!("TG: no headers received"); @@ -176,7 +176,7 @@ async fn send_timed_get_header( return Err(PbsError::RelayResponse { error_msg: "no headers received".to_string(), code: TIMEOUT_ERROR_CODE, - }) + }); } } } @@ -255,7 +255,7 @@ async fn send_one_get_header( response = ?response_bytes, "no header from relay" ); - return Ok((start_request_time, None)) + return Ok((start_request_time, None)); } let get_header_response: GetHeaderReponse = serde_json::from_slice(&response_bytes)?; @@ -293,7 +293,7 @@ fn validate_header( let value = signed_header.message.value(); if block_hash == B256::ZERO { - return Err(ValidationError::EmptyBlockhash) + return Err(ValidationError::EmptyBlockhash); } if parent_hash != signed_header.message.header.parent_hash { @@ -315,7 +315,7 @@ fn validate_header( return Err(ValidationError::PubkeyMismatch { expected: expected_relay_pubkey, got: received_relay_pubkey, - }) + }); } if !skip_sig_verify { diff --git a/crates/pbs/src/mev_boost/status.rs b/crates/pbs/src/mev_boost/status.rs index 463198c7..cd025cbd 100644 --- a/crates/pbs/src/mev_boost/status.rs +++ b/crates/pbs/src/mev_boost/status.rs @@ -63,7 +63,7 @@ async fn send_relay_check(relay: &RelayClient, headers: HeaderMap) -> Result<(), RELAY_STATUS_CODE .with_label_values(&[TIMEOUT_ERROR_CODE_STR, STATUS_ENDPOINT_TAG, &relay.id]) .inc(); - return Err(err.into()) + return Err(err.into()); } }; let request_latency = start_request.elapsed(); @@ -82,7 +82,7 @@ async fn send_relay_check(relay: &RelayClient, headers: HeaderMap) -> Result<(), }; error!(?err, "status failed"); - return Err(err) + return Err(err); }; debug!(?code, latency = ?request_latency, "status passed"); diff --git a/crates/pbs/src/mev_boost/submit_block.rs b/crates/pbs/src/mev_boost/submit_block.rs index 8eb38948..444d04a1 100644 --- a/crates/pbs/src/mev_boost/submit_block.rs +++ b/crates/pbs/src/mev_boost/submit_block.rs @@ -83,7 +83,7 @@ async fn send_submit_block( &relay.id, ]) .inc(); - return Err(err.into()) + return Err(err.into()); } }; let request_latency = start_request.elapsed(); @@ -105,7 +105,7 @@ async fn send_submit_block( // we request payload to all relays, but some may have not received it warn!(?err, "failed to get payload (this might be ok if other relays have it)"); - return Err(err) + return Err(err); }; let block_response: SubmitBlindedBlockResponse = serde_json::from_slice(&response_bytes)?; @@ -120,7 +120,7 @@ async fn send_submit_block( return Err(PbsError::Validation(ValidationError::BlockHashMismatch { expected: signed_blinded_block.block_hash(), got: block_response.block_hash(), - })) + })); } if let Some(blobs) = &block_response.data.blobs_bundle { @@ -134,7 +134,7 @@ async fn send_submit_block( got_blobs: blobs.blobs.len(), got_commitments: blobs.commitments.len(), got_proofs: blobs.proofs.len(), - })) + })); } for (i, comm) in expected_committments.iter().enumerate() { @@ -144,7 +144,7 @@ async fn send_submit_block( expected: format!("{comm}"), got: format!("{}", blobs.commitments[i]), index: i, - })) + })); } } } diff --git a/examples/builder_log/Cargo.toml b/examples/builder_log/Cargo.toml index ee5b2780..4011210e 100644 --- a/examples/builder_log/Cargo.toml +++ b/examples/builder_log/Cargo.toml @@ -19,3 +19,4 @@ serde.workspace = true # telemetry tracing.workspace = true + diff --git a/examples/builder_log/src/main.rs b/examples/builder_log/src/main.rs index 6bad4d06..b29dd966 100644 --- a/examples/builder_log/src/main.rs +++ b/examples/builder_log/src/main.rs @@ -14,12 +14,10 @@ impl OnBuilderApiEvent for LogProcessor { #[tokio::main] async fn main() { - initialize_tracing_log(); - match load_builder_module_config::<()>() { Ok(config) => { info!(module_id = config.id, "Starting module"); - + let _guard = initialize_tracing_log(&config.id); let client = BuilderEventClient::new(config.server_port, LogProcessor); if let Err(err) = client.run().await { diff --git a/examples/custom_boost.rs b/examples/custom_boost.rs index d2587fdb..3b5b504f 100644 --- a/examples/custom_boost.rs +++ b/examples/custom_boost.rs @@ -58,9 +58,10 @@ async fn handle_stats(State(state): State>) -> Respo async fn main() { color_eyre::install()?; - initialize_tracing_log(); + let (chain, config) = load_pbs_config(); + let _guard = initialize_tracing_log(config.id); info!("Starting custom pbs module"); diff --git a/examples/da_commit/src/main.rs b/examples/da_commit/src/main.rs index 77ae251c..567c46cc 100644 --- a/examples/da_commit/src/main.rs +++ b/examples/da_commit/src/main.rs @@ -71,7 +71,6 @@ impl DaCommitService { #[tokio::main] async fn main() -> Result<()> { color_eyre::install()?; - initialize_tracing_log(); // Remember to register all your metrics before starting the process MY_CUSTOM_REGISTRY.register(Box::new(SIG_RECEIVED_COUNTER.clone()))?; @@ -85,7 +84,7 @@ async fn main() -> Result<()> { sleep_secs = config.extra.sleep_secs, "Starting module with custom data" ); - + let _guard = initialize_tracing_log(&config.id); let service = DaCommitService { config }; if let Err(err) = service.run().await { diff --git a/scripts/build_local_images.sh b/scripts/build_local_images.sh old mode 100644 new mode 100755 diff --git a/scripts/build_local_modules.sh b/scripts/build_local_modules.sh old mode 100644 new mode 100755