Transactions stuck in pending in dev-mode

[nikitagashkov]

System information

• Geth version

  Geth
  Version: 1.13.14-stable
  Git Commit: 2bd6bd01d2e8561dd7fc21b631f4a34ac16627a1
  Git Commit Date: 20240227
  Architecture: arm64
  Go Version: go1.21.0
  Operating System: darwin
  GOPATH=
  GOROOT=/Users/gashkov/.asdf/installs/golang/1.22.0/go
  

• CL client & version: none (dev-mode)
• OS & Version: macOS Sonoma 14.4.1 (23E224)
• Commit hash: not applicable

Steps to reproduce the behaviour

1. Run go-ethereum in a dev-mode with block generation on demand
2. Send a batch of transactions concurrently

Stress-testing script I used for reproducing this behavior.

package main

import (
	"fmt"
	"github.com/ethereum/go-ethereum/common"
	"github.com/ethereum/go-ethereum/common/hexutil"
	"github.com/ethereum/go-ethereum/core/types"
	"github.com/ethereum/go-ethereum/rpc"
	"log"
	"sync"
	"time"
)

func getCoinbase(c *rpc.Client) common.Address {
	var coinbase common.Address

	if err := c.Call(&coinbase, "eth_coinbase"); err != nil {
		log.Fatalln("error obtaining coinbase", err)
	} else {
		log.Printf("coinbase=%v", coinbase)
	}

	return coinbase
}

func getTransactionCount(c *rpc.Client, address common.Address) hexutil.Uint {
	var nonce hexutil.Uint

	if err := c.Call(&nonce, "eth_getTransactionCount", address, "latest"); err != nil {
		log.Fatalln("error obtaining coinbase's initial nonce", err)
	} else {
		log.Printf("nonce=%v", nonce)
	}

	return nonce
}

func sendTransactionToSelf(c *rpc.Client, address common.Address, nonce hexutil.Uint) (common.Hash, error) {
	txObject := map[string]any{"from": address, "to": address, "nonce": nonce}

	var txHash common.Hash
	if err := c.Call(&txHash, "eth_sendTransaction", txObject); err != nil {
		return common.Hash{}, err
	}

	return txHash, nil
}

func waitTransactionReceipt(c *rpc.Client, txHash common.Hash) (*types.Receipt, error) {
	for i := 0; i < 10; i++ {
		var txReceipt *types.Receipt
		if err := c.Call(&txReceipt, "eth_getTransactionReceipt", txHash); err != nil {
			if fmt.Sprint(err) == "transaction indexing is in progress" {
				// `transaction indexing is in progress` is returned when
				// `eth_getTransactionCount` is called with no previously mined
				// blocks.
				time.Sleep(1 * time.Second)
			} else {
				return nil, err
			}
		}

		if txReceipt != nil {
			return txReceipt, nil
		}

		time.Sleep(100 * time.Millisecond)
	}

	return nil, fmt.Errorf("timeout waiting tx hash=%v to be mined", txHash)
}

func main() {
	c, err := rpc.Dial("http://localhost:8545")

	if err != nil {
		log.Fatal("error dialing server", "url", "http://localhost:8545")
	}

	coinbase := getCoinbase(c)
	startingNonce := getTransactionCount(c, coinbase)

	var (
		wg  sync.WaitGroup
		sem = make(chan struct{}, 5)
	)

	for nonce := startingNonce; nonce <= startingNonce+15; nonce++ {
		nonce := nonce
		sem <- struct{}{}
		wg.Add(1)

		go func() {
			defer func() { <-sem }()
			defer wg.Done()

			if txHash, err := sendTransactionToSelf(c, coinbase, nonce); err != nil {
				log.Printf("error sending tx nonce=%v err=%v", uint64(nonce), err)
			} else if receipt, err := waitTransactionReceipt(c, txHash); err != nil {
				log.Printf("error waiting tx nonce=%v err=%v", uint64(nonce), err)
			} else {
				log.Printf("sent tx hash=%v nonce=%v blockNumber=%v", receipt.TxHash, uint64(nonce), receipt.BlockNumber)
			}
		}()
	}

	wg.Wait()
}

Stress-testing output

