503 Error, and genesis time not set on fresh beaconchain setup

[Jwdev-wr]

🐞 Bug Report

Description

A clear and concise description of the problem...

When first starting up the beacon chain using --clear-db I was getting a repeating error with 503 error, and warning for genesis time not set. It would get some data from the PoW chain, and then drop back into error repeating and so on.. Seemed possibly related to peers.

It eventually will get through to processing blocks after a few times of restarting it.

Has this worked before in a previous version?

Yes, the previous version in which this bug was not present was: ....

🔬 Minimal Reproduction

I built the docker image using bazel image_bundle, and then launched the image using --clear-db flag.

🔥 Error

   GOROOT/src/runtime/asm_amd64.s:1373 peer=16Uiu2HAmLdcPNMwpFh4dide4r7Wcspdu747kt2CBueTFMK3TDtqd topic=/eth2/beacon_chain/req/status/1/ssz_snappy
[2020-05-26 00:03:40] ERROR powchain: Unable to process past logs 503 Service Unavailable
[2020-05-26 00:03:42]  INFO powchain: Connected to eth1 proof-of-work chain endpoint=wss://goerli.prylabs.net/websocket
[2020-05-26 00:04:12]  WARN sync: Failed to handle p2p RPC error=genesis time is not set
github.com/prysmaticlabs/prysm/shared/p2putils.CreateForkDigest
    shared/p2putils/fork.go:21
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).forkDigest
    beacon-chain/sync/subscriber.go:403
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).validateStatusMessage
    beacon-chain/sync/rpc_status.go:239
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).statusRPCHandler
    beacon-chain/sync/rpc_status.go:160
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).registerRPC.func1
    beacon-chain/sync/rpc.go:123
github.com/libp2p/go-libp2p/p2p/host/basic.(*BasicHost).SetStreamHandler.func1
    external/com_github_libp2p_go_libp2p/p2p/host/basic/basic_host.go:397
runtime.goexit
    GOROOT/src/runtime/asm_amd64.s:1373 peer=16Uiu2HAmEbP6WKWG5JAFHzdngvxGyBFdK8cq7bs4acTUbmnT1i7C topic=/eth2/beacon_chain/req/status/1/ssz_snappy1

🌍 Your Environment

Operating System:

  
Ubuntu 18.04 LTS
  

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

  
latest (alpha.8)

  

[cyber-hokie]

I am running into the same "genesis time is not set" issue on latest, alpha.8 (7be8942)

System: Windows 10 (Docker 2.3.0.2)
Prysm Version: alpha.8 (7be8942)
Previous Prysm Version: alpha.5 (95f1676)

Backstory: I was running alpha.5 (sorry, lazy node runner here) without issue up until late last night when it began throwing goodbye messages/stream errors and being unable to connect to peers. I decided to pull the latest release, alpha.8, and rebuilt my beacon-node container, not changing or modifying any data in the /data-dir using the same command as previously:
docker run -it --restart always -v c:/prysm/:/data -p 4000:4000 -p 13000:13000 --name beacon-node gcr.io/prysmaticlabs/prysm/beacon-chain:latest --datadir=/data --p2p-host-ip XXX.XXX.XXX.XXX --min-sync-peers 7 --p2p-max-peers 30

Current Issue: Now I am encountering multiple issues including the "genesis time is not set" error:

2020/05/27 17:19:12 maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined
[2020-05-27 17:19:12] INFO node: Checking DB database-path=/data/beaconchaindata
[2020-05-27 17:19:17] INFO node: Starting beacon node version=Prysm/Git commit: 7be8942. Built at: 2020-05-27 15:14:25+00:00
[2020-05-27 17:19:17] INFO rpc: RPC-API listening on port address=0.0.0.0:4000
[2020-05-27 17:19:17] WARN rpc: You are using an insecure gRPC connection! Provide a certificate and key to connect securely
[2020-05-27 17:19:17] INFO blockchain: Waiting to reach the validator deposit threshold to start the beacon chain...
[2020-05-27 17:19:17] INFO powchain: Connected to eth1 proof-of-work chain endpoint=wss://goerli.prylabs.net/websocket
[2020-05-27 17:19:31] WARN powchain: eth1 client is not syncing
[2020-05-27 17:20:01] WARN sync: Failed to handle p2p RPC error=genesis time is not set
github.com/prysmaticlabs/prysm/shared/p2putils.CreateForkDigest
shared/p2putils/fork.go:21
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).forkDigest
beacon-chain/sync/subscriber.go:403
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).validateStatusMessage
beacon-chain/sync/rpc_status.go:239
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).statusRPCHandler
beacon-chain/sync/rpc_status.go:160
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).registerRPC.func1
beacon-chain/sync/rpc.go:123
github.com/libp2p/go-libp2p/p2p/host/basic.(*BasicHost).SetStreamHandler.func1
external/com_github_libp2p_go_libp2p/p2p/host/basic/basic_host.go:397
runtime.goexit
GOROOT/src/runtime/asm_amd64.s:1373 peer=16Uiu2HAmUasofc9zVerwSFUDJkd7Hr43vkPdeKpYMR5DGU8zhmQe topic=/eth2/beacon_chain/req/status/1/ssz_snappy

[prestonvanloon]

@terencechain can you please triage or investigate. This might be a potential blocker for alpha.9

[terencechain]

I was able to reproduce the same issue with a clear-db, it eventually converges to work. This is likely due to flakey goreil node hosted by prysmatic labs. I highest recommend stakers to run their own eth1 node

[2020-05-27 10:34:41] ERROR powchain: Could not connect to powchain endpoint error=websocket: bad handshake (HTTP status 503 Service Unavailable)
could not dial eth1 nodes
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).connectToPowChain
	beacon-chain/powchain/service.go:340
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).waitForConnection
	beacon-chain/powchain/service.go:382
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).Start.func1
	beacon-chain/powchain/service.go:236
runtime.goexit
	GOROOT/src/runtime/asm_amd64.s:1373
[2020-05-27 10:34:58] ERROR powchain: Could not connect to powchain endpoint error=websocket: bad handshake (HTTP status 503 Service Unavailable)
could not dial eth1 nodes
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).connectToPowChain
	beacon-chain/powchain/service.go:340
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).waitForConnection
	beacon-chain/powchain/service.go:395
github.com/prysmaticlabs/prysm/beacon-chain/powchain.(*Service).Start.func1
	beacon-chain/powchain/service.go:236
runtime.goexit
	GOROOT/src/runtime/asm_amd64.s:1373
[2020-05-27 10:34:58]  INFO powchain: Connected to eth1 proof-of-work chain endpoint=wss://goerli.prylabs.net/websocket
[2020-05-27 10:37:00]  INFO powchain: Processing deposits from Ethereum 1 chain deposits=512 genesisValidators=492

I personally don't think this is a release blocker. Also cc @nisdas and @rauljordan for inputs. They more experiences in this field.

[cyber-hokie]

Tried rebuilding beacon-node container using docker pull gcr.io/prysmaticlabs/prysm/beacon-chain:HEAD-f831a7 per Stefan's instructions on Discord which reverted me to alpha.8 stable (f831a79). Did not appear to remedy the issue:

2020/05/27 17:37:05 maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined
[2020-05-27 17:37:05] WARN flags: Using default mainnet config
[2020-05-27 17:37:05] INFO node: Checking DB database-path=/data/beaconchaindata
[2020-05-27 17:37:10] INFO node: Starting beacon node version=Prysm/Git commit: f831a79. Built at: 2020-05-14 00:39:01+00:00
[2020-05-27 17:37:10] INFO rpc: RPC-API listening on port address=0.0.0.0:4000
[2020-05-27 17:37:10] WARN rpc: You are using an insecure gRPC connection! Provide a certificate and key to connect securely
[2020-05-27 17:37:10] INFO blockchain: Waiting to reach the validator deposit threshold to start the beacon chain...
[2020-05-27 17:37:10] INFO powchain: Connected to eth1 proof-of-work chain endpoint=wss://goerli.prylabs.net/websocket
[2020-05-27 17:37:15] WARN powchain: eth1 client is not syncing
[2020-05-27 17:38:41] WARN sync: Failed to handle p2p RPC error=genesis time is not set
github.com/prysmaticlabs/prysm/shared/p2putils.CreateForkDigest
shared/p2putils/fork.go:21
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).forkDigest
beacon-chain/sync/subscriber.go:403
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).validateStatusMessage
beacon-chain/sync/rpc_status.go:212
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).statusRPCHandler
beacon-chain/sync/rpc_status.go:152
github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).registerRPC.func1
beacon-chain/sync/rpc.go:123
github.com/libp2p/go-libp2p/p2p/host/basic.(*BasicHost).SetStreamHandler.func1
external/com_github_libp2p_go_libp2p/p2p/host/basic/basic_host.go:397
runtime.goexit
GOROOT/src/runtime/asm_amd64.s:1373 peer=16Uiu2HAkykz8ZjHiRoyXQLg7jcgQ9ydYH4cTe3gN2ovFf5ui1T39 topic=/eth2/beacon_chain/req/status/1/ssz_snappy

[prestonvanloon]

So one of the prylabs eth1 nodes is out of sync?
This issue should still resolve itself in the event that the eth1 node is out of sync and then becomes in sync again.

Maybe not a release blocker for alpha.9 but seems like a v1 blocking bug to me until we can gracefully recover from out of sync eth1 node

[terencechain]

Maybe not a release blocker for alpha.9 but seems like a v1 blocking bug to me until we can gracefully recover from out of sync eth1 node

I agree

[nisdas]

This doesn't really have to do with powchain but rpc, a peer is pinging @cyber-hokie @Jwdev-wr before they have reached genesis. So that is why the error comes about, its a mostly cosmetic error but I will try to get this fixed soon. Its not really a blocker for release

[nisdas]

This should be fixed by #6020 , we can add that to our next release.