Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0 #10920

Closed
duktig666 opened this issue Jun 22, 2022 · 13 comments

Comments

@duktig666
Copy link

🐞 Bug Report

Description

beacon-node sync question. Syncing for about 10 minutes causes this problem:

"Peer summary" activePeers=2 inbound=0 outbound=2 prefix=p2p
"Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0

some info:

time="2022-06-21 11:29:58" level=warning msg="Running on the Prater Testnet" prefix=flags
time="2022-06-21 11:29:58" level=info msg="Checking DB" database-path="/home/prysm/kotal-data/beaconchaindata" prefix=node
time="2022-06-21 11:29:58" level=info msg="Deposit contract: 0xff50ed3d0ec03ac01d4c79aad74928bff48a7b2b" prefix=node
time="2022-06-21 11:29:58" level=info msg="Waiting for state to be initialized" prefix=initial-sync
time="2022-06-21 11:29:58" level=info msg="Starting beacon node" prefix=node version="Prysm/Unknown/. Built at: 2021-12-22 16:17:22+00:00"
time="2022-06-21 11:29:58" level=info msg="Waiting to reach the validator deposit threshold to start the beacon chain..." prefix=blockchain
time="2022-06-21 11:29:58" level=info msg="gRPC server listening on port" address="0.0.0.0:8888" prefix=rpc
time="2022-06-21 11:29:58" level=info msg="Starting API middleware" prefix=gateway
time="2022-06-21 11:29:58" level=info msg="Starting gRPC gateway" address="0.0.0.0:9999" prefix=gateway
time="2022-06-21 11:29:58" level=info msg="Connected to eth1 proof-of-work chain" endpoint="http://ethereum-goerli-api:8599" prefix=powchain
time="2022-06-21 11:30:02" level=info msg="gRPC client connected to beacon node" addr="100.168.170.108:58762" prefix=rpc
time="2022-06-21 11:34:23" level=info msg="Processing deposits from Ethereum 1 chain" deposits=512 genesisValidators=507 prefix=powchain
time="2022-06-21 11:37:31" level=info msg="Processing deposits from Ethereum 1 chain" deposits=1024 genesisValidators=1007 prefix=powchain
time="2022-06-21 11:37:49" level=info msg="Processing deposits from Ethereum 1 chain" deposits=1536 genesisValidators=1518 prefix=powchain
................
genesisValidators=4034 prefix=powchain
time="2022-06-21 11:40:51" level=info msg="Processing deposits from Ethereum 1 chain" deposits=4608 genesisValidators=4546 prefix=powchain
time="2022-06-21 11:40:53" level=info msg="Processing deposits from Ethereum 1 chain" deposits=5120 genesisValidators=5057 prefix=powchain

sync "deposits=16384" case this question

[2022-06-21 09:42:11]  INFO powchain: Processing deposits from Ethereum 1 chain deposits=15360 genesisValidators=15157
[2022-06-21 09:42:12]  INFO powchain: Processing deposits from Ethereum 1 chain deposits=15872 genesisValidators=15669
[2022-06-21 09:42:14]  INFO powchain: Processing deposits from Ethereum 1 chain deposits=16384 genesisValidators=16181
[2022-06-21 09:42:14]  INFO powchain: Minimum number of validators reached for beacon-chain to start ChainStartTime=2021-10-02 22:06:22 +0000 UTC
[2022-06-21 09:42:14]  WARN blockchain: ProcessAttestations routine waiting for genesis time
[2022-06-21 09:42:15]  INFO blockchain: Initialized beacon chain genesis state
[2022-06-21 09:42:15]  INFO slotutil: Chain genesis time reached genesisStateRoot=41623786591fc8d9ae48eb4adab15421131d0fa91c8ff9ff861cadf57144ffb6 genesisTime=2021-10-02 22:06:22 +0000 UTC genesisValidators=16393
[2022-06-21 09:42:15]  INFO initial-sync: Starting initial chain sync...
[2022-06-21 09:42:15]  INFO initial-sync: Waiting for enough suitable peers before syncing required=3 suitable=0
[2022-06-21 09:42:15]  INFO p2p: Started discovery v5 ENR=enr:-MK4QBlgJhNolh36QDew4vkvlQwDBYSXsGHeNaZXaytIYaUaKHy2NsSqYy_wN2rn1o-d110mSebf7pmjYW2CfY7eki2GAYGFpCGUh2F0dG5ldHOIAAAAAAAAAACEZXRoMpB1IkQuAgAQIP__________gmlkgnY0gmlwhKwRAAWJc2VjcDI1NmsxoQP5gjbWoKR0qeIFkbARjCNtWaSmyRa4-GtBfYh_Z61S8YhzeW5jbmV0cwCDdGNwgjLIg3VkcIIu4A
[2022-06-21 09:42:15]  INFO p2p: Node started p2p server multiAddr=/ip4/172.17.0.5/tcp/13000/p2p/16Uiu2HAmVSy2fRbfnXngdMPTux6rZLx79Pg62uWtcMt6SnQxMxoS
[2022-06-21 09:42:15]  WARN blockchain: Genesis time received, now available to process attestations
[2022-06-21 09:42:20]  INFO initial-sync: Waiting for enough suitable peers before syncing required=3 suitable=0
[2022-06-21 09:42:25]  INFO initial-sync: Waiting for enough suitable peers before syncing required=3 suitable=0

🔬 Minimal Reproduction

🔥 Error

beacon-node :

"Peer summary" activePeers=2 inbound=0 outbound=2 prefix=p2p
"Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0

validator:

time="2022-06-22 03:14:35" level=info msg="Waiting for beacon node to sync to latest chain head" prefix=validator
--
Wed, Jun 22 2022 11:14:41 am | time="2022-06-22 03:14:41" level=info msg="Waiting for beacon node to sync to latest chain head" prefix=validator
Wed, Jun 22 2022 11:14:47 am | time="2022-06-22 03:14:47" level=info msg="Waiting for beacon node to sync to latest chain head" prefix=validator

🌍 Your Environment

Operating System:

  
   ubuntu   
  

What version of Prysm are you running? (Which release)

  
   2.1.2
  

Importantly

see issue:

But there is no problem to solve the substance.

@ChiefSgt
Copy link