% go run main.go
2024/04/06 20:13:14 coinbase=0xfb8c69691E914275e19Eb9d42735844A120067aD
2024/04/06 20:13:14 nonce=0x0
2024/04/06 20:13:15 sent tx hash=0xad155b491b06bffa28d2e0ebd4cf4f85a8e5bec108428cb2492b0048395fc3b7 nonce=2 blockNumber=1
2024/04/06 20:13:15 sent tx hash=0x7c7d61049a6118838cb0babd50aa05d5f8feece647637313d2e432dc2448e6e4 nonce=1 blockNumber=1
2024/04/06 20:13:15 sent tx hash=0xa53f94890c86c1d20f6c6398c8cd07d8c91bad816c91b7119c525f597ae7237a nonce=0 blockNumber=1
2024/04/06 20:13:15 sent tx hash=0x06bbb3c89850442f73ac53fff35b42a529dac62dde0167480455dda21e4b54e4 nonce=4 blockNumber=1
2024/04/06 20:13:15 sent tx hash=0xb55986ad438a261b8225e6384eba83a3dd710f196a5105526f149d0c8f85c0a8 nonce=3 blockNumber=1
2024/04/06 20:13:15 sent tx hash=0xc2f5aa3063d679fd39d9f2495577cb204519e9b8ecd68065155083f9c13a9aae nonce=7 blockNumber=2
2024/04/06 20:13:15 sent tx hash=0xedb2c69e889019102540da5800c4717aa3e9178fa9f8a8e4ac260235827b122d nonce=5 blockNumber=2
2024/04/06 20:13:15 sent tx hash=0xcc36386a360e4c35ccf7da2cd6d87ec4509f619f6f1620a3a9e3c43d0a050f71 nonce=6 blockNumber=2
2024/04/06 20:13:15 sent tx hash=0xf7f8a37a85beb5d366c989295cd46961a9e2bb59fac54b58fcb69fd93c7caa25 nonce=8 blockNumber=2
2024/04/06 20:13:16 error waiting tx nonce=9 err=timeout waiting tx hash=0x9b54d66bb30c77334f95e2931ca4ab6f11f61b139af1a6fc517b3fb4fe8b5e93 to be mined
2024/04/06 20:13:16 error waiting tx nonce=11 err=timeout waiting tx hash=0x6bd2490d9e4539f37ef2493389cd1066a25b32b4b2f50076e2824437335ead8f to be mined
2024/04/06 20:13:16 error waiting tx nonce=13 err=timeout waiting tx hash=0x2298fea2beeae800aa07c9e1751de1a4995d3fc506e0af3fc9039d77e89309e9 to be mined
2024/04/06 20:13:16 error waiting tx nonce=10 err=timeout waiting tx hash=0x034b4941ac6c1de3fd8e32b5c9d9976fb5896c6dbd6f37e9bb019db9e136d825 to be mined
2024/04/06 20:13:16 error waiting tx nonce=12 err=timeout waiting tx hash=0x24ca4ec05d745c4271e7b4a70d7a74d403daa38306ef7a6f6ae01a8394db7964 to be mined
2024/04/06 20:13:17 error waiting tx nonce=14 err=timeout waiting tx hash=0x2120f1d967a28ba0c467fd6c638db89959d64a92872569e7e0869ba0f3abad43 to be mined
2024/04/06 20:13:17 error waiting tx nonce=15 err=timeout waiting tx hash=0xb0e0165e29eb44545cd852da79937ad50c5933bead69cf54fbc122b5b50163e6 to be mined

Expected behaviour

geth --dev accepts and executes transactions concurrently.

Actual behaviour

Transactions are accepted but stuck in the pool:

% curl \
  -s \
  -X POST http://localhost:8545/ \
  -H 'content-type: application/json' \
  -H 'accept: application/json, */*;q=0.5' \
  -d '{"jsonrpc":"2.0","id":"1","method":"txpool_inspect","params":[]}' | jq

{
  "jsonrpc": "2.0",
  "id": "1",
  "result": {
    "pending": {
      "0xfb8c69691E914275e19Eb9d42735844A120067aD": {
        "9": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1750000001 wei"
      }
    },
    "queued": {
      "0xfb8c69691E914275e19Eb9d42735844A120067aD": {
        "10": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei",
        "11": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei",
        "12": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei",
        "13": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei",
        "14": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei",
        "15": "0xfb8c69691E914275e19Eb9d42735844A120067aD: 0 wei + 21000 gas × 1535240671 wei"
      }
    }
  }
}

Looks like the root cause is the deadlock between SimulatedBeacon and
TxPool waiting each other. Overall, the following happens:

SimulatedBeacon.loop():
  case <-newTxs:
    SimulatedBeacon.SealBlock()
      TxPool.Sync()  // Runs pool reorg and waits until done
        LegacyPool.runReorg()

and at the same time

SubmitTransaction(newTx)
  EthAPIBackend.SendTx(newTx)
    LegacyPool.add(newTx)
      LegacyPool.runReorg()
        txFeed.send(newTx)
          newTxs <- newTx // Waits until SimulatedBeacon.loop will be ready

So, when new TXs are sent concurrently, LegacyPool waits SimulatedBeacon
to react to the new TX but the SimulatedBeacon itself waits LegacyPool to
sync itself.

Backtrace

Nothing too suspicious in logs, but stacktraces contain two goroutines
indirectly waiting each other though:

