Timeout every minute when subscribing to a transaction

[arvin-lau]

Checklist

• This is not a security-related bug/issue. If it is, please follow please follow the security policy.
• I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
• I am running the Latest release, the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
• I did not make any code changes to lotus.

Lotus component

• lotus daemon - chain sync
• lotus fvm/fevm - Lotus FVM and FEVM interactions
• lotus miner/worker - sealing
• lotus miner - proving(WindowPoSt/WinningPoSt)
• lotus JSON-RPC API
• lotus message management (mpool)
• Other

Lotus Version

lotus version 1.31.0+mainnet+git.198ee01e3

Repro Steps

1.Run the following code

package main

import (
	"context"
	"github.com/ethereum/go-ethereum/common"
	"github.com/ethereum/go-ethereum/ethclient/gethclient"
	"github.com/ethereum/go-ethereum/rpc"
	"log"
	"time"
)

func main() {
	rpcCli, err := rpc.Dial("ws://192.168.199.161:1182/rpc/v1")
	if err != nil {
		log.Printf("rpc.Dial err: %v", err)
		return
	}
	evmListenClient := gethclient.New(rpcCli)
	txch := make(chan common.Hash, 500)
lable:
	c, err := evmListenClient.SubscribePendingTransactions(context.Background(), txch)
	if err != nil {
		log.Printf("SubscribePendingTransactions err: %v\n", err)
		time.Sleep(time.Second)
		goto lable
	}
	errChan := c.Err()
	for {
		select {
		case <-txch:
			//todo
		case err := <-errChan:
			log.Printf("channel err: %v\n", err)
			goto lable
		}
	}
}

2. err message

2025/01/28 20:05:17 channel err: read tcp 192.168.199.148:51613->192.168.199.161:1182: i/o timeout
2025/01/28 20:06:17 channel err: read tcp 192.168.199.148:52534->192.168.199.161:1182: i/o timeout
2025/01/28 20:07:17 channel err: read tcp 192.168.199.148:53400->192.168.199.161:1182: i/o timeout
2025/01/28 20:08:17 channel err: read tcp 192.168.199.148:54480->192.168.199.161:1182: i/o timeout
2025/01/28 20:09:17 channel err: read tcp 192.168.199.148:55531->192.168.199.161:1182: i/o timeout
2025/01/28 20:10:17 channel err: read tcp 192.168.199.148:56479->192.168.199.161:1182: i/o timeout
2025/01/28 20:11:17 channel err: read tcp 192.168.199.148:57149->192.168.199.161:1182: i/o timeout
2025/01/28 20:12:17 channel err: read tcp 192.168.199.148:57931->192.168.199.161:1182: i/o timeout
2025/01/28 20:13:17 channel err: read tcp 192.168.199.148:58701->192.168.199.161:1182: i/o timeout
2025/01/28 20:14:17 channel err: read tcp 192.168.199.148:59382->192.168.199.161:1182: i/o timeout
2025/01/28 20:15:17 channel err: read tcp 192.168.199.148:60121->192.168.199.161:1182: i/o timeout
2025/01/28 20:16:17 channel err: read tcp 192.168.199.148:60801->192.168.199.161:1182: i/o timeout
2025/01/28 20:17:17 channel err: read tcp 192.168.199.148:61512->192.168.199.161:1182: i/o timeout
2025/01/28 20:18:17 channel err: read tcp 192.168.199.148:62204->192.168.199.161:1182: i/o timeout

3. geth version

github.com/ethereum/go-ethereum v1.13.14

Describe the Bug

I'm using the code described above to subscribe to the transaction, and it looks like there's still a problem with lotus compatibility with eth.

Logging Information

2025-01-28T20:13:06.069+0800 WARN nat nat/nat.go:239 failed to establish port mapping: SOAP fault. Code: s:Client | Explanation: UPnPError | Detail: <UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError>
2025-01-28T20:13:06.093+0800 WARN nat nat/nat.go:239 failed to establish port mapping: SOAP fault. Code: s:Client | Explanation: UPnPError | Detail: <UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError>
C2025-01-28T20:13:18.561+0800 WARN fullnode full/eth_events.go:300 error sending subscription response, killing subscription {"sub": "0x86deb0c5d5b740e1a00ae51bbbeafd3b00000000000000000000000000000000", "error": "RPC client error: sendRequest failed: websocket routine exiting"}
2025-01-28T20:13:18.561+0800 WARN fullnode full/eth_events.go:413 failed to remove filter when unsubscribing: filter not found
2025-01-28T20:13:26.569+0800 WARN nat nat/nat.go:239 failed to establish port mapping: SOAP fault. Code: s:Client | Explanation: UPnPError | Detail: <UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError>
2025-01-28T20:13:26.601+0800 WARN nat nat/nat.go:239 failed to establish port mapping: SOAP fault. Code: s:Client | Explanation: UPnPError | Detail: <UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError>

[rvagg]

Thanks for the code @arvin-lau, we should be able to use this to reproduce it on our end and figure out what the problem is, my guess is that there's some kind of API mismatch between how we do filters/subscriptions and how this particular Eth client expects it to work but we'll have to dig a bit deeper to figure out what that is.