diff --git a/Cargo.lock b/Cargo.lock index 3ecf6d76f..121173949 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -101,7 +101,7 @@ checksum = "061a7acccaa286c011ddc30970520b98fa40e00c9d644633fb26b5fc63a265e3" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -135,7 +135,7 @@ dependencies = [ "proc-macro-error", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -147,7 +147,7 @@ dependencies = [ "proc-macro-error", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -560,7 +560,7 @@ dependencies = [ "proc-macro-error", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -898,7 +898,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ccc0a48a9b826acdf4028595adc9db92caea352f7af011a3034acd172a52a0aa" dependencies = [ "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -961,7 +961,7 @@ checksum = "4fb810d30a7c1953f91334de7244731fc3f3c10d7fe163338a35b9f640960321" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -1297,7 +1297,7 @@ dependencies = [ "reqwest", "serde", "serde_json", - "syn", + "syn 1.0.103", "tempfile", "toml", "url", @@ -1314,7 +1314,7 @@ dependencies = [ "proc-macro2", "quote", "serde_json", - "syn", + "syn 1.0.103", ] [[package]] @@ -1342,7 +1342,7 @@ dependencies = [ "serde", "serde_json", "strum", - "syn", + "syn 1.0.103", "thiserror", "tiny-keccak", "unicode-xid", @@ -1357,7 +1357,7 @@ dependencies = [ "hex", "quote", "serde_json", - "syn", + "syn 1.0.103", ] [[package]] @@ -1406,6 +1406,7 @@ dependencies = [ "tokio", "tracing", "tracing-futures", + "tracing-test", "url", ] @@ -1717,7 +1718,7 @@ checksum = "bdfb8ce053d86b91919aad980c220b1fb8401a9394410e1c289ed7e66b61835d" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2076,7 +2077,7 @@ checksum = "d5dacb10c5b3bb92d46ba347505a9041e676bb20ad220101326bffb0c93031ee" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2515,7 +2516,7 @@ dependencies = [ "bytes", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2620,7 +2621,7 @@ dependencies = [ "proc-macro-crate", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2781,7 +2782,7 @@ dependencies = [ "proc-macro-hack", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2825,7 +2826,7 @@ checksum = "710faf75e1b33345361201d36d04e98ac1ed8909151a017ed384700836104c74" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -2941,7 +2942,7 @@ dependencies = [ "proc-macro-error-attr", "proc-macro2", "quote", - "syn", + "syn 1.0.103", "version_check", ] @@ -2964,9 +2965,9 @@ checksum = "dbf0c48bc1d91375ae5c3cd81e3722dff1abcf81a30960240640d223f59fe0e5" [[package]] name = "proc-macro2" -version = "1.0.47" +version = "1.0.92" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5ea3d908b0e36316caf9e9e2c4625cdde190a7e6f440d794667ed17a1855e725" +checksum = "37d3544b3f2748c54e147655edb5025752e2303145b5aefb3c3ea2c78b973bb0" dependencies = [ "unicode-ident", ] @@ -2979,9 +2980,9 @@ checksum = "47c327e191621a2158159df97cdbc2e7074bb4e940275e35abf38eb3d2595754" [[package]] name = "quote" -version = "1.0.16" +version = "1.0.38" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b4af2ec4714533fcdf07e886f17025ace8b997b9ce51204ee69b6da831c3da57" +checksum = "0e4dccaaaf89514f546c693ddc140f729f958c247918a13380cccc6078391acc" dependencies = [ "proc-macro2", ] @@ -3241,7 +3242,7 @@ checksum = "e33d7b2abe0c340d8797fe2907d3f20d3b5ea5908683618bfe80df7f621f672a" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -3438,7 +3439,7 @@ dependencies = [ "proc-macro-crate", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -3585,7 +3586,7 @@ checksum = "94ed3a816fb1d101812f83e789f888322c34e291f894f19590dc310963e87a00" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -3634,7 +3635,7 @@ dependencies = [ "proc-macro-error", "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -3759,7 +3760,7 @@ checksum = "96e6310f022b5c02b3bba689166e833f6b96994a6ce1f138b653d2fd0519920f" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -3863,7 +3864,7 @@ dependencies = [ "proc-macro2", "quote", "rustversion", - "syn", + "syn 1.0.103", ] [[package]] @@ -3927,6 +3928,17 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "syn" +version = "2.0.93" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9c786062daee0d6db1132800e623df74274a0a87322d8e183338e01b3d98d058" +dependencies = [ + "proc-macro2", + "quote", + "unicode-ident", +] + [[package]] name = "synstructure" version = "0.12.6" @@ -3935,7 +3947,7 @@ checksum = "f36bdaa60a83aca3921b5259d5400cbf5e90fc51931376a9bd4a0eb79aa7210f" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", "unicode-xid", ] @@ -4021,7 +4033,7 @@ checksum = "982d17546b47146b28f7c22e3d08465f6b8903d0ea13c1660d9d84a6e7adcdbb" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -4114,7 +4126,7 @@ checksum = "b557f72f448c511a979e2564e55d74e6c4432fc96ff4f6241bc6bded342643b7" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -4205,7 +4217,7 @@ checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", ] [[package]] @@ -4257,6 +4269,27 @@ dependencies = [ "tracing-log", ] +[[package]] +name = "tracing-test" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "557b891436fe0d5e0e363427fc7f217abf9ccd510d5136549847bdcbcd011d68" +dependencies = [ + "tracing-core", + "tracing-subscriber", + "tracing-test-macro", +] + +[[package]] +name = "tracing-test-macro" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "04659ddb06c87d233c566112c1c9c5b9e98256d9af50ec3bc9c8327f873a7568" +dependencies = [ + "quote", + "syn 2.0.93", +] + [[package]] name = "trezor-client" version = "0.0.7" @@ -4479,7 +4512,7 @@ dependencies = [ "once_cell", "proc-macro2", "quote", - "syn", + "syn 1.0.103", "wasm-bindgen-shared", ] @@ -4513,7 +4546,7 @@ checksum = "07bc0c051dc5f23e307b13285f9d75df86bfdf816c5721e573dec1f9b8aa193c" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", "wasm-bindgen-backend", "wasm-bindgen-shared", ] @@ -4834,7 +4867,7 @@ checksum = "81e8f13fef10b63c06356d65d416b070798ddabcadc10d3ece0c5be9b3c7eddb" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 1.0.103", "synstructure", ] diff --git a/ethers-middleware/Cargo.toml b/ethers-middleware/Cargo.toml index b53788bf8..41b57dd58 100644 --- a/ethers-middleware/Cargo.toml +++ b/ethers-middleware/Cargo.toml @@ -29,6 +29,7 @@ futures-util = { version = "^0.3" } futures-locks = { version = "0.7", default-features = false } tracing = { version = "0.1.37", default-features = false } tracing-futures = { version = "0.2.5", default-features = false } +tracing-test = "0.2.2" # for gas oracles reqwest = { version = "0.11.13", default-features = false, features = ["json", "rustls-tls"] } diff --git a/ethers-middleware/src/gas_escalator/mod.rs b/ethers-middleware/src/gas_escalator/mod.rs index 7d3be4552..9ca6d3531 100644 --- a/ethers-middleware/src/gas_escalator/mod.rs +++ b/ethers-middleware/src/gas_escalator/mod.rs @@ -184,6 +184,7 @@ where &self.inner.inner } + #[instrument(skip(self, tx, block), name = "GasOracle::send_transaction")] async fn send_transaction + Send + Sync>( &self, tx: T, @@ -206,7 +207,7 @@ where match self.inner.send_transaction(tx.clone(), block).await { Ok(pending_tx) => { - // insert the tx in the pending txs + tracing::debug!(tx = ?tx, tx_hash = ?pending_tx.tx_hash(), "Sent tx, adding to gas escalator watcher"); let mut lock = self.txs.lock().await; lock.push(MonitoredTransaction { hash: Some(*pending_tx), @@ -217,7 +218,7 @@ where Ok(pending_tx) } Err(err) => { - // insert the tx in the pending txs + tracing::warn!(tx = ?tx, "Failed to send tx, adding to gas escalator watcher regardless"); let mut lock = self.txs.lock().await; lock.push(MonitoredTransaction { hash: None, @@ -269,6 +270,9 @@ pub struct EscalationTask { txs: ToEscalate, } +const RETRYABLE_ERRORS: [&str; 3] = + ["replacement transaction underpriced", "already known", "Fair pubdata price too high"]; + #[cfg(not(target_arch = "wasm32"))] impl EscalationTask { pub fn new(inner: M, escalator: E, frequency: Frequency, txs: ToEscalate) -> Self { @@ -288,23 +292,13 @@ impl EscalationTask { // already landed onchain, meaning we no longer need to escalate it tracing::warn!(err = err_message, ?old_monitored_tx, ?new_tx, "Nonce error when escalating gas price. Tx may have already been included onchain. Dropping it from escalator"); None - } else if err_message.contains("replacement transaction underpriced") { - // the gas escalation wasn't sufficient - tracing::warn!( - err = err_message, - old_tx = ?old_monitored_tx, - new_tx = ?new_tx, - "Escalated gas price was underpriced, re-adding to escalator" - ); - // return the old tx_hash and creation time so the transaction is re-escalated - // as soon as `monitored_txs` are evaluated again - Some((old_monitored_tx.hash, old_monitored_tx.creation_time)) - } else if err_message.contains("already known") { + } else if RETRYABLE_ERRORS.iter().any(|err_msg| err_message.contains(err_msg)) { + // if the error is one of the known retryable errors, we can keep trying to escalate tracing::warn!( err = err_message, - old_tx = ?old_monitored_tx, + old_tx = ?old_monitored_tx.hash, new_tx = ?new_tx, - "The escalator broadcasted the same transaction twice. Re-adding to attempt re-escalating" + "Encountered retryable error, re-adding to escalator" ); // return the old tx_hash and creation time so the transaction is re-escalated // as soon as `monitored_txs` are evaluated again @@ -312,7 +306,7 @@ impl EscalationTask { } else { tracing::error!( err = err_message, - old_tx = ?old_monitored_tx, + old_tx = ?old_monitored_tx.hash, new_tx = ?new_tx, "Unexpected error when broadcasting gas-escalated transaction. Dropping it from escalator." ); @@ -378,9 +372,9 @@ impl EscalationTask { None }; - if receipt.is_some() { + if let Some(receipt) = receipt { // tx was already included, can drop from escalator - tracing::debug!(tx = ?old_monitored_tx, "Transaction was included onchain, dropping from escalator"); + tracing::debug!(tx = ?receipt.transaction_hash, "Transaction was included onchain, dropping from escalator"); continue; } let Some(new_tx) = old_monitored_tx.escalate_gas_price(self.escalator.clone()) else { diff --git a/ethers-middleware/src/gas_oracle/middleware.rs b/ethers-middleware/src/gas_oracle/middleware.rs index 272b01509..df5c42b0e 100644 --- a/ethers-middleware/src/gas_oracle/middleware.rs +++ b/ethers-middleware/src/gas_oracle/middleware.rs @@ -3,6 +3,7 @@ use async_trait::async_trait; use ethers_core::types::{transaction::eip2718::TypedTransaction, *}; use ethers_providers::{FromErr, Middleware, PendingTransaction}; use thiserror::Error; +use tracing::instrument; #[derive(Debug)] /// Middleware used for fetching gas prices over an API instead of `eth_gasPrice` @@ -56,6 +57,7 @@ where &self.inner } + #[instrument(skip(self), name = "GasOracle::fill_transaction")] async fn fill_transaction( &self, tx: &mut TypedTransaction, @@ -85,6 +87,7 @@ where } } }; + tracing::debug!(?tx, "Filled transaction"); self.inner().fill_transaction(tx, block).await.map_err(FromErr::from) } @@ -100,12 +103,14 @@ where Ok(self.gas_oracle.estimate_eip1559_fees().await?) } + #[instrument(skip(self, tx, block), name = "GasOracle::send_transaction")] async fn send_transaction + Send + Sync>( &self, tx: T, block: Option, ) -> Result, Self::Error> { let mut tx = tx.into(); + tracing::debug!(?tx, "Sending transaction"); self.fill_transaction(&mut tx, block).await?; self.inner.send_transaction(tx, block).await.map_err(MiddlewareError::MiddlewareError) } diff --git a/ethers-middleware/src/nonce_manager.rs b/ethers-middleware/src/nonce_manager.rs index b4a92c3dd..7905c7b78 100644 --- a/ethers-middleware/src/nonce_manager.rs +++ b/ethers-middleware/src/nonce_manager.rs @@ -3,6 +3,7 @@ use ethers_core::types::{transaction::eip2718::TypedTransaction, *}; use ethers_providers::{FromErr, Middleware, PendingTransaction}; use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use thiserror::Error; +use tracing::instrument; #[derive(Debug)] /// Middleware used for calculating nonces locally, useful for signing multiple @@ -106,6 +107,7 @@ where &self.inner } + #[instrument(skip(self), name = "NonceManager::fill_transaction")] async fn fill_transaction( &self, tx: &mut TypedTransaction, @@ -125,6 +127,7 @@ where /// Signs and broadcasts the transaction. The optional parameter `block` can be passed so that /// gas cost and nonce calculations take it into account. For simple transactions this can be /// left to `None`. + #[instrument(skip(self, tx, block), name = "NonceManager::send_transaction")] async fn send_transaction + Send + Sync>( &self, tx: T, @@ -135,21 +138,43 @@ where if tx.nonce().is_none() { tx.set_nonce(self.get_transaction_count_with_manager(block).await?); } - + let nonce = tx.nonce(); + tracing::debug!(?nonce, "Sending transaction"); match self.inner.send_transaction(tx.clone(), block).await { - Ok(tx_hash) => Ok(tx_hash), + Ok(pending_tx) => { + tracing::debug!(?nonce, "Sent transaction"); + Ok(pending_tx) + } Err(err) => { - let nonce = self.get_transaction_count(self.address, block).await?; - if nonce != self.nonce.load(Ordering::SeqCst).into() { + tracing::error!( + ?nonce, + error=?err, + "Error sending transaction. Checking onchain nonce." + ); + let onchain_nonce = self.get_transaction_count(self.address, block).await?; + let internal_nonce = self.nonce.load(Ordering::SeqCst); + if onchain_nonce != internal_nonce.into() { // try re-submitting the transaction with the correct nonce if there // was a nonce mismatch - self.nonce.store(nonce.as_u64(), Ordering::SeqCst); - tx.set_nonce(nonce); + self.nonce.store(onchain_nonce.as_u64(), Ordering::SeqCst); + tx.set_nonce(onchain_nonce); + tracing::warn!( + onchain_nonce=?onchain_nonce.as_u64(), + ?internal_nonce, + error=?err, + "Onchain nonce didn't match internal nonce. Resending transaction with updated nonce." + ); self.inner .send_transaction(tx, block) .await .map_err(NonceManagerError::MiddlewareError) } else { + tracing::warn!( + onchain_nonce=?onchain_nonce.as_u64(), + ?internal_nonce, + error=?err, + "Onchain nonce matches internal nonce. Propagating error." + ); // propagate the error otherwise Err(NonceManagerError::MiddlewareError(err)) } diff --git a/ethers-middleware/src/signer.rs b/ethers-middleware/src/signer.rs index 36af4f031..924643ae2 100644 --- a/ethers-middleware/src/signer.rs +++ b/ethers-middleware/src/signer.rs @@ -5,6 +5,7 @@ use ethers_core::types::{ use ethers_providers::{maybe, FromErr, Middleware, PendingTransaction}; use ethers_signers::Signer; use std::convert::TryFrom; +use tracing::instrument; use async_trait::async_trait; use thiserror::Error; @@ -233,6 +234,7 @@ where } /// Helper for filling a transaction's nonce using the wallet + #[instrument(skip(self), name = "SignerMiddleware::fill_transaction")] async fn fill_transaction( &self, tx: &mut TypedTransaction, @@ -276,12 +278,14 @@ where /// Signs and broadcasts the transaction. The optional parameter `block` can be passed so that /// gas cost and nonce calculations take it into account. For simple transactions this can be /// left to `None`. + #[instrument(skip(self, tx, block), name = "SignerMiddleware::send_transaction")] async fn send_transaction + Send + Sync>( &self, tx: T, block: Option, ) -> Result, Self::Error> { let mut tx = tx.into(); + tracing::debug!(nonce=?tx.nonce(), "Sending transaction"); // fill any missing fields self.fill_transaction(&mut tx, block).await?; @@ -292,7 +296,7 @@ where .inner .send_transaction(tx, block) .await - .map_err(SignerMiddlewareError::MiddlewareError) + .map_err(SignerMiddlewareError::MiddlewareError); } // if we have a nonce manager set, we should try handling the result in diff --git a/ethers-middleware/tests/gas_escalator.rs b/ethers-middleware/tests/gas_escalator.rs index 3cbea38ee..0e5981c08 100644 --- a/ethers-middleware/tests/gas_escalator.rs +++ b/ethers-middleware/tests/gas_escalator.rs @@ -15,6 +15,7 @@ use instant::Duration; use tokio::time::sleep; #[tokio::test] +#[tracing_test::traced_test] async fn gas_escalator_legacy_works() { // TODO: show tracing logs in the test @@ -63,6 +64,7 @@ async fn gas_escalator_legacy_works() { } #[tokio::test] +#[tracing_test::traced_test] async fn gas_escalator_1559_works() { // TODO: show tracing logs in the test