goroutine 4279 [chan receive, 1 minutes]:
github.com/ethereum/go-ethereum/core/txpool.(*TxPool).Sync(0xc000513e60)
        /Users/gashkov/dev/go-ethereum/core/txpool/txpool.go:478 +0x148
github.com/ethereum/go-ethereum/eth/catalyst.(*ConsensusAPI).forkchoiceUpdated(0xc000178be0, {{0xc9, 0x10, 0x26, 0x77, 0xa1, 0x3, 0x24, 0x7, 0xab, ...}, ...}, ...)
        /Users/gashkov/dev/go-ethereum/eth/catalyst/api.go:397 +0x28d0
github.com/ethereum/go-ethereum/eth/catalyst.(*SimulatedBeacon).sealBlock(0xc0006626e0, {0x108c0da00, 0x0, 0x0}, 0x661190bc)
        /Users/gashkov/dev/go-ethereum/eth/catalyst/simulated_beacon.go:159 +0x4f4
github.com/ethereum/go-ethereum/eth/catalyst.(*SimulatedBeacon).Commit(0xc0006626e0)
        /Users/gashkov/dev/go-ethereum/eth/catalyst/simulated_beacon.go:249 +0xc4
github.com/ethereum/go-ethereum/eth/catalyst.(*api).loop(0xc0001b6980)
        /Users/gashkov/dev/go-ethereum/eth/catalyst/simulated_beacon_api.go:50 +0x2d8
created by github.com/ethereum/go-ethereum/eth/catalyst.RegisterSimulatedBeaconAPIs in goroutine 1
        /Users/gashkov/dev/go-ethereum/eth/catalyst/simulated_beacon.go:294 +0x14c

goroutine 4369 [select, 1 minutes]:
reflect.rselect({0xc00001d148, 0x2, 0x99?})
        /Users/gashkov/.asdf/installs/golang/1.21.0/go/src/runtime/select.go:589 +0x2d0
reflect.Select({0xc000000b40, 0x2, 0x5})
        /Users/gashkov/.asdf/installs/golang/1.21.0/go/src/reflect/value.go:3104 +0xa00
github.com/ethereum/go-ethereum/event.(*Feed).Send(0xc0003b9c90, {0x106d49200, 0xc000b78078})
        /Users/gashkov/dev/go-ethereum/event/feed.go:160 +0x758
github.com/ethereum/go-ethereum/core/txpool/legacypool.(*LegacyPool).runReorg(0xc0003b9c00, 0xc0005e8fc0, 0xc000488ed0, 0xc000458ce0, 0xc00089d290)
        /Users/gashkov/dev/go-ethereum/core/txpool/legacypool/legacypool.go:1336 +0xbf0
created by github.com/ethereum/go-ethereum/core/txpool/legacypool.(*LegacyPool).scheduleReorgLoop in goroutine 46
        /Users/gashkov/dev/go-ethereum/core/txpool/legacypool/legacypool.go:1205 +0x37c

• All logs
• All stacktraces

Thank you for reviewing this report!

[holiman]

PSA: @fuelmessenger is not anything we're familiar with , might be a scam, so I'll hide those posts

[maoueh]

Ok it was not related after all. The stuckness I am experiencing was done first sequentially, one transaction after the other and not in parallel.

• Web3.js 1.3.0 is doing a eth_getTransactionReceipt call but was getting WARN [04-09|16:08:34.719] Served eth_getTransactionReceipt reqid=1368187869315370 duration="36.333µs" err="transaction indexing is in progress" errdata="transaction indexing is in progress"
• This version of Web3.js I had was never retrying correctly leading to being stuck. Updating to Web3.js 1.10 fixed the issue. It's still stalls for a bit but it resolves at some point.

I have problem too sending parallel transactions to geth --dev using Web3.js hitting already known error through IPC, but I'll dig further here to understand it better and maybe I'll open a different issue.

[Pman-me]

simaoueh's solution does not solve my problem
I use web3py
I think the problem is the upgrade of geth in dev mode
Because there was none in version 1.13.5

[Pman-me]

Ok it was not related after all. The stuckness I am experiencing was done first sequentially, one transaction after the other and not in parallel.

* Web3.js 1.3.0 is doing a `eth_getTransactionReceipt` call but was getting `WARN [04-09|16:08:34.719] Served eth_getTransactionReceipt         reqid=1368187869315370 duration="36.333µs" err="transaction indexing is in progress" errdata="transaction indexing is in progress"`

* This version of Web3.js I had was never retrying correctly leading to being stuck. Updating to Web3.js 1.10 fixed the issue. It's still stalls for a bit but it resolves at some point.

I have problem too sending parallel transactions to geth --dev using Web3.js hitting already known error through IPC, but I'll dig further here to understand it better and maybe I'll open a different issue.

The reason is that the transaction indexing is in progress error
What does it give?