Beacon node doesn't notice finished up sync of geth

[stefa2k]

💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎💎-->

🐞 Bug Report

Description

Beacon node starts at the same time as geth. Geth syncs up, but beacon node doesn't notice geth is synced up and stays in "waiting" mode. After restarting the beacon node it connects properly to geth and starts working.

# docker-compose logs --tail=10 geth
Attaching to geth
geth          | INFO [06-06|13:44:07.227] Upgrading chain index                    type=bloombits                               percentage=84
geth          | INFO [06-06|13:44:08.389] Deep froze chain segment                 blocks=4     elapsed=11.025ms    number=2737025 hash="aaa840…12179c"
geth          | INFO [06-06|13:44:15.341] Upgrading chain index                    type=bloombits                               percentage=90
geth          | INFO [06-06|13:44:18.210] Chain reorg detected                     number=2827024 hash="bcc65d…6e7087" drop=2 dropfrom="1b9dc0…1342c0" add=3 addfrom="276590…8d1439"
geth          | INFO [06-06|13:44:18.211] Imported new chain segment               blocks=1     txs=0   mgas=0.000  elapsed=1.178ms     mgasps=0.000   number=2827027 hash="276590…8d1439" dirty=3.87MiB
geth          | INFO [06-06|13:44:23.399] Upgrading chain index                    type=bloombits                               percentage=95
geth          | INFO [06-06|13:44:30.184] Finished upgrading chain index           type=bloombits
geth          | INFO [06-06|13:44:33.070] Imported new chain segment               blocks=1     txs=1   mgas=0.051  elapsed=3.033ms     mgasps=16.801  number=2827028 hash="d25b94…0f0ad1" dirty=3.88MiB
geth          | INFO [06-06|13:44:34.878] Imported new chain segment               blocks=1     txs=1   mgas=0.051  elapsed=2.586ms     mgasps=19.698  number=2827028 hash="708565…1d4e41" dirty=3.89MiB
geth          | INFO [06-06|13:44:48.880] Imported new chain segment               blocks=1     txs=0   mgas=0.000  elapsed="644.485µs" mgasps=0.000   number=2827029 hash="36562e…8536d1" dirty=3.89MiB
# docker-compose logs --tail=10 beacon
Attaching to beacon-chain
beacon-chain  | time="2020-06-06 13:43:57" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:03" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:09" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:15" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:21" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:27" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:33" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:39" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:45" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
beacon-chain  | time="2020-06-06 13:44:51" level=error msg="Could not connect to powchain endpoint" error="could not dial eth1 nodes: dial tcp 172.18.0.2:8546: connect: cannot assign requested address" prefix=powchain
# docker-compose stop beacon && docker-compose up -d beacon
Stopping beacon-chain ... done
geth is up-to-date
Starting beacon-chain ... done
# docker-compose logs --tail=10 beacon
Attaching to beacon-chain
beacon-chain  | time="2020-06-06 13:45:10" level=info msg="Stopping beacon node" prefix=node
beacon-chain  | time="2020-06-06 13:45:10" level=error msg="Received a nil head subscription, exiting service" prefix=powchain
beacon-chain  | time="2020-06-06T13:45:30Z" level=error msg="Failed to calculate roughtime offset" error="no valid responses" prefix=roughtime
beacon-chain  | 2020/06/06 13:45:30 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined
beacon-chain  | time="2020-06-06 13:45:30" level=info msg="Checking DB" database-path="/data/beaconchaindata" prefix=node
beacon-chain  | time="2020-06-06 13:45:30" level=info msg="Starting beacon node" prefix=node version="Prysm/Git commit: 3fe47c00433907176d44521d01ee97b1b0cab8ca. Built at: 2020-05-28 17:40:20+00:00"
beacon-chain  | time="2020-06-06 13:45:30" level=info msg="Waiting to reach the validator deposit threshold to start the beacon chain..." prefix=blockchain
beacon-chain  | time="2020-06-06 13:45:30" level=info msg="RPC-API listening on port" address="0.0.0.0:4000" prefix=rpc
beacon-chain  | time="2020-06-06 13:45:30" level=warning msg="You are using an insecure gRPC connection! Provide a certificate and key to connect securely" prefix=rpc
beacon-chain  | time="2020-06-06 13:45:30" level=info msg="Connected to eth1 proof-of-work chain" endpoint="ws://geth:8546" prefix=powchain

Has this worked before in a previous version?

Never worked in any version I ran

🔬 Minimal Reproduction

git clone https://github.com/stefa2k/prysm-docker-compose
docker-compose up -d geth beacon

Wait for geth to sync up and look at the logs of beacon.

🌍 Your Environment

Operating System:

  
Ubuntu 18.04 LTS
Ubuntu 20.04 LTS
  

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

  
alpha.8
alpha.9
  

Anything else relevant (validator index / public key)?

[nisdas]

We did update our geth version, so that might have had something to do with it. Although can you consistently reproduce this ?

[stefa2k]

Not reproducible anymore with alpha.10