Beacon Chain v1.0.0-alpha.5 Cannot Connect to Eth1 Node

[metanull-operator]

🐞 Bug Report

Description

Beacon chain running alpha.5 unable to connect to my Goerli eth1 node, but second beacon chain running alpha.4 continues to connect to eth1 node successfully.

Has this worked before in a previous version?

Yes, the previous version in which this bug was not present was: v1.0.0-alpha.4

🔬 Minimal Reproduction

beacon-chain --datadir=/home/eth2/prysm --min-sync-peers=7 --p2p-max-peers=200 --monitoring-port 8080 --p2p-tcp-port 13001 --p2p-udp-port 12001 --rpc-port 4000 --p2p-host-ip=XXX.XXX.XXX.XXX --http-web3provider http://192.168.XXX.XXX:8545 --web3provider ws://192.168.XXX.XXX:8546 --peer /ip4/192.168.XXX.XXX/tcp/13000/p2p/16Uiu2HAmVauqo3yKF6kXxD1qaqXg3wD9kdaD12HGRr3MshMpo75J

I did not modify this comment between running alpha.4 and alpha.5.

🔥 Error

Apr 22 11:34:57 beacon02 beacon-chain[917]: 2020/04/22 11:34:57 maxprocs: Leaving GOMAXPROCS=6: CPU quota undefined
Apr 22 11:34:57 beacon02 beacon-chain[917]: time="2020-04-22 11:34:57" level=warning msg="Using default mainnet config" prefix=flags
Apr 22 11:34:57 beacon02 beacon-chain[917]: time="2020-04-22 11:34:57" level=info msg="Checking DB" database-path="/home/eth2/prysm/beaconchaindata" prefix=node
Apr 22 11:34:58 beacon02 beacon-chain[917]: time="2020-04-22 11:34:58" level=info msg="Starting beacon node" prefix=node version="Prysm/Git commit: f880fb4ee404e9dd6a7d5de06c387c8e8ba865b7. Built at: 2020-04-22 04:19:12+00:00"
Apr 22 11:34:58 beacon02 beacon-chain[917]: time="2020-04-22 11:34:58" level=info msg="RPC-API listening on port" address="0.0.0.0:4000" prefix=rpc
Apr 22 11:34:58 beacon02 beacon-chain[917]: time="2020-04-22 11:34:58" level=warning msg="You are using an insecure gRPC connection! Provide a certificate and key to connect securely" prefix=rpc
Apr 22 11:34:58 beacon02 beacon-chain[917]: time="2020-04-22 11:34:58" level=info msg="Connected to eth1 proof-of-work chain" endpoint="ws://192.168.XXX.XXX:8546" prefix=powchain
Apr 22 11:34:58 beacon02 beacon-chain[917]: time="2020-04-22 11:34:58" level=info msg="Waiting to reach the validator deposit threshold to start the beacon chain..." prefix=blockchain
Apr 22 11:35:00 beacon02 beacon-chain[917]: time="2020-04-22 11:35:00" level=warning msg="eth1 client is not syncing" prefix=powchain

Log ends there. Eth1 client IS syncing though:

Apr 22 11:02:53 eth01 geth[522]: INFO [04-22|11:02:53.805] Imported new chain segment               blocks=1 txs=0   mgas=0.000 elapsed=2.252ms   mgasps=0.000   number=2569509 hash=4438b9…42ed58 dirty=3.45MiB
Apr 22 11:03:07 eth01 geth[522]: INFO [04-22|11:03:07.121] Imported new chain segment               blocks=1 txs=0   mgas=0.000 elapsed=2.263ms   mgasps=0.000   number=2569510 hash=ebe97f…1009ce dirty=3.45MiB
Apr 22 11:03:22 eth01 geth[522]: INFO [04-22|11:03:22.557] Imported new chain segment               blocks=1 txs=0   mgas=0.000 elapsed=2.759ms   mgasps=0.000   number=2569511 hash=2d60e9…b22847 dirty=3.43MiB
Apr 22 11:03:24 eth01 geth[522]: INFO [04-22|11:03:24.459] Chain reorg detected                     number=2569510 hash=ebe97f…1009ce drop=1 dropfrom=2d60e9…b22847 add=1 addfrom=1cf79e…f7236b
Apr 22 11:03:24 eth01 geth[522]: INFO [04-22|11:03:24.462] Imported new chain segment               blocks=1 txs=0   mgas=0.000 elapsed=5.041ms   mgasps=0.000   number=2569511 hash=1cf79e…f7236b dirty=3.43MiB
Apr 22 11:03:34 eth01 geth[522]: INFO [04-22|11:03:34.007] Deep froze chain segment                 blocks=4 elapsed=71.065ms  number=2479510 hash=2007e5…e94e94
Apr 22 11:03:37 eth01 geth[522]: INFO [04-22|11:03:37.458] Chain reorg detected                     number=2569510 hash=ebe97f…1009ce drop=1 dropfrom=1cf79e…f7236b add=2 addfrom=53a622…3b6c39
Apr 22 11:03:37 eth01 geth[522]: INFO [04-22|11:03:37.459] Imported new chain segment               blocks=1 txs=1   mgas=0.303 elapsed=27.667ms  mgasps=10.962  number=2569512 hash=53a622…3b6c39 dirty=3.45MiB
Apr 22 11:03:38 eth01 geth[522]: INFO [04-22|11:03:38.362] Chain reorg detected                     number=2569511 hash=2d60e9…b22847 drop=1 dropfrom=53a622…3b6c39 add=1 addfrom=0cb65e…64910c
Apr 22 11:03:38 eth01 geth[522]: INFO [04-22|11:03:38.363] Imported new chain segment               blocks=1 txs=1   mgas=0.303 elapsed=26.394ms  mgasps=11.491  number=2569512 hash=0cb65e…64910c dirty=3.46MiB

