Speculative logging support in Aptos VM (#6708)

Cargo.toml

@@ -16,6 +16,7 @@ members = [
     "aptos-move/aptos-transactional-test-harness",
     "aptos-move/aptos-validator-interface",
     "aptos-move/aptos-vm",
+    "aptos-move/aptos-vm-logging",
     "aptos-move/aptos-vm-profiling",
     "aptos-move/block-executor",
     "aptos-move/e2e-move-tests",
@@ -293,6 +294,7 @@ aptos-types = { path = "types" }
 aptos-validator-interface = { path = "aptos-move/aptos-validator-interface" }
 aptos-vault-client = { path = "secure/storage/vault" }
 aptos-vm = { path = "aptos-move/aptos-vm" }
+aptos-vm-logging = { path = "aptos-move/aptos-vm-logging" }
 aptos-vm-genesis = { path = "aptos-move/vm-genesis" }
 aptos-vm-validator = { path = "vm-validator" }
 aptos-warp-webserver = { path = "crates/aptos-warp-webserver" }

aptos-move/aptos-vm-logging/Cargo.toml

@@ -0,0 +1,24 @@
+[package]
+name = "aptos-vm-logging"
+description = "Aptos VM speculative logging utility"
+version = "0.1.0"
+
+# Workspace inherited keys
+authors = { workspace = true }
+edition = { workspace = true }
+homepage = { workspace = true }
+license = { workspace = true }
+publish = { workspace = true }
+repository = { workspace = true }
+rust-version = { workspace = true }
+
+[dependencies]
+aptos-crypto = { workspace = true }
+aptos-logger = { workspace = true }
+aptos-metrics-core = { workspace = true }
+aptos-speculative-state-helper = { workspace = true }
+aptos-state-view = { workspace = true }
+aptos-types = { workspace = true }
+arc-swap = { workspace = true }
+once_cell = { workspace = true }
+serde = { workspace = true }

aptos-move/aptos-vm-logging/src/counters.rs

@@ -0,0 +1,11 @@
+// Copyright © Aptos Foundation
+// SPDX-License-Identifier: Apache-2.0
+
+use aptos_metrics_core::{register_int_counter, IntCounter};
+use once_cell::sync::Lazy;
+
+/// Count the number of errors. This is not intended for display on a dashboard,
+/// but rather for triggering alerts.
+pub static CRITICAL_ERRORS: Lazy<IntCounter> = Lazy::new(|| {
+    register_int_counter!("aptos_vm_critical_errors", "Number of critical errors").unwrap()
+});

aptos-move/aptos-vm-logging/src/lib.rs

@@ -0,0 +1,167 @@
+// Copyright © Aptos Foundation
+// SPDX-License-Identifier: Apache-2.0
+
+pub mod counters;
+pub mod log_schema;
+
+pub mod prelude {
+    pub use crate::{
+        alert, counters::CRITICAL_ERRORS, speculative_debug, speculative_error, speculative_info,
+        speculative_log, speculative_trace, speculative_warn,
+    };
+}
+
+use crate::{counters::CRITICAL_ERRORS, log_schema::AdapterLogSchema};
+use aptos_logger::{prelude::*, Level};
+use aptos_speculative_state_helper::{SpeculativeEvent, SpeculativeEvents};
+use arc_swap::ArcSwapOption;
+use once_cell::sync::Lazy;
+use std::sync::Arc;
+
+struct VMLogEntry {
+    level: Level,
+    context: AdapterLogSchema,
+    message: String,
+}
+
+impl VMLogEntry {
+    fn new(level: Level, context: AdapterLogSchema, message: String) -> Self {
+        Self {
+            level,
+            context,
+            message,
+        }
+    }
+}
+
+// Implement dispatching for a recorded VM log entry to support recording
+// as speculative logging event (and eventual dispatching as needed).
+impl SpeculativeEvent for VMLogEntry {
+    fn dispatch(self) {
+        match self.level {
+            Level::Error => {
+                // TODO: Consider using SpeculativeCounter to increase CRITICAL_ERRORS
+                // on the critical path instead of async dispatching.
+                alert!(self.context, "{}", self.message);
+            },
+            Level::Warn => warn!(self.context, "{}", self.message),
+            Level::Info => info!(self.context, "{}", self.message),
+            Level::Debug => debug!(self.context, "{}", self.message),
+            Level::Trace => trace!(self.context, "{}", self.message),
+        }
+    }
+}
+
+static BUFFERED_LOG_EVENTS: Lazy<ArcSwapOption<SpeculativeEvents<VMLogEntry>>> =
+    Lazy::new(|| ArcSwapOption::from(None));
+
+/// Initializes the storage of speculative logs for num_txns many transactions.
+pub fn init_speculative_logs(num_txns: usize) {
+    BUFFERED_LOG_EVENTS.swap(Some(Arc::new(SpeculativeEvents::new(num_txns))));
+}
+
+/// Adds a message at a specified logging level and given context (that includes txn index)
+/// to speculative buffer. Logs directly and logs a separate (new error) if the speculative
+/// events storage is not initialized or appropriately sized.
+pub fn speculative_log(level: Level, context: &AdapterLogSchema, message: String) {
+    let txn_idx = context.get_txn_idx();
+    match &*BUFFERED_LOG_EVENTS.load() {
+        Some(log_events) => {
+            let log_event = VMLogEntry::new(level, context.clone(), message);
+            if let Err(e) = log_events.record(txn_idx, log_event) {
+                alert!("{:?}", e);
+            };
+        },
+        None => {
+            alert!(
+                "Speculative state not initialized to log message = {}",
+                message
+            );
+        },
+    };
+}
+
+/// Flushes the currently stored logs, and swaps the speculative log / event storage with None.
+/// Must be called after block execution is complete (removes the storage from Arc).
+pub fn flush_speculative_logs() {
+    match BUFFERED_LOG_EVENTS.swap(None) {
+        Some(log_events_ptr) => match Arc::try_unwrap(log_events_ptr) {
+            Ok(log_events) => log_events.flush(),
+            Err(_) => {
+                alert!("Speculative log storage must be uniquely owned to flush");
+            },
+        },
+        None => {
+            alert!("Flush called on uninitialized speculative log storage");
+        },
+    }
+}
+
+/// Clear speculative logs recorded for a specific transction, useful when transaction
+/// execution fails validation and aborts - setting stage for the re-execution.
+pub fn clear_speculative_txn_logs(txn_idx: usize) {
+    match &*BUFFERED_LOG_EVENTS.load() {
+        Some(log_events) => {
+            if let Err(e) = log_events.clear_txn_events(txn_idx) {
+                alert!("{:?}", e);
+            };
+        },
+        None => {
+            alert!("Clear all logs called on uninitialized speculative log storage");
+        },
+    }
+}
+
+/// Combine logging and error and incrementing critical errors counter for alerting.
+#[macro_export]
+macro_rules! alert {
+    ($($args:tt)+) => {
+	error!($($args)+);
+	CRITICAL_ERRORS.inc();
+    };
+}
+
+#[macro_export]
+macro_rules! speculative_error {
+    ($($args:tt)+) => {
+        if enabled!(Level::Error) {
+            speculative_log(Level::Error, $($args)+);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! speculative_warn {
+    ($($args:tt)+) => {
+        if enabled!(Level::Warn) {
+            speculative_log(Level::Warn, $($args)+);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! speculative_info {
+    ($($args:tt)+) => {
+        if enabled!(Level::Info) {
+            speculative_log(Level::Info, $($args)+);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! speculative_debug {
+    ($($args:tt)+) => {
+        if enabled!(Level::Debug) {
+            speculative_log(Level::Debug, $($args)+);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! speculative_trace {
+    ($($args:tt)+) => {
+        if enabled!(Level::Trace) {
+            speculative_log(Level::Trace, $($args)+);
+        }
+    };
+}

aptos-move/aptos-vm/src/logging.rs → aptos-move/aptos-vm-logging/src/log_schema.rs

@@ -2,7 +2,6 @@
 // Parts of the project are originally copyright © Meta Platforms, Inc.
 // SPDX-License-Identifier: Apache-2.0
 
-use crate::counters::CRITICAL_ERRORS;
 use aptos_crypto::HashValue;
 use aptos_logger::Schema;
 use aptos_state_view::StateViewId;
@@ -27,46 +26,45 @@ pub struct AdapterLogSchema {
 
     // transaction position in the list of transactions in the block,
     // 0 if the transaction is not part of a block (i.e. validation).
-    txn_id: usize,
+    txn_idx: usize,
 }
 
 impl AdapterLogSchema {
-    pub fn new(view_id: StateViewId, txn_id: usize) -> Self {
+    pub fn new(view_id: StateViewId, txn_idx: usize) -> Self {
         match view_id {
             StateViewId::BlockExecution { block_id } => Self {
                 name: LogEntry::Execution,
                 block_id: Some(block_id),
                 first_version: None,
                 base_version: None,
-                txn_id,
+                txn_idx,
             },
             StateViewId::ChunkExecution { first_version } => Self {
                 name: LogEntry::Execution,
                 block_id: None,
                 first_version: Some(first_version),
                 base_version: None,
-                txn_id,
+                txn_idx,
             },
             StateViewId::TransactionValidation { base_version } => Self {
                 name: LogEntry::Validation,
                 block_id: None,
                 first_version: None,
                 base_version: Some(base_version),
-                txn_id,
+                txn_idx,
             },
             StateViewId::Miscellaneous => Self {
                 name: LogEntry::Miscellaneous,
                 block_id: None,
                 first_version: None,
                 base_version: None,
-                txn_id,
+                txn_idx,
             },
         }
     }
 
-    // Increment the `CRITICAL_ERRORS` monitor event that will fire an alert
-    pub fn alert(&self) {
-        CRITICAL_ERRORS.inc();
+    pub(crate) fn get_txn_idx(&self) -> usize {
+        self.txn_idx
     }
 }
 

aptos-move/aptos-vm/Cargo.toml

@@ -25,6 +25,7 @@ aptos-metrics-core = { workspace = true }
 aptos-mvhashmap = { workspace = true }
 aptos-state-view = { workspace = true }
 aptos-types = { workspace = true }
+aptos-vm-logging = { workspace = true }
 bcs = { workspace = true }
 dashmap = { workspace = true }
 fail = { workspace = true }

aptos-move/aptos-vm/src/adapter_common.rs

@@ -2,10 +2,7 @@
 // Parts of the project are originally copyright © Meta Platforms, Inc.
 // SPDX-License-Identifier: Apache-2.0
 
-use crate::{
-    logging::AdapterLogSchema,
-    move_vm_ext::{MoveResolverExt, SessionExt, SessionId},
-};
+use crate::move_vm_ext::{MoveResolverExt, SessionExt, SessionId};
 use anyhow::Result;
 use aptos_aggregator::transaction::TransactionOutputExt;
 use aptos_types::{
@@ -17,6 +14,7 @@ use aptos_types::{
     vm_status::{StatusCode, VMStatus},
     write_set::WriteSet,
 };
+use aptos_vm_logging::log_schema::AdapterLogSchema;
 
 /// This trait describes the VM adapter's interface.
 /// TODO: bring more of the execution logic in aptos_vm into this file.

aptos-move/aptos-vm/src/aptos_vm.rs

@@ -12,7 +12,6 @@ use crate::{
     data_cache::{AsMoveResolver, IntoMoveResolver},
     delta_state_view::DeltaStateView,
     errors::expect_only_successful_execution,
-    logging::AdapterLogSchema,
     move_vm_ext::{MoveResolverExt, SessionExt, SessionId},
     system_module_names::*,
     transaction_metadata::TransactionMetadata,
@@ -42,6 +41,7 @@ use aptos_types::{
     vm_status::{AbortLocation, DiscardedVMStatus, StatusCode, VMStatus},
     write_set::WriteSet,
 };
+use aptos_vm_logging::log_schema::AdapterLogSchema;
 use fail::fail_point;
 use move_binary_format::{
     access::ModuleAccess,