I had exactly the same problem for a couple of days setting up a new server to take part in the upcoming Goerli/Prater merge testing.

Geth synced fine with Goerli chain and Beacon connected to local Geth and processed deposits before it went into a "Waiting for enough suitable peers" cycle for over 24 hours. It seem to never reach 3 peers which is required.

Tested older versions of Prysm, --bootstrap-node parameter, delete beacon folder and resync a couple of times.

My solution was in the end to use an old Prater genesis file.

  1. Delete all files in beacon folder.
  2. Download genesis file from https://github.com/eth-clients/eth2-networks/tree/master/shared/prater
  3. Added --genesis-state /path/to/genesis.ssz to beacon chain config and started up sync again.

I hope this information can help to narrow down the cause for this, and help others in the same situation.

Test system
Ubuntu 22.04 (i7-4790, 32GB RAM, 512GB SSD)
Geth 1.10.20
Prysm 2.1.3 (official release amd64 Linux binary)

Beacon-chain config
ExecStart=/usr/local/bin/beacon-chain --datadir /var/lib/prysm/beacon --http-web3provider http://localhost:8545 --jwt-secret /var/lib/secrets/jwtsecret --suggested-fee-recipient --enable-vectorized-htr --accept-terms-of-use --p2p-tcp-port 13001 --p2p-udp-port 12001 --prater

@JustinAvaLabs
Copy link

I'm still running in to this issue. With Goerli and Mainnet and Sepolia.

Running from a kubernetes cluster in EKS. The same helm chart/config works fine in 3 of my other clusters, but constantly fails in one. I've tried destroying the data volume, setting "--force-clear-db", and restarting multiple times with different chains.

Below is the trace log. I've confirmed the genesis is correct, the Geth node is running normally, and I'm able to telnet to random peers :13000.

I notice the "WHOAREYOU" step never happens.

Any ideas on how I can further debug this?

