fix: properly calculate deadline, use chrono for calculating timestamps (#123)

* chore: use chrono, debug

* quick mafs

* chore: productionize

* refactor: simplify slot_still_valid

* fix: convert calc debugs into span attrs

* Update src/tasks/submit/task.rs

---------

Co-authored-by: James <[email protected]>

Author: Evalir

Cargo.lock

@@ -54,6 +54,7 @@ openssl = { version = "0.10", features = ["vendored"] }
 reqwest = { version = "0.11.24", features = ["blocking", "json"] }
 serde_json = "1.0"
 tokio = { version = "1.36.0", features = ["full", "macros", "rt-multi-thread"] }
+chrono = "0.4.40"
 
 tokio-stream = "0.1.17"
 url = "2.5.4"

Cargo.toml

@@ -20,7 +20,7 @@ use tokio::{
     },
     task::JoinHandle,
 };
-use tracing::info;
+use tracing::{Instrument, info, instrument};
 use trevm::revm::{
     context::BlockEnv,
     database::{AlloyDB, WrapDatabaseAsync},
@@ -92,14 +92,18 @@ impl Simulator {
     /// # Returns
     ///
     /// A `Result` containing the built block or an error.
+    #[instrument(skip_all, fields(
+        block_number = block_env.number,
+        tx_count = sim_items.len(),
+        millis_to_deadline = finish_by.duration_since(Instant::now()).as_millis()
+    ))]
     pub async fn handle_build(
         &self,
         constants: SignetSystemConstants,
         sim_items: SimCache,
         finish_by: Instant,
         block_env: BlockEnv,
     ) -> eyre::Result<BuiltBlock> {
-        debug!(block_number = block_env.number, tx_count = sim_items.len(), "starting block build",);
         let concurrency_limit = self.config.concurrency_limit();
 
         // NB: Build AlloyDB from the previous block number's state, since block_env maps to the in-progress block
@@ -116,7 +120,7 @@ impl Simulator {
             self.config.rollup_block_gas_limit,
         );
 
-        let built_block = block_build.build().await;
+        let built_block = block_build.build().in_current_span().await;
         debug!(
             tx_count = built_block.tx_count(),
             block_number = built_block.block_number(),
@@ -205,21 +209,20 @@ impl Simulator {
     ///
     /// # Returns
     ///
-    /// An `Instant` representing the simulation deadline, as calculated by determining
-    /// the time left in the current slot and adding that to the current timestamp in UNIX seconds.
+    /// An `Instant` representing the simulation deadline, as calculated by
+    /// determining the time left in the current slot and adding that to the
+    /// current timestamp in UNIX seconds.
     pub fn calculate_deadline(&self) -> Instant {
         // Get the current timepoint within the slot.
         let timepoint =
             self.slot_calculator().current_point_within_slot().expect("host chain has started");
 
         // We have the timepoint in seconds into the slot. To find out what's
         // remaining, we need to subtract it from the slot duration
-        let remaining = self.slot_calculator().slot_duration() - timepoint;
-
-        // We add a 2500 ms buffer to account for sequencer stopping signing.
-        let deadline =
-            Instant::now() + Duration::from_secs(remaining) - Duration::from_millis(2500);
+        // we also subtract 3 seconds to account for the sequencer stopping signing.
+        let remaining = (self.slot_calculator().slot_duration() - timepoint).saturating_sub(3);
 
+        let deadline = Instant::now() + Duration::from_secs(remaining);
         deadline.max(Instant::now())
     }
 

src/tasks/block/sim.rs

@@ -37,6 +37,21 @@ macro_rules! spawn_provider_send {
     };
 }
 
+macro_rules! check_slot_still_valid {
+    ($self:expr, $initial_slot:expr) => {
+        if !$self.slot_still_valid($initial_slot) {
+            debug!(
+                current_slot =
+                    $self.config.slot_calculator.current_slot().expect("host chain has started"),
+                initial_slot = $initial_slot,
+                "slot changed before submission - skipping block"
+            );
+            counter!("builder.slot_missed").increment(1);
+            return Ok(ControlFlow::Skip);
+        }
+    };
+}
+
 /// Control flow for transaction submission.
 #[derive(Debug, Copy, Clone, PartialEq, Eq)]
 pub enum ControlFlow {
@@ -130,18 +145,9 @@ impl SubmitTask {
         retry_limit: usize,
     ) -> eyre::Result<ControlFlow> {
         let submitting_start_time = Instant::now();
-        let now = utils::now();
 
         let (expected_slot, window) = self.get_expected_slot_and_window();
 
-        debug!(
-            expected_slot,
-            start = window.start,
-            end = window.end,
-            now,
-            "calculating target slot window"
-        );
-
         let mut req = bumpable.req().clone();
 
         // Retry loop
@@ -151,27 +157,26 @@ impl SubmitTask {
                 "SubmitTask::retrying_send",
                 retries = bumpable.bump_count(),
                 nonce = bumpable.req().nonce,
+                expected_slot,
+                start = window.start,
+                end = window.end,
+                unix_now = utils::now(),
             );
 
-            let inbound_result = match self.send_transaction(req).instrument(span.clone()).await {
-                Ok(control_flow) => control_flow,
-                Err(error) => {
-                    if let Some(value) = self.slot_still_valid(expected_slot) {
-                        return value;
-                    }
-                    // Log error and retry
-                    error!(%error, "error handling inbound block");
-                    ControlFlow::Retry
-                }
-            };
+            // Check at the top of the loop if the slot is still valid. This
+            // will prevent unnecessary retries if the slot has changed.
+            check_slot_still_valid!(self, expected_slot);
 
-            let guard = span.entered();
+            let inbound_result = self
+                .send_transaction(req)
+                .instrument(span.clone())
+                .await
+                .inspect_err(|e| error!(error = %e, "error sending transaction"))
+                .unwrap_or(ControlFlow::Retry);
 
+            let guard = span.entered();
             match inbound_result {
                 ControlFlow::Retry => {
-                    if let Some(value) = self.slot_still_valid(expected_slot) {
-                        return value;
-                    }
                     // bump the req
                     req = bumpable.bumped();
                     if bumpable.bump_count() > retry_limit {
@@ -221,17 +226,8 @@ impl SubmitTask {
     }
 
     /// Checks if a slot is still valid during submission retries.
-    fn slot_still_valid(&self, initial_slot: usize) -> Option<Result<ControlFlow, eyre::Error>> {
-        let current_slot =
-            self.config.slot_calculator.current_slot().expect("host chain has started");
-        if current_slot != initial_slot {
-            // If the slot has changed, skip the block
-            debug!(current_slot, initial_slot, "slot changed before submission - skipping block");
-            counter!("builder.slot_missed").increment(1);
-            return Some(Ok(ControlFlow::Skip));
-        }
-        debug!(current_slot, "slot still valid - continuing submission");
-        None
+    fn slot_still_valid(&self, initial_slot: usize) -> bool {
+        initial_slot == self.config.slot_calculator.current_slot().expect("host chain has started")
     }
 
     /// Task future for the submit task. This function runs the main loop of the task.

src/tasks/submit/task.rs

@@ -6,12 +6,10 @@ use alloy::{
 };
 use signet_sim::BuiltBlock;
 use signet_zenith::BundleHelper::FillPermit2;
-use std::time::UNIX_EPOCH;
 
 /// Returns the current timestamp in seconds since the UNIX epoch.
 pub(crate) fn now() -> u64 {
-    let now = std::time::SystemTime::now();
-    now.duration_since(UNIX_EPOCH).unwrap().as_secs()
+    chrono::Utc::now().timestamp() as u64
 }
 
 // This function converts &[SignedFill] into [FillPermit2]