And alpha.4 beacon chain humming along:

Apr 22 12:27:19 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:19" level=info msg="RPC-API listening on port" address="0.0.0.0:4000" prefix=rpc
Apr 22 12:27:19 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:19" level=warning msg="You are using an insecure gRPC connection! Provide a certificate and key to connect securely" prefix=rpc
Apr 22 12:27:19 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:19" level=info msg="Connected to eth1 proof-of-work chain" endpoint="ws://192.168.XXX.XXX:8546" prefix=powchain
Apr 22 12:27:20 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:20" level=info msg="Blockchain data already exists in DB, initializing..." prefix=blockchain
Apr 22 12:27:20 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:20" level=info msg="Starting initial chain sync..." prefix=initial-sync
Apr 22 12:27:20 beacon01 beacon-chain[32262]: time="2020-04-22 12:27:20" level=info msg="Waiting for enough suitable peers before syncing" prefix=initial-sync required=7 suitable=0

Apr 22 12:28:26 beacon01 beacon-chain[32262]: time="2020-04-22 12:28:26" level=info msg="Executing state transition on block" prefix=blockchain root=0xb7e81032... slot=34342
Apr 22 12:28:26 beacon01 beacon-chain[32262]: time="2020-04-22 12:28:26" level=info msg="Finished applying state transition" attestations=13 attesterSlashings=0 deposits=0 prefix=blockchain proposerSlashings=0 slot=34342 voluntaryExits=0

🌍 Your Environment

Operating System:

  
Ubuntu 18.04 LTS
  

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

  
v1.0.0-alpha.5
  

Anything else relevant (validator index / public key)?

[prestonvanloon]

I believe we updated the ethclient in #5554

[metanull-operator]

This was s different variation I once saw, which includes an EOF error:

Apr 21 22:48:30 beacon02 beacon-chain[2512]: time="2020-04-21 22:48:30" level=warning msg="eth1 client is not syncing" prefix=powchain
Apr 22 10:23:22 beacon02 beacon-chain[2512]: time="2020-04-22 10:23:22" level=warning msg="Failed to handle p2p RPC" error="genesis time is not set" peer=16Uiu2HAmVauqo3yKF6kXxD1qaqXg3wD9kdaD12HGRr3MshMpo75J prefix=sync topic="/eth2/beacon_chain/req/status/1/ssz_snappy"
Apr 22 10:24:50 beacon02 beacon-chain[2512]: time="2020-04-22 10:24:50" level=warning msg="Subscription to new head notifier failed" error="websocket: close 1006 (abnormal closure): unexpected EOF" prefix=powchain
Apr 22 10:24:50 beacon02 beacon-chain[2512]: time="2020-04-22 10:24:50" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 192.168.XXX.XXX:8546: connect: connection refused" prefix=powchain
Apr 22 10:24:56 beacon02 beacon-chain[2512]: time="2020-04-22 10:24:56" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 192.168.XXX.XXX:8546: connect: connection refused" prefix=powchain
Apr 22 10:25:33 beacon02 beacon-chain[2512]: time="2020-04-22 10:25:33" level=info msg="Connected to eth1 proof-of-work chain" endpoint="ws://192.168.XXX.XXX:8546" prefix=powchain```

[prestonvanloon]

We've added some additional functionality to help in these scenarios in #5583. Eth1 node connection can negatively affect block proposals, but having a short timeout with a graceful fall back should help with this issue.

Given that, I'm lowering priority slightly.

[rauljordan]

Was your ETH1 node having problems @metanull-operator ? Are you still seeing the issue?

[nisdas]

@metanull-operator I am closing this, given this was resolved on your end in our offline conversations.