Merge pull request #157 from ralexstokes/mev-boost-logging

Mev boost logging

mev-boost-rs/src/relay_mux.rs

@@ -1,6 +1,6 @@
 use async_trait::async_trait;
 use ethereum_consensus::{
-    primitives::{BlsPublicKey, Slot, U256},
+    primitives::{BlsPublicKey, Epoch, Slot, U256},
     state_transition::Context,
 };
 use futures::{stream, StreamExt};
@@ -15,7 +15,7 @@ use mev_rs::{
 use parking_lot::Mutex;
 use rand::prelude::*;
 use std::{cmp::Ordering, collections::HashMap, ops::Deref, sync::Arc, time::Duration};
-use tracing::{info, warn};
+use tracing::{debug, info, warn};
 
 // See note in the `mev-relay-rs::Relay` about this constant.
 // TODO likely drop this feature...
@@ -83,6 +83,7 @@ pub struct Inner {
 struct State {
     // map from bid requests to index of `Relay` in collection
     outstanding_bids: HashMap<BidRequest, Vec<Arc<Relay>>>,
+    current_epoch_registration_count: usize,
     latest_pubkey: BlsPublicKey,
 }
 
@@ -99,6 +100,16 @@ impl RelayMux {
             .outstanding_bids
             .retain(|bid_request, _| bid_request.slot + PROPOSAL_TOLERANCE_DELAY >= slot);
     }
+
+    pub fn on_epoch(&self, epoch: Epoch) {
+        let count = {
+            let mut state = self.state.lock();
+            let count = state.current_epoch_registration_count;
+            state.current_epoch_registration_count = 0;
+            count
+        };
+        info!(count, epoch, "processed validator registrations")
+    }
 }
 
 #[async_trait]
@@ -127,6 +138,8 @@ impl BlindedBlockProvider for RelayMux {
         if num_failures == self.relays.len() {
             Err(Error::CouldNotRegister)
         } else {
+            let mut state = self.state.lock();
+            state.current_epoch_registration_count += registrations.len();
             Ok(())
         }
     }
@@ -146,18 +159,22 @@ impl BlindedBlockProvider for RelayMux {
                 match response {
                     Ok(Ok(mut bid)) => {
                         if let Err(err) = validate_bid(&mut bid, &relay.public_key, &self.context) {
-                            warn!(%relay, %err, "invalid signed builder bid");
+                            warn!(%err, %relay, "invalid signed builder bid");
                             None
                         } else {
                             Some((relay, bid))
                         }
                     }
+                    Ok(Err(Error::NoBidPrepared(bid_request))) => {
+                        debug!(%bid_request, %relay, "relay did not have a bid prepared");
+                        None
+                    }
                     Ok(Err(err)) => {
-                        warn!(%relay, %err, "failed to get a bid");
+                        warn!(%err, %relay, "failed to get a bid");
                         None
                     }
                     Err(_) => {
-                        warn!(%relay, timeout_in_sec = FETCH_BEST_BID_TIME_OUT_SECS, "timeout when fetching bid");
+                        warn!(timeout_in_sec = FETCH_BEST_BID_TIME_OUT_SECS, %relay, "timeout when fetching bid");
                         None
                     }
                 }
@@ -196,7 +213,7 @@ impl BlindedBlockProvider for RelayMux {
             .map(|relay| format!("{relay}"))
             .reduce(|desc, next| format!("{desc}, {next}"))
             .expect("at least one relay");
-        info!(slot = bid_request.slot, block_hash = %best_block_hash, relays=relays_desc, "acquired best bid");
+        info!(%bid_request, %best_bid, relays=relays_desc, "acquired best bid");
 
         {
             let mut state = self.state.lock();
@@ -213,10 +230,11 @@ impl BlindedBlockProvider for RelayMux {
         &self,
         signed_block: &mut SignedBlindedBeaconBlock,
     ) -> Result<ExecutionPayload, Error> {
-        let relays = {
+        let (bid_request, relays) = {
             let mut state = self.state.lock();
             let key = bid_key_from(signed_block, &state.latest_pubkey);
-            state.outstanding_bids.remove(&key).ok_or(Error::MissingOpenBid)?
+            let relays = state.outstanding_bids.remove(&key).ok_or(Error::MissingOpenBid)?;
+            (key, relays)
         };
 
         let signed_block = &signed_block;
@@ -238,13 +256,14 @@ impl BlindedBlockProvider for RelayMux {
                 Ok(payload) => {
                     let block_hash = payload.block_hash();
                     if block_hash == expected_block_hash {
+                        info!(%bid_request, %block_hash, %relay, "acquired payload");
                         return Ok(payload)
                     } else {
-                        warn!(%relay, ?block_hash, ?expected_block_hash, "incorrect block hash delivered by relay");
+                        warn!(?block_hash, ?expected_block_hash, %relay, "incorrect block hash delivered by relay");
                     }
                 }
                 Err(err) => {
-                    warn!(%relay, %err, "error opening bid");
+                    warn!(%err, %relay, "error opening bid");
                 }
             }
         }

mev-boost-rs/src/service.rs

@@ -12,7 +12,7 @@ use mev_rs::{
 use serde::Deserialize;
 use std::{future::Future, net::Ipv4Addr, pin::Pin, task::Poll};
 use tokio::task::{JoinError, JoinHandle};
-use tracing::info;
+use tracing::{error, info, warn};
 use url::Url;
 
 #[derive(Debug, Deserialize)]
@@ -35,9 +35,9 @@ fn parse_relay_endpoints(relay_urls: &[String]) -> Vec<RelayEndpoint> {
         match relay_url.parse::<Url>() {
             Ok(url) => match RelayEndpoint::try_from(url) {
                 Ok(relay) => relays.push(relay),
-                Err(err) => tracing::warn!("error parsing relay from URL `{relay_url}`: {err}"),
+                Err(err) => warn!(%err, %relay_url, "error parsing relay from URL"),
             },
-            Err(err) => tracing::warn!("error parsing relay URL `{relay_url}` from config: {err}"),
+            Err(err) => warn!(%err, %relay_url, "error parsing relay URL from config"),
         }
     }
     relays
@@ -62,7 +62,7 @@ impl Service {
         let Self { host, port, relays, network } = self;
 
         if relays.is_empty() {
-            tracing::error!("no valid relays provided; please restart with correct configuration");
+            error!("no valid relays provided; please restart with correct configuration");
         } else {
             let count = relays.len();
             info!("configured with {count} relay(s)");
@@ -85,8 +85,16 @@ impl Service {
 
             tokio::pin!(slots);
 
+            let mut current_epoch = clock.current_epoch().expect("after genesis");
+            relay_mux_clone.on_epoch(current_epoch);
             while let Some(slot) = slots.next().await {
                 relay_mux_clone.on_slot(slot);
+
+                let epoch = clock.current_epoch().expect("after genesis");
+                if epoch != current_epoch {
+                    relay_mux_clone.on_epoch(epoch);
+                    current_epoch = epoch;
+                }
             }
         });
 

mev-rs/src/blinded_block_provider/api/server.rs

@@ -17,6 +17,7 @@ use beacon_api_client::VersionedValue;
 use hyper::server::conn::AddrIncoming;
 use std::net::{Ipv4Addr, SocketAddr};
 use tokio::task::JoinHandle;
+use tracing::{error, info, trace};
 
 /// Type alias for the configured axum server
 pub type BlockProviderServer = axum::Server<AddrIncoming, IntoMakeService<Router>>;
@@ -29,8 +30,7 @@ async fn handle_validator_registration<B: BlindedBlockProvider>(
     State(builder): State<B>,
     Json(mut registrations): Json<Vec<SignedValidatorRegistration>>,
 ) -> Result<(), Error> {
-    let registration_count = registrations.len();
-    tracing::info!("processing {registration_count} validator registrations");
+    trace!(count = registrations.len(), "processing validator registrations");
     builder.register_validators(&mut registrations).await.map_err(From::from)
 }
 
@@ -39,7 +39,7 @@ async fn handle_fetch_bid<B: BlindedBlockProvider>(
     Path(bid_request): Path<BidRequest>,
 ) -> Result<Json<VersionedValue<SignedBuilderBid>>, Error> {
     let signed_bid = builder.fetch_best_bid(&bid_request).await?;
-    tracing::info!("returning bid with {signed_bid} for bid request at {bid_request}");
+    trace!(%bid_request, %signed_bid, "returning bid");
     let version = signed_bid.version();
     let response = VersionedValue { version, data: signed_bid, meta: Default::default() };
     Ok(Json(response))
@@ -52,7 +52,7 @@ async fn handle_open_bid<B: BlindedBlockProvider>(
     let payload = builder.open_bid(&mut block).await?;
     let block_hash = payload.block_hash();
     let slot = block.message().slot();
-    tracing::info!("returning provided payload in slot {slot} with block_hash {block_hash}");
+    trace!(%slot, %block_hash, "returning payload");
     let version = payload.version();
     let response = VersionedValue { version, data: payload, meta: Default::default() };
     Ok(Json(response))
@@ -89,9 +89,9 @@ impl<B: BlindedBlockProvider + Clone + Send + Sync + 'static> Server<B> {
         let server = self.serve();
         let address = server.local_addr();
         tokio::spawn(async move {
-            tracing::info!("listening at {address}...");
+            info!("listening at {address}...");
             if let Err(err) = server.await {
-                tracing::error!("error while listening for incoming: {err}")
+                error!(%err, "error while listening for incoming")
             }
         })
     }

mev-rs/src/error.rs

@@ -10,7 +10,7 @@ use thiserror::Error;
 pub enum Error {
     #[error("bid public key {bid} does not match relay public key {relay}")]
     BidPublicKeyMismatch { bid: BlsPublicKey, relay: BlsPublicKey },
-    #[error("no bid prepared for request {0:?}")]
+    #[error("no bid prepared for request {0}")]
     NoBidPrepared(Box<BidRequest>),
     #[error("no valid bids returned for proposal")]
     NoBids,
@@ -36,13 +36,13 @@ pub enum Error {
     UnknownFeeRecipient(BlsPublicKey, ExecutionAddress),
     #[error("validator with public key {0} is not currently registered")]
     ValidatorNotRegistered(BlsPublicKey),
-    #[error("{0}")]
+    #[error(transparent)]
     Consensus(#[from] ConsensusError),
-    #[error("{0}")]
+    #[error(transparent)]
     Api(#[from] ApiError),
-    #[error("{0}")]
+    #[error(transparent)]
     ValidatorRegistry(#[from] crate::validator_registry::Error),
-    #[error("{0}")]
+    #[error(transparent)]
     ProposerScheduler(#[from] crate::proposer_scheduler::Error),
 }
 

mev-rs/src/serde.rs

@@ -1 +1,26 @@
 pub(crate) use ethereum_consensus::serde::as_str;
+
+#[cfg(test)]
+mod tests {
+    use ethereum_consensus::{primitives::U256, types::mainnet::ExecutionPayloadHeader};
+
+    use crate::types::{BidRequest, BuilderBid, SignedBuilderBid};
+
+    #[test]
+    fn test_fmt() {
+        let signed_bid = SignedBuilderBid {
+            message: BuilderBid {
+                header: ExecutionPayloadHeader::Deneb(Default::default()),
+                value: U256::from(234),
+                public_key: Default::default(),
+            },
+            signature: Default::default(),
+        };
+
+        dbg!(&signed_bid);
+        println!("{signed_bid}");
+        let bid_request = BidRequest::default();
+        dbg!(&bid_request);
+        println!("{bid_request}");
+    }
+}

mev-rs/src/types/builder_bid.rs

@@ -8,6 +8,7 @@ use ethereum_consensus::{
     state_transition::Context,
     Error, Fork,
 };
+use std::fmt;
 
 #[derive(Debug, Clone, Merkleized)]
 #[cfg_attr(feature = "serde", derive(serde::Serialize, serde::Deserialize))]
@@ -41,7 +42,7 @@ impl SignedBuilderBid {
     }
 }
 
-impl std::fmt::Display for SignedBuilderBid {
+impl fmt::Display for SignedBuilderBid {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         let block_hash = self.message.header.block_hash();
         let value = &self.message.value;