test: Investigate L1 "nonce too low" errors

core/bin/external_node/src/config/observability.rs

@@ -95,11 +95,10 @@ impl ObservabilityENConfig {
                 )
             })
             .transpose()?;
-        let guard = zksync_vlog::ObservabilityBuilder::new()
+        zksync_vlog::ObservabilityBuilder::new()
             .with_logs(Some(logs))
             .with_sentry(sentry)
-            .build();
-        Ok(guard)
+            .try_build()
     }
 
     pub(crate) fn from_configs(general_config: &GeneralConfig) -> anyhow::Result<Self> {

core/bin/external_node/src/config/tests.rs

@@ -63,7 +63,10 @@ fn parsing_observability_config() {
 fn using_unset_sentry_url() {
     let env_vars = MockEnvironment::new(&[("MISC_SENTRY_URL", "unset")]);
     let config = ObservabilityENConfig::new(&env_vars).unwrap();
-    config.build_observability().unwrap();
+    if let Err(err) = config.build_observability() {
+        // Global tracer may be installed by another test, but the logic shouldn't fail before that.
+        assert!(format!("{err:?}").contains("global tracer"), "{err:?}");
+    }
 }
 
 #[test]

core/bin/external_node/src/tests/mod.rs

@@ -21,7 +21,7 @@ const POLL_INTERVAL: Duration = Duration::from_millis(100);
 #[tokio::test]
 #[tracing::instrument] // Add args to the test logs
 async fn external_node_basics(components_str: &'static str) {
-    let _guard = zksync_vlog::ObservabilityBuilder::new().build(); // Enable logging to simplify debugging
+    let _guard = zksync_vlog::ObservabilityBuilder::new().try_build().ok(); // Enable logging to simplify debugging
 
     let (env, env_handles) = utils::TestEnvironment::with_genesis_block(components_str).await;
 
@@ -92,7 +92,7 @@ async fn external_node_basics(components_str: &'static str) {
 
 #[tokio::test]
 async fn node_reacts_to_stop_signal_during_initial_reorg_detection() {
-    let _guard = zksync_vlog::ObservabilityBuilder::new().build(); // Enable logging to simplify debugging
+    let _guard = zksync_vlog::ObservabilityBuilder::new().try_build().ok(); // Enable logging to simplify debugging
     let (env, env_handles) = utils::TestEnvironment::with_genesis_block("core").await;
 
     let l2_client = utils::mock_l2_client_hanging();
@@ -128,7 +128,7 @@ async fn node_reacts_to_stop_signal_during_initial_reorg_detection() {
 
 #[tokio::test]
 async fn running_tree_without_core_is_not_allowed() {
-    let _guard = zksync_vlog::ObservabilityBuilder::new().build(); // Enable logging to simplify debugging
+    let _guard = zksync_vlog::ObservabilityBuilder::new().try_build().ok(); // Enable logging to simplify debugging
     let (env, _env_handles) = utils::TestEnvironment::with_genesis_block("tree").await;
 
     let l2_client = utils::mock_l2_client(&env);
@@ -165,7 +165,7 @@ async fn running_tree_without_core_is_not_allowed() {
 
 #[tokio::test]
 async fn running_tree_api_without_tree_is_not_allowed() {
-    let _guard = zksync_vlog::ObservabilityBuilder::new().build(); // Enable logging to simplify debugging
+    let _guard = zksync_vlog::ObservabilityBuilder::new().try_build().ok(); // Enable logging to simplify debugging
     let (env, _env_handles) = utils::TestEnvironment::with_genesis_block("core,tree_api").await;
 
     let l2_client = utils::mock_l2_client(&env);

core/lib/vlog/src/lib.rs

@@ -4,6 +4,7 @@
 use std::time::Duration;
 
 use ::sentry::ClientInitGuard;
+use anyhow::Context as _;
 use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
 pub use crate::{logs::Logs, opentelemetry::OpenTelemetry, sentry::Sentry};
@@ -126,8 +127,9 @@ impl ObservabilityBuilder {
         self
     }
 
-    /// Initializes the observability subsystem.
-    pub fn build(self) -> ObservabilityGuard {
+    /// Tries to initialize the observability subsystem. Returns an error if it's already initialized.
+    /// This is mostly useful in tests.
+    pub fn try_build(self) -> anyhow::Result<ObservabilityGuard> {
         let logs = self.logs.unwrap_or_default();
         logs.install_panic_hook();
 
@@ -151,14 +153,20 @@ impl ObservabilityBuilder {
             .with(logs_layer)
             .with(otlp_tracing_layer)
             .with(otlp_logging_layer)
-            .init();
+            .try_init()
+            .context("failed installing global tracer / logger")?;
 
         let sentry_guard = self.sentry.map(|sentry| sentry.install());
 
-        ObservabilityGuard {
+        Ok(ObservabilityGuard {
             otlp_tracing_provider,
             otlp_logging_provider,
             sentry_guard,
-        }
+        })
+    }
+
+    /// Initializes the observability subsystem.
+    pub fn build(self) -> ObservabilityGuard {
+        self.try_build().unwrap()
     }
 }

core/tests/recovery-test/src/index.ts

@@ -271,23 +271,23 @@ export class FundedWallet {
         await depositTx.waitFinalize();
     }
 
-    /** Generates at least one L1 batch by transfering funds to itself. */
+    /** Generates at least one L1 batch by transferring funds to itself. */
     async generateL1Batch(): Promise<number> {
         const transactionResponse = await this.wallet.transfer({
             to: this.wallet.address,
             amount: 1,
             token: zksync.utils.ETH_ADDRESS
         });
         console.log('Generated a transaction from funded wallet', transactionResponse);
-        const receipt = await transactionResponse.wait();
-        console.log('Got finalized transaction receipt', receipt);
 
-        // Wait until an L1 batch with the transaction is sealed.
-        const pastL1BatchNumber = await this.wallet.provider.getL1BatchNumber();
-        let newL1BatchNumber: number;
-        while ((newL1BatchNumber = await this.wallet.provider.getL1BatchNumber()) <= pastL1BatchNumber) {
+        let receipt: zksync.types.TransactionReceipt;
+        while (!(receipt = await transactionResponse.wait()).l1BatchNumber) {
+            console.log('Transaction is not included in L1 batch; sleeping');
             await sleep(1000);
         }
+
+        console.log('Got finalized transaction receipt', receipt);
+        const newL1BatchNumber = receipt.l1BatchNumber;
         console.log(`Sealed L1 batch #${newL1BatchNumber}`);
         return newL1BatchNumber;
     }

core/tests/ts-integration/jest.config.json

@@ -14,6 +14,7 @@
   "testTimeout": 605000,
   "globalSetup": "<rootDir>/src/jest-setup/global-setup.ts",
   "globalTeardown": "<rootDir>/src/jest-setup/global-teardown.ts",
+  "testEnvironment": "<rootDir>/src/jest-setup/env.ts",
   "setupFilesAfterEnv": [
     "<rootDir>/src/jest-setup/add-matchers.ts"
   ],

core/tests/ts-integration/package.json

@@ -25,6 +25,7 @@
     "ethers": "^6.7.1",
     "hardhat": "=2.22.2",
     "jest": "^29.0.3",
+    "jest-environment-node": "^29.0.3",
     "jest-matcher-utils": "^29.0.3",
     "node-fetch": "^2.6.1",
     "ts-jest": "^29.0.1",

core/tests/ts-integration/src/jest-setup/env.ts

@@ -0,0 +1,14 @@
+import NodeEnvironment from 'jest-environment-node';
+import type { EnvironmentContext, JestEnvironmentConfig } from '@jest/environment';
+
+export default class IntegrationTestEnvironment extends NodeEnvironment {
+    constructor(config: JestEnvironmentConfig, context: EnvironmentContext) {
+        super(config, context);
+    }
+
+    override async setup() {
+        await super.setup();
+        // Provide access to raw console in order to produce less cluttered debug messages
+        this.global.rawWriteToConsole = console.log;
+    }
+}

core/tests/ts-integration/src/jest-setup/global-setup.ts

@@ -11,11 +11,12 @@ declare global {
  */
 async function performSetup(_globalConfig: any, _projectConfig: any) {
     // Perform the test initialization.
-    // This is an expensive operation that preceeds running any tests, as we need
+    // This is an expensive operation that precedes running any tests, as we need
     // to deposit & distribute funds, deploy some contracts, and perform basic server checks.
 
     // Jest writes an initial message without a newline, so we have to do it manually.
     console.log('');
+    globalThis.rawWriteToConsole = console.log;
 
     // Before starting any actual logic, we need to ensure that the server is running (it may not
     // be the case, for example, right after deployment on stage).

core/tests/ts-integration/src/l1-provider.ts

@@ -0,0 +1,82 @@
+import {
+    ethers,
+    JsonRpcProvider,
+    Network,
+    TransactionRequest,
+    TransactionResponse,
+    TransactionResponseParams
+} from 'ethers';
+import { Reporter } from './reporter';
+import { AugmentedTransactionResponse } from './transaction-response';
+
+export class L1Provider extends JsonRpcProvider {
+    readonly reporter: Reporter;
+
+    constructor(url: string, reporter?: Reporter) {
+        super(url, undefined, { batchMaxCount: 1 });
+        this.reporter = reporter ?? new Reporter();
+    }
+
+    override _wrapTransactionResponse(tx: TransactionResponseParams, network: Network): L1TransactionResponse {
+        const base = super._wrapTransactionResponse(tx, network);
+        return new L1TransactionResponse(base, this.reporter);
+    }
+}
+
+class L1TransactionResponse extends ethers.TransactionResponse implements AugmentedTransactionResponse {
+    public readonly kind = 'L1';
+    private isWaitingReported: boolean = false;
+    private isReceiptReported: boolean = false;
+
+    constructor(base: ethers.TransactionResponse, public readonly reporter: Reporter) {
+        super(base, base.provider);
+    }
+
+    override async wait(confirmations?: number, timeout?: number) {
+        if (!this.isWaitingReported) {
+            this.reporter.debug(
+                `Started waiting for L1 transaction ${this.hash} (from=${this.from}, nonce=${this.nonce})`
+            );
+            this.isWaitingReported = true;
+        }
+
+        const receipt = await super.wait(confirmations, timeout);
+        if (receipt !== null && !this.isReceiptReported) {
+            this.reporter.debug(
+                `Obtained receipt for L1 transaction ${this.hash}: blockNumber=${receipt.blockNumber}, status=${receipt.status}`
+            );
+            this.isReceiptReported = true;
+        }
+        return receipt;
+    }
+
+    override replaceableTransaction(startBlock: number): L1TransactionResponse {
+        const base = super.replaceableTransaction(startBlock);
+        return new L1TransactionResponse(base, this.reporter);
+    }
+}
+
+/** Wallet that retries `sendTransaction` requests on "nonce expired" errors, provided that it's possible (i.e., no nonce is set in the request). */
+export class RetryableL1Wallet extends ethers.Wallet {
+    constructor(key: string, provider: L1Provider) {
+        super(key, provider);
+    }
+
+    override async sendTransaction(tx: TransactionRequest): Promise<TransactionResponse> {
+        const reporter = (<L1Provider>this.provider!).reporter;
+        while (true) {
+            try {
+                return await super.sendTransaction(tx);
+            } catch (err: any) {
+                // For unknown reason, `reth` sometimes returns outdated transaction count under load, leading to transactions getting rejected.
+                // This is a workaround for this issue.
+                reporter.debug('L1 transaction request failed', tx, err);
+                if (err.code === 'NONCE_EXPIRED' && (tx.nonce === null || tx.nonce === undefined)) {
+                    reporter.debug('Retrying L1 transaction request', tx);
+                } else {
+                    throw err;
+                }
+            }
+        }
+    }
+}

core/tests/ts-integration/src/matchers/transaction.ts

@@ -1,7 +1,8 @@
 import { TestMessage } from './matcher-helpers';
 import { MatcherModifier } from '../modifiers';
 import * as zksync from 'zksync-ethers';
-import { AugmentedTransactionResponse } from '../retry-provider';
+import { AugmentedTransactionResponse } from '../transaction-response';
+import { ethers } from 'ethers';
 
 // This file contains implementation of matchers for ZKsync/ethereum transaction.
 // For actual doc-comments, see `typings/jest.d.ts` file.
@@ -207,7 +208,7 @@ function fail(message: string) {
  *
  * @returns If check has failed, returns a Jest error object. Otherwise, returns `undefined`.
  */
-function checkReceiptFields(request: zksync.types.TransactionResponse, receipt: zksync.types.TransactionReceipt) {
+function checkReceiptFields(request: ethers.TransactionResponseParams, receipt: zksync.types.TransactionReceipt) {
     const errorMessageBuilder = new TestMessage()
         .matcherHint('.checkReceiptFields')
         .line('Transaction receipt is not properly formatted. Transaction request:')

core/tests/ts-integration/src/reporter.ts

@@ -102,7 +102,7 @@ export class Reporter {
             // Timestamps only make sense to include in tests.
             const timestampString = testName === undefined ? '' : timestamp(`${new Date().toISOString()} `);
             const testString = testName ? info(` [${testName}]`) : '';
-            console.log(this.indent(`${timestampString}DEBUG${testString}: ${message}`), ...args);
+            rawWriteToConsole(this.indent(`${timestampString}DEBUG${testString}: ${message}`), ...args);
         }
     }
 

core/tests/ts-integration/src/retry-provider.ts

@@ -1,12 +1,15 @@
 import * as zksync from 'zksync-ethers';
 import * as ethers from 'ethers';
 import { Reporter } from './reporter';
+import { AugmentedTransactionResponse } from './transaction-response';
+import { L1Provider, RetryableL1Wallet } from './l1-provider';
 
 /**
  * RetryProvider retries every RPC request if it detects a timeout-related issue on the server side.
  */
 export class RetryProvider extends zksync.Provider {
     private readonly reporter: Reporter;
+    private readonly knownTransactionHashes: Set<string> = new Set();
 
     constructor(_url?: string | { url: string; timeout: number }, network?: ethers.Networkish, reporter?: Reporter) {
         let url;
@@ -55,15 +58,63 @@ export class RetryProvider extends zksync.Provider {
         }
     }
 
+    override _wrapTransactionResponse(txResponse: any): L2TransactionResponse {
+        const base = super._wrapTransactionResponse(txResponse);
+        this.knownTransactionHashes.add(base.hash);
+        return new L2TransactionResponse(base, this.reporter);
+    }
+
     override _wrapTransactionReceipt(receipt: any): zksync.types.TransactionReceipt {
         const wrapped = super._wrapTransactionReceipt(receipt);
-        this.reporter.debug(
-            `Obtained receipt for transaction ${receipt.transactionHash}: blockNumber=${receipt.blockNumber}, status=${receipt.status}`
-        );
+        if (!this.knownTransactionHashes.has(receipt.transactionHash)) {
+            this.knownTransactionHashes.add(receipt.transactionHash);
+            this.reporter.debug(
+                `Obtained receipt for L2 transaction ${receipt.transactionHash}: blockNumber=${receipt.blockNumber}, status=${receipt.status}`
+            );
+        }
         return wrapped;
     }
 }
 
-export interface AugmentedTransactionResponse extends zksync.types.TransactionResponse {
-    readonly reporter?: Reporter;
+class L2TransactionResponse extends zksync.types.TransactionResponse implements AugmentedTransactionResponse {
+    public readonly kind = 'L2';
+    private isWaitingReported: boolean = false;
+    private isReceiptReported: boolean = false;
+
+    constructor(base: zksync.types.TransactionResponse, public readonly reporter: Reporter) {
+        super(base, base.provider);
+    }
+
+    override async wait(confirmations?: number) {
+        if (!this.isWaitingReported) {
+            this.reporter.debug(
+                `Started waiting for L2 transaction ${this.hash} (from=${this.from}, nonce=${this.nonce})`
+            );
+            this.isWaitingReported = true;
+        }
+        const receipt = await super.wait(confirmations);
+        if (receipt !== null && !this.isReceiptReported) {
+            this.reporter.debug(
+                `Obtained receipt for L2 transaction ${this.hash}: blockNumber=${receipt.blockNumber}, status=${receipt.status}`
+            );
+            this.isReceiptReported = true;
+        }
+        return receipt;
+    }
+
+    override replaceableTransaction(startBlock: number): L2TransactionResponse {
+        const base = super.replaceableTransaction(startBlock);
+        return new L2TransactionResponse(base, this.reporter);
+    }
+}
+
+/** Wallet that retries expired nonce errors for L1 transactions. */
+export class RetryableWallet extends zksync.Wallet {
+    constructor(privateKey: string, l2Provider: RetryProvider, l1Provider: L1Provider) {
+        super(privateKey, l2Provider, l1Provider);
+    }
+
+    override ethWallet(): RetryableL1Wallet {
+        return new RetryableL1Wallet(this.privateKey, <L1Provider>this._providerL1());
+    }
 }