time="2022-07-28 15:58:11" level=info msg="Raised fd limit to 1048576 from 1048576"
time="2022-07-28 15:58:11" level=warning msg="Running on the Prater Testnet" prefix=flags
time="2022-07-28 15:58:11" level=debug msg="Starting DB" prefix=node
time="2022-07-28 15:58:11" level=info msg="Checking DB" database-path="/root/.eth2/beaconchaindata" prefix=node
time="2022-07-28 15:58:11" level=info msg="Opening Bolt DB at /root/.eth2/beaconchaindata/beaconchain.db" prefix=db
time="2022-07-28 15:58:11" level=warning msg="Removing database" prefix=node
time="2022-07-28 15:58:11" level=info msg="Opening Bolt DB at /root/.eth2/beaconchaindata/beaconchain.db" prefix=db
time="2022-07-28 15:58:13" level=info msg="Deposit contract: 0xff50ed3d0ec03ac01d4c79aad74928bff48a7b2b" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Starting Slashing DB" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Starting State Gen" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering P2P Service" prefix=node
time="2022-07-28 15:58:13" level=info msg="Running node with peer id of 16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD " prefix=p2p
time="2022-07-28 15:58:13" level=debug msg="ECDSA private key generated" prefix=p2p
2022-07-28T15:58:13.650Z	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
time="2022-07-28 15:58:13" level=debug msg="Registering POW Chain Service" prefix=node
2022-07-28T15:58:13.651Z	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
2022-07-28T15:58:13.651Z	DEBUG	basichost	basic/basic_host.go:313	failed to fetch local IPv6 address	{"error": "no route found for ::"}
time="2022-07-28 15:58:13" level=debug msg="Registering Attestation Pool Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering Determinstic Genesis Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Starting Fork Choice" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering Blockchain Service" prefix=node
time="2022-07-28 15:58:13" level=info msg="--weak-subjectivity-checkpoint not provided. Prysm recommends providing a weak subjectivity checkpointfor nodes synced from genesis, or manual verification of block and state roots for checkpoint sync nodes." prefix=blockchain
time="2022-07-28 15:58:13" level=debug msg="Registering Intial Sync Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering Sync Service" prefix=node
time="2022-07-28 15:58:13" level=info msg="Waiting for state to be initialized" prefix=initial-sync
time="2022-07-28 15:58:13" level=debug msg="Registering Slasher Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering RPC Service" prefix=node
time="2022-07-28 15:58:13" level=info msg="gRPC server listening on port" address="0.0.0.0:4000" prefix=rpc
time="2022-07-28 15:58:13" level=warning msg="You are using an insecure gRPC server. If you are running your beacon node and validator on the same machines, you can ignore this message. If you want to know how to enable secure connections, see: https://docs.prylabs.network/docs/prysm-usage/secure-grpc" prefix=rpc
time="2022-07-28 15:58:13" level=debug msg="Registering GRPC Gateway Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering Validator Monitoring Service" prefix=node
time="2022-07-28 15:58:13" level=debug msg="Registering Prometheus Service" prefix=node
time="2022-07-28 15:58:13" level=info msg="Starting beacon node" prefix=node version="Prysm/v2.1.3/4de92bafc4bb0051381fba48eb36830aa181d7ee. Built at: 2022-07-06 19:14:48+00:00"
time="2022-07-28 15:58:13" level=debug msg="Starting 9 services: [*p2p.Service *powchain.Service *attestations.Service *blockchain.Service *initialsync.Service *sync.Service *rpc.Service *gateway.Gateway *prometheus.Service]" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *p2p.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *powchain.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *attestations.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *blockchain.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *initialsync.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *sync.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *rpc.Service" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *gateway.Gateway" prefix=registry
time="2022-07-28 15:58:13" level=debug msg="Starting service type *prometheus.Service" prefix=registry
time="2022-07-28 15:58:13" level=info msg="Blockchain data already exists in DB, initializing..." prefix=blockchain
time="2022-07-28 15:58:13" level=debug msg="Starting prometheus service" address="0.0.0.0:8080" prefix=prometheus
time="2022-07-28 15:58:13" level=info msg="Starting API middleware" prefix=gateway
time="2022-07-28 15:58:13" level=error msg="Could not connect to execution endpoint" error="could not make initial request to verify execution chain ID: Post "http://localhost:8545": dial tcp 127.0.0.1:8545: connect: connection refused" prefix=powchain
time="2022-07-28 15:58:13" level=info msg="Starting gRPC gateway" address="127.0.0.1:3500" prefix=gateway
time="2022-07-28 15:58:13" level=debug msg="Received state initialized event" prefix=initial-sync starttime=2021-03-23 14:00:00 +0000 UTC
time="2022-07-28 15:58:13" level=debug msg="Received state initialized event" prefix=sync starttime=2021-03-23 14:00:00 +0000 UTC
time="2022-07-28 15:58:13" level=info msg="Starting initial chain sync..." prefix=initial-sync
time="2022-07-28 15:58:13" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0
time="2022-07-28 15:58:13" level=debug msg="Chain started in sync service" prefix=sync starttime=2021-03-23 14:00:00 +0000 UTC
�[34mTRACE�[0m[07-28|15:58:14.000] Found seed node in database              �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000 �[34mage�[0m=460839h58m14.000570125s
�[32mINFO �[0m[07-28|15:58:14.001] New local node record                    �[32mseq�[0m=1,659,023,894,000 �[32mid�[0m=2bafb0e551d5005f �[32mip�[0m=10.192.21.133 �[32mudp�[0m=12000 �[32mtcp�[0m=13000
�[34mTRACE�[0m[07-28|15:58:14.001] Found seed node in database              �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000 �[34mage�[0m=460839h58m14.001983244s
�[34mTRACE�[0m[07-28|15:58:14.001] Found seed node in database              �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000   �[34mage�[0m=460839h58m14.002001822s
�[34mTRACE�[0m[07-28|15:58:14.002] Found seed node in database              �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000  �[34mage�[0m=460839h58m14.002016556s
time="2022-07-28 15:58:14" level=info msg="Started discovery v5" ENR="enr:-MK4QFQdFj8BZ4baXPAwB_y_HQrFx-5j-UHfkw6L6ZYZ_da2dmpSXShh4QS5XEAJPdw2gj6nrdrLFw3P5RjPlCHLJjeGAYJFh6Xwh2F0dG5ldHOIAAAAAAAAAACEZXRoMpCC9KcrAgAQIP__________gmlkgnY0gmlwhArAFYWJc2VjcDI1NmsxoQIRL3llifwtm_kT8s9KN1yDSRX_9pJj7-k2yuMaJQ4mXohzeW5jbmV0cwCDdGNwgjLIg3VkcIIu4A" prefix=p2p
�[34mTRACE�[0m[07-28|15:58:14.002] Found seed node in database              �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000  �[34mage�[0m=460839h58m14.002302651s
�[34mTRACE�[0m[07-28|15:58:14.002] Found seed node in database              �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000 �[34mage�[0m=460839h58m14.002325456s
�[34mTRACE�[0m[07-28|15:58:14.002] Found seed node in database              �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000   �[34mage�[0m=460839h58m14.0023406s
�[34mTRACE�[0m[07-28|15:58:14.002] Found seed node in database              �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000  �[34mage�[0m=460839h58m14.002356679s
�[34mTRACE�[0m[07-28|15:58:14.002] >> FINDNODE/v5                           �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000
�[34mTRACE�[0m[07-28|15:58:14.002] >> FINDNODE/v5                           �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000
�[34mTRACE�[0m[07-28|15:58:14.002] >> FINDNODE/v5                           �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000
time="2022-07-28 15:58:14" level=info msg="Node started p2p server" multiAddr="/ip4/10.192.21.133/tcp/13000/p2p/16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD" prefix=p2p
2022-07-28T15:58:14.002Z	DEBUG	basichost	basic/basic_host.go:771	host 16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD dialing 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj
2022-07-28T15:58:14.002Z	DEBUG	basichost	basic/basic_host.go:771	host 16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD dialing 16Uiu2HAmTttt9ZTmCmwmKiV3QR7iTAfnAckwzhswrNmWkthi6meB
2022-07-28T15:58:14.002Z	DEBUG	basichost	basic/basic_host.go:771	host 16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD dialing 16Uiu2HAm2quPWmMyE7yaXaW7LSTkUaUpnw95kXaYLkDtipGBkdsT
2022-07-28T15:58:14.002Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:241	dialing peer	{"from": "16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD", "to": "16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj"}
2022-07-28T15:58:14.002Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:241	dialing peer	{"from": "16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD", "to": "16Uiu2HAm2quPWmMyE7yaXaW7LSTkUaUpnw95kXaYLkDtipGBkdsT"}
2022-07-28T15:58:14.002Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:241	dialing peer	{"from": "16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD", "to": "16Uiu2HAmTttt9ZTmCmwmKiV3QR7iTAfnAckwzhswrNmWkthi6meB"}
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/135.181.182.51/tcp/9000
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:161	[limiter] taking FD token: peer: 16Uiu2HAmTttt9ZTmCmwmKiV3QR7iTAfnAckwzhswrNmWkthi6meB; addr: /ip4/135.181.182.51/tcp/9000; prev consuming: 0
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:167	[limiter] executing dial; peer: 16Uiu2HAmTttt9ZTmCmwmKiV3QR7iTAfnAckwzhswrNmWkthi6meB; addr: /ip4/135.181.182.51/tcp/9000; FD consuming: 1; waiting: 0
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/52.77.252.254/tcp/9000
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:161	[limiter] taking FD token: peer: 16Uiu2HAm2quPWmMyE7yaXaW7LSTkUaUpnw95kXaYLkDtipGBkdsT; addr: /ip4/52.77.252.254/tcp/9000; prev consuming: 1
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:167	[limiter] executing dial; peer: 16Uiu2HAm2quPWmMyE7yaXaW7LSTkUaUpnw95kXaYLkDtipGBkdsT; addr: /ip4/52.77.252.254/tcp/9000; FD consuming: 2; waiting: 0
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:193	[limiter] adding a dial job through limiter: /ip4/135.181.181.239/tcp/9000
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:161	[limiter] taking FD token: peer: 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj; addr: /ip4/135.181.181.239/tcp/9000; prev consuming: 2
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:167	[limiter] executing dial; peer: 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj; addr: /ip4/135.181.181.239/tcp/9000; FD consuming: 3; waiting: 0
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:386	16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD swarm dialing 16Uiu2HAmTttt9ZTmCmwmKiV3QR7iTAfnAckwzhswrNmWkthi6meB /ip4/135.181.182.51/tcp/9000
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:386	16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD swarm dialing 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj /ip4/135.181.181.239/tcp/9000
2022-07-28T15:58:14.003Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:386	16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD swarm dialing 16Uiu2HAm2quPWmMyE7yaXaW7LSTkUaUpnw95kXaYLkDtipGBkdsT /ip4/52.77.252.254/tcp/9000
�[32mINFO �[0m[07-28|15:58:14.003] New local node record                    �[32mseq�[0m=1,659,023,894,001 �[32mid�[0m=2bafb0e551d5005f �[32mip�[0m=10.192.21.133 �[32mudp�[0m=12000 �[32mtcp�[0m=13000
time="2022-07-28 15:58:14" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -KG4QCIzJZTY_fs_2vqWEatJL9RrtnPwDCv-jRBuO5FQ2qBrfJubWOWazri6s9HsyZdu-fRUfEzkebhf1nvO42_FVzwDhGV0aDKQed8EKAAAECD__________4JpZIJ2NIJpcISHtbYziXNlY3AyNTZrMaED4m9AqVs6F32rSCGsjtYcsyfQE2K8nDiGmocUY_iq-TSDdGNwgiMog3VkcIIjKA==: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
time="2022-07-28 15:58:14" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -LK4QH1xnjotgXwg25IDPjrqRGFnH1ScgNHA3dv1Z8xHCp4uP3N3Jjl_aYv_WIxQRdwZvSukzbwspXZ7JjpldyeVDzMCh2F0dG5ldHOIAAAAAAAAAACEZXRoMpB53wQoAAAQIP__________gmlkgnY0gmlwhIe1te-Jc2VjcDI1NmsxoQOkcGXqbCJYbcClZ3z5f6NWhX_1YPFRYRRWQpJjwSHpVIN0Y3CCIyiDdWRwgiMo: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
time="2022-07-28 15:58:14" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -LK4QLINdtobGquK7jukLDAKmsrH2ZuHM4k0TklY5jDTD4ZgfxR9weZmo5Jwu81hlKu3qPAvk24xHGBDjYs4o8f1gZ0Bh2F0dG5ldHOIAAAAAAAAAACEZXRoMpB53wQoAAAQIP__________gmlkgnY0gmlwhDRN_P6Jc2VjcDI1NmsxoQJuNujTgsJUHUgVZML3pzrtgNtYg7rQ4K1tkWERgl0DdoN0Y3CCIyiDdWRwgiMo: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
�[34mTRACE�[0m[07-28|15:58:14.003] >> FINDNODE/v5                           �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000
2022-07-28T15:58:14.108Z	DEBUG	reuseport-transport	com_github_libp2p_go_reuseport_transport/reuseport.go:31	failed to reuse port, will try again with a random port: dial tcp4 0.0.0.0:13000->135.181.181.239:9000: connect: connection refused
2022-07-28T15:58:14.213Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:73	[limiter] freeing FD token; waiting: 0; consuming: 3
2022-07-28T15:58:14.213Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:100	[limiter] freeing peer token; peer 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj; addr: /ip4/135.181.181.239/tcp/9000; active for peer: 1; waiting on peer limit: 0
2022-07-28T15:58:14.213Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/swarm_dial.go:266	network for 16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD finished dialing 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj
2022-07-28T15:58:14.213Z	DEBUG	swarm2	com_github_libp2p_go_libp2p_swarm/limiter.go:201	[limiter] clearing all peer dials: 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj
time="2022-07-28 15:58:14" level=trace msg="Could not connect with peer {16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj: [/ip4/135.181.181.239/tcp/9000]}" error="failed to dial 16Uiu2HAmPitcpwsGZf1vGiu6hdwZHsVLyFzVZeNqaSmUaSyM7Xvj:
  * [/ip4/135.181.181.239/tcp/9000] dial tcp4 135.181.181.239:9000: connect: connection refused" prefix=p2p
�[34mTRACE�[0m[07-28|15:58:14.703] FINDNODE failed                          �[34mid�[0m=2066746905d616b2 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:14.703] >> FINDNODE/v5                           �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000
�[34mTRACE�[0m[07-28|15:58:14.703] FINDNODE failed                          �[34mid�[0m=e7c268588f3983b9 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:14.703] >> FINDNODE/v5                           �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000
�[34mTRACE�[0m[07-28|15:58:14.703] >> FINDNODE/v5                           �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000
�[34mTRACE�[0m[07-28|15:58:14.703] FINDNODE failed                          �[34mid�[0m=89c01940262d81f2 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:14.703] >> FINDNODE/v5                           �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000
�[34mTRACE�[0m[07-28|15:58:14.703] FINDNODE failed                          �[34mid�[0m=b24bac2e191b48e5 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:15.404] FINDNODE failed                          �[34mid�[0m=b24bac2e191b48e5 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:15.404] FINDNODE failed                          �[34mid�[0m=89c01940262d81f2 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:15.404] FINDNODE failed                          �[34mid�[0m=e7c268588f3983b9 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:15.404] FINDNODE failed                          �[34mid�[0m=2066746905d616b2 �[34mfailcount�[0m=1 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
time="2022-07-28 15:58:15" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -LK4QLINdtobGquK7jukLDAKmsrH2ZuHM4k0TklY5jDTD4ZgfxR9weZmo5Jwu81hlKu3qPAvk24xHGBDjYs4o8f1gZ0Bh2F0dG5ldHOIAAAAAAAAAACEZXRoMpB53wQoAAAQIP__________gmlkgnY0gmlwhDRN_P6Jc2VjcDI1NmsxoQJuNujTgsJUHUgVZML3pzrtgNtYg7rQ4K1tkWERgl0DdoN0Y3CCIyiDdWRwgiMo: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
time="2022-07-28 15:58:15" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -LK4QH1xnjotgXwg25IDPjrqRGFnH1ScgNHA3dv1Z8xHCp4uP3N3Jjl_aYv_WIxQRdwZvSukzbwspXZ7JjpldyeVDzMCh2F0dG5ldHOIAAAAAAAAAACEZXRoMpB53wQoAAAQIP__________gmlkgnY0gmlwhIe1te-Jc2VjcDI1NmsxoQOkcGXqbCJYbcClZ3z5f6NWhX_1YPFRYRRWQpJjwSHpVIN0Y3CCIyiDdWRwgiMo: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
�[34mTRACE�[0m[07-28|15:58:15.404] >> FINDNODE/v5                           �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000
time="2022-07-28 15:58:15" level=trace msg="Fork ENR mismatches between peer and local node" error="fork digest of peer with ENR -KG4QCIzJZTY_fs_2vqWEatJL9RrtnPwDCv-jRBuO5FQ2qBrfJubWOWazri6s9HsyZdu-fRUfEzkebhf1nvO42_FVzwDhGV0aDKQed8EKAAAECD__________4JpZIJ2NIJpcISHtbYziXNlY3AyNTZrMaED4m9AqVs6F32rSCGsjtYcsyfQE2K8nDiGmocUY_iq-TSDdGNwgiMog3VkcIIjKA==: [121 223 4 40], does not match local value: [130 244 167 43]" prefix=p2p
�[34mTRACE�[0m[07-28|15:58:15.404] >> FINDNODE/v5                           �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000
�[34mTRACE�[0m[07-28|15:58:15.404] >> FINDNODE/v5                           �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000
�[34mTRACE�[0m[07-28|15:58:15.404] >> FINDNODE/v5                           �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000
�[34mTRACE�[0m[07-28|15:58:16.105] FINDNODE failed                          �[34mid�[0m=89c01940262d81f2 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.105] FINDNODE failed                          �[34mid�[0m=e7c268588f3983b9 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.105] >> FINDNODE/v5                           �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000
�[34mTRACE�[0m[07-28|15:58:16.105] >> FINDNODE/v5                           �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000
�[34mTRACE�[0m[07-28|15:58:16.105] FINDNODE failed                          �[34mid�[0m=2066746905d616b2 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.105] >> FINDNODE/v5                           �[34mid�[0m=2066746905d616b2 �[34maddr�[0m=18.223.219.100:7000
�[34mTRACE�[0m[07-28|15:58:16.105] >> FINDNODE/v5                           �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000
�[34mTRACE�[0m[07-28|15:58:16.105] FINDNODE failed                          �[34mid�[0m=b24bac2e191b48e5 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.806] FINDNODE failed                          �[34mid�[0m=89c01940262d81f2 �[34mfailcount�[0m=3 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.806] FINDNODE failed                          �[34mid�[0m=2066746905d616b2 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.806] FINDNODE failed                          �[34mid�[0m=b24bac2e191b48e5 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.806] >> FINDNODE/v5                           �[34mid�[0m=b24bac2e191b48e5 �[34maddr�[0m=135.181.181.239:9000
�[34mTRACE�[0m[07-28|15:58:16.806] >> FINDNODE/v5                           �[34mid�[0m=89c01940262d81f2 �[34maddr�[0m=52.77.252.254:9000
�[34mTRACE�[0m[07-28|15:58:16.806] FINDNODE failed                          �[34mid�[0m=e7c268588f3983b9 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"
�[34mTRACE�[0m[07-28|15:58:16.806] >> FINDNODE/v5                           �[34mid�[0m=e7c268588f3983b9 �[34maddr�[0m=135.181.182.51:9000

Here are the responses from a couple prysm endpoints

/ # curl http://localhost:3500/eth/v1/beacon/genesis
{"data":{"genesis_time":"1616508000","genesis_validators_root":"0x043db0d9a83813551ee2f33450d23797757d430911a9320530ad8a0eabc43efb","genesis_fork_version":"0x00001020"}}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/node/peers
{"data":[]}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/config/spec
{"data":{"ALTAIR_FORK_EPOCH":"36660","ALTAIR_FORK_VERSION":"0x01001020","BASE_REWARD_FACTOR":"64","BELLATRIX_FORK_EPOCH":"18446744073709551615","BELLATRIX_FORK_VERSION":"0x02001020","BLS_WITHDRAWAL_PREFIX":"0x00","CHURN_LIMIT_QUOTIENT":"65536","CONFIG_NAME":"prater","DEPOSIT_CHAIN_ID":"5","DEPOSIT_CONTRACT_ADDRESS":"0xff50ed3d0ec03aC01D4C79aAd74928BFF48a7b2b","DEPOSIT_NETWORK_ID":"5","DOMAIN_AGGREGATE_AND_PROOF":"0x06000000","DOMAIN_APPLICATION_MASK":"0x00000001","DOMAIN_BEACON_ATTESTER":"0x01000000","DOMAIN_BEACON_PROPOSER":"0x00000000","DOMAIN_CONTRIBUTION_AND_PROOF":"0x09000000","DOMAIN_DEPOSIT":"0x03000000","DOMAIN_RANDAO":"0x02000000","DOMAIN_SELECTION_PROOF":"0x05000000","DOMAIN_SYNC_COMMITTEE":"0x07000000","DOMAIN_SYNC_COMMITTEE_SELECTION_PROOF":"0x08000000","DOMAIN_VOLUNTARY_EXIT":"0x04000000","EFFECTIVE_BALANCE_INCREMENT":"1000000000","EJECTION_BALANCE":"16000000000","EPOCHS_PER_ETH1_VOTING_PERIOD":"64","EPOCHS_PER_HISTORICAL_VECTOR":"65536","EPOCHS_PER_RANDOM_SUBNET_SUBSCRIPTION":"256","EPOCHS_PER_SLASHINGS_VECTOR":"8192","EPOCHS_PER_SYNC_COMMITTEE_PERIOD":"256","ETH1_FOLLOW_DISTANCE":"2048","GENESIS_DELAY":"1919188","GENESIS_FORK_VERSION":"0x00001020","HISTORICAL_ROOTS_LIMIT":"16777216","HYSTERESIS_DOWNWARD_MULTIPLIER":"1","HYSTERESIS_QUOTIENT":"4","HYSTERESIS_UPWARD_MULTIPLIER":"5","INACTIVITY_PENALTY_QUOTIENT":"67108864","INACTIVITY_PENALTY_QUOTIENT_ALTAIR":"50331648","INACTIVITY_PENALTY_QUOTIENT_BELLATRIX":"16777216","INACTIVITY_SCORE_BIAS":"4","INACTIVITY_SCORE_RECOVERY_RATE":"16","INTERVALS_PER_SLOT":"3","MAX_ATTESTATIONS":"128","MAX_ATTESTER_SLASHINGS":"2","MAX_COMMITTEES_PER_SLOT":"64","MAX_DEPOSITS":"16","MAX_EFFECTIVE_BALANCE":"32000000000","MAX_PROPOSER_SLASHINGS":"16","MAX_SEED_LOOKAHEAD":"4","MAX_VALIDATORS_PER_COMMITTEE":"2048","MAX_VOLUNTARY_EXITS":"16","MIN_ATTESTATION_INCLUSION_DELAY":"1","MIN_DEPOSIT_AMOUNT":"1000000000","MIN_EPOCHS_TO_INACTIVITY_PENALTY":"4","MIN_GENESIS_ACTIVE_VALIDATOR_COUNT":"16384","MIN_GENESIS_TIME":"1614588812","MIN_PER_EPOCH_CHURN_LIMIT":"4","MIN_SEED_LOOKAHEAD":"1","MIN_SLASHING_PENALTY_QUOTIENT":"128","MIN_SLASHING_PENALTY_QUOTIENT_ALTAIR":"64","MIN_SLASHING_PENALTY_QUOTIENT_BELLATRIX":"32","MIN_SYNC_COMMITTEE_PARTICIPANTS":"1","MIN_VALIDATOR_WITHDRAWABILITY_DELAY":"256","PRESET_BASE":"mainnet","PROPORTIONAL_SLASHING_MULTIPLIER":"1","PROPORTIONAL_SLASHING_MULTIPLIER_ALTAIR":"2","PROPORTIONAL_SLASHING_MULTIPLIER_BELLATRIX":"3","PROPOSER_REWARD_QUOTIENT":"8","PROPOSER_SCORE_BOOST":"40","PROPOSER_WEIGHT":"8","RANDOM_SUBNETS_PER_VALIDATOR":"1","SAFE_SLOTS_TO_IMPORT_OPTIMISTICALLY":"0","SAFE_SLOTS_TO_UPDATE_JUSTIFIED":"8","SECONDS_PER_ETH1_BLOCK":"14","SECONDS_PER_SLOT":"12","SHARDING_FORK_EPOCH":"18446744073709551615","SHARDING_FORK_VERSION":"0x03001020","SHARD_COMMITTEE_PERIOD":"256","SHUFFLE_ROUND_COUNT":"90","SLOTS_PER_EPOCH":"32","SLOTS_PER_HISTORICAL_ROOT":"8192","SYNC_COMMITTEE_SIZE":"512","SYNC_COMMITTEE_SUBNET_COUNT":"4","SYNC_REWARD_WEIGHT":"2","TARGET_AGGREGATORS_PER_COMMITTEE":"16","TARGET_AGGREGATORS_PER_SYNC_SUBCOMMITTEE":"16","TARGET_COMMITTEE_SIZE":"128","TERMINAL_BLOCK_HASH":"0x0000000000000000000000000000000000000000000000000000000000000000","TERMINAL_BLOCK_HASH_ACTIVATION_EPOCH":"18446744073709551615","TERMINAL_TOTAL_DIFFICULTY":"4294967296","TIMELY_HEAD_FLAG_INDEX":"0x02","TIMELY_HEAD_WEIGHT":"14","TIMELY_SOURCE_FLAG_INDEX":"0x00","TIMELY_SOURCE_WEIGHT":"14","TIMELY_TARGET_FLAG_INDEX":"0x01","TIMELY_TARGET_WEIGHT":"26","VALIDATOR_REGISTRY_LIMIT":"1099511627776","WEIGHT_DENOMINATOR":"64","WHISTLEBLOWER_REWARD_QUOTIENT":"512"}}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/beacon/headers
{"data":[{"root":"0x8c0ebce425ca04612f8a4c9b3d9b339121a62a8fe2baf8ff2c6f77b81194ee87","canonical":false,"header":{"message":{"slot":"0","proposer_index":"0","parent_root":"0x0000000000000000000000000000000000000000000000000000000000000000","state_root":"0x895390e92edc03df7096e9f51e51896e8dbe6e7e838180dadbfd869fdd77a659","body_root":"0xccb62460692be0ec813b56be97f68a82cf57abc102e27bf49ebf4190ff22eedd"},"signature":"0x000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000"}}],"execution_optimistic":false}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/beacon/states/genesis/root
{"data":{"root":"0x895390e92edc03df7096e9f51e51896e8dbe6e7e838180dadbfd869fdd77a659"},"execution_optimistic":false}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/node/identity
{"data":{"peer_id":"16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD","enr":"enr:-MK4QIrlzfObBbQtK2PjVAxtkhN7UO966scKLRr-m9y1NLMEFholHA2rbj_y2IFLMj3vx8PwH6oaw_UulcNffY7WfXaGAYJFh6Xxh2F0dG5ldHOIAAAAAAAAAACEZXRoMpCC9KcrAgAQIP__________gmlkgnY0gmlwhArAFYWJc2VjcDI1NmsxoQIRL3llifwtm_kT8s9KN1yDSRX_9pJj7-k2yuMaJQ4mXohzeW5jbmV0cwCDdGNwgjLIg3VkcIIu4A==","p2p_addresses":["/ip4/10.192.21.133/tcp/13000/p2p/16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD"],"discovery_addresses":["/ip4/10.192.21.133/udp/12000/p2p/16Uiu2HAkvaktzjwag3aqF9SxQ7vaN5aptRcmqMMLnhDYwcRV5rLD"],"metadata":{"seq_number":"1","attnets":"0x0000000000000000"}}}/ # 
/ # 
/ # curl http://localhost:3500/eth/v1/node/version
{"data":{"version":"Prysm/v2.1.3 (linux amd64)"}}/ # 
/ # 
/ # 

@nisdas
Copy link
Member

nisdas commented Jul 29, 2022

Assuming you are using the correct genesis file as mentioned above, is port 12000 open ? We use that for discovery via UDP

@JustinAvaLabs
Copy link

Is that required to gather outbound peers? We are using the same config in all of our clusters, which contain secure components. Our other clusters were able to acquire an acceptable amount of outbound peers without opening inbound ports

@nisdas
Copy link
Member

nisdas commented Jul 29, 2022

It isnt required, but it does appear something is blocking outbound udp packets in your cluster. So I am not too sure:

�[34mTRACE�[0m[07-28|15:58:16.105] FINDNODE failed                          �[34mid�[0m=89c01940262d81f2 �[34mfailcount�[0m=2 �[34mdropped�[0m=false �[34merr�[0m="RPC timeout"

@JustinAvaLabs
Copy link

@nisdas I was able to confirm that outbound UDP works fine. There is nothing blocking and test packets went through.
Also, all other outbound traffic is working fine.

Any other suggestions?

@JustinAvaLabs
Copy link

If I manually add a long list of peers, I am able to retain a couple and start processing blocks.

time="2022-07-29 18:55:13" level=info msg="Raised fd limit to 1048576 from 1048576"
time="2022-07-29 18:55:13" level=warning msg="Running on the Prater Testnet" prefix=flags
time="2022-07-29 18:55:13" level=info msg="Checking DB" database-path="/root/.eth2/beaconchaindata" prefix=node
time="2022-07-29 18:55:13" level=info msg="Opening Bolt DB at /root/.eth2/beaconchaindata/beaconchain.db" prefix=db
time="2022-07-29 18:55:16" level=info msg="Deposit contract: 0xff50ed3d0ec03ac01d4c79aad74928bff48a7b2b" prefix=node
time="2022-07-29 18:55:17" level=info msg="Running node with peer id of 16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 " prefix=p2p
time="2022-07-29 18:55:17" level=info msg="--weak-subjectivity-checkpoint not provided. Prysm recommends providing a weak subjectivity checkpointfor nodes synced from genesis, or manual verification of block and state roots for checkpoint sync nodes." prefix=blockchain
time="2022-07-29 18:55:17" level=info msg="Waiting for state to be initialized" prefix=initial-sync
time="2022-07-29 18:55:17" level=info msg="gRPC server listening on port" address="0.0.0.0:4000" prefix=rpc
time="2022-07-29 18:55:17" level=warning msg="You are using an insecure gRPC server. If you are running your beacon node and validator on the same machines, you can ignore this message. If you want to know how to enable secure connections, see: https://docs.prylabs.network/docs/prysm-usage/secure-grpc" prefix=rpc
time="2022-07-29 18:55:17" level=info msg="Starting beacon node" prefix=node version="Prysm/v2.1.3/4de92bafc4bb0051381fba48eb36830aa181d7ee. Built at: 2022-07-06 19:14:48+00:00"
time="2022-07-29 18:55:17" level=info msg="Blockchain data already exists in DB, initializing..." prefix=blockchain
time="2022-07-29 18:55:17" level=info msg="Cleaning up dirty states" count=1 prefix=db
time="2022-07-29 18:55:17" level=info msg="Starting API middleware" prefix=gateway
time="2022-07-29 18:55:17" level=info msg="Starting gRPC gateway" address="127.0.0.1:3500" prefix=gateway
time="2022-07-29 18:55:18" level=info msg="Starting initial chain sync..." prefix=initial-sync
time="2022-07-29 18:55:18" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0
time="2022-07-29 18:55:18" level=info msg="Started discovery v5" ENR="enr:-MK4QOqm_kb4ntJ0NW4wx_ZLkX0KROh5UsuOlWmviBIePh73ZBY8VPP9k9jLjhgKzucKp8zfj8i04cfoXFjFFO5F-HCGAYJLUCBZh2F0dG5ldHOIAAAAAAAAAACEZXRoMpCC9KcrAgAQIP__________gmlkgnY0gmlwhArACw-Jc2VjcDI1NmsxoQLoP-nWMmD9YuiEjjqy5LRt7OW7xgB9TA-5UjlybBcVgIhzeW5jbmV0cwCDdGNwgjLIg3VkcIIu4A" prefix=p2p
time="2022-07-29 18:55:18" level=info msg="Node started p2p server" multiAddr="/ip4/10.192.11.15/tcp/13000/p2p/16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3" prefix=p2p
2022-07-29T18:55:19.123Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAm3ohGqGjZVdHnqp2AVTrLkB617J4KQXJf6KF7yrL8r183 mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.127Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAmL9mivATwKZp3anWgeMQZ2fzyLsDbt8wu5cdgrJ43mA8k mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.128Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAm1shsRmqUUQEa35yRYMoyCbRSLes3iQkPMp3imv7cZYQV mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.130Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAmHzwXQCJco3feL8iRFc7hdSmC1f4GdieMZANdVNxBLan5 mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.133Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAmK8Lnm1T4t6CdySsSDTDsWYjpz65H3RZur54vzmB62zdp mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.134Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAm33BSCo5Lq6X58RrqQiT8JmKmFq2XHuURgRJVwuQUiji7 mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.135Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAmHaD5LLrDGYjW3fZ9QdpYpKYVrVA4ViG5VFzu3TRiN8AJ mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.135Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAm6JaCmYNqphGjUKXWCPLsiRYFJkryLHiU4t8nrY2UuoTk mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
2022-07-29T18:55:19.137Z    ERROR   net/identify    identify/id.go:696  16Uiu2HAmB4H6FBPWdY74kHgZwzjYuExdQ8Z5rihGqxfKAsDTXTY3 received key for remote peer 16Uiu2HAm9DMoorfHJGni7jxhH5yPcJaYfrg4YDi8vori2aFNzNnk mismatch: 16Uiu2HAm3qabKGir2djfGvUUvqsY3o2D9kgD9TMHZuBmrVpvx3uZ
time="2022-07-29 18:55:26" level=info msg="Processing block batch of size 29 starting from  0xaacde822... 3937/3551077 - estimated time remaining 679h31m43s" blocksPerSecond=1.4 peers=18 prefix=initial-sync
time="2022-07-29 18:55:32" level=info msg="Connected to new endpoint: http://localhost:8545" prefix=powchain
time="2022-07-29 18:55:47" level=info msg="Processing block batch of size 61 starting from  0x2470e8ef... 3968/3551078 - estimated time remaining 323h3m6s" blocksPerSecond=3.0 peers=7 prefix=initial-sync
time="2022-07-29 18:55:55" level=info msg="Processing block batch of size 59 starting from  0x81318a30... 4032/3551079 - estimated time remaining 164h12m54s" blocksPerSecond=6.0 peers=7 prefix=initial-sync
time="2022-07-29 18:56:01" level=info msg="Processing block batch of size 61 starting from  0x6c2cdfec... 4097/3551080 - estimated time remaining 108h52m11s" blocksPerSecond=9.1 peers=7 prefix=initial-sync
time="2022-07-29 18:56:08" level=info msg="Processing block batch of size 62 starting from  0x918de32c... 4160/3551080 - estimated time remaining 108h16m11s" blocksPerSecond=9.1 peers=6 prefix=initial-sync
time="2022-07-29 18:56:14" level=info msg="Saved state in DB" prefix=state-gen root=b02bcc109576 slot=4095
time="2022-07-29 18:56:14" level=info msg="Processing block batch of size 59 starting from  0x75427693... 4224/3551081 - estimated time remaining 81h45m44s" blocksPerSecond=12.1 peers=6 prefix=initial-sync
time="2022-07-29 18:56:18" level=info msg="Peer summary" activePeers=6 inbound=0 outbound=6 prefix=p2p
time="2022-07-29 18:56:21" level=info msg="Processing block batch of size 62 starting from  0x41e3b3d1... 4288/3551081 - estimated time remaining 107h40m27s" blocksPerSecond=9.2 peers=6 prefix=initial-sync
time="2022-07-29 18:56:27" level=info msg="Processing block batch of size 62 starting from  0xfde998c9... 4352/3551082 - estimated time remaining 80h25m28s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:56:33" level=info msg="Processing block batch of size 61 starting from  0x6e7b67c5... 4416/3551082 - estimated time remaining 80h45m10s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:56:39" level=info msg="Processing block batch of size 60 starting from  0x570db0e6... 4481/3551083 - estimated time remaining 80h25m18s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:56:46" level=info msg="Processing block batch of size 63 starting from  0x8ef18f44... 4544/3551083 - estimated time remaining 80h5m36s" blocksPerSecond=12.3 peers=6 prefix=initial-sync
time="2022-07-29 18:56:52" level=info msg="Processing block batch of size 61 starting from  0x0a33c167... 4608/3551084 - estimated time remaining 80h25m8s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:56:58" level=info msg="Processing block batch of size 63 starting from  0x3bdf6e3b... 4672/3551084 - estimated time remaining 79h45m58s" blocksPerSecond=12.3 peers=6 prefix=initial-sync
time="2022-07-29 18:57:04" level=info msg="Processing block batch of size 61 starting from  0x2ab80240... 4737/3551085 - estimated time remaining 79h26m35s" blocksPerSecond=12.4 peers=6 prefix=initial-sync
time="2022-07-29 18:57:10" level=info msg="Processing block batch of size 61 starting from  0x054ed6c5... 4800/3551085 - estimated time remaining 80h5m15s" blocksPerSecond=12.3 peers=6 prefix=initial-sync
time="2022-07-29 18:57:16" level=info msg="Processing block batch of size 60 starting from  0x0947ecd1... 4864/3551086 - estimated time remaining 80h24m47s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:57:18" level=info msg="Peer summary" activePeers=6 inbound=0 outbound=6 prefix=p2p
time="2022-07-29 18:57:22" level=info msg="Processing block batch of size 62 starting from  0x254e0f47... 4928/3551086 - estimated time remaining 80h44m28s" blocksPerSecond=12.2 peers=6 prefix=initial-sync
time="2022-07-29 18:57:28" level=info msg="Processing block batch of size 63 starting from  0xc38e8a60... 4992/3551087 - estimated time remaining 80h5m0s" blocksPerSecond=12.3 peers=6 prefix=initial-sync
time="2022-07-29 18:57:35" level=info msg="Processing block batch of size 59 starting from  0x3ab064db... 5056/3551087 - estimated time remaining 80h44m18s" blocksPerSecond=12.2 peers=6 prefix=initial-sync

@JustinAvaLabs
Copy link

I worry that these peers will drop over time and the node will not be able to recover. Any ideas on what might be causing the peer discovery to fail in this way?

@JustinAvaLabs
Copy link

As suspected, the peers dropped off one by one and eventually the node stopped bootstrapping because of a lack of suitable peers.

@nisdas
Copy link
Member

nisdas commented Jul 30, 2022

The same helm chart/config works fine in 3 of my other clusters, but constantly fails in one.

I am not too sure, the fact that your 3 other clusters work might point to some specific issues with firewalls in the current cluster. How did you test the UDP networking ? Were you able to make a roundtrip connection with a remote peer ? Ex:

cluster --> remote peer ( successfully sent outbound packet) 
cluster <-- remote peer ( successfully received response packet)

The error logs do indicate that it isn't able to get a response back from the bootnodes.

@00ssh
Copy link

00ssh commented Sep 6, 2022

I am getting the same repeating pattern in the logs. It does not seem to surpass 2 peers in the last 2 hours. I'm trying Goerli.

time="2022-09-06 09:50:28" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0
time="2022-09-06 09:50:30" level=warning msg="Unable to cache headers for execution client votes" error="(1662375902 > 1660182298): provided time is later than the current eth1 head" prefix=powchain
time="2022-09-06 09:50:33" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0
time="2022-09-06 09:50:38" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0
time="2022-09-06 09:50:43" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=3 suitable=0```

@web3d3v
Copy link

web3d3v commented Nov 1, 2022

I'm on arch linux, latest prysm, latest geth.

Managed to sync up to latest about a week ago, afterwards gracefully shutdown. Since then for a week:

Waiting for enough suitable peers before syncing required=3 suitable=0

Increasing --p2p-max-peers did not solve the issue. Deleting .eth2 and trying to start over did not solve the issue either.

@nisdas
Copy link
Member

nisdas commented Feb 1, 2023

For those stuck on this, either you are running for goerli incorrectly. The correct way is detailed here:
https://docs.prylabs.network/docs/install/install-with-bazel#run-a-beacon-node

If not, it would most likely point to an issue with your firewall. If you have verified the above both are fine and you are still having issues, feel free to ping this issue and I will reopen it. If not, I am closing the issue for now.

@nisdas nisdas closed this as completed Feb 1, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants